LKML Archive on lore.kernel.org
help / color / mirror / Atom feed
* [RESEND PATCH v1 2/2] trace: events: block: Add tag in block trace events
@ 2018-04-16 14:33 Bean Huo (beanhuo)
  2018-04-16 15:29 ` Steven Rostedt
                   ` (2 more replies)
  0 siblings, 3 replies; 5+ messages in thread
From: Bean Huo (beanhuo) @ 2018-04-16 14:33 UTC (permalink / raw)
  To: Steven Rostedt, axboe, jejb, martin.petersen
  Cc: linux-block, linux-scsi, linux-kernel, mingo, Bart.VanAssche,
	linux-kernel, Bean Huo (beanhuo),
	rajatja

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 <beanhuo@micron.com>
---
 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
@@ -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 */
-- 
2.7.4

^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: [RESEND PATCH v1 2/2] trace: events: block: Add tag in block trace events
  2018-04-16 14:33 [RESEND PATCH v1 2/2] trace: events: block: Add tag in block trace events Bean Huo (beanhuo)
@ 2018-04-16 15:29 ` Steven Rostedt
  2018-04-16 20:49 ` Bart Van Assche
  2018-04-23 12:43 ` Steffen Maier
  2 siblings, 0 replies; 5+ messages in thread
From: Steven Rostedt @ 2018-04-16 15:29 UTC (permalink / raw)
  To: Bean Huo (beanhuo)
  Cc: axboe, jejb, martin.petersen, linux-block, linux-scsi,
	linux-kernel, mingo, Bart.VanAssche, rajatja

On Mon, 16 Apr 2018 14:33:29 +0000
"Bean Huo (beanhuo)" <beanhuo@micron.com> 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 <beanhuo@micron.com>

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

Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org>

Others need to check the content.

-- Steve


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

^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: [RESEND PATCH v1 2/2] trace: events: block: Add tag in block trace events
  2018-04-16 14:33 [RESEND PATCH v1 2/2] trace: events: block: Add tag in block trace events Bean Huo (beanhuo)
  2018-04-16 15:29 ` Steven Rostedt
@ 2018-04-16 20:49 ` Bart Van Assche
  2018-04-23 12:43 ` Steffen Maier
  2 siblings, 0 replies; 5+ messages in thread
From: Bart Van Assche @ 2018-04-16 20:49 UTC (permalink / raw)
  To: beanhuo, jejb, rostedt, martin.petersen, axboe
  Cc: linux-scsi, linux-kernel, mingo, linux-block, rajatja

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.

^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: [RESEND PATCH v1 2/2] trace: events: block: Add tag in block trace events
  2018-04-16 14:33 [RESEND PATCH v1 2/2] trace: events: block: Add tag in block trace events Bean Huo (beanhuo)
  2018-04-16 15:29 ` Steven Rostedt
  2018-04-16 20:49 ` Bart Van Assche
@ 2018-04-23 12:43 ` Steffen Maier
  2018-04-23 13:34   ` Steven Rostedt
  2 siblings, 1 reply; 5+ messages in thread
From: Steffen Maier @ 2018-04-23 12:43 UTC (permalink / raw)
  To: Bean Huo (beanhuo), Steven Rostedt, axboe, jejb, martin.petersen
  Cc: linux-block, linux-scsi, linux-kernel, mingo, Bart.VanAssche, rajatja


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 <beanhuo@micron.com>
> ---
>   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")



-- 
Mit freundlichen Grüßen / Kind regards
Steffen Maier

Linux on z Systems Development

IBM Deutschland Research & Development GmbH
Vorsitzende des Aufsichtsrats: Martina Koederitz
Geschaeftsfuehrung: Dirk Wittkopp
Sitz der Gesellschaft: Boeblingen
Registergericht: Amtsgericht Stuttgart, HRB 243294

^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: [RESEND PATCH v1 2/2] trace: events: block: Add tag in block trace events
  2018-04-23 12:43 ` Steffen Maier
@ 2018-04-23 13:34   ` Steven Rostedt
  0 siblings, 0 replies; 5+ messages in thread
From: Steven Rostedt @ 2018-04-23 13:34 UTC (permalink / raw)
  To: Steffen Maier
  Cc: Bean Huo (beanhuo),
	axboe, jejb, martin.petersen, linux-block, linux-scsi,
	linux-kernel, mingo, Bart.VanAssche, rajatja

On Mon, 23 Apr 2018 14:43:13 +0200
Steffen Maier <maier@linux.ibm.com> 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

^ permalink raw reply	[flat|nested] 5+ messages in thread

end of thread, other threads:[~2018-04-23 13:34 UTC | newest]

Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-04-16 14:33 [RESEND PATCH v1 2/2] trace: events: block: Add tag in block trace events Bean Huo (beanhuo)
2018-04-16 15:29 ` Steven Rostedt
2018-04-16 20:49 ` Bart Van Assche
2018-04-23 12:43 ` Steffen Maier
2018-04-23 13:34   ` Steven Rostedt

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).