Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events
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 -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) -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
>On Mon, 2018-04-16 at 20:27 +, 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
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.21360 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.19818 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 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,
Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events
On Mon, 16 Apr 2018 21:30:54 + Bart Van Assche 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
On Mon, 2018-04-16 at 17:24 -0400, Steven Rostedt wrote: > On Mon, 16 Apr 2018 20:49:12 + > Bart Van Assche 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
On Mon, 16 Apr 2018 20:49:12 + Bart Van Assche 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
On Mon, 2018-04-16 at 21:10 +, Bean Huo (beanhuo) wrote: > Hi, Bart > > > mi...@redhad.com; linux-bl...@vger.kernel.org; raja...@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 +, 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
Hi, Bart >mi...@redhad.com; linux-bl...@vger.kernel.org; raja...@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 +, 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
On Mon, 2018-04-16 at 14:31 +, 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
On Mon, 2018-04-16 at 20:27 +, 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
>>> 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
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 wrote: On Mon, 16 Apr 2018 14:31:49 + "Bean Huo (beanhuo)" wrote: Print the request tag along with other information while tracing a command. Signed-off-by: Bean Huo Acked-by: Rajat Jain 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
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 >wrote: >> > On Mon, 16 Apr 2018 14:31:49 + >> > "Bean Huo (beanhuo)" wrote: >> > >> > > Print the request tag along with other information while tracing a >> > > command. >> > > >> > > Signed-off-by: Bean Huo >> >> Acked-by: Rajat Jain > >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. > >
Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events
On Mon, 2018-04-16 at 09:41 -0700, Rajat Jain wrote: > On Mon, Apr 16, 2018 at 8:28 AM, Steven Rostedt wrote: > > On Mon, 16 Apr 2018 14:31:49 + > > "Bean Huo (beanhuo)" wrote: > > > > > Print the request tag along with other information > > > while tracing a command. > > > > > > Signed-off-by: Bean Huo > > Acked-by: Rajat Jain 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
On Mon, Apr 16, 2018 at 8:28 AM, Steven Rostedt wrote: > On Mon, 16 Apr 2018 14:31:49 + > "Bean Huo (beanhuo)" wrote: > >> Print the request tag along with other information >> while tracing a command. >> >> Signed-off-by: Bean Huo Acked-by: Rajat Jain >> --- > > I don't see any issue with the tracing part. > > Acked-by: Steven Rostedt (VMware) > > Others need to check the content. > > -- Steve
Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events
On Mon, 16 Apr 2018 14:31:49 + "Bean Huo (beanhuo)" wrote: > Print the request tag along with other information > while tracing a command. > > 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