[RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events

[RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events

[Bean Huo (beanhuo)]

Print the request tag along with other information
while tracing a command.

Signed-off-by: Bean Huo <beanhuo@micron.com>
---
 include/trace/events/scsi.h | 20 +++++++++++++-------
 1 file changed, 13 insertions(+), 7 deletions(-)

diff --git a/include/trace/events/scsi.h b/include/trace/events/scsi.h
index f624969..a4ada90 100644
--- a/include/trace/events/scsi.h
+++ b/include/trace/events/scsi.h
@@ -210,6 +210,7 @@ TRACE_EVENT(scsi_dispatch_cmd_start,
 		__field( unsigned int,	lun	)
 		__field( unsigned int,	opcode	)
 		__field( unsigned int,	cmd_len )
+		__field( int,		tag )
 		__field( unsigned int,	data_sglen )
 		__field( unsigned int,	prot_sglen )
 		__field( unsigned char,	prot_op )
@@ -223,6 +224,7 @@ TRACE_EVENT(scsi_dispatch_cmd_start,
 		__entry->lun		= cmd->device->lun;
 		__entry->opcode		= cmd->cmnd[0];
 		__entry->cmd_len	= cmd->cmd_len;
+		__entry->tag		= cmd->request->tag;
 		__entry->data_sglen	= scsi_sg_count(cmd);
 		__entry->prot_sglen	= scsi_prot_sg_count(cmd);
 		__entry->prot_op	= scsi_get_prot_op(cmd);
@@ -230,10 +232,10 @@ TRACE_EVENT(scsi_dispatch_cmd_start,
 	),
 
 	TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u prot_sgl=%u" \
-		  " prot_op=%s cmnd=(%s %s raw=%s)",
+		  " prot_op=%s tag=%d cmnd=(%s %s raw=%s)",
 		  __entry->host_no, __entry->channel, __entry->id,
 		  __entry->lun, __entry->data_sglen, __entry->prot_sglen,
-		  show_prot_op_name(__entry->prot_op),
+		  show_prot_op_name(__entry->prot_op), __entry->tag,
 		  show_opcode_name(__entry->opcode),
 		  __parse_cdb(__get_dynamic_array(cmnd), __entry->cmd_len),
 		  __print_hex(__get_dynamic_array(cmnd), __entry->cmd_len))
@@ -253,6 +255,7 @@ TRACE_EVENT(scsi_dispatch_cmd_error,
 		__field( int,		rtn	)
 		__field( unsigned int,	opcode	)
 		__field( unsigned int,	cmd_len )
+		__field( int,		tag )
 		__field( unsigned int,	data_sglen )
 		__field( unsigned int,	prot_sglen )
 		__field( unsigned char,	prot_op )
@@ -267,6 +270,7 @@ TRACE_EVENT(scsi_dispatch_cmd_error,
 		__entry->rtn		= rtn;
 		__entry->opcode		= cmd->cmnd[0];
 		__entry->cmd_len	= cmd->cmd_len;
+		__entry->tag		= cmd->request->tag;
 		__entry->data_sglen	= scsi_sg_count(cmd);
 		__entry->prot_sglen	= scsi_prot_sg_count(cmd);
 		__entry->prot_op	= scsi_get_prot_op(cmd);
@@ -274,10 +278,10 @@ TRACE_EVENT(scsi_dispatch_cmd_error,
 	),
 
 	TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u prot_sgl=%u" \
-		  " prot_op=%s cmnd=(%s %s raw=%s) rtn=%d",
+		  " prot_op=%s tag=%d cmnd=(%s %s raw=%s) rtn=%d",
 		  __entry->host_no, __entry->channel, __entry->id,
 		  __entry->lun, __entry->data_sglen, __entry->prot_sglen,
-		  show_prot_op_name(__entry->prot_op),
+		  show_prot_op_name(__entry->prot_op), __entry->tag,
 		  show_opcode_name(__entry->opcode),
 		  __parse_cdb(__get_dynamic_array(cmnd), __entry->cmd_len),
 		  __print_hex(__get_dynamic_array(cmnd), __entry->cmd_len),
@@ -298,6 +302,7 @@ DECLARE_EVENT_CLASS(scsi_cmd_done_timeout_template,
 		__field( int,		result	)
 		__field( unsigned int,	opcode	)
 		__field( unsigned int,	cmd_len )
+		__field( int,		tag )
 		__field( unsigned int,	data_sglen )
 		__field( unsigned int,	prot_sglen )
 		__field( unsigned char,	prot_op )
@@ -312,6 +317,7 @@ DECLARE_EVENT_CLASS(scsi_cmd_done_timeout_template,
 		__entry->result		= cmd->result;
 		__entry->opcode		= cmd->cmnd[0];
 		__entry->cmd_len	= cmd->cmd_len;
+		__entry->tag		= cmd->request->tag;
 		__entry->data_sglen	= scsi_sg_count(cmd);
 		__entry->prot_sglen	= scsi_prot_sg_count(cmd);
 		__entry->prot_op	= scsi_get_prot_op(cmd);
@@ -319,11 +325,11 @@ DECLARE_EVENT_CLASS(scsi_cmd_done_timeout_template,
 	),
 
 	TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u " \
-		  "prot_sgl=%u prot_op=%s cmnd=(%s %s raw=%s) result=(driver=" \
-		  "%s host=%s message=%s status=%s)",
+		  "prot_sgl=%u prot_op=%s tag=%d cmnd=(%s %s raw=%s) " \
+		  "result=(driver=%s host=%s message=%s status=%s)",
 		  __entry->host_no, __entry->channel, __entry->id,
 		  __entry->lun, __entry->data_sglen, __entry->prot_sglen,
-		  show_prot_op_name(__entry->prot_op),
+		  show_prot_op_name(__entry->prot_op), __entry->tag,
 		  show_opcode_name(__entry->opcode),
 		  __parse_cdb(__get_dynamic_array(cmnd), __entry->cmd_len),
 		  __print_hex(__get_dynamic_array(cmnd), __entry->cmd_len),
-- 
2.7.4

Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events

[Steven Rostedt]

On Mon, 16 Apr 2018 14:31:49 +0000
"Bean Huo (beanhuo)" <beanhuo@micron.com> wrote:

> Print the request tag along with other information
> while tracing a command.
> 
> 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

Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events

[Rajat Jain]

On Mon, Apr 16, 2018 at 8:28 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Mon, 16 Apr 2018 14:31:49 +0000
> "Bean Huo (beanhuo)" <beanhuo@micron.com> wrote:
>
>> Print the request tag along with other information
>> while tracing a command.
>>
>> Signed-off-by: Bean Huo <beanhuo@micron.com>
Acked-by: Rajat Jain <rajatja@google.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

Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events

[Bart Van Assche]

On Mon, 2018-04-16 at 09:41 -0700, Rajat Jain wrote:
> On Mon, Apr 16, 2018 at 8:28 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> > On Mon, 16 Apr 2018 14:31:49 +0000
> > "Bean Huo (beanhuo)" <beanhuo@micron.com> wrote:
> > 
> > > Print the request tag along with other information
> > > while tracing a command.
> > > 
> > > Signed-off-by: Bean Huo <beanhuo@micron.com>
> 
> Acked-by: Rajat Jain <rajatja@google.com>

This patch is not acceptable because it adds support for tag tracing to the
legacy block layer only. Any patch that adds a new feature to the legacy block
layer must also add it to blk-mq.

Bart.

Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events

[Bart Van Assche]

On Mon, 2018-04-16 at 14:31 +0000, Bean Huo (beanhuo) wrote:
>  	TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u prot_sgl=%u" \
> -		  " prot_op=%s cmnd=(%s %s raw=%s)",
> +		  " prot_op=%s tag=%d cmnd=(%s %s raw=%s)",
> 
> [ ... ]
>  	TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u prot_sgl=%u" \
> -		  " prot_op=%s cmnd=(%s %s raw=%s) rtn=%d",
> +		  " prot_op=%s tag=%d cmnd=(%s %s raw=%s) rtn=%d",
> [ ... ]
>  	TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u " \
> -		  "prot_sgl=%u prot_op=%s cmnd=(%s %s raw=%s) result=(driver=" \
> -		  "%s host=%s message=%s status=%s)",
> +		  "prot_sgl=%u prot_op=%s tag=%d cmnd=(%s %s raw=%s) " \
> +		  "result=(driver=%s host=%s message=%s status=%s)",

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 1/2] trace: events: scsi: Add tag in SCSI trace events

[Steven Rostedt]

On Mon, 16 Apr 2018 20:49:12 +0000
Bart Van Assche <Bart.VanAssche@wdc.com> wrote:

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

Ideally, tools shouldn't process trace event strings, but I'm sure some
do. :-/

Getting libtraceevent out as a library is a high priority of mine, and
hopefully I should get something out in a couple of months.

Ideally, tools should parse the raw data and then new fields will not
affect them.

-- Steve

Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events

[Bart Van Assche]

On Mon, 2018-04-16 at 17:24 -0400, Steven Rostedt wrote:
> On Mon, 16 Apr 2018 20:49:12 +0000
> Bart Van Assche <Bart.VanAssche@wdc.com> wrote:
> 
> > 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?
> 
> Ideally, tools shouldn't process trace event strings, but I'm sure some
> do. :-/
> 
> Getting libtraceevent out as a library is a high priority of mine, and
> hopefully I should get something out in a couple of months.
> 
> Ideally, tools should parse the raw data and then new fields will not
> affect them.

Hello Steve,

The tool I'm most concerned about is blktrace. I'm not sure though how this
tool receives event data from the block layer core.

Thanks,

Bart.

Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events

[Steven Rostedt]

On Mon, 16 Apr 2018 21:30:54 +0000
Bart Van Assche <Bart.VanAssche@wdc.com> wrote:

> Hello Steve,
> 
> The tool I'm most concerned about is blktrace. I'm not sure though how this
> tool receives event data from the block layer core.

Yeah, blktrace is "special", it looks like it registers its callbacks
from the tracepoints, and writes the data to its own relay buffer. As
it's not relying on the output from the tracing directory, additional
fields being added shouldn't affect it.

Looking at the trace event "block_rq_requeue" we have in the blktrace
kernel code:

static void blk_register_tracepoints(void)
{
	int ret;

	ret = register_trace_block_rq_insert(blk_add_trace_rq_insert, NULL);


Where the callback blk_add_trace_rq_insert() gets called when the
trace event is hit.

static void blk_add_trace_rq_insert(void *ignore,
				    struct request_queue *q, struct request *rq)
{
	blk_add_trace_rq(rq, 0, blk_rq_bytes(rq), BLK_TA_INSERT,
			 blk_trace_request_get_cgid(q, rq));
}

Where:

static void blk_add_trace_rq(struct request *rq, int error,
			     unsigned int nr_bytes, u32 what,
			     union kernfs_node_id *cgid)
{

calls

	__blk_add_trace(bt, blk_rq_trace_sector(rq), nr_bytes, req_op(rq),
			rq->cmd_flags, what, error, 0, NULL, cgid);

Which calls either the ftrace tracing file or its own relay buffer.

Looking at the code from
git://git.kernel.org/pub/scm/linux/kernel/git/axboe/blktrace.git

It appears that it does not rely on the ftrace ring buffers.

So I'm guessing blktrace is not affected by this patch.

-- Steve

Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events

[Steffen Maier]

On 04/17/2018 12:00 PM, Bean Huo (beanhuo) wrote:

> #Cat trace
> iozone-4055  [000] ....   665.039276: block_unplug: [iozone] 1 Sync
> iozone-4055  [000] ...1   665.039278: block_rq_insert: 8,48 WS 0 () 39604352 + 128 tag=18 [iozone]
> iozone-4055  [000] ...1   665.039280: block_rq_issue: 8,48 WS 0 () 39604352 + 128 tag=18 [iozone]
> iozone-4055  [000] ...1   665.039284: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL tag=18 cmnd=(WRITE_10 lba=4950544 txlen=16 protect=0 raw=2a 00 00 4b 8a 10 00 00 10 00)
> iozone-4056  [002] ....   665.039284: block_dirty_buffer: 8,62 sector=44375 size=4096
> <idle>-0     [000] d.h2   665.039319: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL tag=24 cmnd=(WRITE_10 lba=4944016 txlen=16 protect=0 raw=2a 00 00 4b 70 90 00 00 10 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
> <idle>-0     [000] d.h3   665.039321: block_rq_complete: 8,48 WS () 39552128 + 128 tag=24 [0]

> iozone-4058  [003] ....   665.039362: block_bio_remap: 8,48 WS 39568768 + 128 <- (8,62) 337280
> iozone-4058  [003] ....   665.039364: block_bio_queue: 8,48 WS 39568768 + 128 [iozone]
> iozone-4058  [003] ...1   665.039366: block_getrq: 8,48 WS 39568768 + 128 [iozone]

I'm not familiar with block/scsi command tagging.

Some block events now would get a tag field.
Some block events would not get a tag field (maybe because for some the 
tag is not (yet) known).

So all block events that belong to the same request would still need to 
be correlated by something like (devt, RWBS, LBA, length) because not 
all have a tag field.

> Especially, the ftrace log with tag information, I can easily figure out one I/O request between block layer and SCSI.

Provided this is done correctly, I would be in favor of a solution.
Since
v4.11 commit 48b77ad60844 (``block: cleanup tracing'')\newline
v4.11 commit 82ed4db499b8 (``block: split scsi\_request out of struct 
request'')
we don't have the SCSI CDB in block traces (nor in blktrace traditional 
relayfs trace format, nor in ftrace 'blk' tracer binary synthesized 
output [1]) any more (empty Packet Command payload).
Being able to correlate block events with scsi events would indeed be 
very helpful for some cases.

Is a correlation between block and scsi only necessary for these pairs?:

block_rq_issue causes scsi_dispatch_cmd_start, and
scsi_dispatch_cmd_done causes block_rq_complete.

If so, only those two block trace events would need to get a new field?


[1] v2.6.30 commit 08a06b83ff8b (``blkftrace: binary tracing, 
synthesizing old format'')
     v2.6.31 commit f3948f8857ef (``blktrace: fix context-info when 
mixed-using blk tracer and trace events'')

-- 
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 1/2] trace: events: scsi: Add tag in SCSI trace events

[Bean Huo (beanhuo)]

>On Mon, 2018-04-16 at 20:27 +0000, Bean Huo (beanhuo) wrote:
>> By the way, these patches are not to add new feature, they are just to
>> add print tag along with the other exist printed request parameters.
>
>Are you aware that there are two tag fields in struct request, namely "tag"
>and "internal_tag"? Are you aware that how these fields are used depends on
>whether or not a scheduler is attached to a request queue? Have you verified
>that the "tag" field contains a meaningful value for blk-mq for every blk-mq
>tracepoint?
>
>Thanks,
>
>Bart.
>
>
Yes, I noticed and was aware, there are tag and internal_tag.
One thing I was not aware is that the patches would make such a big impact on blk-mq based on
Your comments.

I am not expert on block layer, that is why I added block maintainer here.
Please point out which line and what is problem? If there is some wrong with the patch.
Which one is correct "tag" to track request? 

Thanks,
//Bean Huo

Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events

[Bean Huo (beanhuo)]

Hi, Steve 
Right, Please see below portion log from ftrace and blktrace,
There is no any impact on blktrace. 
>
>Looking at the code from
>git://git.kernel.org/pub/scm/linux/kernel/git/axboe/blktrace.git
>
>It appears that it does not rely on the ftrace ring buffers.
>
>So I'm guessing blktrace is not affected by this patch.
>
>-- Steve


#/blktrace -d /dev/block/sdd14 -o - | ./blkparse -i -  
  8,62   3     1162     0.213039583  4116  P   N [iozone]
  8,62   3     1163     0.213041146  4116  U   N [iozone] 1
  8,62   3     1164     0.213042708  4116  I  WS 39573632 + 128 [iozone]
  8,62   3     1165     0.213044791  4116  D  WS 39573632 + 128 [iozone]
  8,48   3     1166     0.213585416  4116  A  WS 39573760 + 128 <- (8,62) 342272
  8,62   3     1167     0.213590104  4116  Q  WS 39573760 + 128 [iozone]
  8,62   3     1168     0.213592187  4116  G  WS 39573760 + 128 [iozone]
  8,62   3     1169     0.213594271  4116  P   N [iozone]
  8,62   3     1170     0.213595833  4116  U   N [iozone] 1
  8,62   3     1171     0.213597396  4116  I  WS 39573760 + 128 [iozone]
  8,62   3     1172     0.213600000  4116  D  WS 39573760 + 128 [iozone]
  8,48   3     1173     0.214092187  4116  A  WS 39573888 + 128 <- (8,62) 342400
  8,62   3     1174     0.214094791  4116  Q  WS 39573888 + 128 [iozone]
  8,62   3     1175     0.214097916  4116  G  WS 39573888 + 128 [iozone]
  8,62   3     1176     0.214102604  4116  P   N [iozone]
  8,62   3     1177     0.214105208  4116  U   N [iozone] 1
  8,62   3     1178     0.214106771  4116  I  WS 39573888 + 128 [iozone]
  8,62   3     1179     0.214111458  4116  D  WS 39573888 + 128 [iozone]
  8,48   3     1180     0.216531771  4115  A  WS 39546496 + 128 <- (8,62) 315008
  8,62   3     1181     0.216534896  4115  Q  WS 39546496 + 128 [iozone]
  8,62   3     1182     0.216538021  4115  G  WS 39546496 + 128 [iozone]
  8,62   3     1183     0.216540625  4115  P   N [iozone]
  8,62   3     1184     0.216543229  4115  U   N [iozone] 1
  8,62   3     1185     0.216544791  4115  I  WS 39546496 + 128 [iozone]
  8,62   3     1186     0.216547396  4115  D  WS 39546496 + 128 [iozone]
  8,48   3     1187     0.217146354  4115  A  WS 39546624 + 128 <- (8,62) 315136
  8,62   3     1188     0.217148437  4115  Q  WS 39546624 + 128 [iozone]
  8,62   3     1189     0.217151041  4115  G  WS 39546624 + 128 [iozone]
  8,62   3     1190     0.217153646  4115  P   N [iozone]
  8,62   3     1191     0.217155208  4115  U   N [iozone] 1
  8,62   3     1192     0.217156771  4115  I  WS 39546624 + 128 [iozone]
  8,62   3     1193     0.217159896  4115  D  WS 39546624 + 128 [iozone]
  8,48   3     1194     0.217712500  4115  A  WS 39546752 + 128 <- (8,62) 315264
  8,62   3     1195     0.217714583  4115  Q  WS 39546752 + 128 [iozone]
  8,62   3     1196     0.217717708  4115  G  WS 39546752 + 128 [iozone]
  8,62   3     1197     0.217722396  4115  P   N [iozone]
  8,62   3     1198     0.217724479  4115  U   N [iozone] 1
  8,62   3     1199     0.217726041  4115  I  WS 39546752 + 128 [iozone]
  8,62   3     1200     0.217728646  4115  D  WS 39546752 + 128 [iozone]
  8,62   5     1150     0.198047916     0  C  WS 39569920 + 128 [0]
  8,62   4     1104     0.198104687     0  C  WS 39576448 + 128 [0]
  8,48   5     1151     0.198182291  4116  A  WS 39570048 + 128 <- (8,62) 338560
  8,62   5     1152     0.198183333  4116  Q  WS 39570048 + 128 [iozone]
  8,62   5     1153     0.198184375  4116  G  WS 39570048 + 128 [iozone]
  8,62   5     1154     0.198185937  4116  P   N [iozone]
  8,62   5     1155     0.198186458  4116  U   N [iozone] 1
  8,62   5     1156     0.198186979  4116  I  WS 39570048 + 128 [iozone]
  8,62   5     1157     0.198188541  4116  D  WS 39570048 + 128 [iozone]
  8,48   4     1105     0.198218229  4114  A  WS 39576576 + 128 <- (8,62) 345088
  8,62   4     1106     0.198219271  4114  Q  WS 39576576 + 128 [iozone]
  8,62   4     1107     0.198220312  4114  G  WS 39576576 + 128 [iozone]
  8,62   4     1108     0.198221354  4114  P   N [iozone]
  8,62   4     1109     0.198221875  4114  U   N [iozone] 1
  8,62   4     1110     0.198222396  4114  I  WS 39576576 + 128 [iozone]
  8,62   4     1111     0.198223437  4114  D  WS 39576576 + 128 [iozone]
  8,62   4     1112     0.198245312  4114  C  WS 39594368 + 128 [0]
  8,62   5     1158     0.198336979     0  C  WS 39570048 + 128 [0]
  8,62   4     1113     0.198409375     0  C  WS 39576576 + 128 [0]
  8,48   5     1159     0.199219791  4113  A  WS 39594624 + 128 <- (8,62) 363136
  8,62   5     1160     0.199220833  4113  Q  WS 39594624 + 128 [iozone]
  8,62   5     1161     0.199222396  4113  G  WS 39594624 + 128 [iozone]
  8,62   5     1162     0.199223437  4113  P   N [iozone]
  8,62   5     1163     0.199224479  4113  U   N [iozone] 1
  8,62   5     1164     0.199225000  4113  I  WS 39594624 + 128 [iozone]
  8,62   5     1165     0.199226562  4113  D  WS 39594624 + 128 [iozone]
  8,48   4     1114     0.199235937  4116  A  WS 39570176 + 128 <- (8,62) 338688
  8,62   4     1115     0.199236979  4116  Q  WS 39570176 + 128 [iozone]
  8,62   4     1116     0.199238021  4116  G  WS 39570176 + 128 [iozone]
  8,62   4     1117     0.199239062  4116  P   N [iozone]
  8,62   4     1118     0.199239583  4116  U   N [iozone] 1
  8,62   4     1119     0.199240104  4116  I  WS 39570176 + 128 [iozone]
  8,62   4     1120     0.199241666  4116  D  WS 39570176 + 128 [iozone]
  8,62   4     1121     0.199404687     0  C  WS 39570176 + 128 [0]
  8,62   5     1166     0.199467187     0  C  WS 39594624 + 128 [0]
  8,48   5     1167     0.199960416  4113  A  WS 39594752 + 128 <- (8,62) 363264
  8,62   5     1168     0.199960937  4113  Q  WS 39594752 + 128 [iozone]
  8,62   5     1169     0.199961979  4113  G  WS 39594752 + 128 [iozone]
  8,62   5     1170     0.199963541  4113  P   N [iozone]
  8,62   5     1171     0.199964062  4113  U   N [iozone] 1
  8,62   5     1172     0.199964583  4113  I  WS 39594752 + 128 [iozone]
  8,62   5     1173     0.199966146  4113  D  WS 39594752 + 128 [iozone]
  8,48   4     1122     0.199970833  4116  A  WS 39570304 + 128 <- (8,62) 338816
  8,62   4     1123     0.199971875  4116  Q  WS 39570304 + 128 [iozone]
  8,62   4     1124     0.199972916  4116  G  WS 39570304 + 128 [iozone]
  8,62   4     1125     0.199973958  4116  P   N [iozone]
  8,62   4     1126     0.199974479  4116  U   N [iozone] 1

#Cat trace
iozone-4055  [000] ....   665.039276: block_unplug: [iozone] 1 Sync
iozone-4055  [000] ...1   665.039278: block_rq_insert: 8,48 WS 0 () 39604352 + 128 tag=18 [iozone]
iozone-4055  [000] ...1   665.039280: block_rq_issue: 8,48 WS 0 () 39604352 + 128 tag=18 [iozone]
iozone-4055  [000] ...1   665.039284: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL tag=18 cmnd=(WRITE_10 lba=4950544 txlen=16 protect=0 raw=2a 00 00 4b 8a 10 00 00 10 00)
iozone-4056  [002] ....   665.039284: block_dirty_buffer: 8,62 sector=44375 size=4096
<idle>-0     [000] d.h2   665.039319: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL tag=24 cmnd=(WRITE_10 lba=4944016 txlen=16 protect=0 raw=2a 00 00 4b 70 90 00 00 10 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
<idle>-0     [000] d.h3   665.039321: block_rq_complete: 8,48 WS () 39552128 + 128 tag=24 [0]
iozone-4056  [002] ....   665.039325: block_dirty_buffer: 8,62 sector=44380 size=4096
iozone-4058  [003] ....   665.039362: block_bio_remap: 8,48 WS 39568768 + 128 <- (8,62) 337280
iozone-4058  [003] ....   665.039364: block_bio_queue: 8,48 WS 39568768 + 128 [iozone]
iozone-4058  [003] ...1   665.039366: block_getrq: 8,48 WS 39568768 + 128 [iozone]
iozone-4058  [003] ...1   665.039368: block_plug: [iozone]
iozone-4058  [003] ....   665.039369: block_unplug: [iozone] 1 Sync
iozone-4058  [003] ...1   665.039371: block_rq_insert: 8,48 WS 0 () 39568768 + 128 tag=16 [iozone]
iozone-4058  [003] ...1   665.039373: block_rq_issue: 8,48 WS 0 () 39568768 + 128 tag=16 [iozone]
iozone-4058  [003] ...1   665.039375: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL tag=16 cmnd=(WRITE_10 lba=4946096 txlen=16 protect=0 raw=2a 00 00 4b 78 b0 00 00 10 00)
iozone-4057  [001] ....   665.039402: block_touch_buffer: 8,62 sector=1034 size=4096
<idle>-0     [000] d.h2   665.039410: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=3 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL tag=18 cmnd=(WRITE_10 lba=4950544 txlen=16 protect=0 raw=2a 00 00 4b 8a 10 00 00 10 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
<idle>-0     [000] d.h3   665.039412: block_rq_complete: 8,48 WS () 39604352 + 128 tag=18 [0]
iozone-4057  [001] ....   665.039415: block_dirty_buffer: 8,62 sector=40096 size=4096
iozone-4056  [002] ....   665.039425: block_bio_remap: 8,48 WS 39586432 + 128 <- (8,62) 354944
iozone-4056  [002] ....   665.039427: block_bio_queue: 8,48 WS 39586432 + 128 [iozone]
iozone-4057  [001] ....   665.039427: block_dirty_buffer: 8,62 sector=40097 size=4096
iozone-4056  [002] ...1   665.039430: block_getrq: 8,48 WS 39586432 + 128 [iozone]
iozone-4056  [002] ...1   665.039432: block_plug: [iozone]
iozone-4056  [002] ....   665.039434: block_unplug: [iozone] 1 Sync
iozone-4056  [002] ...1   665.039435: block_rq_insert: 8,48 WS 0 () 39586432 + 128 tag=30 [iozone]
iozone-4057  [001] ....   665.039437: block_dirty_buffer: 8,62 sector=40098 size=4096
iozone-4056  [002] ...1   665.039437: block_rq_issue: 8,48 WS 0 () 39586432 + 128 tag=30 [iozone]
iozone-4056  [002] ...1   665.039439: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=3 data_sgl=16 prot_sgl=0 prot_op=SCSI_PROT_NORMAL tag=30 cmnd=(WRITE_10 lba=4948304 txlen=16 protect=0 raw=2a 00 00 4b 81 50 00 00 10 00)

Especially, the ftrace log with tag information, I can easily figure out one I/O request between block layer and SCSI.

//Bean Huo

Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events

[Bart Van Assche]

On Mon, 2018-04-16 at 21:10 +0000, Bean Huo (beanhuo) wrote:
> Hi, Bart
> 
> > mingo@redhad.com; linux-block@vger.kernel.org; rajatja@google.com
> > Subject: [EXT] Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI
> > trace events
> > 
> > On Mon, 2018-04-16 at 14:31 +0000, Bean Huo (beanhuo) wrote:
> > >  	TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u
> > 
> > prot_sgl=%u" \
> > > -		  " prot_op=%s cmnd=(%s %s raw=%s)",
> > > +		  " prot_op=%s tag=%d cmnd=(%s %s raw=%s)",
> > > 
> > > [ ... ]
> > >  	TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u
> > 
> > prot_sgl=%u" \
> > > -		  " prot_op=%s cmnd=(%s %s raw=%s) rtn=%d",
> > > +		  " prot_op=%s tag=%d cmnd=(%s %s raw=%s) rtn=%d",
> > > [ ... ]
> > >  	TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u " \
> > > -		  "prot_sgl=%u prot_op=%s cmnd=(%s %s raw=%s)
> > 
> > result=(driver=" \
> > > -		  "%s host=%s message=%s status=%s)",
> > > +		  "prot_sgl=%u prot_op=%s tag=%d cmnd=(%s %s raw=%s) " \
> > > +		  "result=(driver=%s host=%s message=%s status=%s)",
> > 
> > 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?
> > 
> 
> I don't use one certain special tool to analyze this string, I am using ftrace with event.
> With tag information, I can see how many tasks in storage device and easily to trace each request
> under multiple thread workload. 
> Event there is someone who using certain tool to analyze this string, after adding additional
> tag printout, in my opinion, they are happy to see it there. 

Since you want to change these strings it is your job to determine which
user space tools parse these strings and also whether or not this change
will break any of these tools.

Thanks,

Bart.

Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events

[Bean Huo (beanhuo)]

Hi, Bart

>mingo@redhad.com; linux-block@vger.kernel.org; rajatja@google.com
>Subject: [EXT] Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI
>trace events
>
>On Mon, 2018-04-16 at 14:31 +0000, Bean Huo (beanhuo) wrote:
>>  	TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u
>prot_sgl=%u" \
>> -		  " prot_op=%s cmnd=(%s %s raw=%s)",
>> +		  " prot_op=%s tag=%d cmnd=(%s %s raw=%s)",
>>
>> [ ... ]
>>  	TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u
>prot_sgl=%u" \
>> -		  " prot_op=%s cmnd=(%s %s raw=%s) rtn=%d",
>> +		  " prot_op=%s tag=%d cmnd=(%s %s raw=%s) rtn=%d",
>> [ ... ]
>>  	TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u " \
>> -		  "prot_sgl=%u prot_op=%s cmnd=(%s %s raw=%s)
>result=(driver=" \
>> -		  "%s host=%s message=%s status=%s)",
>> +		  "prot_sgl=%u prot_op=%s tag=%d cmnd=(%s %s raw=%s) " \
>> +		  "result=(driver=%s host=%s message=%s status=%s)",
>
>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?
> 

I don't use one certain special tool to analyze this string, I am using ftrace with event.
With tag information, I can see how many tasks in storage device and easily to trace each request
under multiple thread workload. 
Event there is someone who using certain tool to analyze this string, after adding additional
tag printout, in my opinion, they are happy to see it there. 

Again, you said if we add new feature in legacy block, we will also add new feature in blk-mq.
I still don't understand here.  "include/trace/event/block.h ... scsi.h" will be changed?
If yes, how? Because blk-mq is still using the events defined in include/trace/event/block.h.

Bean Huo

>Thanks,
>
>Bart.
>

Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events

[Bart Van Assche]

On Mon, 2018-04-16 at 20:27 +0000, Bean Huo (beanhuo) wrote:
> By the way, these patches are not to add new feature, they are just to
> add print tag along with the other exist printed request parameters.

Are you aware that there are two tag fields in struct request, namely "tag"
and "internal_tag"? Are you aware that how these fields are used depends on
whether or not a scheduler is attached to a request queue? Have you verified
that the "tag" field contains a meaningful value for blk-mq for every blk-mq
tracepoint?

Thanks,

Bart.

Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events

[Bean Huo (beanhuo)]

>>> This patch is not acceptable because it adds support for tag tracing
>>> to the legacy block layer only. Any patch that adds a new feature to
>>> the legacy block layer must also add it to blk-mq.
>>>
>> To be honest, I don't understand your point, can you give me more
>explanation?
>
>The legacy block layer will be removed as soon as blk-mq provides all the
>functionality of the legacy block layer and as soon as it performs at least as
>well as the legacy block layer for all use cases. If new features are added to
>the legacy block layer but not to blk-mq that prevents removal of the legacy
>block layer. Hence the requirement I explained in my previous e-mail.
>
>Bart.

Thanks for your information.
I have several questions again.
When the legacy block layer will be replaced by blk-mq? 
And "include/trece/event/block.h .. scsi.h" will also be changed? 
Do you have the related git rep or mail list about this topic?
Maybe this is great big change, I am very interested in that. And want to have a look at.

By the way, these patches are not to add new feature, they are just to add print tag along with the other exist
Printed request parameters.  The blk-mq is now still using "include/trace/evet/block.h" defined trace events.

For example: 
void blk_mq_start_request(struct request *rq)  
{
...
...
trace_block_rq_issue(q, rq);
...
...
}
Do you mean that this will also be removed/replaced by someone else?

Bean Huo

Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events

[Bart Van Assche]

On 04/16/18 10:05, Bean Huo (beanhuo) wrote:
>> On Mon, 2018-04-16 at 09:41 -0700, Rajat Jain wrote:
>>> On Mon, Apr 16, 2018 at 8:28 AM, Steven Rostedt <rostedt@goodmis.org>
>> wrote:
>>>> On Mon, 16 Apr 2018 14:31:49 +0000
>>>> "Bean Huo (beanhuo)" <beanhuo@micron.com> wrote:
>>>>
>>>>> Print the request tag along with other information while tracing a
>>>>> command.
>>>>>
>>>>> Signed-off-by: Bean Huo <beanhuo@micron.com>
>>>
>>> Acked-by: Rajat Jain <rajatja@google.com>
>>
>> This patch is not acceptable because it adds support for tag tracing to the
>> legacy block layer only. Any patch that adds a new feature to the legacy block
>> layer must also add it to blk-mq.
>>
> To be honest, I don't understand your point, can you give me more explanation?

The legacy block layer will be removed as soon as blk-mq provides all 
the functionality of the legacy block layer and as soon as it performs 
at least as well as the legacy block layer for all use cases. If new 
features are added to the legacy block layer but not to blk-mq that 
prevents removal of the legacy block layer. Hence the requirement I 
explained in my previous e-mail.

Bart.

Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events

[Bean Huo (beanhuo)]

Hi, Bart

>On Mon, 2018-04-16 at 09:41 -0700, Rajat Jain wrote:
>> On Mon, Apr 16, 2018 at 8:28 AM, Steven Rostedt <rostedt@goodmis.org>
>wrote:
>> > On Mon, 16 Apr 2018 14:31:49 +0000
>> > "Bean Huo (beanhuo)" <beanhuo@micron.com> wrote:
>> >
>> > > Print the request tag along with other information while tracing a
>> > > command.
>> > >
>> > > Signed-off-by: Bean Huo <beanhuo@micron.com>
>>
>> Acked-by: Rajat Jain <rajatja@google.com>
>
>This patch is not acceptable because it adds support for tag tracing to the
>legacy block layer only. Any patch that adds a new feature to the legacy block
>layer must also add it to blk-mq.
>
To be honest, I don't understand your point, can you give me more explanation?

>Bart.
>
>