* [PATCH] trace: events: scsi: Print driver_tag and scheduler_tag in SCSI trace
@ 2022-06-20 20:26 Changyuan Lyu
2022-06-21 3:56 ` Bart Van Assche
0 siblings, 1 reply; 6+ messages in thread
From: Changyuan Lyu @ 2022-06-20 20:26 UTC (permalink / raw)
To: Steven Rostedt, Ingo Molnar, Bart van Assche, Rajat Jain
Cc: linux-scsi, linux-block, Changyuan Lyu, Vishakha Channapattan,
Jolly Shah
Traces like scsi_dispatch_cmd_start and scsi_dispatch_cmd_done are
useful for tracking a command thoughout its lifetime. But for some ATA
passthrough commands, the information printed in current logs are not
enough to identify and match them. For example, if two threads send
SMART cmd to the same disk at the same time, their trace logs may
look the same, which makes it hard to match scsi_dispatch_cmd_done and
scsi_dispatch_cmd_start. Printing tags can help us solve the problem.
Further, if a command failed for some reason and then retried, its
driver_tag will change. So scheduler_tag is also included such that we
can track the retries of a command.
Reviewed-by: Vishakha Channapattan <vishakhavc@google.com>
Reviewed-by: Jolly Shah <jollys@google.com>
Signed-off-by: Changyuan Lyu <changyuanl@google.com>
---
include/trace/events/scsi.h | 35 ++++++++++++++++++++++++-----------
1 file changed, 24 insertions(+), 11 deletions(-)
diff --git a/include/trace/events/scsi.h b/include/trace/events/scsi.h
index 370ade0d4093..a2c7befd451a 100644
--- a/include/trace/events/scsi.h
+++ b/include/trace/events/scsi.h
@@ -166,6 +166,8 @@ TRACE_EVENT(scsi_dispatch_cmd_start,
__field( unsigned int, lun )
__field( unsigned int, opcode )
__field( unsigned int, cmd_len )
+ __field( int, driver_tag)
+ __field( int, scheduler_tag)
__field( unsigned int, data_sglen )
__field( unsigned int, prot_sglen )
__field( unsigned char, prot_op )
@@ -179,6 +181,8 @@ TRACE_EVENT(scsi_dispatch_cmd_start,
__entry->lun = cmd->device->lun;
__entry->opcode = cmd->cmnd[0];
__entry->cmd_len = cmd->cmd_len;
+ __entry->driver_tag = scsi_cmd_to_rq(cmd)->tag;
+ __entry->scheduler_tag = scsi_cmd_to_rq(cmd)->internal_tag;
__entry->data_sglen = scsi_sg_count(cmd);
__entry->prot_sglen = scsi_prot_sg_count(cmd);
__entry->prot_op = scsi_get_prot_op(cmd);
@@ -186,11 +190,11 @@ 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 driver_tag=%d scheduler_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_opcode_name(__entry->opcode),
+ show_prot_op_name(__entry->prot_op), __entry->driver_tag,
+ __entry->scheduler_tag, show_opcode_name(__entry->opcode),
__parse_cdb(__get_dynamic_array(cmnd), __entry->cmd_len),
__print_hex(__get_dynamic_array(cmnd), __entry->cmd_len))
);
@@ -209,6 +213,8 @@ TRACE_EVENT(scsi_dispatch_cmd_error,
__field( int, rtn )
__field( unsigned int, opcode )
__field( unsigned int, cmd_len )
+ __field( int, driver_tag)
+ __field( int, scheduler_tag)
__field( unsigned int, data_sglen )
__field( unsigned int, prot_sglen )
__field( unsigned char, prot_op )
@@ -223,6 +229,8 @@ TRACE_EVENT(scsi_dispatch_cmd_error,
__entry->rtn = rtn;
__entry->opcode = cmd->cmnd[0];
__entry->cmd_len = cmd->cmd_len;
+ __entry->driver_tag = scsi_cmd_to_rq(cmd)->tag;
+ __entry->scheduler_tag = scsi_cmd_to_rq(cmd)->internal_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,11 +238,12 @@ 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 driver_tag=%d scheduler_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_opcode_name(__entry->opcode),
+ show_prot_op_name(__entry->prot_op), __entry->driver_tag,
+ __entry->scheduler_tag, show_opcode_name(__entry->opcode),
__parse_cdb(__get_dynamic_array(cmnd), __entry->cmd_len),
__print_hex(__get_dynamic_array(cmnd), __entry->cmd_len),
__entry->rtn)
@@ -254,6 +263,8 @@ DECLARE_EVENT_CLASS(scsi_cmd_done_timeout_template,
__field( int, result )
__field( unsigned int, opcode )
__field( unsigned int, cmd_len )
+ __field( int, driver_tag)
+ __field( int, scheduler_tag)
__field( unsigned int, data_sglen )
__field( unsigned int, prot_sglen )
__field( unsigned char, prot_op )
@@ -268,19 +279,21 @@ DECLARE_EVENT_CLASS(scsi_cmd_done_timeout_template,
__entry->result = cmd->result;
__entry->opcode = cmd->cmnd[0];
__entry->cmd_len = cmd->cmd_len;
+ __entry->driver_tag = scsi_cmd_to_rq(cmd)->tag;
+ __entry->scheduler_tag = scsi_cmd_to_rq(cmd)->internal_tag;
__entry->data_sglen = scsi_sg_count(cmd);
__entry->prot_sglen = scsi_prot_sg_count(cmd);
__entry->prot_op = scsi_get_prot_op(cmd);
memcpy(__get_dynamic_array(cmnd), cmd->cmnd, cmd->cmd_len);
),
- 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)",
+ TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u prot_sgl=%u " \
+ "prot_op=%s driver_tag=%d scheduler_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_opcode_name(__entry->opcode),
+ show_prot_op_name(__entry->prot_op), __entry->driver_tag,
+ __entry->scheduler_tag, show_opcode_name(__entry->opcode),
__parse_cdb(__get_dynamic_array(cmnd), __entry->cmd_len),
__print_hex(__get_dynamic_array(cmnd), __entry->cmd_len),
"DRIVER_OK",
--
2.37.0.rc0.104.g0611611a94-goog
^ permalink raw reply related [flat|nested] 6+ messages in thread* Re: [PATCH] trace: events: scsi: Print driver_tag and scheduler_tag in SCSI trace
2022-06-20 20:26 [PATCH] trace: events: scsi: Print driver_tag and scheduler_tag in SCSI trace Changyuan Lyu
@ 2022-06-21 3:56 ` Bart Van Assche
2022-06-21 18:11 ` [PATCH v2] " Changyuan Lyu
2022-06-21 18:30 ` [PATCH] " Changyuan Lyu
0 siblings, 2 replies; 6+ messages in thread
From: Bart Van Assche @ 2022-06-21 3:56 UTC (permalink / raw)
To: Changyuan Lyu, Steven Rostedt, Ingo Molnar, Rajat Jain
Cc: linux-scsi, linux-block, Vishakha Channapattan, Jolly Shah
On 6/20/22 13:26, Changyuan Lyu wrote:
> Traces like scsi_dispatch_cmd_start and scsi_dispatch_cmd_done are
^^^^^^
Aren't these called "trace events" instead of "traces"?
> useful for tracking a command thoughout its lifetime. But for some ATA
^^^^^^^^^
throughout?
> passthrough commands, the information printed in current logs are not
^^^
is?
> enough to identify and match them. For example, if two threads send
> SMART cmd to the same disk at the same time, their trace logs may
> look the same, which makes it hard to match scsi_dispatch_cmd_done and
> scsi_dispatch_cmd_start. Printing tags can help us solve the problem.
> Further, if a command failed for some reason and then retried, its
^^^^^^^
is retried?
> driver_tag will change. So scheduler_tag is also included such that we
> can track the retries of a command.
Despite the above comments, thanks for the detailed and very informative
patch description.
Reviewed-by: Bart Van Assche <bvanassche@acm.org>
^ permalink raw reply [flat|nested] 6+ messages in thread* [PATCH v2] trace: events: scsi: Print driver_tag and scheduler_tag in SCSI trace
2022-06-21 3:56 ` Bart Van Assche
@ 2022-06-21 18:11 ` Changyuan Lyu
2022-06-22 1:43 ` Martin K. Petersen
2022-06-28 3:24 ` Martin K. Petersen
2022-06-21 18:30 ` [PATCH] " Changyuan Lyu
1 sibling, 2 replies; 6+ messages in thread
From: Changyuan Lyu @ 2022-06-21 18:11 UTC (permalink / raw)
To: Steven Rostedt, Ingo Molnar, Bart van Assche, Rajat Jain
Cc: linux-scsi, linux-block, Changyuan Lyu, Vishakha Channapattan,
Jolly Shah
Trace events like scsi_dispatch_cmd_start and scsi_dispatch_cmd_done
are useful for tracking a command throughout its lifetime. But for
some ATA passthrough commands, the information printed in current logs
is not enough to identify and match them. For example, if two threads
send SMART cmd to the same disk at the same time, their trace logs may
look the same, which makes it hard to match scsi_dispatch_cmd_done and
scsi_dispatch_cmd_start. Printing tags can help us solve the problem.
Further, if a command failed for some reason and then is retried, its
driver_tag will change. So scheduler_tag is also included such that we
can track the retries of a command.
Reviewed-by: Vishakha Channapattan <vishakhavc@google.com>
Reviewed-by: Jolly Shah <jollys@google.com>
Reviewed-by: Bart Van Assche <bvanassche@acm.org>
Signed-off-by: Changyuan Lyu <changyuanl@google.com>
---
v2: fixed typos and misuse of terminology in the commit message.
---
include/trace/events/scsi.h | 35 ++++++++++++++++++++++++-----------
1 file changed, 24 insertions(+), 11 deletions(-)
diff --git a/include/trace/events/scsi.h b/include/trace/events/scsi.h
index 370ade0d4093..a2c7befd451a 100644
--- a/include/trace/events/scsi.h
+++ b/include/trace/events/scsi.h
@@ -166,6 +166,8 @@ TRACE_EVENT(scsi_dispatch_cmd_start,
__field( unsigned int, lun )
__field( unsigned int, opcode )
__field( unsigned int, cmd_len )
+ __field( int, driver_tag)
+ __field( int, scheduler_tag)
__field( unsigned int, data_sglen )
__field( unsigned int, prot_sglen )
__field( unsigned char, prot_op )
@@ -179,6 +181,8 @@ TRACE_EVENT(scsi_dispatch_cmd_start,
__entry->lun = cmd->device->lun;
__entry->opcode = cmd->cmnd[0];
__entry->cmd_len = cmd->cmd_len;
+ __entry->driver_tag = scsi_cmd_to_rq(cmd)->tag;
+ __entry->scheduler_tag = scsi_cmd_to_rq(cmd)->internal_tag;
__entry->data_sglen = scsi_sg_count(cmd);
__entry->prot_sglen = scsi_prot_sg_count(cmd);
__entry->prot_op = scsi_get_prot_op(cmd);
@@ -186,11 +190,11 @@ 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 driver_tag=%d scheduler_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_opcode_name(__entry->opcode),
+ show_prot_op_name(__entry->prot_op), __entry->driver_tag,
+ __entry->scheduler_tag, show_opcode_name(__entry->opcode),
__parse_cdb(__get_dynamic_array(cmnd), __entry->cmd_len),
__print_hex(__get_dynamic_array(cmnd), __entry->cmd_len))
);
@@ -209,6 +213,8 @@ TRACE_EVENT(scsi_dispatch_cmd_error,
__field( int, rtn )
__field( unsigned int, opcode )
__field( unsigned int, cmd_len )
+ __field( int, driver_tag)
+ __field( int, scheduler_tag)
__field( unsigned int, data_sglen )
__field( unsigned int, prot_sglen )
__field( unsigned char, prot_op )
@@ -223,6 +229,8 @@ TRACE_EVENT(scsi_dispatch_cmd_error,
__entry->rtn = rtn;
__entry->opcode = cmd->cmnd[0];
__entry->cmd_len = cmd->cmd_len;
+ __entry->driver_tag = scsi_cmd_to_rq(cmd)->tag;
+ __entry->scheduler_tag = scsi_cmd_to_rq(cmd)->internal_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,11 +238,12 @@ 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 driver_tag=%d scheduler_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_opcode_name(__entry->opcode),
+ show_prot_op_name(__entry->prot_op), __entry->driver_tag,
+ __entry->scheduler_tag, show_opcode_name(__entry->opcode),
__parse_cdb(__get_dynamic_array(cmnd), __entry->cmd_len),
__print_hex(__get_dynamic_array(cmnd), __entry->cmd_len),
__entry->rtn)
@@ -254,6 +263,8 @@ DECLARE_EVENT_CLASS(scsi_cmd_done_timeout_template,
__field( int, result )
__field( unsigned int, opcode )
__field( unsigned int, cmd_len )
+ __field( int, driver_tag)
+ __field( int, scheduler_tag)
__field( unsigned int, data_sglen )
__field( unsigned int, prot_sglen )
__field( unsigned char, prot_op )
@@ -268,19 +279,21 @@ DECLARE_EVENT_CLASS(scsi_cmd_done_timeout_template,
__entry->result = cmd->result;
__entry->opcode = cmd->cmnd[0];
__entry->cmd_len = cmd->cmd_len;
+ __entry->driver_tag = scsi_cmd_to_rq(cmd)->tag;
+ __entry->scheduler_tag = scsi_cmd_to_rq(cmd)->internal_tag;
__entry->data_sglen = scsi_sg_count(cmd);
__entry->prot_sglen = scsi_prot_sg_count(cmd);
__entry->prot_op = scsi_get_prot_op(cmd);
memcpy(__get_dynamic_array(cmnd), cmd->cmnd, cmd->cmd_len);
),
- 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)",
+ TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u prot_sgl=%u " \
+ "prot_op=%s driver_tag=%d scheduler_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_opcode_name(__entry->opcode),
+ show_prot_op_name(__entry->prot_op), __entry->driver_tag,
+ __entry->scheduler_tag, show_opcode_name(__entry->opcode),
__parse_cdb(__get_dynamic_array(cmnd), __entry->cmd_len),
__print_hex(__get_dynamic_array(cmnd), __entry->cmd_len),
"DRIVER_OK",
--
2.37.0.rc0.104.g0611611a94-goog
^ permalink raw reply related [flat|nested] 6+ messages in thread* Re: [PATCH v2] trace: events: scsi: Print driver_tag and scheduler_tag in SCSI trace
2022-06-21 18:11 ` [PATCH v2] " Changyuan Lyu
@ 2022-06-22 1:43 ` Martin K. Petersen
2022-06-28 3:24 ` Martin K. Petersen
1 sibling, 0 replies; 6+ messages in thread
From: Martin K. Petersen @ 2022-06-22 1:43 UTC (permalink / raw)
To: Changyuan Lyu
Cc: Steven Rostedt, Ingo Molnar, Bart van Assche, Rajat Jain,
linux-scsi, linux-block, Vishakha Channapattan, Jolly Shah
Changyuan,
> Trace events like scsi_dispatch_cmd_start and scsi_dispatch_cmd_done
> are useful for tracking a command throughout its lifetime. But for
> some ATA passthrough commands, the information printed in current logs
> is not enough to identify and match them. For example, if two threads
> send SMART cmd to the same disk at the same time, their trace logs may
> look the same, which makes it hard to match scsi_dispatch_cmd_done and
> scsi_dispatch_cmd_start. Printing tags can help us solve the problem.
> Further, if a command failed for some reason and then is retried, its
> driver_tag will change. So scheduler_tag is also included such that we
> can track the retries of a command.
Applied to 5.20/scsi-staging, thanks!
--
Martin K. Petersen Oracle Linux Engineering
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH v2] trace: events: scsi: Print driver_tag and scheduler_tag in SCSI trace
2022-06-21 18:11 ` [PATCH v2] " Changyuan Lyu
2022-06-22 1:43 ` Martin K. Petersen
@ 2022-06-28 3:24 ` Martin K. Petersen
1 sibling, 0 replies; 6+ messages in thread
From: Martin K. Petersen @ 2022-06-28 3:24 UTC (permalink / raw)
To: Steven Rostedt, Ingo Molnar, Changyuan Lyu, Bart van Assche, Rajat Jain
Cc: Martin K . Petersen, linux-block, Jolly Shah,
Vishakha Channapattan, linux-scsi
On Tue, 21 Jun 2022 18:11:25 +0000, Changyuan Lyu wrote:
> Trace events like scsi_dispatch_cmd_start and scsi_dispatch_cmd_done
> are useful for tracking a command throughout its lifetime. But for
> some ATA passthrough commands, the information printed in current logs
> is not enough to identify and match them. For example, if two threads
> send SMART cmd to the same disk at the same time, their trace logs may
> look the same, which makes it hard to match scsi_dispatch_cmd_done and
> scsi_dispatch_cmd_start. Printing tags can help us solve the problem.
> Further, if a command failed for some reason and then is retried, its
> driver_tag will change. So scheduler_tag is also included such that we
> can track the retries of a command.
>
> [...]
Applied to 5.20/scsi-queue, thanks!
[1/1] trace: events: scsi: Print driver_tag and scheduler_tag in SCSI trace
https://git.kernel.org/mkp/scsi/c/cc06af0bbc21
--
Martin K. Petersen Oracle Linux Engineering
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH] trace: events: scsi: Print driver_tag and scheduler_tag in SCSI trace
2022-06-21 3:56 ` Bart Van Assche
2022-06-21 18:11 ` [PATCH v2] " Changyuan Lyu
@ 2022-06-21 18:30 ` Changyuan Lyu
1 sibling, 0 replies; 6+ messages in thread
From: Changyuan Lyu @ 2022-06-21 18:30 UTC (permalink / raw)
To: Bart Van Assche
Cc: Steven Rostedt, Ingo Molnar, Rajat Jain, linux-scsi, linux-block,
Vishakha Channapattan, Jolly Shah
On 06/20/2022 20:56, Bart Van Assche <bvanassche@acm.org> wrote:
> Despite the above comments, thanks for the detailed and very
> informative patch description.
Thanks for helping me improve the commit message. I fixed these
issues in v2.
Best,
Changyuan Lyu
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2022-06-28 3:25 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-06-20 20:26 [PATCH] trace: events: scsi: Print driver_tag and scheduler_tag in SCSI trace Changyuan Lyu
2022-06-21 3:56 ` Bart Van Assche
2022-06-21 18:11 ` [PATCH v2] " Changyuan Lyu
2022-06-22 1:43 ` Martin K. Petersen
2022-06-28 3:24 ` Martin K. Petersen
2022-06-21 18:30 ` [PATCH] " Changyuan Lyu
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).