Inspiration
A QNX system is a set of processes that talk by synchronous message passing. When a control thread misses its deadline, the cause usually sits in a server it was waiting for, in a server that server was waiting for, or in a lower-priority thread that ran at the wrong moment. The kernel event trace (.kev) holds the events that show this. trace-studio turns those events into an answer to "why was this request late?" and shows it in Perfetto, the open trace viewer and SQL engine.
What it does
- Reads
.kevfiles on any host with its own parser; no QNX libraries are needed on the host. The output matches the SDP'straceprinterevent by event. - Converts to Perfetto: per-CPU scheduling, the kernel's thread states (SEND, RECEIVE, REPLY, MUTEX, ...), QNX priorities with inheritance boosts, pulses, interrupts, resource-manager message names, and the message exchanges it can link (MsgSend, the server's handling, MsgReply), joined by arrows.
analyze: latency per client and server, deadline misses, the critical path of a request across servers, and suspected priority inversions with their evidence: the blocked client, the server thread READY at its priority, the threads that held every CPU it could use, and whether the channel was created with_NTO_CHF_FIXED_PRIORITY.- Mutex owner chains: when a server thread blocks on a mutex, the chain continues to the owner and to what the owner was waiting for. The owner is named when its own successful unlock of the same mutex is in the trace. QNX's mutex priority inheritance appears in the priority tracks.
diff: two traces before and after a change, side by side.open: one command from a.kevto the Perfetto UI, with the tracks of the worst requests pinned. The trace is served to the local browser only, with a per-run token.check: real-time regression tests for CI. It asserts deadlines per client and server and the absence of priority inversions, exits 1 with the evidence, writes JUnit XML, and fails when the trace lost data or covers too few requests.tools/ci_qemu_check.shruns the whole loop: build the workload with the SDP, boot a QNX target in QEMU, capture with tracelogger, check.- Exchanges that cross lost events or carry contradictory kernel data are marked untrustworthy and left out of the analyses. Conclusions the trace cannot support are reported as "insufficient evidence" with the reason, for example a run mask set before tracing started.
How we built it
Python on the host; a C workload on the target that logs its own requests as ground truth; QNX OS 8.0 x86_64 and aarch64le in QEMU with tracelogger in wide mode. Each capture is compared with traceprinter, the message linking with the workload's logs, and loss handling with kernel buffers removed on purpose.
Challenges we ran into
- The
.kevformat: events split across 16-byte slots that interleave with other events, 32-bit timestamps extended per CPU, kernel buffers that arrive per CPU and out of order, and buffers that can be lost. - Linking messages: an rcvid names one pending message and is reused (up to 186 times in one capture), two server threads can receive on one channel, and replies can come from another thread.
- Inversion evidence on a multi-core system: the server has to be READY at a lower priority while every CPU it may run on is busy with higher-priority threads, at least one of them below the client. Without the server's run mask in the trace, the verdict is "insufficient evidence".
Accomplishments that we're proud of
- 739,841 events across 17 x86_64 captures identical to
traceprinter, and 2,428,184 argument values identical, sign included. - 1,040 of 1,040 logged requests linked to the right client thread, server thread, rcvid, coid and outcome, including all 160 forwarded requests linked to their parent.
- With a fixed-priority channel, 20 of 20 high-priority requests miss a 5 ms deadline and all 20 are flagged as suspected inversions; with priority inheritance, 0 of 20 miss and none are flagged.
- With 4 of 15 kernel buffers removed, 108 of 200 requests are matched and none is linked wrongly.
- In the CI example on QNX 8.0 in QEMU,
tracestudio check --deadline hi@ts_psrv=5000 --no-inversionsfails the fixed-priority build with 20 suspected inversions and passes the fixed build. - 60 of 60 logged mutex waits matched to the right owner, address and release time. With mutex priority inheritance turned off, the waits grow from about 2.4 ms to about 7.5 ms; in the slowest request the mutex owner waited on a server whose thread sat READY for 5.2 ms while the hog held the CPU.
- On aarch64le (QEMU virt), 158,352 events and 487,334 argument values are identical to
traceprinter, all 280 logged requests are linked, and the inversion verdicts andcheckresults match the x86_64 runs. - 82 tests, including a counterexample test for each review finding.
What we learned
On QNX the server's priority rises at the moment a higher-priority client sends, as the System Architecture guide describes; a channel created with _NTO_CHF_FIXED_PRIORITY keeps the server at its own priority. An inversion verdict on a multi-core system needs the server's run mask, the occupant of every CPU and the priorities at each instant.
What's next
Condition variables and semaphores in the chains, interrupt-to-thread latency, runs on real ARM hardware, and a .kev importer for Perfetto upstream.
Evidence of QNX use (for reviewers)
- Reader:
tracestudio/kev.py(header, syspage, combine events, timestamps, buffer accounting, from<sys/trace.h>); kernel-call layouts intracestudio/events.pyandtracestudio/qnx_tables.py(SAT documentation,<sys/neutrino.h>,_IO_*types from<sys/iomsg.h>). - QNX workload:
workload/(ChannelCreatewith and without_NTO_CHF_FIXED_PRIORITY,name_attach,MsgSend,MsgReceive,MsgReply,MsgSendPulse, SCHED_FIFO priorities, run masks, mutexes) andworkload/run_scenarios.shwith thetraceloggercommands. - Target: QNX OS 8.0.0 x86_64 and aarch64le images built with mkqnximage, run in QEMU 6.2; toolchain: QNX SDP 8.0 qcc.
- Comparison with the SDP's
traceprinter:tools/compare_traceprinter.py; measurements and their commands:docs/DESIGN.md; CI loop:tools/ci_qemu_check.sh.
