[RESEND,v1,2/2] trace: events: block: Add tag in block trace events

Commit Message

Bean Huo April 16, 2018, 2:33 p.m. UTC

Print the request tag along with other information in block trace events
when tracing request , and unplug type (Sync / Async).

Signed-off-by: Bean Huo <[e-mail]>
---
 include/trace/events/block.h | 36 +++++++++++++++++++++++++-----------
 1 file changed, 25 insertions(+), 11 deletions(-)

Comments

Steven Rostedt April 16, 2018, 3:29 p.m. UTC | #1

On Mon, 16 Apr 2018 14:33:29 +0000
"Bean Huo (beanhuo)" <[e-mail]> wrote:

> Print the request tag along with other information in block trace events
> when tracing request , and unplug type (Sync / Async).
> 
> Signed-off-by: Bean Huo <[e-mail]>

I don't see any issue with the tracing part.

Acked-by: Steven Rostedt (VMware) <[e-mail]>

Others need to check the content.

-- Steve


> ---
>  include/trace/events/block.h | 36 +++++++++++++++++++++++++-----------
>  1 file changed, 25 insertions(+), 11 deletions(-)
>

Bart Van Assche April 16, 2018, 8:49 p.m. UTC | #2

On Mon, 2018-04-16 at 14:33 +0000, Bean Huo (beanhuo) wrote:
> [ ... ]

