Skip to content

Progress Log: Duration Timestamp Consistency Analysis (v1.9.3)

Task Description

v1.9.2（detection_processでのバッファリング）を実装した後、シリアルモニターの出力を確認したらtimedelta_usフィールドで異常な差分を発見した。 （duration_us -> timedelta_usにリネームした）

  • キューなし（ENABLE_FREERTOS_QUEUE=0）: timedelta_us = 76-88 us
  • キューあり（ENABLE_FREERTOS_QUEUE=1）: timedelta_us = 2330-2357 us
  • キューを有効にしたほうが約30倍大きい

この時刻の差分の根本原因を調査し、設計上の問題かバグかを判定した。 また、v1.9.3での修正方針を検討した。

作業スコープ

  • DEADTIME_MS=0でビルドし、ハードウェアテストで実測した結果を分析
  • 両モード間のtimedelta_usの計算ロジックを比較
  • タイムスタンプ基準点のズレの根本原因を特定
  • v1.9.3での修正方針の評価

Outcome

ハードウェアテストの結果（実測値）

  • ENABLE_FREERTOS_QUEUE=0（キューなし）
    • DEADTIME_MS=0でビルド
    • timedelta_us: 76-88 us (typical)
    • イベント間隔: ~50-60ms
    • GET_BUFFER_STATSコマンド：未実装（エラー応答を確認）
  • ENABLE_FREERTOS_QUEUE=1（キューあり）
    • DEADTIME_MS=0でビルド
    • timedelta_us: 2330-2357 us (typical)、514646 us（コマンド実行中）
    • イベント間隔: ~50-60ms
    • GET_BUFFER_STATSコマンド：統計情報を確認

根本原因の分析

3つのタイムスタンプ基準点が異なるタイミングで記録される

Timeline of detection_process()

以下のシーケンス図は、2つの連続した検出イベント（Event 1, Event 2）における時刻計測ポイントの関係を示します：

sequenceDiagram
    participant Main as Main Loop<br/>(loop())
    participant Detector as Cosmic Detector<br/>(detection_process)
    participant Serial as Serial / Queue<br/>(send/buffer)
    participant LED as LED Control<br/>(delay 50ms)

    Note over Detector: Event 1<br/>Detection Cycle

    Detector->>Detector: T_A1: current_micros = micros()<br/>(Detection Time)
    Note right of Detector: A1点 = 検出時刻<br/>timedelta_us = T_A1 - T_C0

    Detector->>Detector: センサー読み込み<br/>(GPIO HAL / ADC)
    Note right of Detector: ~1-2ms 処理時間

    Detector->>Serial: T_B1: detection_buffer_queue()<br/>or send_sensor_data()
    Note right of Serial: B1点 = キュー/送信時刻<br/>データ記録

    Detector->>LED: LED フィードバック開始
    LED->>LED: delay(50ms)<br/>(T_LED遅延)
    Note right of LED: LED点灯 → 遅延 → 消灯

    Detector->>Detector: T_C1: last_event_time_us = micros()<br/>(Next Reference)
    Note right of Detector: C1点 = 次回計測基準<br/>T_C1 = T_A1 + LED遅延 + その他処理

    Note over Main,LED: イベント間隔<br/>~50-60ms<br/>(宇宙線の検出なし)

    Note over Detector: Event 2<br/>Detection Cycle

    Detector->>Detector: T_A2: current_micros = micros()<br/>(Detection Time)
    Note right of Detector: A2点 = 検出時刻<br/>timedelta_us = T_A2 - T_C1

    Detector->>Detector: センサー読み込み<br/>(GPIO HAL / ADC)

    Detector->>Serial: T_B2: detection_buffer_queue()<br/>or send_sensor_data()

    Detector->>LED: LED フィードバック
    LED->>LED: delay(50ms)

    Detector->>Detector: T_C2: last_event_time_us = micros()
    Note right of Detector: C2点 = 次回計測基準

時刻ポイント解説

ポイント 説明 実装箇所
A点 検出時刻（current_micros = micros()） detection_process() 冒頭
B点 キュー/送信時刻（detection_buffer_queue() or send_sensor_data()） 検出後 ~1-2ms
C点 次回計測基準（last_event_time_us = micros()） LED制御後、リセット前
T_LED LED遅延（delay(50ms)） B点 → C点 の間

timedelta_us計算

  • Event 1: timedelta_us = T_A1 - T_C0（前回のC点から現在の検出まで）
  • Event 2: timedelta_us = T_A2 - T_C1（前回のC点から現在の検出まで）
  • 観測される値: ~50-60 ms（イベント間隔）+ A点での計測時刻差
  • 問題点: ENABLE_FREERTOS_QUEUEの有無で、C点の更新タイミングが異なり、timedelta_usの値が相互に影響

なぜENABLE_FREERTOS_QUEUE=0では小さいのか？

