Chapter 21

デバッグとトレース — 見えないものは直せない

この章がなぜ必要なのか——RTOS のバグはブレークポイントで追えない.

シングルスレッドのプログラムなら、ブレークポイントを置いて 1 行ずつ追えばよい。

だが RTOS では、止めた瞬間にタイミングが変わる。 レースコンディションは消え、デッドラインは全部破られ、 ウォッチドッグが発火し、通信相手はタイムアウトする。

「止めずに見る」技術が要る。 それがトレースである。

この章で使う既出の用語（定義は各リンク先）. TCB（02 章 2 節）、スタック（02 章 2 節）、タスク（02 章 2 節）、スケジューラ（03 章 2 節）、移植層（03 章 2 節）、Blocked（04 章 1 節）、Ready（04 章 1 節）、Running（04 章 1 節）、Suspended（04 章 1 節）、時間待ち（04 章 4 節）、CFS（06 章 1 節）、FreeRTOS（06 章 4 節）、削除（07 章 2 節）、ウォッチドッグ（09 章 5 節）、タイムアウト（10 章 3 節）、ブロック（13 章 1 節）、キュー（14 章 7 節）、ティック（15 章 1 節）、MPU（17 章 5 節）、デッドライン（20 章 2 節）、周期（20 章 2 節）

1. まず設定を正しくする

デバッグの前に、カーネルが用意している検出機構を全部有効にする。

/* 開発中は必ずこの構成にする */
#define configASSERT( x )                    if( ( x ) == 0 ) { vAssertCalled( __FILE__, __LINE__ ); }
#define configCHECK_FOR_STACK_OVERFLOW       2
#define configUSE_MALLOC_FAILED_HOOK         1
#define configUSE_TRACE_FACILITY             1
#define configGENERATE_RUN_TIME_STATS        1
#define configUSE_STATS_FORMATTING_FUNCTIONS 1
#define configRECORD_STACK_HIGH_ADDRESS      1
#define configQUEUE_REGISTRY_SIZE            10

configASSERT の実装

void vAssertCalled( const char *pcFile, unsigned long ulLine )
{
    volatile unsigned long ul = 0;

    taskENTER_CRITICAL();
    {
        /* デバッガで止まったら、pcFile と ulLine を見る。
           ul に 0 以外を書き込めば処理を継続できる */
        while( ul == 0 ) { __NOP(); }
    }
    taskEXIT_CRITICAL();
}

configASSERT は「300 か所以上の無料のチェック」である.

• ISR から非 ISR 版 API を呼んだ
• 割り込み優先度の設定が間違っている（18 章）
• ハンドルが NULL
• vTaskDelay をスケジューラ停止中に呼んだ
• ミューテックスを所有者以外が Give した

これらが即座に、原因の場所で捕まる。 定義しないと、全部が「後で起きる謎の暴走」に化ける。

2. 実行時間統計 — 誰が CPU を食っているか

#define configGENERATE_RUN_TIME_STATS  1

/* 高分解能タイマを用意する（ティックの 10〜100 倍の分解能が目安） */
#define portCONFIGURE_TIMER_FOR_RUN_TIME_STATS()  vConfigureTimerForRunTimeStats()
#define portGET_RUN_TIME_COUNTER_VALUE()          ulGetRunTimeCounterValue()

/* Cortex-M の DWT サイクルカウンタを使う例 */
void vConfigureTimerForRunTimeStats( void )
{
    CoreDebug->DEMCR |= CoreDebug_DEMCR_TRCENA_Msk;
    DWT->CYCCNT = 0;
    DWT->CTRL  |= DWT_CTRL_CYCCNTENA_Msk;
}

uint32_t ulGetRunTimeCounterValue( void )
{
    return DWT->CYCCNT;
}

カーネルは、コンテキストスイッチのたびにタスクごとの実行時間を積算する。

/* vTaskSwitchContext の中 */
#if ( configGENERATE_RUN_TIME_STATS == 1 )
{
    ulTotalRunTime = portGET_RUN_TIME_COUNTER_VALUE();

    if( ulTotalRunTime > ulTaskSwitchedInTime ) {
        pxCurrentTCB->ulRunTimeCounter += ( ulTotalRunTime - ulTaskSwitchedInTime );
    }
    ulTaskSwitchedInTime = ulTotalRunTime;
}
#endif

結果を見る

char buf[ 1024 ];
vTaskGetRunTimeStats( buf );
printf( "%s", buf );

Task            Abs Time        % Time
------------------------------------------
IDLE            48219341        72%
Control          8721053        13%
Comm             4102938         6%
Display          3011882         4%
Tmr Svc           892011         1%
LogTask           610223         <1%