> -	TP_printk("%d,%d %s (%s) %llu + %u [%d]",

> +	TP_printk("%d,%d %s (%s) %llu + %u tag=%d [%d]",

> [ ... ]

> -	TP_printk("%d,%d %s (%s) %llu + %u [%d]",

> +	TP_printk("%d,%d %s (%s) %llu + %u tag=%d [%d]",

> [ ... ]


Which tools process these strings? Has it been verified whether or not
the tools that process these strings still work fine with this patch
applied?

Thanks,

Bart.

Steffen Maier April 23, 2018, 12:43 p.m. UTC | #3

On 04/16/2018 04:33 PM, Bean Huo (beanhuo) wrote:
> Print the request tag along with other information in block trace events
> when tracing request , and unplug type (Sync / Async).
> 
> Signed-off-by: Bean Huo <[e-mail]>
> ---
>   include/trace/events/block.h | 36 +++++++++++++++++++++++++-----------
>   1 file changed, 25 insertions(+), 11 deletions(-)
> 
> diff --git a/include/trace/events/block.h b/include/trace/events/block.h
> index 81b43f5..f8c0b9e 100644
> --- a/include/trace/events/block.h
> +++ b/include/trace/events/block.h

> @@ -478,15 +486,18 @@ DECLARE_EVENT_CLASS(block_unplug,
> 
>   	TP_STRUCT__entry(
>   		__field( int,		nr_rq			)
> +		__field( bool,		explicit		)
>   		__array( char,		comm,	TASK_COMM_LEN	)
>   	),
> 
>   	TP_fast_assign(
>   		__entry->nr_rq = depth;
> +		__entry->explicit = explicit;
>   		memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
>   	),
> 
> -	TP_printk("[%s] %d", __entry->comm, __entry->nr_rq)
> +	TP_printk("[%s] %d %s", __entry->comm, __entry->nr_rq,
> +		   __entry->explicit ? "Sync" : "Async")
>   );
> 
>   /**

This entire hunk does not seem related to this patch description.
Also, I'm not sure trace-cmd and perf et al. could format it accordingly.
See also my patch for this same functionality:
https://www.spinics.net/lists/linux-block/msg24691.html
("[PATCH v2 1/2] tracing/events: block: track and print if unplug was 
explicit or schedule")

Steven Rostedt April 23, 2018, 1:34 p.m. UTC | #4

On Mon, 23 Apr 2018 14:43:13 +0200
Steffen Maier <[e-mail]> wrote:

> > -	TP_printk("[%s] %d", __entry->comm, __entry->nr_rq)
> > +	TP_printk("[%s] %d %s", __entry->comm, __entry->nr_rq,
> > +		   __entry->explicit ? "Sync" : "Async")
> >   );
> > 
> >   /**  
> 
> This entire hunk does not seem related to this patch description.
> Also, I'm not sure trace-cmd and perf et al. could format it accordingly.

You mean the "?:" operation? trace-cmd and perf can handle it fine.
Just look at the trace event irq_handler_exit:

 print fmt: "irq=%d ret=%s", REC->irq, REC->ret ? "handled" : "unhandled"

# trace-cmd record -e irq_handler_exit
# trace-cmd report
          <idle>-0     [001] 856960.382767: irq_handler_exit:     irq=29 ret=handled
          <idle>-0     [001] 856961.745640: irq_handler_exit:     irq=29 ret=handled
          <idle>-0     [001] 856961.865762: irq_handler_exit:     irq=29 ret=handled


-- Steve

Patch

diff --git a/include/trace/events/block.h b/include/trace/events/block.h
index 81b43f5..f8c0b9e 100644
--- a/include/trace/events/block.h
+++ b/include/trace/events/block.h
@@ -81,6 +81,7 @@  TRACE_EVENT(block_rq_requeue,
 		__field(  dev_t,	dev			)
 		__field(  sector_t,	sector			)
 		__field(  unsigned int,	nr_sector		)
+		__field(  int,		tag			)
 		__array(  char,		rwbs,	RWBS_LEN	)
 		__dynamic_array( char,	cmd,	1		)
 	),
@@ -89,16 +90,17 @@  TRACE_EVENT(block_rq_requeue,
 		__entry->dev	   = rq->rq_disk ? disk_devt(rq->rq_disk) : 0;
 		__entry->sector    = blk_rq_trace_sector(rq);
 		__entry->nr_sector = blk_rq_trace_nr_sectors(rq);
+		__entry->tag	   = rq->tag;
 
 		blk_fill_rwbs(__entry->rwbs, rq->cmd_flags, blk_rq_bytes(rq));
 		__get_str(cmd)[0] = '\0';
 	),
 
-	TP_printk("%d,%d %s (%s) %llu + %u [%d]",
+	TP_printk("%d,%d %s (%s) %llu + %u tag=%d [%d]",
 		  MAJOR(__entry->dev), MINOR(__entry->dev),
 		  __entry->rwbs, __get_str(cmd),
 		  (unsigned long long)__entry->sector,
-		  __entry->nr_sector, 0)
+		  __entry->nr_sector, __entry->tag, 0)
 );
 
 /**
@@ -124,6 +126,7 @@  TRACE_EVENT(block_rq_complete,
 		__field(  sector_t,	sector			)
 		__field(  unsigned int,	nr_sector		)
 		__field(  int,		error			)
+		__field(  int,		tag			)
 		__array(  char,		rwbs,	RWBS_LEN	)
 		__dynamic_array( char,	cmd,	1		)
 	),
@@ -133,16 +136,17 @@  TRACE_EVENT(block_rq_complete,
 		__entry->sector    = blk_rq_pos(rq);
 		__entry->nr_sector = nr_bytes >> 9;
 		__entry->error     = error;
+		__entry->tag	   = rq->tag;
 
 		blk_fill_rwbs(__entry->rwbs, rq->cmd_flags, nr_bytes);
 		__get_str(cmd)[0] = '\0';
 	),
 
-	TP_printk("%d,%d %s (%s) %llu + %u [%d]",
+	TP_printk("%d,%d %s (%s) %llu + %u tag=%d [%d]",
 		  MAJOR(__entry->dev), MINOR(__entry->dev),
 		  __entry->rwbs, __get_str(cmd),
 		  (unsigned long long)__entry->sector,
-		  __entry->nr_sector, __entry->error)
+		  __entry->nr_sector, __entry->tag, __entry->error)
 );
 
 DECLARE_EVENT_CLASS(block_rq,
@@ -156,6 +160,7 @@  DECLARE_EVENT_CLASS(block_rq,
 		__field(  sector_t,	sector			)
 		__field(  unsigned int,	nr_sector		)
 		__field(  unsigned int,	bytes			)
+		__field(  int,		tag			)
 		__array(  char,		rwbs,	RWBS_LEN	)
 		__array(  char,         comm,   TASK_COMM_LEN   )
 		__dynamic_array( char,	cmd,	1		)
@@ -166,17 +171,18 @@  DECLARE_EVENT_CLASS(block_rq,
 		__entry->sector    = blk_rq_trace_sector(rq);
 		__entry->nr_sector = blk_rq_trace_nr_sectors(rq);
 		__entry->bytes     = blk_rq_bytes(rq);
+		__entry->tag	   = rq->tag;
 
 		blk_fill_rwbs(__entry->rwbs, rq->cmd_flags, blk_rq_bytes(rq));
 		__get_str(cmd)[0] = '\0';
 		memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
 	),
 
-	TP_printk("%d,%d %s %u (%s) %llu + %u [%s]",
+	TP_printk("%d,%d %s %u (%s) %llu + %u tag=%d [%s]",
 		  MAJOR(__entry->dev), MINOR(__entry->dev),
 		  __entry->rwbs, __entry->bytes, __get_str(cmd),
 		  (unsigned long long)__entry->sector,
-		  __entry->nr_sector, __entry->comm)
+		  __entry->nr_sector, __entry->tag, __entry->comm)
 );
 
 /**
@@ -297,6 +303,7 @@  DECLARE_EVENT_CLASS(block_bio_merge,
 		__field( dev_t,		dev			)
 		__field( sector_t,	sector			)
 		__field( unsigned int,	nr_sector		)
+		__field( int,		tag			)
 		__array( char,		rwbs,	RWBS_LEN	)
 		__array( char,		comm,	TASK_COMM_LEN	)
 	),
@@ -305,14 +312,15 @@  DECLARE_EVENT_CLASS(block_bio_merge,
 		__entry->dev		= bio_dev(bio);
 		__entry->sector		= bio->bi_iter.bi_sector;
 		__entry->nr_sector	= bio_sectors(bio);
+		__entry->tag		= rq->tag;
 		blk_fill_rwbs(__entry->rwbs, bio->bi_opf, bio->bi_iter.bi_size);
 		memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
 	),
 
-	TP_printk("%d,%d %s %llu + %u [%s]",
+	TP_printk("%d,%d %s %llu + %u tag=%d [%s]",
 		  MAJOR(__entry->dev), MINOR(__entry->dev), __entry->rwbs,
 		  (unsigned long long)__entry->sector,
-		  __entry->nr_sector, __entry->comm)
+		  __entry->nr_sector, __entry->tag, __entry->comm)
 );
 
 /**
@@ -478,15 +486,18 @@  DECLARE_EVENT_CLASS(block_unplug,
 
 	TP_STRUCT__entry(
 		__field( int,		nr_rq			)
+		__field( bool,		explicit		)
 		__array( char,		comm,	TASK_COMM_LEN	)
 	),
 
 	TP_fast_assign(
 		__entry->nr_rq = depth;
+		__entry->explicit = explicit;
 		memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
 	),
 
-	TP_printk("[%s] %d", __entry->comm, __entry->nr_rq)
+	TP_printk("[%s] %d %s", __entry->comm, __entry->nr_rq,
+		   __entry->explicit ? "Sync" : "Async")
 );
 
 /**
@@ -611,6 +622,7 @@  TRACE_EVENT(block_rq_remap,
 		__field( dev_t,		dev		)
 		__field( sector_t,	sector		)
 		__field( unsigned int,	nr_sector	)
+		__field( int,		tag		)
 		__field( dev_t,		old_dev		)
 		__field( sector_t,	old_sector	)
 		__field( unsigned int,	nr_bios		)
@@ -621,18 +633,20 @@  TRACE_EVENT(block_rq_remap,
 		__entry->dev		= disk_devt(rq->rq_disk);
 		__entry->sector		= blk_rq_pos(rq);
 		__entry->nr_sector	= blk_rq_sectors(rq);
+		__entry->tag		= rq->tag;
 		__entry->old_dev	= dev;
 		__entry->old_sector	= from;
 		__entry->nr_bios	= blk_rq_count_bios(rq);
 		blk_fill_rwbs(__entry->rwbs, rq->cmd_flags, blk_rq_bytes(rq));
 	),
 
-	TP_printk("%d,%d %s %llu + %u <- (%d,%d) %llu %u",
+	TP_printk("%d,%d %s %llu + %u <- (%d,%d) %llu %u, tag=%d",
 		  MAJOR(__entry->dev), MINOR(__entry->dev), __entry->rwbs,
 		  (unsigned long long)__entry->sector,
 		  __entry->nr_sector,
 		  MAJOR(__entry->old_dev), MINOR(__entry->old_dev),
-		  (unsigned long long)__entry->old_sector, __entry->nr_bios)
+		  (unsigned long long)__entry->old_sector, __entry->nr_bios,
+		  __entry->tag)
 );
 
 #endif /* _TRACE_BLOCK_H */