Read the flat function tracer, and the flags column it prints

[tamnd]

kxray.trace had one parser in it. function_graph gives you the call tree with a duration against every frame, and it is the right tool for showing the shape of a system call, which is what the three lessons so far use it for.

It is the wrong tool for about half of what M1 needs. It does not print the one column that says what state the machine was in when a call happened, and that column is what decides whether the code on the line was allowed to do what it did. So this adds the flat function tracer, which prints one line per call with no nesting and no duration, and prints that column on every line.

Two real captures, not fixtures

Both came off the pinned 7.2.2 under v86, on this machine, through node kxbox/web/headless.js. Both are evidence = true and both record the exact set_ftrace_filter that produced them, so either can be taken again and compared rather than argued about.

corpora/traces/tier0/flat-write.txt is the same one byte write that write-1byte.txt already shows as a tree, taken the other way. It is here to be read next to that file. Seven lines, and the flags column is ..... on all seven, which means process context the whole way down and every rule that applies to sleeping code applies to the entire write. That is the boring case and it is worth seeing before the other one.

The last line of it is a second vfs_write and it is not the byte going in twice. It is the echo 0 > tracing_on that stopped the recording, which is a write like any other and therefore matches the filter. The tracer records the act of switching itself off.

corpora/traces/tier0/flat-interrupt.txt is one second of an idle machine with the filter set to the interrupt and softirq path. Eight lines, and this is what the new parser makes of them:

time      cpu  task      context    function                called by
--------  ---  --------  ---------  ----------------------  --------------------
7.712200  0    sleep-37  hardirq    handle_irq_event        handle_level_irq
7.712263  0    sleep-37  hardirq    hrtimer_run_queues      update_process_times
7.712292  0    sleep-37  hardirq    raise_softirq           invoke_rcu_core
7.712308  0    sleep-37  hardirq    __raise_softirq_irqoff  raise_softirq
7.712379  0    sleep-37  nopreempt  do_softirq_own_stack    irq_exit_rcu
7.712394  0    sleep-37  nopreempt  __do_softirq            do_softirq_own_stack
7.712408  0    sleep-37  nopreempt  handle_softirqs         __do_softirq
7.712426  0    sleep-37  softirq    rcu_core                rcu_core_si

Two things in there are hard to show any other way.

The task column says sleep on every line and sleep did none of this. A timer interrupt runs on whichever task was on the CPU when it arrived and borrows that task's stack and its name, so the comm column answers who got interrupted rather than who ran. The flags column is the only thing on the line that says which is which, and a reader who does not know that will spend a while wondering why sleep is calling into RCU.

And the middle four lines are a gap rather than a delay. raise_softirq at 7.712292 is the interrupt handler writing down that work is needed. handle_softirqs at 7.712408 is that work running, afterwards, with interrupts back on. The handler did not do the job, it left a note. That gap is what deferred work means and here it is with timestamps on it.

What the flags column is read as

'.....' -> process context
'd.h2.' -> hardirq context, interrupts off, preemption count 2
'dN.1.' -> nopreempt context, interrupts off, reschedule pending, preemption count 1
'.Ns1.' -> softirq context, reschedule pending, preemption count 1

Flags.context maps the column onto kxray/vocabulary.py, and it answers five of the six contexts. It never answers atomic, and that is a limit rather than an omission. A held spinlock raises the preemption count and so does a bare preempt_disable(), the column carries only the count, and nothing in it can tell the two apart. So both come back as nopreempt, which is true of both, and the docstring says why. A parser that guessed there would be right most of the time and wrong in exactly the cases somebody was debugging.

Four character columns are read too. Kernels from before migrate-disable existed print four, and a trace somebody took in 2021 is still a trace.

The shared header

Three ftrace formats print the same six columns before they print anything of their own, so kxray/trace/common.py reads them once and hands the rest of the line back. The flat tracer takes it now and the event reader will take it next.

The one thing in there worth knowing is that the pid anchors the regular expression rather than the comm, because a comm can hold dashes and slashes and spaces. kworker/0:1-9 is one task called kworker/0:1 with pid 9, and there is a test for it and for my prog-7.

Two existing tests got narrower

test_every_committed_recording_is_one_task_doing_one_thing and the bridge options check both globbed every .txt in corpora/traces/tier0/ and both assumed function_graph. They now filter on the tracer key in each capture's metadata. The interrupt capture has no single task in it by design, which is the whole point of it, and it was never a both-ways recipe.

corpora/BASELINE.toml grows two rows. The new route has to sit above the existing one, because both tracers write .txt into the same directory and flat- on the front of the name is what tells them apart.

Not done here

The kxray.trace row in #2 also asks for trace_pipe events read through each event's own format file, and that is the next PR rather than this one, so the row stays unticked. common.py exists in the shape it does because of that half.