include/trace/events/scsi.h | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-)
In default it showed rtn in decimal.
kworker/3:1H-183 [003] .... 51.035474: scsi_dispatch_cmd_error: host_no=0 channel=0 id=0 lun=4 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=3907214 txlen=1 protect=0 raw=28 00 00 3b 9e 8e 00 00 01 00) rtn=4181
In source code we define these possible value as hexadecimal:
include/scsi/scsi.h
SCSI_MLQUEUE_HOST_BUSY 0x1055
SCSI_MLQUEUE_DEVICE_BUSY 0x1056
SCSI_MLQUEUE_EH_RETRY 0x1057
SCSI_MLQUEUE_TARGET_BUSY 0x1058
This change shows the string type.
Signed-off-by: Kassey Li <quic_yingangl@quicinc.com>
---
include/trace/events/scsi.h | 8 ++++++--
1 file changed, 6 insertions(+), 2 deletions(-)
diff --git a/include/trace/events/scsi.h b/include/trace/events/scsi.h
index bf6cc98d9122..56987f98ba4a 100644
--- a/include/trace/events/scsi.h
+++ b/include/trace/events/scsi.h
@@ -240,14 +240,18 @@ 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 driver_tag=%d scheduler_tag=%d cmnd=(%s %s raw=%s)" \
- " rtn=%d",
+ " rtn=%s",
__entry->host_no, __entry->channel, __entry->id,
__entry->lun, __entry->data_sglen, __entry->prot_sglen,
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)
+ __print_symbolic(rtn, { SCSI_MLQUEUE_HOST_BUSY, "HOST_BUSY" },
+ { SCSI_MLQUEUE_DEVICE_BUSY, "DEVICE_BUSY" },
+ { SCSI_MLQUEUE_EH_RETRY, "EH_RETRY" },
+ { SCSI_MLQUEUE_TARGET_BUSY, "TARGET_BUSY" })
+ )
);
DECLARE_EVENT_CLASS(scsi_cmd_done_timeout_template,
--
2.34.1Hi Kassey,
kernel test robot noticed the following build errors:
[auto build test ERROR on trace/for-next]
[also build test ERROR on jejb-scsi/for-next mkp-scsi/for-next linus/master v6.15-rc6 next-20250514]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]
url: https://github.com/intel-lab-lkp/linux/commits/Kassey-Li/scsi-trace-change-the-rtn-log-in-string/20250514-155034
base: https://git.kernel.org/pub/scm/linux/kernel/git/trace/linux-trace for-next
patch link: https://lore.kernel.org/r/20250514074456.450006-1-quic_yingangl%40quicinc.com
patch subject: [PATCH v2] scsi: trace: change the rtn log in string
config: i386-buildonly-randconfig-001-20250515 (https://download.01.org/0day-ci/archive/20250515/202505150658.uk9oRnKr-lkp@intel.com/config)
compiler: gcc-11 (Debian 11.3.0-12) 11.3.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20250515/202505150658.uk9oRnKr-lkp@intel.com/reproduce)
If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202505150658.uk9oRnKr-lkp@intel.com/
All errors (new ones prefixed by >>):
In file included from include/trace/define_trace.h:119,
from include/trace/events/scsi.h:355,
from drivers/scsi/scsi.c:73:
include/trace/events/scsi.h: In function 'trace_raw_output_scsi_dispatch_cmd_error':
>> include/trace/events/scsi.h:250:36: error: 'rtn' undeclared (first use in this function)
250 | __print_symbolic(rtn, { SCSI_MLQUEUE_HOST_BUSY, "HOST_BUSY" },
| ^~~
include/trace/trace_events.h:219:34: note: in definition of macro 'DECLARE_EVENT_CLASS'
219 | trace_event_printf(iter, print); \
| ^~~~~
include/trace/trace_events.h:45:30: note: in expansion of macro 'PARAMS'
45 | PARAMS(print)); \
| ^~~~~~
include/trace/events/scsi.h:203:1: note: in expansion of macro 'TRACE_EVENT'
203 | TRACE_EVENT(scsi_dispatch_cmd_error,
| ^~~~~~~~~~~
include/trace/events/scsi.h:241:9: note: in expansion of macro 'TP_printk'
241 | TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u prot_sgl=%u" \
| ^~~~~~~~~
include/trace/events/scsi.h:250:19: note: in expansion of macro '__print_symbolic'
250 | __print_symbolic(rtn, { SCSI_MLQUEUE_HOST_BUSY, "HOST_BUSY" },
| ^~~~~~~~~~~~~~~~
include/trace/events/scsi.h:250:36: note: each undeclared identifier is reported only once for each function it appears in
250 | __print_symbolic(rtn, { SCSI_MLQUEUE_HOST_BUSY, "HOST_BUSY" },
| ^~~
include/trace/trace_events.h:219:34: note: in definition of macro 'DECLARE_EVENT_CLASS'
219 | trace_event_printf(iter, print); \
| ^~~~~
include/trace/trace_events.h:45:30: note: in expansion of macro 'PARAMS'
45 | PARAMS(print)); \
| ^~~~~~
include/trace/events/scsi.h:203:1: note: in expansion of macro 'TRACE_EVENT'
203 | TRACE_EVENT(scsi_dispatch_cmd_error,
| ^~~~~~~~~~~
include/trace/events/scsi.h:241:9: note: in expansion of macro 'TP_printk'
241 | TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u prot_sgl=%u" \
| ^~~~~~~~~
include/trace/events/scsi.h:250:19: note: in expansion of macro '__print_symbolic'
250 | __print_symbolic(rtn, { SCSI_MLQUEUE_HOST_BUSY, "HOST_BUSY" },
| ^~~~~~~~~~~~~~~~
vim +/rtn +250 include/trace/events/scsi.h
204
205 TP_PROTO(struct scsi_cmnd *cmd, int rtn),
206
207 TP_ARGS(cmd, rtn),
208
209 TP_STRUCT__entry(
210 __field( unsigned int, host_no )
211 __field( unsigned int, channel )
212 __field( unsigned int, id )
213 __field( unsigned int, lun )
214 __field( int, rtn )
215 __field( unsigned int, opcode )
216 __field( unsigned int, cmd_len )
217 __field( int, driver_tag)
218 __field( int, scheduler_tag)
219 __field( unsigned int, data_sglen )
220 __field( unsigned int, prot_sglen )
221 __field( unsigned char, prot_op )
222 __dynamic_array(unsigned char, cmnd, cmd->cmd_len)
223 ),
224
225 TP_fast_assign(
226 __entry->host_no = cmd->device->host->host_no;
227 __entry->channel = cmd->device->channel;
228 __entry->id = cmd->device->id;
229 __entry->lun = cmd->device->lun;
230 __entry->rtn = rtn;
231 __entry->opcode = cmd->cmnd[0];
232 __entry->cmd_len = cmd->cmd_len;
233 __entry->driver_tag = scsi_cmd_to_rq(cmd)->tag;
234 __entry->scheduler_tag = scsi_cmd_to_rq(cmd)->internal_tag;
235 __entry->data_sglen = scsi_sg_count(cmd);
236 __entry->prot_sglen = scsi_prot_sg_count(cmd);
237 __entry->prot_op = scsi_get_prot_op(cmd);
238 memcpy(__get_dynamic_array(cmnd), cmd->cmnd, cmd->cmd_len);
239 ),
240
241 TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u prot_sgl=%u" \
242 " prot_op=%s driver_tag=%d scheduler_tag=%d cmnd=(%s %s raw=%s)" \
243 " rtn=%s",
244 __entry->host_no, __entry->channel, __entry->id,
245 __entry->lun, __entry->data_sglen, __entry->prot_sglen,
246 show_prot_op_name(__entry->prot_op), __entry->driver_tag,
247 __entry->scheduler_tag, show_opcode_name(__entry->opcode),
248 __parse_cdb(__get_dynamic_array(cmnd), __entry->cmd_len),
249 __print_hex(__get_dynamic_array(cmnd), __entry->cmd_len),
> 250 __print_symbolic(rtn, { SCSI_MLQUEUE_HOST_BUSY, "HOST_BUSY" },
251 { SCSI_MLQUEUE_DEVICE_BUSY, "DEVICE_BUSY" },
252 { SCSI_MLQUEUE_EH_RETRY, "EH_RETRY" },
253 { SCSI_MLQUEUE_TARGET_BUSY, "TARGET_BUSY" })
254 )
255 );
256
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
On Wed, 2025-05-14 at 15:44 +0800, Kassey Li wrote:
> In default it showed rtn in decimal.
>
> kworker/3:1H-183 [003] .... 51.035474: scsi_dispatch_cmd_error:
> host_no=0 channel=0 id=0 lun=4 data_sgl=1 prot_sgl=0
> prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=3907214 txlen=1 protect=0
> raw=28 00 00 3b 9e 8e 00 00 01 00) rtn=4181
>
> In source code we define these possible value as hexadecimal:
>
> include/scsi/scsi.h
>
> SCSI_MLQUEUE_HOST_BUSY 0x1055
> SCSI_MLQUEUE_DEVICE_BUSY 0x1056
> SCSI_MLQUEUE_EH_RETRY 0x1057
> SCSI_MLQUEUE_TARGET_BUSY 0x1058
>
> This change shows the string type.
>
> Signed-off-by: Kassey Li <quic_yingangl@quicinc.com>
> ---
> include/trace/events/scsi.h | 8 ++++++--
> 1 file changed, 6 insertions(+), 2 deletions(-)
>
> diff --git a/include/trace/events/scsi.h
> b/include/trace/events/scsi.h
> index bf6cc98d9122..56987f98ba4a 100644
> --- a/include/trace/events/scsi.h
> +++ b/include/trace/events/scsi.h
> @@ -240,14 +240,18 @@ 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 driver_tag=%d scheduler_tag=%d
> cmnd=(%s %s raw=%s)" \
> - " rtn=%d",
> + " rtn=%s",
> __entry->host_no, __entry->channel, __entry->id,
> __entry->lun, __entry->data_sglen, __entry-
> >prot_sglen,
> 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)
> + __print_symbolic(rtn, { SCSI_MLQUEUE_HOST_BUSY,
> "HOST_BUSY" },
> + { SCSI_MLQUEUE_DEVICE_BUSY, "DEVICE_BUSY"
> },
> + { SCSI_MLQUEUE_EH_RETRY, "EH_RETRY" },
> + { SCSI_MLQUEUE_TARGET_BUSY, "TARGET_BUSY"
> })
> + )
We tend to do global print_symbolics as show_XXX_name definitions at
the top of the file even if they only occur once, just in case some
other trace point wants to use them.
Regards,
James
On 2025/5/14 21:39, James Bottomley wrote:
> On Wed, 2025-05-14 at 15:44 +0800, Kassey Li wrote:
>> In default it showed rtn in decimal.
>>
>> kworker/3:1H-183 [003] .... 51.035474: scsi_dispatch_cmd_error:
>> host_no=0 channel=0 id=0 lun=4 data_sgl=1 prot_sgl=0
>> prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=3907214 txlen=1 protect=0
>> raw=28 00 00 3b 9e 8e 00 00 01 00) rtn=4181
>>
>> In source code we define these possible value as hexadecimal:
>>
>> include/scsi/scsi.h
>>
>> SCSI_MLQUEUE_HOST_BUSY 0x1055
>> SCSI_MLQUEUE_DEVICE_BUSY 0x1056
>> SCSI_MLQUEUE_EH_RETRY 0x1057
>> SCSI_MLQUEUE_TARGET_BUSY 0x1058
>>
>> This change shows the string type.
>>
>> Signed-off-by: Kassey Li <quic_yingangl@quicinc.com>
>> ---
>> include/trace/events/scsi.h | 8 ++++++--
>> 1 file changed, 6 insertions(+), 2 deletions(-)
>>
>> diff --git a/include/trace/events/scsi.h
>> b/include/trace/events/scsi.h
>> index bf6cc98d9122..56987f98ba4a 100644
>> --- a/include/trace/events/scsi.h
>> +++ b/include/trace/events/scsi.h
>> @@ -240,14 +240,18 @@ 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 driver_tag=%d scheduler_tag=%d
>> cmnd=(%s %s raw=%s)" \
>> - " rtn=%d",
>> + " rtn=%s",
>> __entry->host_no, __entry->channel, __entry->id,
>> __entry->lun, __entry->data_sglen, __entry-
>>> prot_sglen,
>> 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)
>> + __print_symbolic(rtn, { SCSI_MLQUEUE_HOST_BUSY,
>> "HOST_BUSY" },
>> + { SCSI_MLQUEUE_DEVICE_BUSY, "DEVICE_BUSY"
>> },
>> + { SCSI_MLQUEUE_EH_RETRY, "EH_RETRY" },
>> + { SCSI_MLQUEUE_TARGET_BUSY, "TARGET_BUSY"
>> })
>> + )
>
> We tend to do global print_symbolics as show_XXX_name definitions at
> the top of the file even if they only occur once, just in case some
> other trace point wants to use them.
Ok, will follow this suggest in V3.
diff --git a/include/trace/events/scsi.h b/include/trace/events/scsi.h
index 8e2d9b1b0e77..cee057910cb3 100644
--- a/include/trace/events/scsi.h
+++ b/include/trace/events/scsi.h
@@ -199,6 +199,12 @@ TRACE_EVENT(scsi_dispatch_cmd_start,
__print_hex(__get_dynamic_array(cmnd), __entry->cmd_len))
);
+#define show_rtn_type(rtn) \
+ __print_symbolic(rtn, { SCSI_MLQUEUE_HOST_BUSY, "HOST_BUSY" }, \
+ { SCSI_MLQUEUE_DEVICE_BUSY, "DEVICE_BUSY" }, \
+ { SCSI_MLQUEUE_EH_RETRY, "EH_RETRY" }, \
+ { SCSI_MLQUEUE_TARGET_BUSY, "TARGET_BUSY" })
+
TRACE_EVENT(scsi_dispatch_cmd_error,
TP_PROTO(struct scsi_cmnd *cmd, int rtn),
@@ -239,14 +245,15 @@ 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 driver_tag=%d scheduler_tag=%d cmnd=(%s
%s raw=%s)" \
- " rtn=%d",
+ " rtn=%s",
__entry->host_no, __entry->channel, __entry->id,
__entry->lun, __entry->data_sglen, __entry->prot_sglen,
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)
+ show_rtn_type(__entry->rtn)
+ )
);
>
> Regards,
>
> James
>
On Wed, 14 May 2025 15:44:56 +0800 Kassey Li <quic_yingangl@quicinc.com> wrote: > In default it showed rtn in decimal. > > kworker/3:1H-183 [003] .... 51.035474: scsi_dispatch_cmd_error: host_no=0 channel=0 id=0 lun=4 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=3907214 txlen=1 protect=0 raw=28 00 00 3b 9e 8e 00 00 01 00) rtn=4181 > > In source code we define these possible value as hexadecimal: > > include/scsi/scsi.h > > SCSI_MLQUEUE_HOST_BUSY 0x1055 > SCSI_MLQUEUE_DEVICE_BUSY 0x1056 > SCSI_MLQUEUE_EH_RETRY 0x1057 > SCSI_MLQUEUE_TARGET_BUSY 0x1058 > > This change shows the string type. Nit, but would an example of the new output be useful in the change log? > > Signed-off-by: Kassey Li <quic_yingangl@quicinc.com> Other than that, Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org> -- Steve
On 2025/5/14 21:09, Steven Rostedt wrote:
> On Wed, 14 May 2025 15:44:56 +0800
> Kassey Li <quic_yingangl@quicinc.com> wrote:
>
>> In default it showed rtn in decimal.
>>
>> kworker/3:1H-183 [003] .... 51.035474: scsi_dispatch_cmd_error: host_no=0 channel=0 id=0 lun=4 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=3907214 txlen=1 protect=0 raw=28 00 00 3b 9e 8e 00 00 01 00) rtn=4181
>>
>> In source code we define these possible value as hexadecimal:
>>
>> include/scsi/scsi.h
>>
>> SCSI_MLQUEUE_HOST_BUSY 0x1055
>> SCSI_MLQUEUE_DEVICE_BUSY 0x1056
>> SCSI_MLQUEUE_EH_RETRY 0x1057
>> SCSI_MLQUEUE_TARGET_BUSY 0x1058
>>
>> This change shows the string type.
>
> Nit, but would an example of the new output be useful in the change log?
it is not 100% to reproduce the error path.
So I forced to show this by below change,
is this fine to test this ?
change to enforce the log:
diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
index 2b27a412aad9..cbc76a09dc75 100644
--- a/drivers/scsi/scsi_lib.c
+++ b/drivers/scsi/scsi_lib.c
@@ -1518,6 +1518,7 @@ static int scsi_dispatch_cmd(struct scsi_cmnd *cmd)
trace_scsi_dispatch_cmd_start(cmd);
rtn = host->hostt->queuecommand(host, cmd);
+ trace_scsi_dispatch_cmd_error(cmd, rtn);
if (rtn) {
atomic_dec(&cmd->device->iorequest_cnt);
trace_scsi_dispatch_cmd_error(cmd, rtn);
test cmd:
echo 1 > /sys/kernel/tracing/events/scsi/scsi_dispatch_cmd_error/enable
cat /sys/kernel/tracing/trace_pipe &
dd if=/dev/block/sde of=/oem/1.txt bs=1M count=1
log:
dd-1092 [007] ..... 40.975673: scsi_dispatch_cmd_error: host_no=0
channel=0 id=0 lun=4 data_sgl=33 prot_sgl=0 prot_op=SCSI_PROT_NORMAL
driver_tag=57 scheduler_tag=52 cmnd=(READ_10 lba=3328 txlen=128
protect=0 raw=28 00 00 00 0d 00 00 00 80 00) rtn=0x0
>
>>
>> Signed-off-by: Kassey Li <quic_yingangl@quicinc.com>
>
> Other than that,
>
> Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org>
>
> -- Steve
© 2016 - 2026 Red Hat, Inc.