[PATCH 2/4] drm/i915/display: Store pipe name in trace events

[Gustavo Sousa]

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 at intel.com>
>
>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 at intel.com>

Thanks!

--
Gustavo Sousa