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

[Steven Rostedt]

On Mon, 23 Apr 2018 14:43:13 +0200
Steffen Maier  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
  -0 [001] 856960.382767: irq_handler_exit: irq=29 
ret=handled
  -0 [001] 856961.745640: irq_handler_exit: irq=29 
ret=handled
  -0 [001] 856961.865762: irq_handler_exit: irq=29 
ret=handled


-- Steve

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

[Steven Rostedt]

On Mon, 23 Apr 2018 14:43:13 +0200
Steffen Maier  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
  -0 [001] 856960.382767: irq_handler_exit: irq=29 
ret=handled
  -0 [001] 856961.745640: irq_handler_exit: irq=29 
ret=handled
  -0 [001] 856961.865762: irq_handler_exit: irq=29 
ret=handled


-- Steve

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

[Steffen Maier]

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

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

[Steffen Maier]

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

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

[Bart Van Assche]

On Mon, 2018-04-16 at 14:33 +, 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.

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

[Bart Van Assche]

On Mon, 2018-04-16 at 14:33 +, 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.

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

[Steven Rostedt]

On Mon, 16 Apr 2018 14:33:29 +
"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 

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

Acked-by: Steven Rostedt (VMware) 

Others need to check the content.

-- Steve


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

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

[Steven Rostedt]

On Mon, 16 Apr 2018 14:33:29 +
"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 

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

Acked-by: Steven Rostedt (VMware) 

Others need to check the content.

-- Steve


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

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

[Bean Huo (beanhuo)]

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 
---
 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= 

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

[Bean Huo (beanhuo)]

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 
---
 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);