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
