[PATCH 3/4] drm/i915/display: Do not use ids from enum pipe in TP_printk()

Matt Roper matthew.d.roper at intel.com
Wed Sep 18 22:41:42 UTC 2024


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

Reviewed-by: Matt Roper <matthew.d.roper at intel.com>

> ---
>  .../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


More information about the Intel-gfx mailing list