How long does a block's step function take, did the trigger meet its deadlines, and when a cycle overruns its period: why? microblx has four mechanisms to answer that, from cheapest to most powerful: trigger timing statistics, the overrun and latency counters of ptrig, and the compile-time SDT probes and ftrace markers, the latter two new on the dev branch. All examples below were run on a BeagleBone Black (1 GHz single-core Cortex-A8) using the threshold.usc demo that ships with microblx: a 1 kHz ptrig triggering the chain ramp -> sin -> thres.

As a rule of thumb: use tstats and the ptrig counters to detect a timing problem, SDT to quantify it, and MARKER to find its cause.

Trigger timing statistics (tstats)

The trigger blocks ubx/trig and ubx/ptrig can measure the duration of each chain run and of the individual block step() functions. This is a config option away, no rebuild needed:

{ name="trigger",
  config = {
     period = { sec=0, usec=1000 },  -- 1 kHz
     tstats_mode = 2,                -- 0: off, 1: per-chain, 2: per-block
     tstats_profile_path = "/tmp",   -- write csv profile on stop
     chain0 = {
        { b="#ramp" },
        { b="#sin" },
        { b="#thres" } }
  }
}

On stop, each trigger writes a small csv profile (values in microseconds):

$ ubx-launch -t 3 -c threshold.usc
$ cat /tmp/trigger.tstats
block, cnt, min_us, max_us, avg_us
chain0,ramp, 2992, 2, 14, 4
chain0,sin, 2992, 3, 30, 4
chain0,thres, 2992, 2, 112, 3
chain0,#total#, 2992, 15, 130, 18

For online monitoring, the trigger emits the raw struct ubx_tstat samples on its tstats port (rate limited by tstats_output_rate). Export the port via an mqueue:

connections = {
   { src="trigger.tstats", type="ubx/mqueue" },
}

and read it at runtime from outside the application:

$ ubx-mq list
   mq id           type name         array len  type hash
1  trigger.tstats  struct ubx_tstat  1          243b40de92698defa93a145ace0616d2
$ ubx-mq read trigger.tstats
{total={nsec=15249,sec=0},cnt=1,min={nsec=15249,sec=0},id="chain0,ramp",max={nsec=15249,sec=0}}
{total={nsec=128954,sec=0},cnt=22,min={nsec=4083,sec=0},id="chain0,sin",max={nsec=30290,sec=0}}
{total={nsec=176451,sec=0},cnt=43,min={nsec=2708,sec=0},id="chain0,thres",max={nsec=38123,sec=0}}
{total={nsec=1397471,sec=0},cnt=63,min={nsec=18916,sec=0},id="chain0,#total#",max={nsec=89329,sec=0}}

Overruns and trigger latency

The tstats measure how long the chain ran. They say nothing about whether it ran on time. That part is built into ptrig and also only a config away.

A trigger deadline is missed when the chain plus the wakeup latency of the sleep mode takes longer than the period. ptrig then drops the missed tick(s) and resumes on the original grid: it never triggers back-to-back to catch up, so the phase of all later triggers is unchanged. The number of dropped ticks is added to the overrun_cnt port, and the total is logged on stop:

OVERRUNS: 7 missed trigger deadline(s)

Note that overrun_cnt counts whole periods lost. A trigger that consistently fires 200 µs late on a 1 ms period registers as zero overruns, even though that lateness is exactly what the sleep modes trade CPU time against. To see it, set latency_stats = 1: the difference between the actual trigger time and the deadline grid point ptrig slept to is written to the latency_ns port every cycle, and min/max/avg are logged on stop next to the overrun line:

LATENCY: cnt 5624, min 11843 ns, max 34102 ns, avg 12971 ns

This costs one extra clock read per cycle (some 15 ns with the ARM generic timer), which is why it is opt-in. The logged summary skips the first tstats_skip_first samples, because on the first cycle after a start the deadline grid has just been anchored to now and the measurement spans startup instead of a period.

The latency_ns port carries every sample, so for the standard deviation connect it to a ubx/stats block:

blocks = {
   { name="lat", type="ubx/stats" },
},

configurations = {
   { name="lat", config = { type="int64_t" } },
   { name="trigger", config = { latency_stats = 1, ... } },
},

connections = {
   { src="trigger.latency_ns", tgt="lat.in" },
},

Two caveats: the value can be slightly negative in sleep_mode 1 and 2, where the busy-wait exits on the first clock read at or past the deadline, and it is not measured under SCHED_DEADLINE, where the kernel paces the thread and deadline_throt_cnt is the port to watch.

Aggregates and counters tell you that something is off, but they compress away when and why. For that there is per-event tracing.

Compile-time per-event tracing

The tracing backend is selected at compile time and defaults to off, in which case the trace macros compile to nothing, i.e. zero overhead:

$ cmake -DTRACING=SDT ..     # USDT probes (requires systemtap-sdt-dev)
$ cmake -DTRACING=MARKER ..  # ftrace trace_marker
$ cmake -DTRACING=OFF ..     # disabled (default)

(In Yocto builds, meta-microblx provides the corresponding TRACING_SDT and TRACING_MARKER PACKAGECONFIGs.)

