Late Start or Long Run? Catching a Rare Missed Window

Picture a device running smoothly for months, then suddenly missing its communication window once every few thousand cycles. The logs show no obvious errors. The question arises: was the work late, or was it slow? This article explores a technique to distinguish between these two possibilities, providing insights that logs alone cannot offer.

why logs and averages miss this

Logs typically record discrete events, not the duration of tasks, making them inadequate for diagnosing timing issues. A rare spike in task duration can easily disappear when averaged over thousands of cycles. Such faults often appear after long uptimes because they require two independent activities to align in a specific way, like a burst of interrupt work coinciding with a held lock. These rare alignments need many cycles to manifest, explaining why they are often missed in shorter tests. Additionally, these faults leave a pattern indicative of timing issues rather than a stack trace, complicating direct diagnosis through logs alone.

the technique

To address this, we record the worst-case start lag and run time, instead of just the latest values, because rare faults are often outliers. Separating start lag from run time helps pinpoint whether delays occur before or during task execution. The task step looks like this:

static volatile uint32_t worst_lag_us;
static volatile uint32_t worst_run_us;
static volatile uint32_t overrun_count;

void comm_task_step(uint32_t scheduled_us) {
    uint32_t t0 = now_us();
    uint32_t start_lag = t0 - scheduled_us;

    gpio_set(DEBUG_PIN);
    do_communication_work();
    gpio_clear(DEBUG_PIN);

    uint32_t run_us = now_us() - t0;

    if (start_lag > worst_lag_us) worst_lag_us = start_lag;
    if (run_us > worst_run_us) worst_run_us = run_us;

    if (start_lag + run_us > BUDGET_US) {
        overrun_count++;
        trace_push(EV_LATE_START, start_lag);
        trace_push(EV_RUN_TIME, run_us);
    }
}

This code uses unsigned subtraction for time calculations to handle timer wraparound, and both scheduled_us and now_us() must share the same time base. The GPIO pulse width includes preemption time, making it valuable for understanding task execution duration, though it does not capture start lag. On the oscilloscope, set a trigger for pulse widths longer than the budget, and use persistence mode to keep rare wide pulses visible.

The trace buffer is a small ring:

typedef struct {
    uint32_t t_us;
    uint16_t id;
    uint32_t value;
} trace_entry_t;

static trace_entry_t trace_buf[TRACE_LEN];
static volatile uint32_t trace_head;

void trace_push(uint16_t id, uint32_t value) {
    uint32_t i = trace_head++ & (TRACE_LEN - 1u);
    trace_buf[i].t_us = now_us();
    trace_buf[i].id = id;
    trace_buf[i].value = value;
}

This ring buffer keeps recent history without requiring dynamic allocation. It can be drained over a debug UART or copied to a reserved flash region for crash logs when a fault is detected. Note that trace_head++ is not atomic, so the function assumes a single writer; if both an ISR and a task call it, protect the index update with a short critical section. The two trace_push calls create separate entries, so they should be paired by timestamp when read back.

how to read the result

A wide pulse or a large worst_run_us suggests either the task itself is slow or it is being preempted during execution. If the run time is consistently large or grows with workload, the issue likely lies within the task. Conversely, normal run times with rare spikes point toward mid-run preemption. A large worst_lag_us with a normal pulse points toward preemption or blocking before task start, potentially due to a higher-priority task, an ISR, a held lock, or priority inversion.

To test such candidates, toggle a second pin in the suspect task or ISR, view it on a second scope channel, and check if the lag spikes align with that pulse. If they never align, that candidate is ruled out. If both values are normal yet windows are missed, it suggests the issue lies outside the task's timing, possibly on the other side of the communication link.

what this cannot tell you

A slow memory leak won't widen the pulse or lag until memory allocations start failing. Therefore, logging a free-heap low-water mark separately is advisable. This technique won't catch faults unrelated to this task's timing. Also, the instrumentation itself costs some time, and the trace buffer is finite, meaning very old history is overwritten.

How do you differentiate between a preempted-before-start fault and a blocked-on-a-lock fault in a field device?

Originally published at StoneHMI
This post was drafted with AI assistance and reviewed by a human before publishing.