IDLE の割合が CPU の余裕である。 上の例では 72 % 空いている。

実行時間統計を見る

タスクの負荷を変えて、CPU 配分がどう変わるかを確かめられる。

カウンタのオーバーフローに注意.

DWT のサイクルカウンタは 32 bit である。 168 MHz なら 25.6 秒で折り返す。

長時間の統計を取りたいなら、 ティックの数倍程度の粗いタイマを使うか、 定期的に統計をリセットする必要がある。

/* 目安: ティック周波数の 10〜100 倍 */
/* 1 kHz ティックなら 10〜100 kHz のタイマ */

3. タスクの一覧を見る

char buf[ 512 ];
vTaskList( buf );
printf( "%s", buf );

Name          State  Priority  Stack  Num
------------------------------------------
Control         R        4       142    2
Comm            B        3        88    3
Display         B        2       210    4
IDLE            R        0       112    1
Tmr Svc         B        5       180    5

vTaskList() と vTaskGetRunTimeStats() は本番で使ってはいけない.

どちらも内部で vTaskSuspendAll() を呼び、全タスクを走査する。 タスクが 10 個あれば数百マイクロ秒かかる。その間、全タスクの起床が遅れる（10 章）。

開発時のデバッグ用と割り切ること。 本番でも統計が欲しいなら、uxTaskGetSystemState() で生データを取り、 整形は別の場所（PC 側）で行う。

プログラムから取る

UBaseType_t n = uxTaskGetNumberOfTasks();
TaskStatus_t *pxStatus = pvPortMalloc( n * sizeof( TaskStatus_t ) );
uint32_t ulTotalRunTime;

n = uxTaskGetSystemState( pxStatus, n, &ulTotalRunTime );

for( UBaseType_t i = 0; i < n; i++ ) {
    /* pxStatus[i].pcTaskName
       pxStatus[i].eCurrentState
       pxStatus[i].uxCurrentPriority
       pxStatus[i].usStackHighWaterMark
       pxStatus[i].ulRunTimeCounter          */
}
vPortFree( pxStatus );

4. トレースフック — カーネルの動きを記録する

FreeRTOS には、カーネルの要所に空のマクロが埋め込まれている。 定義すれば、そこにコードを差し込める。

/* FreeRTOSConfig.h か、専用のヘッダで定義する */
#define traceTASK_SWITCHED_IN()     record_event( EV_SWITCH_IN,  pxCurrentTCB->uxTCBNumber )
#define traceTASK_SWITCHED_OUT()    record_event( EV_SWITCH_OUT, pxCurrentTCB->uxTCBNumber )
#define traceQUEUE_SEND( q )        record_event( EV_QSEND,      (uint32_t)(q) )
#define traceQUEUE_RECEIVE( q )     record_event( EV_QRECV,      (uint32_t)(q) )
#define traceTASK_DELAY()           record_event( EV_DELAY,      pxCurrentTCB->uxTCBNumber )
#define traceTASK_CREATE( t )       record_event( EV_CREATE,     (uint32_t)(t) )

主なトレースフック

traceTASK_PRIORITY_INHERIT は非常に有用である.

優先度継承が起きているということは、優先度逆転が発生しているということである。 これが頻繁に起きているなら、設計を見直す価値がある。

volatile uint32_t g_inherit_count = 0;
#define traceTASK_PRIORITY_INHERIT( pxTCB, uxPri )  g_inherit_count++

この 1 行だけでも、有用な情報が得られる。

自前の簡易トレーサ

typedef struct { uint32_t ts; uint8_t ev; uint8_t id; uint16_t arg; } TraceRec_t;

#define TRACE_DEPTH  512
static TraceRec_t g_trace[ TRACE_DEPTH ];
static volatile uint32_t g_trace_idx = 0;

static inline void record_event( uint8_t ev, uint32_t arg )
{
    uint32_t i = g_trace_idx++ & ( TRACE_DEPTH - 1 );    /* リングバッファ */
    g_trace[ i ].ts  = DWT->CYCCNT;
    g_trace[ i ].ev  = ev;
    g_trace[ i ].arg = ( uint16_t ) arg;
}

記録処理は必ず「短く・ブロックせず・排他を使わず」書くこと.

トレースはカーネルの深部（クリティカルセクションの中を含む）から呼ばれる。 ここで重い処理をすると、測定対象の挙動が変わってしまう（観測者効果）。

