scsi: ftrace based scsi tracer
v4 cover scsi: ftrace based scsi tracer
Hi,
This is v4 patch series of SCSI trace. Only a cosmetic change from v3.
Because it's been a while since the first posting, I'll put brief descriptions of the patchset.
Basically, this is a ftrace based SCSI tracer. It prints the following information for scsi-3 commands.
o scsi bus number ("host")
o scsi channel number ("channel")
o scsi id ("id")
o LUN ("lun")
o command info
- op name (ex. "WRITE_10")
- LBA ("lba") (for certain commands only)
- transfer length ("txlen") (for certain commands only)
- CDB (ex. "raw=28 00 03 60 a2 cb 00 00 08 00")
o result of the command
(ex. "result=(driver=DRIVER_OK host=DID_OK
message=COMMAND_COMPLETE status=SAM_STAT_GOOD")
Those information are printed either at a time:
o when a command is to be dispatched,
o when a command dispatched returns in error,
o when a command is done,
o when an error handler is to waken up, or
o when timeout of a command is deteced.
To use it quickly, try these steps:
1) Build a kernel with the patchset applied (ftrace related kernel configs need to be enabled.)
2) Boot the kernel
3) Mount debugfs
ex. mount -t debugfs none /sys/kernel/debug/
4) Indicate events to trace
ex. echo "scsi:*" > /sys/kernel/debug/tracing/set_event
5) Make some I/Os on your scsi devices
ex. ls
6) Retrieve trace log
ex. cat /sys/kernel/debug/tracing/trace
Here is an outputs example:
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
flush-8:0-3746 [001] 1374.517152:scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 cmnd=(WRITE_10 lba=32267539 txlen=8 raw=2a 00 01 ec 5d 13 00 00 08 00)
<idle>-0 [000] 1374.524964:
scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 cmnd=(WRITE_10 lba=32267539 txlen=8 raw=2a 00 01 ec 5d 13 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
This patchset applies to 2.6.34-rc3.
Thanks,
Kei
PATCH v4 1/2 scsi: add __print_hex() to ftrace
This is the same patch from v1.
__print_hex() prints values in an array in hex (w/o '0x') (space separated) EX) 92 33 32 f3 ee 4d
---
linux-2.6.34-rc3-trace-kei/include/linux/ftrace_event.h | 3 +++ linux-2.6.34-rc3-trace-kei/include/trace/ftrace.h | 3 +++ linux-2.6.34-rc3-trace-kei/kernel/trace/trace_output.c | 15 +++++++++++++++ 3 files changed, 21 insertions(+)
include/linux/ftrace_event.h renamed from include/linux/ftrace_event.h~add__print_hex_to_ftrace +3 -0
@@ -25,6 +25,9 @@ const char *ftrace_print_flags_seq(strucconst char *ftrace_print_symbols_seq (struct trace_seq *p,unsigned long val,const struct trace_print_flags *symbol_array); +const char *ftrace_print_hex_seq (struct trace_seq *p, +const unsigned char *buf,int len); +/* * The trace entry - the most basic unit of tracing. This is what * is printed in the end as a single line in the trace output, such as:
include/trace/ftrace.h renamed from include/trace/ftrace.h~add__print_hex_to_ftrace +3 -0
@@ -198,6 +198,9 @@ftrace_print_symbols_seq (p, value, symbols); \ }) +#undef __print_hex +#define __print_hex (buf, buf_len) ftrace_print_hex_seq(p, buf, buf_len) +#undef DECLARE_EVENT_CLASS#define DECLARE_EVENT_CLASS (call, proto, args, tstruct, assign, print) \ static notrace enum print_line_t \
kernel/trace/trace_output.c renamed from kernel/trace/trace_output.c~add__print_hex_to_ftrace +15 -0
@@ -355,6 +355,21 @@ ftrace_print_symbols_seq(struct trace_se }EXPORT_SYMBOL (ftrace_print_symbols_seq); +const char * +ftrace_print_hex_seq (struct trace_seq *p,const unsigned char *buf,int buf_len) +{ +int i; +const char *ret = p->buffer + p->len; + +for (i =0 ; i < buf_len; i++) +trace_seq_printf (p,"%s%2.2x" , i ==0 ?"" :" " , buf[i]); + +trace_seq_putc (p,0 ); + +return ret; +} +EXPORT_SYMBOL (ftrace_print_hex_seq); +#ifdef CONFIG_KRETPROBES static inline const char *kretprobed (const char *name) {
_
Steven Rostedt
maintainerRe: [PATCH 1/2 v4] scsi: add __print_hex() to ftrace
Quoted 49 lines · Kei Tokunaga
This is the same patch from v1.
__print_hex()prints values in an array in hex (w/o '0x') (space separated) EX) 92 33 32 f3 ee 4dSigned-off-by Li Zefan <[email protected]>Signed-off-by Tomohiro Kusumi <[email protected]>Signed-off-by Kei Tokunaga <[email protected]>---
linux-2.6.34-rc3-trace-kei/include/linux/ftrace_event.h | 3 +++ linux-2.6.34-rc3-trace-kei/include/trace/ftrace.h | 3 +++ linux-2.6.34-rc3-trace-kei/kernel/trace/trace_output.c | 15 +++++++++++++++ 3 files changed, 21 insertions(+)diff -puN
include/linux/ftrace_event.h~add__print_hex_to_ftraceinclude/linux/ftrace_event.hinclude/linux/ftrace_event.h renamed from include/linux/ftrace_event.h~add__print_hex_to_ftrace +3
-0@@ -25,6 +25,9 @@ const char *ftrace_print_flags_seq(strucconst char *ftrace_print_symbols_seq (struct trace_seq *p,unsigned long val,const struct trace_print_flags *symbol_array); +const char *ftrace_print_hex_seq (struct trace_seq *p, +const unsigned char *buf,int len); +/* * The trace entry - the most basic unit of tracing. This is what * is printed in the end as a single line in the trace output, such as: diff -puN
include/trace/ftrace.h~add__print_hex_to_ftraceinclude/trace/ftrace.hinclude/trace/ftrace.h renamed from include/trace/ftrace.h~add__print_hex_to_ftrace +3
-0@@ -198,6 +198,9 @@ftrace_print_symbols_seq (p, value, symbols); \ }) +#undef __print_hex +#define __print_hex (buf, buf_len) ftrace_print_hex_seq(p, buf, buf_len) +#undef DECLARE_EVENT_CLASS#define DECLARE_EVENT_CLASS (call, proto, args, tstruct, assign, print) \ static notrace enum print_line_t \diff -puN
kernel/trace/trace_output.c~add__print_hex_to_ftracekernel/trace/trace_output.ckernel/trace/trace_output.c renamed from kernel/trace/trace_output.c~add__print_hex_to_ftrace +0
-0@@ -355,6 +355,21 @@ ftrace_print_symbols_seq(struct trace_se }EXPORT_SYMBOL (ftrace_print_symbols_seq);
kernel/trace/trace_output.c ftrace_print_symbols_seq(struct trace_se · line 367
Quoted 10 lines
kernel/trace/trace_output.c renamed from kernel/trace/trace_output.c~add__print_hex_to_ftrace +10
-0+const char * +ftrace_print_hex_seq (struct trace_seq *p,const unsigned char *buf,int buf_len) +{ +int i; +const char *ret = p->buffer + p->len; + +for (i =0 ; i < buf_len; i++) +trace_seq_printf (p,"%s%2.2x" , i ==0 ?"" :" " , buf[i]); + +trace_seq_putc (p,0 );
I would not put the putc(p, 0) into a helper function. This terminates the buffer, and strings added to the trace_seq will go after the '\0'.
What we need is this in trace_seq.h:
static inline trace_seq_terminate(struct trace_seq *s)
{
if (!s->full)
s->buffer[s->len] = 0;
}This will add a '0' to the buffer after the last string, but will not increment length while doing it. Thus, new data added to the buffer would still be appended correctly.
-- Steve
Quoted 13 lines
kernel/trace/trace_output.c renamed from kernel/trace/trace_output.c~add__print_hex_to_ftrace +5
-0+ +return ret; +} +EXPORT_SYMBOL (ftrace_print_hex_seq); +#ifdef CONFIG_KRETPROBES static inline const char *kretprobed (const char *name) {_
Re: [PATCH 1/2 v4] scsi: add __print_hex() to ftrace
Quoted 10 lines · Steven Rostedt
kernel/trace/trace_output.c ftrace_print_symbols_seq(struct trace_se · line 367
Quoted 10 lines
kernel/trace/trace_output.c renamed from kernel/trace/trace_output.c~add__print_hex_to_ftrace +10
-0+const char * +ftrace_print_hex_seq (struct trace_seq *p,const unsigned char *buf,int buf_len) +{ +int i; +const char *ret = p->buffer + p->len; + +for (i =0 ; i < buf_len; i++) +trace_seq_printf (p,"%s%2.2x" , i ==0 ?"" :" " , buf[i]); + +trace_seq_putc (p,0 );
hex_dump_to_buffer?
Re: [PATCH 1/2 v4] scsi: add __print_hex() to ftrace
Quoted 14 lines · Joe Perches
Quoted 10 lines · Steven Rostedt
kernel/trace/trace_output.c ftrace_print_symbols_seq(struct trace_se · line 367
Quoted 10 lines
kernel/trace/trace_output.c renamed from kernel/trace/trace_output.c~add__print_hex_to_ftrace +10
-0+const char * +ftrace_print_hex_seq (struct trace_seq *p,const unsigned char *buf,int buf_len) +{ +int i; +const char *ret = p->buffer + p->len; + +for (i =0 ; i < buf_len; i++) +trace_seq_printf (p,"%s%2.2x" , i ==0 ?"" :" " , buf[i]); + +trace_seq_putc (p,0 );
hex_dump_to_buffer?
I've replied to you on this long ago, in v3 (or v2) patch.
Re: [PATCH 1/2 v4] scsi: add __print_hex() to ftrace
In reply to Steven RostedtQuoted 5 lines
Quoted 5 lines
kernel/trace/trace_output.c renamed from kernel/trace/trace_output.c~add__print_hex_to_ftrace +5
-0+const char * +ftrace_print_hex_seq (struct trace_seq *p,const unsigned char *buf,int buf_len) +{ +int i; +const char *ret = p->buffer + p->len;
Quoted 9 lines
kernel/trace/trace_output.c ftrace_print_symbols_seq(struct trace_se · line 367
Quoted 5 lines
kernel/trace/trace_output.c renamed from kernel/trace/trace_output.c~add__print_hex_to_ftrace +5
-0+ +for (i =0 ; i < buf_len; i++) +trace_seq_printf (p,"%s%2.2x" , i ==0 ?"" :" " , buf[i]); + +trace_seq_putc (p,0 );I would not put the
putc(p, 0)into a helper function. This terminates the buffer, and strings added to thetrace_seqwill go after the '\0'.
This is exactly what ftrace_print_flags_seq() and ftrace_print_symbols_seq() do, and exactly what we want.
An example:
TP_printk("%s,%s", __print_flags(...), __print_flags(...));
We need 2 seperated strings, while trace_seq_terminate() will make it a single string.
Quoted 18 lines
What we need is this in
trace_seq.h:static inline
trace_seq_terminate(struct trace_seq *s){ if (!s->full) s->buffer[s->len] = 0; }This will add a '0' to the buffer after the last string, but will not increment length while doing it. Thus, new data added to the buffer would still be appended correctly.
-- Steve
Quoted 4 lines
kernel/trace/trace_output.c renamed from kernel/trace/trace_output.c~add__print_hex_to_ftrace +4
-0+ +return ret; +} +EXPORT_SYMBOL (ftrace_print_hex_seq);
Steven Rostedt
maintainerRe: [PATCH 1/2 v4] scsi: add __print_hex() to ftrace
Quoted 18 lines · Li Zefan
Quoted 5 lines
Quoted 5 lines
kernel/trace/trace_output.c renamed from kernel/trace/trace_output.c~add__print_hex_to_ftrace +5
-0+const char * +ftrace_print_hex_seq (struct trace_seq *p,const unsigned char *buf,int buf_len) +{ +int i; +const char *ret = p->buffer + p->len;Quoted 9 lines
kernel/trace/trace_output.c ftrace_print_symbols_seq(struct trace_se · line 367
Quoted 5 lines
kernel/trace/trace_output.c renamed from kernel/trace/trace_output.c~add__print_hex_to_ftrace +5
-0+ +for (i =0 ; i < buf_len; i++) +trace_seq_printf (p,"%s%2.2x" , i ==0 ?"" :" " , buf[i]); + +trace_seq_putc (p,0 );I would not put the
putc(p, 0)into a helper function. This terminates the buffer, and strings added to thetrace_seqwill go after the '\0'.This is exactly what
ftrace_print_flags_seq()andftrace_print_symbols_seq()do, and exactly what we want.
Quoted 6 lines
An example:
TP_printk("%s,%s", __print_flags(...), __print_flags(...));We need 2 seperated strings, while
trace_seq_terminate()will make it a single string.
You're right! But I still don't like it ;-)
I probably should have had that in the __print_flags() macro instead of the function. Oh well. These are only helper functions for the __print*() variants anyway.
OK, you can have my Acked-by: Steven Rostedt <[email protected]> for this.
-- Steve
PATCH v4 2/2 scsi: add scsi trace core functions and put trace points
In reply to Kei TokunagaThis adds scsi trace core functions and trace points.
---
linux-2.6.34-rc3-trace-kei/drivers/scsi/Makefile | 1 linux-2.6.34-rc3-trace-kei/drivers/scsi/scsi.c | 6 linux-2.6.34-rc3-trace-kei/drivers/scsi/scsi_error.c | 4 linux-2.6.34-rc3-trace-kei/drivers/scsi/scsi_trace.c | 185 +++++++++ linux-2.6.34-rc3-trace-kei/include/trace/events/scsi.h | 328 +++++++++++++++++ linux-2.6.34-rc3-trace-kei/kernel/trace/trace_output.c | 1 6 files changed, 525 insertions(+)
drivers/scsi/Makefile renamed from drivers/scsi/Makefile~add_scsi_trace_core_functions_and_put_trace_points +1 -0
@@ -162,6 +162,7 @@ scsi_mod-y += scsi_scan.o scsi_sysfs.o scsi_mod-$(CONFIG_SCSI_NETLINK) += scsi_netlink.o scsi_mod-$(CONFIG_SYSCTL) += scsi_sysctl.o scsi_mod-$(CONFIG_SCSI_PROC_FS) += scsi_proc.o +scsi_mod-y += scsi_trace.o scsi_tgt-y += scsi_tgt_lib.o scsi_tgt_if.o
drivers/scsi/scsi.c renamed from drivers/scsi/scsi.c~add_scsi_trace_core_functions_and_put_trace_points +6 -0
@@ -67,6 +67,9 @@#include "scsi_priv.h" #include "scsi_logging.h" +#define CREATE_TRACE_POINTS +#include <trace/events/scsi.h> +static void scsi_done (struct scsi_cmnd *cmd);/*
@@ -747,10 +750,12 @@ int scsi_dispatch_cmd(struct scsi_cmnd * cmd->result = (DID_NO_CONNECT <<16 );scsi_done (cmd); }else { +trace_scsi_dispatch_cmd_start (cmd); rtn = host->hostt->queuecommand (cmd, scsi_done); }spin_unlock_irqrestore (host->host_lock, flags);if (rtn) { +trace_scsi_dispatch_cmd_error (cmd, rtn);if (rtn !=SCSI_MLQUEUE_DEVICE_BUSY && rtn !=SCSI_MLQUEUE_TARGET_BUSY ) rtn =SCSI_MLQUEUE_HOST_BUSY ;
@@ -781,6 +786,7 @@ int scsi_dispatch_cmd(struct scsi_cmnd **/ static void scsi_done (struct scsi_cmnd *cmd) { +trace_scsi_dispatch_cmd_done (cmd);blk_complete_request (cmd->request); }
drivers/scsi/scsi_error.c renamed from drivers/scsi/scsi_error.c~add_scsi_trace_core_functions_and_put_trace_points +4 -0
@@ -38,6 +38,8 @@#include "scsi_logging.h" #include "scsi_transport_api.h" +#include <trace/events/scsi.h> +#define SENSE_TIMEOUT (10*HZ)/*
@@ -51,6 +53,7 @@void scsi_eh_wakeup (struct Scsi_Host *shost) {if (shost->host_busy == shost->host_failed) { +trace_scsi_eh_wakeup (shost);wake_up_process (shost->ehandler);SCSI_LOG_ERROR_RECOVERY (5 ,printk ("Waking error handler thread\n" ));
@@ -126,6 +129,7 @@ enum blk_eh_timer_return scsi_times_out(struct scsi_cmnd *scmd = req->special;enum blk_eh_timer_return rtn =BLK_EH_NOT_HANDLED ; +trace_scsi_dispatch_cmd_timeout (scmd);scsi_log_completion (scmd,TIMEOUT_ERROR );if (scmd->device->host->transportt->eh_timed_out)
drivers/scsi/scsi_trace.c new file +185 -0
185 lines not on this page · raw message
include/trace/events/scsi.h new file +328 -0
328 lines not on this page · raw message
kernel/trace/trace_output.c renamed from kernel/trace/trace_output.c~add_scsi_trace_core_functions_and_put_trace_points +1 -0
@@ -209,6 +209,7 @@ int trace_seq_putc(struct trace_seq *s,return 1 ; } +EXPORT_SYMBOL (trace_seq_putc);int trace_seq_putmem (struct trace_seq *s,const void *mem,size_t len) {
_