どちらのモードでも基準点last_event_time_usはLED制御後（C点）に更新される。 しかし、測定値に差が生じるのは以下の理由が考えられます。

  1. シリアル出力のタイミング差:

    • ENABLE_FREERTOS_QUEUE=0: send_sensor_data() が検出プロセス内で呼び出される
    • ENABLE_FREERTOS_QUEUE=1: シリアル送信は detection_buffer_send() で loop() 内に非同期化される

  2. 実測環境での予期しない要因:

    • テキストコマンド処理の干渉（"b" コマンド実行時に514646usのスパイク）
    • 他のloop()処理（WiFi、プロトコル）との相互作用

問題の判定：これはバグ🐛

理由

  1. timedelta_us は「（今回の検出）と（前回の検出）の時間差」を表すべきフィールド
  2. ENABLE_FREERTOS_QUEUEの有無で基準点が異なっており、一貫性がない
  3. LED制御の50ms遅延が、次イベントのtimedelta_usに影響を与えている
  4. キューありとキューなしで、実質的に異なる時刻が基準になっている
  5. キューなしの場合は、LED遅延を気にせず、即時にシリアル送信
  6. キューありの場合は、LED操作を待ってから、シリアル送信

修正の戦略（v1.9.3）

キュー内でのtimedelta_usを計算する

メリット

  • ✅ ENABLE_FREERTOS_QUEUEの有無にかかわらず、統一された計算ロジック
  • ✅ timestamp_us（キュー時刻）と timedelta_us（キュー時刻基準）の意味が明確
  • ✅ LED遅延の影響を完全に排除
  • ✅ シリアル出力タイミングによる変動を排除
  • ✅ 最小限のコード変更

実装方針

// detection_process() では timedelta_us を計算しない
data.timedelta_us = 0;  // プレースホルダー

#if ENABLE_FREERTOS_QUEUE
    // キュー内で timedelta_us を計算・記録
    detection_buffer_queue(&data);  // 新関数で内部計算
#else
    // 直送の場合、すぐに計算して送信
    data.timedelta_us = micros() - last_event_time_us;
    send_sensor_data(&data);
    last_event_time_us = micros();  // 即座に更新
#endif

// LED制御（遅延の影響なし）
cosmic_detector_led_feedback(...);
delay(50);

修正後の期待値

  • ENABLE_FREERTOS_QUEUE=0: timedelta_us -> 検出ポーリング間隔（数十～数百us）
  • ENABLE_FREERTOS_QUEUE=1: timedelta_us -> 検出ポーリング間隔（同一値）
  • コマンド処理中のスパイク: 抑制される（各モードで独立した計算）

Learnings

  1. Timestamp の一貫性の重要性
    • 単に「時刻を記録する」のではなく、その時刻が何を表すのか明確にする必要
    • ENABLE_FREERTOS_QUEUEによる分岐は、意味論的な差異を生み出す可能性
    • timestamp_us と timedelta_us (or interval_us)
  2. LED制御などのブロッキング操作の影響
    • LED点灯が見えるようにする50msの遅延（delay(50)）が次イベントのtimestampに影響を与える設計は脆弱
    • timestampを更新するタイミングは、非同期処理と組み合わせる際にとくに慎重に
  3. キューありとキューなしでの差異
    • キューありの場合、すべてのフィールドの計算タイミングを再検討する必要がある
    • シリアル出力のタイミングが変わると、暗黙的に他のフィールドに影響する可能性がある
  4. ハードウェアテストによる発見の価値
  5. 実測値（76 vs 2330us）なしには、この設計問題を検出できなかった
  6. v1.9.2 リリースの評価
  7. v1.9.2の検出バッファー化自体は問題なし（タイムスタンプ精度向上は達成）
  8. ただし、既存の timedelta_us 計算ロジックとの相互作用による副作用を見落としていた
  9. v1.9.3で修正可能な設計上の改善

Implementation Plan (v1.9.3, est. 1-2 hours)

Philosophy: Decouple timedelta_us calculation from serial transmission timing. Calculate at queue/send time consistently regardless of ENABLE_FREERTOS_QUEUE mode.

Phase 1: Code Changes (30-45 min)

1.1 detection_buffer.h/cpp (Queue mode)

// detection_buffer.h に static 変数を追加
static uint64_t g_last_queue_time_us = 0;

// detection_buffer_queue() を拡張
bool detection_buffer_queue(const sensor_data_t *data) {
  detection_event_t event;
  event.data = *data;
  event.timestamp_us = micros();

  // ✅ NEW: timedelta_us を計算（キュー時刻基準）
  if (g_last_queue_time_us == 0) {
    // 初回: ブート時刻から計算
    event.data.timedelta_us = micros() - (millis() * 1000);  // uptime_ms対応
  } else {
    // 通常: 前回キュー時刻から計算
    event.data.timedelta_us = event.timestamp_us - g_last_queue_time_us;
  }
  g_last_queue_time_us = event.timestamp_us;

  // ... 既存のキュー処理
}

1.2 main.cpp (Detection process)

