Trace Compass doesn't show tracing_mark_write event although it is present in trace file

[felix-khlmnn]

Hello everybody,

I have encountered a potential bug/error while trying to analyse an ftrace generated with trace-cmd.
The generated trace.dat contains the tracing_mark_write event and is correctly displayed by Kernelshark, as can be seen from the screenshot below:

The same element in Trace Compass is displayed this way:

The trace was generated by invoking the executable with the following program:

trace-cmd -e sched record --file-version 6 ./<Executable Name>

If you need further information for assistance, I will provide it.

Best regards,
Felix Kuhlmann

[MatthewKhouzam]

Hi Felix, I would like to help, but I would like a trace to test. I have not seen this issue yet. Also, ftrace updates the format, maybe we are out of date. Can you share a trace like this?

[felix-khlmnn]

Hi Matthew, thank you for offering your help.

What is your preferred way of receiving the trace? I figured posting it in this thread would clutter it up. Hence, I'm asking.

Thank you in advance!

[felix-khlmnn]

Edit: I forgot to mention that I started trace-cmd with the --file-version flag set to version 6. I have read that this is the only supported file version for Trace Compass.

[MatthewKhouzam]

Ok, in that case, you're already good.

Regarding the trace format, I think putting a zip in this issue is great for persistence. Can you make a smaller trace?

[felix-khlmnn]

I have found a partial solution for my problem. When exporting a different, shorter trace.dat (file version 6) using trace-cmd report > trace.txt, I was able to import the trace.txt into trace compass. Trace Compass only shows the actual text written when using this format.
This leads me to a different problem: The trace markers written in the test application for this issue can be read without issue. However, the trace of the actual program that I want to analyse doesn't get fully loaded in, despite both the binary and ascii file containing every event from start to finish.

The Statistics windows of the binary trace file trace.dat tells me that there are 1.782.763 events listed. However, the ascii version of the exact same tracing only has 640 events listed. This trace is included in the zip, its name is long_program.{dat,txt}.

I have written a test program that writes 10 times to the trace marker. The source for that is also included in the zip. For this trace, there is no discrepancy in the amount of events between loading the binary or the ascii format.

[felix-khlmnn]

Since Github only allows 25MB uploads, you'll have to create the ascii file of the long program yourself.
Steps to reproduce:
trace-cmd report > long_program.txt

Thanks in advance!
tracecompass-issue-193.zip

[MatthewKhouzam]

I will check it out... disclaimer, I will be on winter holidays soon. But I should respond, if not slowly.

[felix-khlmnn]

No worries, same goes for me ^^
Happy holidays and a successful new year!

[felix-khlmnn]

Hello, returning from winter break, I have continued my research and can share some new ideas.

One interesting thing I have learned is when filtering a ASCII trace file for printing events, storing the subsequent output and reading it into Trace Compass, I can read the text I have written to the trace marker without any issues.

However, the problem with the limited amount of events Trace Compass can load from an ASCII trace file still is a problem I couldn't resolve.

Is there anything in the ftrace parser preventing files over a certain file size to be read in completely?

[felix-khlmnn]

Okay, it seems as if I have finally found the bug, and it seems to be with the parsing.
When parsing a file, I can see that I could only ever see the first 233 events (not related to the uploaded file). By looking at the 234th event with a text editor, I could see that the process's name was (udev-worker). This was the first event that wasn't displayed by Trace Compass, just like all the events that followed. I suspected that the parentheses were a problem for the parser, so I just replaced all occurrences of (udev-worker) with udev-worker. And now all the aforementioned problems are gone, and all events are listed.

I'm sure the actual fix isn't all too big as everything that needs to be adjusted will most likely just be a RegEx. I would like to do the fix myself, but I don't know where to find the actual parser code. If anybody could point me in the correct direction, I'd appreciate that :)

[MatthewKhouzam]

Hi, I am looking into the traces.. I am sorry for the long delay. The issue is in long_program.dat right? I tried opening it both in text and binary... Binary works perfectly, it's just the text that's got the issue. I will patch the regex shortly. I want to confirm, is this the problem, at line 640?

After some programmatic checks, I see that the binary parsing is missing ONE event in 1782764... I will investigate further, I think there are two bugs now.

Parsing the txt file fails at event 640.

Parsing the binary is missing one event.

[felix-khlmnn]

No worries, Matthew, thank you for your help 🙂

Yes, the number of events when loading the ASCII version of the long_program trace is only 640. After analysing the raw text file, I can confirm that this is the same symptom as described above, where the parentheses caused the problem. At the corresponding line, there is the first (udev-worker) occurrence.