Read trace events through each event's own format file - #57
Merged
Merged
Conversation
The kernel publishes the layout of every event at events/<group>/<event>/format so that nothing has to hard code one. It is not a nicety: sched_switch declares `long prev_state`, which is four bytes on the 32 bit box this project pins and eight almost everywhere else, and every field after it moves. Four real format files, one real capture, a reader for each, and the three things reading a line through its format gives you that a plain key=value split cannot.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
This finishes the
kxray.tracerow in #2. #56 did the flat function tracer, and this does the last third: trace events, read through each event's ownformatfile rather than through a layout written down in Python.Why the format file and not a table of offsets
Because the offsets are not a property of the event. They are a property of the machine that compiled the kernel. Here is
sched_switchon the 32 bit box this project pins:On the machine you are reading this on,
longis eight bytes, soprev_stateis eight bytes,next_commstarts at 40, and every field after that has moved too. A parser holding those numbers as constants is right on one of the two machines and reads the wrong bytes on the other, and it reports nothing wrong while doing it. The kernel publishes the file precisely so nobody has to guess, so this reads it.Four formats, one capture, all real Tier 0
The formats are in a new
corpora/events/tier0/, each with its own metadata. They were picked because each has a field shape the others do not.sched_switchforprev_state, above.sched_wakeupforcomm, achar[16]copied into the record when the event fires.sched_process_execforfilename, a__data_loc char[], which is four bytes in the record holding an offset and a length with the string itself further along, and which is why the size column says 4 for a field that prints as/bin/true.sys_enterforargs,unsigned long args[6], the only array here that is not a string: one field of 24 bytes rather than six fields of four.sys_enteris in no capture. It is kept anyway, because a corpus of formats holding only the shapes one capture happened to use is a corpus that tests one code path.corpora/traces/tier0/events-exec.txtis the shell forking, execing/bin/true, and doing it again forsleep. Thirteen events. The banner saystracer: nopand that is correct rather than a mistake: events are not a tracer, they are switched on one at a time underevents/and they record whether or not a tracer is running.The line worth the whole PR
The header says
sleep-38. The payload saysprev_comm=sh prev_pid=38. Same pid, two names, and both are correct.The payload holds a copy of the comm made when the event fired, which was before pid 38 had exec'd. The header is not stored per line at all: ftrace keeps a map from pid to name and fills that column in when the buffer is printed, and by then the map says
sleep. So the payload is the truth about the moment and the header is the truth about the pid afterwards.That is the argument for reading a payload through its format instead of trusting the header, and it is not a hypothetical, it is line nine of the file.
What reading through the format gives you
Three things a plain
key=valuesplit cannot.Values arrive as numbers where the format declares numbers.
pid=38is the integer andcomm=shis the string, and nothing downstream guesses by looking at the characters.target_cpuprints as000because of a%03din the print fmt, and reads back as0.Keys the format does not declare are named, and so are fields the format declares that the line did not print. Neither is a fault. A
print fmtis free to leave a field out. This is how you find out it did, rather than by wondering later where a field went.And a field the format calls a number that arrived as text is recorded as symbolic rather than treated as a failure.
prev_stateis declaredlongand reaches you asS,R+,IorX, becauseprint fmtran it through__print_flagsbefore the text existed. The record and the line are both correct and are not the same thing. On the committed capture,prev_stateis the only symbolic field and every one of the thirteen events binds cleanly to its format with nothing unknown and nothing missing.What this deliberately does not do
It does not read the ring buffer in binary.
trace_pipe_rawis where that lives and it is what the offsets and sizes in a format are actually for, and it is a separate piece of work.It does not evaluate
print fmt. That line is a C expression with nested macro expansions in it, and forkmem:kmallocit is several thousand characters of GFP flag resolution. Evaluating it properly means being a C compiler. It is kept as text, because a person reading it learns something.Housekeeping
TraceLognow holds what all three parsers share: the source, the tracer name, the line accounting, and the buffer counts off the banner that say whether the trace has holes in it. The per tracer classes add only the list of things on their lines. That refactor is whyFunctionLogmoved.The new class is
TraceEventrather thanEvent, becauseEventinkxray/models.pyalready means a non frame line inside a function_graph tape.TraceEventis also what the kernel calls these.tests/test_function_graph.pynow selects its artefacts by thetracerkey in each capture's metadata instead of by globbing every.txt. Three tracers write into those directories now and only one of them is that parser's.