The following events are emitted (see libubx/ubx_trace.h):

The chain/step events live in libubx.so, the overrun events in the ptrig block.

SDT probes (TRACING=SDT)

With TRACING=SDT each event compiles to a USDT probe (provider ubx). An unattached probe is a single nop, so this backend can be left enabled in production builds. The probes are visible in the ELF notes:

$ readelf -n /usr/lib/libubx.so.0.9.2 | grep -A1 Provider
    Provider: ubx
    Name: step_begin
...

The classic USDT consumer is bpftrace, e.g. for a per-block step latency histogram:

# bpftrace -e '
  usdt:/usr/local/lib/libubx.so.*:ubx:step_begin { @t[tid] = nsecs; }
  usdt:/usr/local/lib/libubx.so.*:ubx:step_end /@t[tid]/ {
      @us[str(arg0)] = hist((nsecs - @t[tid]) / 1000); delete(@t[tid]); }'

There is a catch for small embedded targets though: bpftrace and bcc only support 64-bit architectures, so on the 32-bit BeagleBone this is not an option. Fortunately plain perf handles SDT probes on anything with uprobes. Register the probes once, then record as usual:

$ perf buildid-cache --add /usr/lib/libubx.so.0.9.2
$ perf list | grep sdt_ubx
  sdt_ubx:chain_begin        [SDT event]
  sdt_ubx:chain_end          [SDT event]
  sdt_ubx:step_begin         [SDT event]
  sdt_ubx:step_end           [SDT event]
$ for e in chain_begin chain_end step_begin step_end; do
     perf probe sdt_ubx:$e; done

$ perf record -o perf.data \
     -e sdt_ubx:chain_begin -e sdt_ubx:chain_end \
     -e sdt_ubx:step_begin -e sdt_ubx:step_end \
     -a -- ubx-launch -t 3 -c /usr/share/ubx/examples/usc/threshold.usc
$ perf script -i perf.data
trigger   357 [000]  148.948955: sdt_ubx:chain_begin: (b6cbde98)
trigger   357 [000]  148.948998:  sdt_ubx:step_begin: (b6cbc5b8)
trigger   357 [000]  148.949022:    sdt_ubx:step_end: (b6cbc5d0)
...
trigger   357 [000]  148.949124:   sdt_ubx:chain_end: (b6cbdf30)

That's roughly 24000 events for the 3 second run, each with a precise timestamp, which is enough to compute any latency statistic you like. (Unlike bpftrace, perf does not decode the string arguments on ARM, but for a known chain layout the event order identifies the blocks.)

ftrace markers (TRACING=MARKER)

The SDT events tell you what the application did. When a cycle overruns, the interesting question is usually what else the system was doing: preemption, IRQs, other threads. That is what TRACING=MARKER is for: each event is written to /sys/kernel/tracing/trace_marker (one write(2) per event) and ends up in the kernel ftrace ring buffer, timestamped on the same clock as the kernel's own trace events.

A quick look with raw tracefs:

$ cd /sys/kernel/tracing
$ echo 8192 > buffer_size_kb   # default is a tiny 7k until a tracer runs!
$ echo > trace && echo 1 > tracing_on
$ ubx-launch -t 3 -c /usr/share/ubx/examples/usc/threshold.usc
$ echo 0 > tracing_on
$ grep ubx: trace | head -8
<...>-303  [000] .....  2024.212864: tracing_mark_write: ubx:chain_begin: chain0
<...>-303  [000] .....  2024.212869: tracing_mark_write: ubx:step_begin: ramp
<...>-303  [000] .....  2024.212875: tracing_mark_write: ubx:step_end: ramp
<...>-303  [000] .....  2024.212879: tracing_mark_write: ubx:step_begin: sin
<...>-303  [000] .....  2024.212887: tracing_mark_write: ubx:step_end: sin
<...>-303  [000] .....  2024.212892: tracing_mark_write: ubx:step_begin: thres
<...>-303  [000] .....  2024.212898: tracing_mark_write: ubx:step_end: thres
<...>-303  [000] .....  2024.212903: tracing_mark_write: ubx:chain_end: chain0

Note that in contrast to SDT, the marker events carry their arguments (chain id, block name) as plain text, nothing to decode.

For serious analysis, record with trace-cmd together with the kernel events of interest:

$ trace-cmd record -e sched_switch -e irq \
     ubx-launch -t 10 -c /usr/share/ubx/examples/usc/threshold.usc

and load the resulting trace.dat into kernelshark. The microblx events show up as print events interleaved with the scheduler activity:

sched_switch: swapper:0 [120] R ==> trigger:334 [120]
print: ubx:chain_begin: chain0
print: ubx:step_begin: ramp
...

This shows the trigger thread being woken, running its chain and, in the bad cases, what preempted it in between. (The same works for the SDT variant by the way: trace-cmd record -e 'sdt_ubx:*' -e sched_switch ... records the uprobes into the same timeline.)

Which one to use?

The tracing support is on the microblx dev branch. meta-microblx has the matching PACKAGECONFIGs, so enabling it in a Yocto image is a one-liner.