From cc06af0bbc21bcee40d57e3ee569d3a09741dafd Mon Sep 17 00:00:00 2001 From: Changyuan Lyu Date: Tue, 21 Jun 2022 18:11:25 +0000 Subject: [PATCH] scsi: trace: Print driver_tag and scheduler_tag in SCSI trace 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. Link: https://lore.kernel.org/r/20220621181125.3211399-1-changyuanl@google.com Reviewed-by: Vishakha Channapattan Reviewed-by: Jolly Shah Reviewed-by: Bart Van Assche Signed-off-by: Changyuan Lyu Signed-off-by: Martin K. Petersen --- 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",