Quoting Matt Roper (2024-09-18 19:37:35-03:00) >On Thu, Aug 29, 2024 at 07:00:45PM -0300, Gustavo Sousa wrote: >> The first part[1] of the LWN series on using TRACE_EVENT() mentions >> about TP_printk(): >> >> "Do not create new tracepoint-specific helpers, because that will >> confuse user-space tools that know about the TRACE_EVENT() helper >> macros but will not know how to handle ones created for individual >> tracepoints." >> >> It seems this is what we ended up doing when using pipe_name() in >> TP_printk(). >> >> For example, the format for the intel_pipe_update_start event is as >> follows: >> >> # cat /sys/kernel/debug/tracing/events/i915/intel_pipe_update_start/format >> name: intel_pipe_update_start >> ID: 1136 >> format: >> field:unsigned short common_type; offset:0; size:2; signed:0; >> field:unsigned char common_flags; offset:2; size:1; signed:0; >> field:unsigned char common_preempt_count; offset:3; size:1; signed:0; >> field:int common_pid; offset:4; size:4; signed:1; >> >> field:__data_loc char[] dev; offset:8; size:4; signed:0; >> field:enum pipe pipe; offset:12; size:4; signed:1; >> field:u32 frame; offset:16; size:4; signed:0; >> field:u32 scanline; offset:20; size:4; signed:0; >> field:u32 min; offset:24; size:4; signed:0; >> field:u32 max; offset:28; size:4; signed:0; >> >> print fmt: "dev %s, pipe %c, frame=%u, scanline=%u, min=%u, max=%u", __get_str(dev), ((REC->pipe) + 'A'), REC->frame, REC->scanline, REC->min, REC->max >> >> The call to pipe_name(__entry->pipe) is expanted to ((REC->pipe) + 'A') >> and that's how the format is saved. >> >> Even though the output from /sys/kernel/debug/tracing/trace will look >> correct (because it is generated in the kernel), we will see corrupted >> lines when using a tool like trace-cmd to view the data. >> >> While the output looks correct when looking at >> /sys/kernel/debug/tracing/trace, we see corrupted lines when viewing the >> trace data with "trace-cmd report": >> >> $ trace-cmd report \ >> > | sed -n 's/.*dev 0000:00:02\.0, \(pipe .\).*/\1/p' \ >> > | cat -v | uniq -c >> 34 pipe ^A >> >> , where ^A is a non-printable character. >> >> As a fix, let's store the pipe name directly in the event. The fix was >> done by applying the following sed script: >> >> s/__field\s*(\s*enum\s\+pipe\s*,\s*pipe\s*)/__field(char, pipe_name)/ >> s/__entry\s*->\s*pipe\s*=\s*\([^;]\+\);/__entry->pipe_name = pipe_name(\1);/ >> s/pipe_name\s*(\s*__entry\s*->\s*pipe\s*)/__entry->pipe_name/ >> >> After these changes, using the same example, we have the following: >> >> $ trace-cmd report \ >> > | sed -n 's/.*dev 0000:00:02\.0, \(pipe .\).*/\1/p' \ >> > | cat -v | sort | uniq -c >> 396 pipe A >> 34 pipe B >> >> [1] https://lwn.net/Articles/379903/ >> >> Signed-off-by: Gustavo Sousa <gustavo.sousa@xxxxxxxxx> > >Interesting; I hadn't ever realized how the parsing in trace-cmd worked. >Are some of the other macros/function helpers like DRM_RECT_ARG that we >use in our TP_printks similarly problematic? Yep. I noticed some of those as well, but I didn't take time to take a good look at the other cases though (which I wasn't using during a specific debug). I could try looking at other cases a follow-up task. > >Reviewed-by: Matt Roper <matthew.d.roper@xxxxxxxxx> Thanks! -- Gustavo Sousa