• リングバッファに書くだけにする
• printf は絶対に使わない
• ミューテックスも使わない（インデックスは 2 の冪でマスクして、 多少の取りこぼしは許容する）

記録したデータは、後から別のタスクでゆっくり吐き出す。

5. 市販のトレースツール

これらを使うと、こういう図が得られる。

時間 →
Control  ██░░░░░░░░██░░░░░░░░██░░░░░░░░
Comm     ░░████░░░░░░░░████░░░░░░░░████
Display  ░░░░░░████░░░░░░░░░░██░░░░░░░░
IDLE     ░░░░░░░░░░██░░░░░░░░░░░░██░░░░
ISR      ▌  ▌  ▌  ▌  ▌  ▌  ▌  ▌  ▌  ▌
         ↑
     ここで Comm が Control を待たせている

タイムライン表示の価値は非常に大きい.

「なぜか応答が遅い」という問題は、目で見れば一瞬で分かることが多い。

• 誰が誰を待たせているか
• どこで優先度逆転が起きているか
• 割り込みがどれだけ CPU を食っているか

数値の羅列より、1 枚の図の方が速い。 商用ツールは有償だが、難しい問題を 1 つ解決できれば元が取れる。

6. RTT（Real-Time Transfer）

SEGGER が開発した、デバッグ用の高速な出力路である。

• 対象のメモリ上にリングバッファを置く
• デバッガ（J-Link）が動作中の CPU を止めずにそのメモリを読む
• UART より 100 倍以上速い（数 MB/s）

SEGGER_RTT_printf( 0, "value = %d\n", x );

printf によるデバッグの最大の問題は「遅い」ことである.

115200 bps の UART で 80 文字を出すと、約 7 ms かかる。 1 ms 周期のタスクから呼んだら、システムが破綻する。

RTT なら数マイクロ秒で済むので、 リアルタイム性を大きく壊さずにログが出せる。

RTT が使えないなら、ログをキューに積んで、低優先度タスクで吐き出す。

void log_msg( const char *s ) {
    xQueueSend( xLogQueue, &s, 0 );    /* ポインタだけ送る。失敗しても捨てる */
}

void vLogTask( void *pv ) {
    const char *s;
    for (;;) {
        xQueueReceive( xLogQueue, &s, portMAX_DELAY );
        uart_puts( s );                /* ここでだけ時間を使う */
    }
}

7. ハードフォールトの解析

Cortex-M でクラッシュしたとき、フォールトハンドラで原因を特定できる。

void HardFault_Handler( void )
{
    __asm volatile (
        " tst lr, #4          \n"       /* どちらのスタックを使っていたか */
        " ite eq              \n"
        " mrseq r0, msp       \n"
        " mrsne r0, psp       \n"
        " b hard_fault_handler_c \n"
    );
}

void hard_fault_handler_c( uint32_t *sp )
{
    volatile uint32_t r0  = sp[0];
    volatile uint32_t r1  = sp[1];
    volatile uint32_t r2  = sp[2];
    volatile uint32_t r3  = sp[3];
    volatile uint32_t r12 = sp[4];
    volatile uint32_t lr  = sp[5];
    volatile uint32_t pc  = sp[6];      /* ★ クラッシュした命令のアドレス */
    volatile uint32_t psr = sp[7];

    volatile uint32_t cfsr = SCB->CFSR;  /* 何が起きたか */
    volatile uint32_t hfsr = SCB->HFSR;
    volatile uint32_t mmar = SCB->MMFAR; /* MPU 違反のアドレス */
    volatile uint32_t bfar = SCB->BFAR;  /* バスフォールトのアドレス */

    ( void ) r0; ( void ) r1; ( void ) r2; ( void ) r3;
    ( void ) r12; ( void ) lr; ( void ) psr;
    ( void ) cfsr; ( void ) hfsr; ( void ) mmar; ( void ) bfar;

    for( ;; );      /* デバッガで止めて上の変数を見る */
}

pc をマップファイルと突き合わせれば、クラッシュした関数が分かる。

UNDEFINSTR が出たら、まずスタックオーバーフローを疑う（17 章）. スタックが壊れて戻りアドレスが化け、データ領域にジャンプした——というのが典型である。

FreeRTOS のどのタスクで落ちたか

pxCurrentTCB を見れば分かる。

extern TCB_t * volatile pxCurrentTCB;
/* デバッガで pxCurrentTCB->pcTaskName を見る */

8. デバッグの手順

ハングしたときの見どころ

9. この章のまとめ

次章は最終章である。ここまでの内容を設計指針としてまとめ、 他の OS との比較で FreeRTOS の位置づけを確認する。