On Thu, Aug 29, 2024 at 07:00:46PM -0300, Gustavo Sousa wrote: > Because much of kernel tracepoints is implemented at the C preprocessor > level, C identifiers used in TP_printk() are saved verbatim in the event > format, even when they represent compile-time constant values. > > As an example, we can look at the format for the intel_pipe_enable > event: > > # cat /sys/kernel/debug/tracing/events/i915/intel_pipe_enable/format | grep '^print fmt' > print fmt: "dev %s, pipe %c enable, pipe A: frame=%u, scanline=%u, pipe B: frame=%u, scanline=%u, pipe C: frame=%u, scanline=%u", __get_str(dev), REC->pipe_name, REC->frame[PIPE_A], REC->scanline[PIPE_A], REC->frame[PIPE_B], REC->scanline[PIPE_B], REC->frame[PIPE_C], REC->scanline[PIPE_C] > > We see that PIPE_A, PIPE_B and PIPE_C are pasted directly in the format. > Because tools that interact with kernel tracepoints don't know about > those ids, they'll endup failing to parse the format or produce > corrupted output. > > For example, we can see below that trace-cmd repeats PIPE_A's > frame/scanline counts for all pipes (probably because it evaluates > unknown ids as zero): > > $ trace-cmd report -F intel_pipe_enable | tail -n5 > testdisplay-8616 [000] 22048.276758: intel_pipe_enable: dev 0000:00:02.0, pipe A enable, pipe A: frame=861, scanline=480, pipe B: frame=861, scanline=480, pipe C: frame=861, scanline=480 > testdisplay-8616 [001] 22048.490287: intel_pipe_enable: dev 0000:00:02.0, pipe A enable, pipe A: frame=867, scanline=480, pipe B: frame=867, scanline=480, pipe C: frame=867, scanline=480 > testdisplay-8616 [003] 22048.700181: intel_pipe_enable: dev 0000:00:02.0, pipe A enable, pipe A: frame=872, scanline=400, pipe B: frame=872, scanline=400, pipe C: frame=872, scanline=400 > testdisplay-8616 [002] 22049.054220: intel_pipe_enable: dev 0000:00:02.0, pipe A enable, pipe A: frame=881, scanline=2170, pipe B: frame=881, scanline=2170, pipe C: frame=881, scanline=2170 > testdisplay-8616 [002] 22049.166851: intel_pipe_enable: dev 0000:00:02.0, pipe B enable, pipe A: frame=887, scanline=1632, pipe B: frame=887, scanline=1632, pipe C: frame=887, scanline=1632 > > , while in fact we have different values for each pipe, which can be > confirmed with the raw view of the events: > > $ trace-cmd report -R -F intel_pipe_enable | tail -n5 > testdisplay-8616 [000] 22048.276758: intel_pipe_enable: dev=0000:00:02.0 frame=ARRAY[5d, 03, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00] scanline=ARRAY[e0, 01, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00] pipe_name=A > testdisplay-8616 [001] 22048.490287: intel_pipe_enable: dev=0000:00:02.0 frame=ARRAY[63, 03, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00] scanline=ARRAY[e0, 01, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00] pipe_name=A > testdisplay-8616 [003] 22048.700181: intel_pipe_enable: dev=0000:00:02.0 frame=ARRAY[68, 03, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00] scanline=ARRAY[90, 01, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00] pipe_name=A > testdisplay-8616 [002] 22049.054220: intel_pipe_enable: dev=0000:00:02.0 frame=ARRAY[71, 03, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00] scanline=ARRAY[7a, 08, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00] pipe_name=A > testdisplay-8616 [002] 22049.166851: intel_pipe_enable: dev=0000:00:02.0 frame=ARRAY[77, 03, 00, 00, 01, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00] scanline=ARRAY[60, 06, 00, 00, 39, 04, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00] pipe_name=B > > To fix that, we need a fix that looks more like a hack: use macros that > result to integer constants instead of enum pipe values. This fixes the > issue, but could break if, for whatever unlikely reason, the underlying > values in the enum are changed. I guess if we're paranoid about it we could put a BUILD_BUG_ON(_TRACE_PIPE_A != PIPE_A) somewhere to catch that unlikely case? > > In the future, we should find a better way to handle this, but for now, > the hack took care of the job: > > $ trace-cmd report -F intel_pipe_enable | tail -n5 > testdisplay-9224 [003] 24324.455375: intel_pipe_enable: dev 0000:00:02.0, pipe A enable, pipe A: frame=1103, scanline=480, pipe B: frame=0, scanline=0, pipe C: frame=0, scanline=0 > testdisplay-9224 [002] 24324.669845: intel_pipe_enable: dev 0000:00:02.0, pipe A enable, pipe A: frame=1109, scanline=480, pipe B: frame=0, scanline=0, pipe C: frame=0, scanline=0 > testdisplay-9224 [003] 24324.900105: intel_pipe_enable: dev 0000:00:02.0, pipe A enable, pipe A: frame=1115, scanline=31, pipe B: frame=0, scanline=0, pipe C: frame=0, scanline=0 > testdisplay-9224 [002] 24325.256408: intel_pipe_enable: dev 0000:00:02.0, pipe A enable, pipe A: frame=1124, scanline=2171, pipe B: frame=0, scanline=0, pipe C: frame=0, scanline=0 > testdisplay-9224 [003] 24325.380789: intel_pipe_enable: dev 0000:00:02.0, pipe B enable, pipe A: frame=1131, scanline=979, pipe B: frame=1, scanline=1082, pipe C: frame=0, scanline=0 > > Signed-off-by: Gustavo Sousa <gustavo.sousa@xxxxxxxxx> Reviewed-by: Matt Roper <matthew.d.roper@xxxxxxxxx> > --- > .../drm/i915/display/intel_display_trace.h | 27 ++++++++++++------- > 1 file changed, 18 insertions(+), 9 deletions(-) > > diff --git a/drivers/gpu/drm/i915/display/intel_display_trace.h b/drivers/gpu/drm/i915/display/intel_display_trace.h > index ec2ab6fb743d..759b985c84a9 100644 > --- a/drivers/gpu/drm/i915/display/intel_display_trace.h > +++ b/drivers/gpu/drm/i915/display/intel_display_trace.h > @@ -22,6 +22,15 @@ > #define __dev_name_i915(i915) dev_name((i915)->drm.dev) > #define __dev_name_kms(obj) dev_name((obj)->base.dev->dev) > > +/* > + * Using identifiers from enum pipe in TP_printk() will confuse tools that > + * parse /sys/kernel/debug/tracing/{xe,i915}/<event>/format. So we use CPP > + * macros instead. > + */ > +#define _TRACE_PIPE_A 0 > +#define _TRACE_PIPE_B 1 > +#define _TRACE_PIPE_C 2 > + > TRACE_EVENT(intel_pipe_enable, > TP_PROTO(struct intel_crtc *crtc), > TP_ARGS(crtc), > @@ -45,9 +54,9 @@ TRACE_EVENT(intel_pipe_enable, > > TP_printk("dev %s, pipe %c enable, pipe A: frame=%u, scanline=%u, pipe B: frame=%u, scanline=%u, pipe C: frame=%u, scanline=%u", > __get_str(dev), __entry->pipe_name, > - __entry->frame[PIPE_A], __entry->scanline[PIPE_A], > - __entry->frame[PIPE_B], __entry->scanline[PIPE_B], > - __entry->frame[PIPE_C], __entry->scanline[PIPE_C]) > + __entry->frame[_TRACE_PIPE_A], __entry->scanline[_TRACE_PIPE_A], > + __entry->frame[_TRACE_PIPE_B], __entry->scanline[_TRACE_PIPE_B], > + __entry->frame[_TRACE_PIPE_C], __entry->scanline[_TRACE_PIPE_C]) > ); > > TRACE_EVENT(intel_pipe_disable, > @@ -74,9 +83,9 @@ TRACE_EVENT(intel_pipe_disable, > > TP_printk("dev %s, pipe %c disable, pipe A: frame=%u, scanline=%u, pipe B: frame=%u, scanline=%u, pipe C: frame=%u, scanline=%u", > __get_str(dev), __entry->pipe_name, > - __entry->frame[PIPE_A], __entry->scanline[PIPE_A], > - __entry->frame[PIPE_B], __entry->scanline[PIPE_B], > - __entry->frame[PIPE_C], __entry->scanline[PIPE_C]) > + __entry->frame[_TRACE_PIPE_A], __entry->scanline[_TRACE_PIPE_A], > + __entry->frame[_TRACE_PIPE_B], __entry->scanline[_TRACE_PIPE_B], > + __entry->frame[_TRACE_PIPE_C], __entry->scanline[_TRACE_PIPE_C]) > ); > > TRACE_EVENT(intel_crtc_flip_done, > @@ -204,9 +213,9 @@ TRACE_EVENT(intel_memory_cxsr, > > TP_printk("dev %s, cxsr %s->%s, pipe A: frame=%u, scanline=%u, pipe B: frame=%u, scanline=%u, pipe C: frame=%u, scanline=%u", > __get_str(dev), str_on_off(__entry->old), str_on_off(__entry->new), > - __entry->frame[PIPE_A], __entry->scanline[PIPE_A], > - __entry->frame[PIPE_B], __entry->scanline[PIPE_B], > - __entry->frame[PIPE_C], __entry->scanline[PIPE_C]) > + __entry->frame[_TRACE_PIPE_A], __entry->scanline[_TRACE_PIPE_A], > + __entry->frame[_TRACE_PIPE_B], __entry->scanline[_TRACE_PIPE_B], > + __entry->frame[_TRACE_PIPE_C], __entry->scanline[_TRACE_PIPE_C]) > ); > > TRACE_EVENT(g4x_wm, > -- > 2.46.0 > -- Matt Roper Graphics Software Engineer Linux GPU Platform Enablement Intel Corporation