コードの実行時間の計測方法

GPIOピンを使用してオシロスコープでタイミングを観測する手法は、もちろん有効かつ現実的なアプローチです。しかし、MCUや開発ツールが提供する機能を使用すれば、より簡単かつ精密に実行時間を計測することができます。

本記事では、Cortex-M3/M4デバイスとIAR Embedded Workbench for ARMを使用してコードの実行時間を測定するための3つの基本的なテクニックと応用テクニックをいくつか紹介します。

テクニック 1: ログブレークポイントの使用

そこまで正確さを求めず簡単に計測をしたいときに、ログブレークポイントが有用です。ログブレークポイントをセットされたコードが実行されると、使用しているコンピュータの時間がデバッグログウィンドウに表示されます。

特徴

• ソースコードの修正不要
• ログブレークポイントを使用
• 精度は1秒単位

ログブレークポイントの使用方法

実行時間を知りたいコード上で右クリックして、ブレークポイントの切り替え（ログ）を選択.

Lと記載されたブレークポイントが表示されます。

このコードは1秒ごとに実行されるTimer割込みハンドラです。実行結果はデバッグログウィンドウに、下記のように出力されます。

実行時の時間、該当のソースコードおよび、呼ばれた回数が表示

このテクニックは、精度の必要な計測には不向きですが、簡単に計測したい場合には最適な手法です。たとえば同じ処理のループを数千回回して前後の時間を比較する、といった使い方も可能です。

テクニック 2: MCUのCycleCountレジスタを使用

近年のMCUでは実行時間を取得するためのレジスタを搭載していることがあります。ARM Cortex-M3/4/7デバイスではCYCLECOUNTERというレジスタを搭載しています。
コードの2点のCYCLECOUNTERの値を取得しCPUクロック周波数を使って計算をすることで、実処理時間を求めることができます。たとえば、CPUが100MHzで動いている場合、100,000,000（1億）で割ることで、実際に経過した秒数を求めることができます。

特徴

• ソースコードの修正不要
• 精度はCPUサイクル単位
• CYCLECOUNTERレジスタを搭載しているかどうかはデバイス依存

IAR Embedded Workbench for ARMはCYCLECOUNTERを独自に拡張しています。前回表示時のCYCLECOUNTERとの差分をCCSTEPレジスタで簡単に確認することができます。

CYCLECOUNTERの使い方

レジスタウィンドウを開きます。

CPUレジスタを選択します。

CYCLECOUNTERは開始時からの経過サイクルを示します。CCSTEPは前回の表示からの差分サイクルを示します。

ステップオーバをクリックすることで、CYCLECOUNTERの増加と、その増加サイクルがCCSTEPに表示されます。

424（Current CYCLECOUNTER） – 416（Previous CYCLECOUNTER） = 8（Current CCSTEP）

CYCLECOUNTERはARM Cortex-M3/4/7 MCUで提供されていますが、IAR Embedded Workbenchではデフォルトで無効になっています。I-jetを使用する場合、CYCLECOUNTERは自動的に有効になります。その他のエミュレータ（ICE）を使用していてCYCLECOUNTERの値が更新されない場合、Data Watchpoint and Traceレジスタカテゴリの中のDWT Controlレジスタ、CYCNTENAビット（DWT_CTRL.CYCNTEN）を1にセットにしてください。

CYCLECOUNTERは簡単に使用できて、正確に測定することが可能です。実時間が必要な場合はCPUクロックで割ることで求めることができます。CYCLECOUNTERはパイプラインやキャッシュの状態によって差が生じる可能性があります。1命令、2命令単位ではなく数十命令単位以上で使用することを推奨します。

テクニック 3: MCUタイマーの使用

タイマーはMCUに指定時間で処理をさせるために重要な機能です。タイマーのカウントアップ/カウントダウン割込みを使用することが多くありますが、カウント値を読むことで実行時間の計測をすることも可能です。

特徴

