Need to remove char pointers from trace events

Need to remove char pointers from trace events

[Steven Rostedt]

I was doing a bit of an audit on trace events and found this:

# cat /debug/tracing/events/i915/intel_disable_plane/format
name: intel_disable_plane
ID: 1358
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:enum pipe pipe;	offset:8;	size:4;	signed:1;
	field:const char * name;	offset:16;	size:8;	signed:0;
	field:u32 frame;	offset:24;	size:4;	signed:0;
	field:u32 scanline;	offset:28;	size:4;	signed:0;

print fmt: "pipe %c, plane %s, frame=%u, scanline=%u", ((REC->pipe) + 'A'), REC->name, REC->frame, REC->scanline


Same goes for intel_update_plane.


The problem here is:

	field:const char * name;	offset:16;	size:8;	signed:0;

print fmt: "pipe %c, plane %s, frame=%u, scanline=%u", ((REC->pipe) + 'A'), REC->name, REC->frame, REC->scanline


Where the TRACE_EVENT() macro has:

	    TP_fast_assign(
			   __entry->pipe = crtc->pipe;
			   __entry->name = plane->name;
			   __entry->frame = crtc->base.dev->driver->get_vblank_counter(crtc->base.dev,
										       crtc->pipe);
			   __entry->scanline = intel_get_crtc_scanline(crtc);
			   ),

	    TP_printk("pipe %c, plane %s, frame=%u, scanline=%u",
		      pipe_name(__entry->pipe), __entry->name,
		      __entry->frame, __entry->scanline)


The issue here is that you record a pointer address to "plane->name"
and then sometime in the distant future access that same address.
There's usually no guarantee that the contents at that address will
exist when the buffer is read.

The proper way to record strings, is to record the string into the ring
buffer itself, and not rely on it existing hours or days later.

I recommend the following patch:

-- Steve

diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
index 12893304c8f8..d41d914a16ca 100644
--- a/drivers/gpu/drm/i915/i915_trace.h
+++ b/drivers/gpu/drm/i915/i915_trace.h
@@ -298,16 +298,16 @@ TRACE_EVENT(intel_update_plane,
 
 	    TP_STRUCT__entry(
 			     __field(enum pipe, pipe)
-			     __field(const char *, name)
 			     __field(u32, frame)
 			     __field(u32, scanline)
 			     __array(int, src, 4)
 			     __array(int, dst, 4)
+			     __string(name, plane->name)
 			     ),
 
 	    TP_fast_assign(
+			   __assign_str(name, plane->name);
 			   __entry->pipe = crtc->pipe;
-			   __entry->name = plane->name;
 			   __entry->frame = crtc->base.dev->driver->get_vblank_counter(crtc->base.dev,
 										       crtc->pipe);
 			   __entry->scanline = intel_get_crtc_scanline(crtc);
@@ -316,7 +316,7 @@ TRACE_EVENT(intel_update_plane,
 			   ),
 
 	    TP_printk("pipe %c, plane %s, frame=%u, scanline=%u, " DRM_RECT_FP_FMT " -> " DRM_RECT_FMT,
-		      pipe_name(__entry->pipe), __entry->name,
+		      pipe_name(__entry->pipe), __get_str(name),
 		      __entry->frame, __entry->scanline,
 		      DRM_RECT_FP_ARG((const struct drm_rect *)__entry->src),
 		      DRM_RECT_ARG((const struct drm_rect *)__entry->dst))
@@ -328,21 +328,21 @@ TRACE_EVENT(intel_disable_plane,
 
 	    TP_STRUCT__entry(
 			     __field(enum pipe, pipe)
-			     __field(const char *, name)
 			     __field(u32, frame)
 			     __field(u32, scanline)
+			     __string(name, plane->name)
 			     ),
 
 	    TP_fast_assign(
+			   __assign_str(name, plane->name);
 			   __entry->pipe = crtc->pipe;
-			   __entry->name = plane->name;
 			   __entry->frame = crtc->base.dev->driver->get_vblank_counter(crtc->base.dev,
 										       crtc->pipe);
 			   __entry->scanline = intel_get_crtc_scanline(crtc);
 			   ),
 
 	    TP_printk("pipe %c, plane %s, frame=%u, scanline=%u",
-		      pipe_name(__entry->pipe), __entry->name,
+		      pipe_name(__entry->pipe), __get_str(name),
 		      __entry->frame, __entry->scanline)
 );
 

Re: Need to remove char pointers from trace events

[Ville Syrjälä]

On Wed, Jul 10, 2019 at 11:25:49AM -0400, Steven Rostedt wrote:
> I was doing a bit of an audit on trace events and found this:
> 
> # cat /debug/tracing/events/i915/intel_disable_plane/format
> name: intel_disable_plane
> ID: 1358
> 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:enum pipe pipe;	offset:8;	size:4;	signed:1;
> 	field:const char * name;	offset:16;	size:8;	signed:0;
> 	field:u32 frame;	offset:24;	size:4;	signed:0;
> 	field:u32 scanline;	offset:28;	size:4;	signed:0;
> 
> print fmt: "pipe %c, plane %s, frame=%u, scanline=%u", ((REC->pipe) + 'A'), REC->name, REC->frame, REC->scanline
> 
> 
> Same goes for intel_update_plane.
> 
> 
> The problem here is:
> 
> 	field:const char * name;	offset:16;	size:8;	signed:0;
> 
> print fmt: "pipe %c, plane %s, frame=%u, scanline=%u", ((REC->pipe) + 'A'), REC->name, REC->frame, REC->scanline
> 
> 
> Where the TRACE_EVENT() macro has:
> 
> 	    TP_fast_assign(
> 			   __entry->pipe = crtc->pipe;
> 			   __entry->name = plane->name;
> 			   __entry->frame = crtc->base.dev->driver->get_vblank_counter(crtc->base.dev,
> 										       crtc->pipe);
> 			   __entry->scanline = intel_get_crtc_scanline(crtc);
> 			   ),
> 
> 	    TP_printk("pipe %c, plane %s, frame=%u, scanline=%u",
> 		      pipe_name(__entry->pipe), __entry->name,
> 		      __entry->frame, __entry->scanline)
> 
> 
> The issue here is that you record a pointer address to "plane->name"
> and then sometime in the distant future access that same address.
> There's usually no guarantee that the contents at that address will
> exist when the buffer is read.

The only way those can disappear is if the device goes away. But I have
no problem going with your patch. Want to provide a proper commit message
for it?

> 
> The proper way to record strings, is to record the string into the ring
> buffer itself, and not rely on it existing hours or days later.
> 
> I recommend the following patch:
> 
> -- Steve
> 
> diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
> index 12893304c8f8..d41d914a16ca 100644
> --- a/drivers/gpu/drm/i915/i915_trace.h
> +++ b/drivers/gpu/drm/i915/i915_trace.h
> @@ -298,16 +298,16 @@ TRACE_EVENT(intel_update_plane,
>  
>  	    TP_STRUCT__entry(
>  			     __field(enum pipe, pipe)
> -			     __field(const char *, name)
>  			     __field(u32, frame)
>  			     __field(u32, scanline)
>  			     __array(int, src, 4)
>  			     __array(int, dst, 4)
> +			     __string(name, plane->name)
>  			     ),
>  
>  	    TP_fast_assign(
> +			   __assign_str(name, plane->name);
>  			   __entry->pipe = crtc->pipe;
> -			   __entry->name = plane->name;
>  			   __entry->frame = crtc->base.dev->driver->get_vblank_counter(crtc->base.dev,
>  										       crtc->pipe);
>  			   __entry->scanline = intel_get_crtc_scanline(crtc);
> @@ -316,7 +316,7 @@ TRACE_EVENT(intel_update_plane,
>  			   ),
>  
>  	    TP_printk("pipe %c, plane %s, frame=%u, scanline=%u, " DRM_RECT_FP_FMT " -> " DRM_RECT_FMT,
> -		      pipe_name(__entry->pipe), __entry->name,
> +		      pipe_name(__entry->pipe), __get_str(name),
>  		      __entry->frame, __entry->scanline,
>  		      DRM_RECT_FP_ARG((const struct drm_rect *)__entry->src),
>  		      DRM_RECT_ARG((const struct drm_rect *)__entry->dst))
> @@ -328,21 +328,21 @@ TRACE_EVENT(intel_disable_plane,
>  
>  	    TP_STRUCT__entry(
>  			     __field(enum pipe, pipe)
> -			     __field(const char *, name)
>  			     __field(u32, frame)
>  			     __field(u32, scanline)
> +			     __string(name, plane->name)
>  			     ),
>  
>  	    TP_fast_assign(
> +			   __assign_str(name, plane->name);
>  			   __entry->pipe = crtc->pipe;
> -			   __entry->name = plane->name;
>  			   __entry->frame = crtc->base.dev->driver->get_vblank_counter(crtc->base.dev,
>  										       crtc->pipe);
>  			   __entry->scanline = intel_get_crtc_scanline(crtc);
>  			   ),
>  
>  	    TP_printk("pipe %c, plane %s, frame=%u, scanline=%u",
> -		      pipe_name(__entry->pipe), __entry->name,
> +		      pipe_name(__entry->pipe), __get_str(name),
>  		      __entry->frame, __entry->scanline)
>  );
>  

-- 
Ville Syrjälä
Intel

Re: Need to remove char pointers from trace events

[Steven Rostedt]

On Wed, 10 Jul 2019 18:45:24 +0300
Ville Syrjälä <ville.syrjala@linux.intel.com> wrote:

> > 	    TP_printk("pipe %c, plane %s, frame=%u, scanline=%u",
> > 		      pipe_name(__entry->pipe), __entry->name,
> > 		      __entry->frame, __entry->scanline)
> > 
> > 
> > The issue here is that you record a pointer address to "plane->name"
> > and then sometime in the distant future access that same address.
> > There's usually no guarantee that the contents at that address will
> > exist when the buffer is read.  
> 
> The only way those can disappear is if the device goes away. But I have
> no problem going with your patch. Want to provide a proper commit message
> for it?

Sure, but does that mean the trace data will go away with the device?
If not, then you still have the issue.

Also note that perf and trace-cmd will not know how to read that data
either, so adding it to the ring buffer gives them access.

I'll send a patch next, thanks!

-- Steve

> 
> > 
> > The proper way to record strings, is to record the string into the ring
> > buffer itself, and not rely on it existing hours or days later.
> >