Re: [RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events
>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
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
Hi, Bart
>mi...@redhad.com; linux-block@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 +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
>>> 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
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. > >
[RESEND PATCH v1 1/2] trace: events: scsi: Add tag in SCSI trace events
Print the request tag along with other information
while tracing a command.
Signed-off-by: Bean Huo
---
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)",
[RESEND PATCH v1 0/2] Print the request tag in Block/SCSI trace events
These patches are to add the printout of the request tag in Block/SCSI trace events when tracing one request or command, this is very useful for tracing the task running status in the storage device which supports multiple command queue. As for the first patch " Add tag in SCSI trace events", copied from Rajat Jain [1]. I am just re-sending here. [1]https://patchwork.kernel.org/patch/6399661/ -- Resend since patches need to go through the block and SCSI subsystem, and need related maintainer's confirmation. Bean Huo (2): trace: events: scsi: Add tag in SCSI trace events trace: events: block: Add tag in block trace events include/trace/events/block.h | 36 +--- include/trace/events/scsi.h | 20 +--- 2 files changed, 38 insertions(+), 18 deletions(-) -- 2.7.4
[RESEND PATCH v1 2/2] trace: events: block: Add tag in block trace events
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);
