diff mbox series

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

Message ID 20240829220106.80449-4-gustavo.sousa@intel.com (mailing list archive)
State New, archived
Headers show
Series Miscelaneous fixes for display tracepoints | expand

Commit Message

Gustavo Sousa Aug. 29, 2024, 10 p.m. UTC 
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.

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@intel.com>
---
 .../drm/i915/display/intel_display_trace.h    | 27 ++++++++++++-------
 1 file changed, 18 insertions(+), 9 deletions(-)

Comments

Matt Roper Sept. 18, 2024, 10:41 p.m. UTC | #1 
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@intel.com>

Reviewed-by: Matt Roper <matthew.d.roper@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
>
diff mbox series

Patch

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,