void detection_process(void) {
  cosmic_detection_t detection = cosmic_detector_read();

  if (detection.detected) {
    // センサ読取
    float temp = bme280_read_temperature();
    // ... 他のセンサ ...

    // データ構築（timedelta_us は 0 のプレースホルダー）
    sensor_data_t data = {
      .signal1 = detection.signal1,
      .signal2 = detection.signal2,
      .signal3 = detection.signal3,
      .timedelta_us = 0,  // ← プレースホルダー（キュー内で計算）
      // ... その他のフィールド ...
    };

#if ENABLE_FREERTOS_QUEUE
    // キュー内で timedelta_us を計算
    detection_buffer_queue(&data);
#else
    // 直送の場合: ここで計算して即座に更新
    static uint64_t g_last_send_time_us = 0;
    if (g_last_send_time_us == 0) {
      data.timedelta_us = micros() - (millis() * 1000);
    } else {
      data.timedelta_us = micros() - g_last_send_time_us;
    }
    g_last_send_time_us = micros();

    send_sensor_data(&data);
#endif

    // LED フィードバック（LED制御の遅延は timedelta_us に影響しない）
    cosmic_detector_led_feedback(...);
    delay(50);
    cosmic_detector_led_off();

    // リセット
    cosmic_detector_reset();
  }
}

Phase 2: Testing (15-30 min)

  • ENABLE_FREERTOS_QUEUE=1/0 両方でビルド
  • Serial monitor で timedelta_us を測定（両モード）
  • Expected: 両モード共に 50-100 μs 程度（検出ポーリング間隔）
  • Before: 0モード = 76 μs, 1モード = 2330 μs（差分発生）
  • After: Both ≈ 同一値 ✅
  • 複数の高速検出でスパイク確認
  • GET_BUFFER_STATS コマンド実行中も timedelta_us が一貫性を保つ
  • Before: 514646 μs スパイク観測
  • After: スパイク抑制 ✅
  • ビルド検証（prod/debug/dev 全プロファイル）

Phase 3: Documentation (15 min)

  • docs/detection-buffering.md 更新
  • timedelta_us の定義を明確化：「キュー/送信時刻からの間隔」

  • 図示：A点・B点・C点の関係が簡潔に

  • docs/releases/v1.9.3.md 作成

  • Breaking Changes: None (output format unchanged)
  • Bug Fixes: timedelta_us consistency fix
  • Internal Changes: Timestamp calculation moved to queue layer

  • Migration Notes: ENABLE_FREERTOS_QUEUE の動作が統一されたが、外部インターフェイスは変わらない

  • REFACTORING_ROADMAP.md 更新

  • v1.9.3 セクションを簡潔化（「Case 1 採択」を明記）

Checklist (v1.9.3)

  • 修正案の最終確認（Case1に確定）
  • detection_buffer.h/cpp 修正実装
  • main.cpp 修正（ENABLE_FREERTOS_QUEUE=0 分岐）
  • ENABLE_FREERTOS_QUEUE=1/0 両方でテスト実施
  • Serial monitor で timedelta_us 測定値確認（スパイク消失確認）
  • 3ビルドプロファイル全てでビルド成功確認
  • docs/detection-buffering.md 更新
  • docs/releases/v1.9.3.md 作成
  • REFACTORING_ROADMAP.md v1.9.3 セクション簡潔化
  • Commit: fix(timestamp): unify timedelta_us calculation across ENABLE_FREERTOS_QUEUE modes

Field Naming Clarification (v1.9.3)

タイムスタンプのフィールド名を変更した （timedelta_us → timedelta_us）

Field Type Meaning Phase
uptime_ms uint32_t Board uptime since boot (milliseconds) v1.6.9+
timedelta_us uint64_t Interval between consecutive detection events (microseconds) v1.9.3+ (renamed from timedelta_us)
timestamp_us uint64_t Unix timestamp (absolute time) v1.9.4+ (future)

改名の理由

  • duration_us は「継続時間」の意味で曖昧だった
  • timedelta_us で「時間"差"」であることを明確にした
  • Python/NumPyのtimedeltaの慣例に沿っている
  • v1.9.4で対応予定のRTCのタイムスタンプ（unix_timestamp）との区別が明確
  • 相対時刻: uptime_ms, timedelta_us
  • 絶対時刻: unix_timestamp

修正範囲** (v1.9.3実装時)

  • include/sensor_data.h: フィールド名変更 + docstring更新 ✅
  • src/sensor_formatter.cpp: 出力フォーマット更新
  • src/main.cpp: timedelta_us 計算・割り当て更新
  • docs/detection-buffering.md: フィールド定義明確化
  • docs/releases/v1.9.3.md: Breaking Changes セクションで言及

Additional Considerations

  • GET_BUFFER_STATS 出力: 統計情報に「平均 timedelta_us」などの統計情報を追加検討（v1.9.3後半）
  • v1.9.4 RTC対応: unix_timestampを追加予定。相対時刻と絶対時刻の2軸で時系列分析が可能に
  • v2.0.0 multithreading: デュアルコア化時、各タスク間のタイムスタンプ基準点を再検討（timedelta の意味がより重要に）