• ソースコードの変更が必要
• タイマー設定が必要
• タイマー値にアクセスするコードが必要
• サイクル単位の計測が可能
• タイマー設定はMCU毎に異なるが、同様のアプローチが適用可能

MCUタイマーの使い方

最初に確認するのは、クロックソースとプリスケーラです。プリスケーラが10であれば、クロックソースの10サイクルごとに、タイマー値がカウントアップ・ダウンされます。クロックソースがCPUクロックと一緒で、たとえばプリスケーラが1000でCPUクロックが100MHzであれば、タイマーカウントが100のときに0.001秒、つまり1msが経過時間として求められます。

unsigned int cnt1 = 0;
unsigned int cnt2 = 0;

 cnt1 = TIM3->CNT;
 func();
 cnt2 = TIM3->CNT;
 printf("cnt1:%u cnt2:%u diff:%u \n",cnt1,cnt2,cnt2-cnt1);

以下のように結果が出ます。

cnt1:370 cnt2:740 diff:370

タイマーを他の機能でも使用していた場合、割込みが発生した際にカウントはリセットされてしまいますので、計測専用にタイマーを使用することを推奨します。コード実行がブレークポイントなどで停止しているときでもタイマーのカウントは実行されていることがあります。したがって、値は変数などに取得しておく必要があります。

なお、ARM Cortex-M共通のSystickTimerは、CPUが停止中はカウントを停止します。これにより、時間の計測を手軽に行うことができるため、CYCLECOUNTERレジスタを搭載していないCortex-M0/M0+ MCUでは特に有効な手段です。

テクニック 4: データログブレークポイントの使用

データログブレークポイントはARM Cortex-M3/M4デバイスの持っている便利なデバッグ機能の一つです。SWD/SWOをサポートしている、I-jetなどのICE(エミュレータ)を使用することで、データアクセスのログを取ることができ、またタイムスタンプをリアルタイムに取得することが可能です。

デバッグを開始する前にICEの設定をSWDとSWOを使用するように指定します。

サンプルコード:

static int data_main = 0;
static int data_systick = 0;

void Delay(Int32U Dly)
{
  for(volatile Int32U j = Dly; j; j--) { }
}

void SysTick_Handler(void)
{
  data_systick += 10;
}

void main(void)
{
  SystemInit();
  SysTick_Config(900000);
  SysTick_CLKSourceConfig(SysTick_CLKSource_HCLK_Div8);
  
  while(1)
  {
    Delay(100000);
    data_main++;
  }
}

mainループでは data_main 変数が一定のディレイごとにインクリメントされます。SysTick 割込みハンドラでは data_systick 変数をインクリメントしています。データログブレークポイントを使用することで、変数の値とタイミングを見ることができます。

データログブレークポイントの使用方法

エディタ画面のdata_main 変数の上で右クリックして ’data_main’のデータログブレークポイントを設定 を選択します。

data_systick についても同様にデータログブレークポイントを設定します。

C-SPYデバッグセッションを開始します。

データログブレークポイントはエディタ画面に表示されません。
データログブレークポイントを確認するには　表示->ブレークポイント　を選択してください。

リストウィンドウ内で、データログブレークポイントを確認できます。

データログは、デフォルトでは無効になっています。有効にするために、データログウィンドウを開きます。 （I-jet/JTAGjet > データログ）

ウィンドウ内で右クリックして 有効化 を選択します。

ターゲットが実行され、2変数へのアクセスが発生すると、値と時間がデータログウィンドウに表示されます。

サイクルベースのカウントで確認することも可能です。

'data_main' W:12 と'data_main' W:13のデータを見てみると、差分は866,768サイクルであることがわかります。つまりDelay(100000)はおよそ866,768サイクルだと見なすことができます。

元々、データログはデータアクセスをトレースするための機能ですが、このようにコード実行やタイミングのトレースへの適用も実用的なアプローチです。

注:

