Print the request tag along with other information
while tracing a command.
Signed-off-by: Bean Huo <[email protected]>
---
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
On Mon, 16 Apr 2018 14:31:49 +0000
"Bean Huo (beanhuo)" <[email protected]> wrote:
> Print the request tag along with other information
> while tracing a command.
>
> Signed-off-by: Bean Huo <[email protected]>
> ---
I don't see any issue with the tracing part.
Acked-by: Steven Rostedt (VMware) <[email protected]>
Others need to check the content.
-- Steve
On Mon, Apr 16, 2018 at 8:28 AM, Steven Rostedt <[email protected]> wrote:
> On Mon, 16 Apr 2018 14:31:49 +0000
> "Bean Huo (beanhuo)" <[email protected]> wrote:
>
>> Print the request tag along with other information
>> while tracing a command.
>>
>> Signed-off-by: Bean Huo <[email protected]>
Acked-by: Rajat Jain <[email protected]>
>> ---
>
> I don't see any issue with the tracing part.
>
> Acked-by: Steven Rostedt (VMware) <[email protected]>
>
> Others need to check the content.
>
> -- Steve
On Mon, 2018-04-16 at 09:41 -0700, Rajat Jain wrote:
> On Mon, Apr 16, 2018 at 8:28 AM, Steven Rostedt <[email protected]> wrote:
> > On Mon, 16 Apr 2018 14:31:49 +0000
> > "Bean Huo (beanhuo)" <[email protected]> wrote:
> >
> > > Print the request tag along with other information
> > > while tracing a command.
> > >
> > > Signed-off-by: Bean Huo <[email protected]>
>
> Acked-by: Rajat Jain <[email protected]>
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.
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 <[email protected]>
>wrote:
>> > On Mon, 16 Apr 2018 14:31:49 +0000
>> > "Bean Huo (beanhuo)" <[email protected]> wrote:
>> >
>> > > Print the request tag along with other information while tracing a
>> > > command.
>> > >
>> > > Signed-off-by: Bean Huo <[email protected]>
>>
>> Acked-by: Rajat Jain <[email protected]>
>
>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.
>
>
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 <[email protected]>
>> wrote:
>>>> On Mon, 16 Apr 2018 14:31:49 +0000
>>>> "Bean Huo (beanhuo)" <[email protected]> wrote:
>>>>
>>>>> Print the request tag along with other information while tracing a
>>>>> command.
>>>>>
>>>>> Signed-off-by: Bean Huo <[email protected]>
>>>
>>> Acked-by: Rajat Jain <[email protected]>
>>
>> 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.
>>> 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
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.
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.
Hi, Bart
>[email protected]; [email protected]; [email protected]
>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.
>
On Mon, 2018-04-16 at 21:10 +0000, Bean Huo (beanhuo) wrote:
> Hi, Bart
>
> > [email protected]; [email protected]; [email protected]
> > 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.
On Mon, 16 Apr 2018 20:49:12 +0000
Bart Van Assche <[email protected]> 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
On Mon, 2018-04-16 at 17:24 -0400, Steven Rostedt wrote:
> On Mon, 16 Apr 2018 20:49:12 +0000
> Bart Van Assche <[email protected]> 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.
On Mon, 16 Apr 2018 21:30:54 +0000
Bart Van Assche <[email protected]> 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
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
>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
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