経過時間測定テクニック

組込みシステムの開発では特定のコードの実行時間を要求仕様より短くすることが必須です。実行速度は多くの場合アプリケーションにとって極めて重要で、アルゴリズムを修正したり、コンパイラの最適化を適用したりすることで向上が可能です。しかしながら、コードのパフォーマンス改善に取り組む前に実際の処理速度を計測する必要があります。

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

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

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

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

特徴

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

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

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

Measuring elapsed time 1

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

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

Measuring elapsed time 3

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

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

テクニック 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の使い方

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

Measuring elapsed time 4

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

Measuring elapsed time 5

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

Measuring elapsed time 6

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

Measuring elapsed time 7

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にセットにしてください。

Measuring elapsed time 8

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を使用するように指定します。

Measuring elapsed time 9Measuring elapsed time 10

サンプルコード:

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’のデータログブレークポイントを設定 を選択します。

Measuring elapsed time 11

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

Measuring elapsed time 12

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

Measuring elapsed time 13

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

Measuring elapsed time 14

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

Measuring elapsed time 15

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

Measuring elapsed time 16

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

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

Measuring elapsed time 18

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

Measuring elapsed time 19

'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のいずれかを指定します。

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

Measuring elapsed time 20

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

Measuring elapsed time 21

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

Measuring elapsed time 22

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

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

Measuring elapsed time 23

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 > タイムラインウィンドウ を開きます。

Measuring elapsed time 24

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

Measuring elapsed time 25

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

Measuring elapsed time 26

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

Measuring elapsed time 27

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

Measuring elapsed time 28

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

Measuring elapsed time 29

まとめ

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

申し訳ございませんが、弊社サイトではInternet Explorerをサポートしていません。サイトをより快適にご利用いただくために、Chrome、Edge、Firefoxなどの最新ブラウザをお使いいただきますようお願いいたします。