• データログブレークポイントを設定する変数は、静的変数やグローバル変数など、固定アドレスが割り当てられている必要があります。
• データログについては、余分なオーバヘッドはありません。
• ARM Cortex-M3/M4の仕様により、設定可能なデータログブレークポイントの数は4つとなります。

テクニック 5: イベントログを使用

イベントログは、ARM Cortex-M3/M4のもう一つのデバッグ機能です。アプリケーション中にイベントコードを追記することで、そのコードが実行されるごとにイベントログが生成されます。

データログのテストコードを少し修正します。

static int data_main = 0;
static int data_systick = 0;

#include <arm_itm.h>

void Delay(Int32U Dly)
{
  for(volatile Int32U j = Dly; j; j--) { }
}

void SysTick_Handler(void)
{
  data_systick += 10;
  ITM_EVENT32_WITH_PC(2,data_systick);
}

void main(void)
{
  SystemInit();
  SysTick_Config(900000);
  SysTick_CLKSourceConfig(SysTick_CLKSource_HCLK_Div8);
  while(1)
   {
     Delay(100000);
     data_main++;
     ITM_EVENT32_WITH_PC(1,data_main);
   }
}

イベントログを使用するためにarm_itm.hファイルをインクルードする必要があります。

ITM_EVENT32_WITH_PC は上記ヘッダファイルで定義されているマクロで、最初の引数がチャンネル、2つ目の引数がデータとなります。データは定数かあるいは変数を指定します。チャンネルは1から4のいずれかを指定します。

デバッグ画面でイベントログを使用するために、イベントログウィンドウを開き有効化します。

イベントログウィンドウを右クリックし 有効化 を選択します。

準備ができたのでアプリケーションを実行してみます。イベントログデータが取得されます。

チャンネル1で指定したデータはITM1列に、チャンネル2で指定した変数はITM2列に表示されます。
値だけでなく、マクロコード実行時のプログラムカウンタやタイムスタンプも取得できます。

サイクル単位で表示することも可能です。

ITM1の56と57の間は48,541,271 – 47,674,478 = 866,793となります。この数値は、データログで確認したものとほぼ同じ数値となります。

注:

• ITMイベントマクロはコードサイズと実行時間に若干のオーバヘッドがあります。短すぎないコードの実行時間計測に適しています。
• arm_itm.h ファイルの中では、ITM_EVENT16_WITH_PC、ITM_EVENT16などのマクロも用意されています。
  また、プログラムカウンタ情報が不要な際にはITM_EVENT8, 16, 32などを使用することでオーバヘッドを減らすことが可能です。

イベントログのデータはテキストファイルで保存でき、後から解析することが可能です。

データログとイベントログをタイムラインウィンドウに表示

データログとイベントログは、同一時間軸を使用しタイムラインウィンドウ内でで表示させることが可能です。データアクセスやITMイベントがどのようなタイミングで発生し、時差がどの程度かを計測することもできます。

I-jet /JTAGjet > タイムラインウィンドウ を開きます。

タイムラインウィンドウ内にいくつかの項目が表示されます。データログのペインと、イベントのペインを右クリックし 有効化 を選択します。

時間軸のスケールは、ウィンドウ内を右クリックし ズーム から選択可能です。

これで、データログのデータとITMイベントのデータをタイムスタンプ情報とともに可視化することができます。

データ上にマウスオーバーすると、詳細な時間情報を見ることができます。

時間範囲を選択することで、該当範囲の時間情報を取得することも可能です。

まとめ

コードパフォーマンスの最適化に取り組む前に、測定環境を整える必要があります。経過時間を測定するためには、汎用的なテクニックとMCU特有のテクニックが存在します。 この記事で紹介したテクニックを参考にすることで、皆さんの評価環境やデバッグ目的に合わせた測定方法を構築することが可能です。ここで紹介した機能の詳細についてはIAR Embedded WorkbenchのヘルプメニューからC-SPYデバッグガイドを参照してください。