Skip to contentSkip to conversation

scsi: ftrace based scsi tracer

PATCH In review Kei Tokunaga 4 participants 8 messages Apr 1, 2010 – Apr 2, 2010

Subsystems (3)
lore
Share & tools
lore
#0 lore raw

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

#1 lore raw

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
diff -puN include/linux/ftrace_event.h~add__print_hex_to_ftrace include/linux/ftrace_event.h
@@ -25,6 +25,9 @@ const char *ftrace_print_flags_seq(struc
 const 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
diff -puN include/trace/ftrace.h~add__print_hex_to_ftrace include/trace/ftrace.h
@@ -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
diff -puN kernel/trace/trace_output.c~add__print_hex_to_ftrace kernel/trace/trace_output.c
@@ -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)
 {

_

maintainer
#2 lore raw

Re: [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 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(+)

diff -puN include/linux/ftrace_event.h~add__print_hex_to_ftrace include/linux/ftrace_event.h

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(struc
 const 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_ftrace include/trace/ftrace.h

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					\

diff -puN kernel/trace/trace_output.c~add__print_hex_to_ftrace kernel/trace/trace_output.c

kernel/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)
 {

_

#3 lore raw

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?

#4 lore raw

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.

#5 lore raw

Re: [PATCH 1/2 v4] scsi: add __print_hex() to ftrace

In reply to Steven Rostedt
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 the trace_seq will 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);
maintainer
#6 lore raw

Re: [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 the trace_seq will go after the '\0'.

This is exactly what ftrace_print_flags_seq() and ftrace_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

#7 lore raw

PATCH v4 2/2 scsi: add scsi trace core functions and put trace points

In reply to Kei Tokunaga

This 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
diff -puN drivers/scsi/Makefile~add_scsi_trace_core_functions_and_put_trace_points drivers/scsi/Makefile
@@ -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
diff -puN drivers/scsi/scsi.c~add_scsi_trace_core_functions_and_put_trace_points drivers/scsi/scsi.c
@@ -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
diff -puN drivers/scsi/scsi_error.c~add_scsi_trace_core_functions_and_put_trace_points drivers/scsi/scsi_error.c
@@ -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
diff -puN kernel/trace/trace_output.c~add_scsi_trace_core_functions_and_put_trace_points kernel/trace/trace_output.c
@@ -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)
 {

_