Skip to contentSkip to conversation

scsi: ftrace based scsi tracing feature

PATCH Superseded Kei Tokunaga 2 participants 5 messages Feb 1, 2010 – Feb 3, 2010

Subsystems (3)

v2 of 4 Superseded Latest is v4 →

lore
Share & tools
lore
#0 lore raw

v2 cover scsi: ftrace based scsi tracing feature

Hi,

This is v2 patch series of SCSI trace.

Changelog from v1:

- fixed variable length command handling (DIF_TYPE2 case only)
- moved scsi trace functions from kernel/trace/scsitrace.c to drivers/scsi/scsi_trace.c

Here are the links to the discussions on v1:

[PATCH 0/2] scsi: ftrace based scsi tracing feature

    http://marc.info/?l=linux-scsi&m=126396981308416&w=2
  [PATCH 1/2] scsi: add __print_hex() to ftrace
    http://marc.info/?l=linux-scsi&m=126396984308451&w=2
  [PATCH 2/2] scsi: add scsi trace core function and put trace points
    http://marc.info/?l=linux-scsi&m=126396987608486&w=2

This patchset applies to 2.6.33-rc6.

Thanks,
Kei

#1 lore raw

PATCH v2 1/2 scsi: add __print_hex() to ftrace

From: Li Zefan <[email protected]>

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.33-rc6-trace-kei/include/linux/ftrace_event.h |    3 +++
 linux-2.6.33-rc6-trace-kei/include/trace/ftrace.h       |    3 +++
 linux-2.6.33-rc6-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~ftrace_print_hex +3 -0
diff -puN include/linux/ftrace_event.h~ftrace_print_hex include/linux/ftrace_event.h
@@ -24,6 +24,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~ftrace_print_hex +3 -0
diff -puN include/trace/ftrace.h~ftrace_print_hex include/trace/ftrace.h
@@ -321,6 +321,9 @@ ftrace_format_##name(struct ftrace_event
 		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 enum print_line_t						\
kernel/trace/trace_output.c renamed from kernel/trace/trace_output.c~ftrace_print_hex +15 -0
diff -puN kernel/trace/trace_output.c~ftrace_print_hex 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)
 {

_

#2 lore raw

PATCH v2 2/2 scsi: add scsi trace core function and put trace points

In reply to Kei Tokunaga

This is v2 patchset.

Changelog from v1:

- fixed variable length command handling (DIF_TYPE2 case only)
- moved scsi trace functions from kernel/trace/scsitrace.c to drivers/scsi/scsi_trace.c (new file)

Although Martin gave me a good sight that decoding some other fields and some other commands might be nice, those are not added in this version.

Trace points are the same from the last time as follows:

- when a command is about to be dispatched.
- when a command dispatched returns in error.
- when a command is done.
- when an error handler is about to waken up.
- when timeout of a command is detected.

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)

---

 linux-2.6.33-rc6-trace-kei/drivers/scsi/Makefile       |    1 
 linux-2.6.33-rc6-trace-kei/drivers/scsi/scsi.c         |    6 
 linux-2.6.33-rc6-trace-kei/drivers/scsi/scsi_error.c   |    4 
 linux-2.6.33-rc6-trace-kei/drivers/scsi/scsi_trace.c   |  188 +++++++++
 linux-2.6.33-rc6-trace-kei/include/trace/events/scsi.h |  328 +++++++++++++++++
 linux-2.6.33-rc6-trace-kei/kernel/trace/trace_output.c |    1 
 6 files changed, 528 insertions(+)
drivers/scsi/Makefile renamed from drivers/scsi/Makefile~scsi_trace +1 -0
diff -puN drivers/scsi/Makefile~scsi_trace 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~scsi_trace +6 -0
diff -puN drivers/scsi/scsi.c~scsi_trace 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~scsi_trace +4 -0
diff -puN drivers/scsi/scsi_error.c~scsi_trace 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 +188 -0

188 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~scsi_trace +1 -0
diff -puN kernel/trace/trace_output.c~scsi_trace 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)
 {

_

#3 lore raw

Re: [PATCH 2/2 v2] scsi: add scsi trace core function and put trace points

Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line

"Kei" == Kei Tokunaga <[email protected]> writes:

I'm traveling so I won't have time to look at this closely until next week. However, this caught my eye:

+static const char *
+scsi_trace_varlen(struct trace_seq *p, unsigned char *cdb, int len) +{
+ switch (SERVICE_ACTION(cdb)) {
+ case READ_32:
+ case WRITE_32:
+ /* if protection is enabled */
+ if (((cdb[10] >> 5) & 0x7) == 1)
+ return scsi_trace_rw32(p, cdb, len);
+ /* fall through */
+ default:
+ return scsi_trace_misc(p, cdb, len);
+ }
+}

It is not a requirement that a 32-byte READ/WRITE request must have PROTECT set. So that if statement is bogus.

Signature · 1 line
Martin K. Petersen	Oracle Linux Engineering
#4 lore raw

Re: [PATCH 2/2 v2] scsi: add scsi trace core function and put trace points

Quoted 20 lines · Martin K. Petersen
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line

"Kei" == Kei Tokunaga <[email protected]> writes:

I'm traveling so I won't have time to look at this closely until next week. However, this caught my eye:

drivers/scsi/scsi_trace.c new file +14 -0
+static const char *
+scsi_trace_varlen(struct trace_seq *p, unsigned char *cdb, int len)
+{
+	switch (SERVICE_ACTION(cdb)) {
+	case READ_32:
+	case WRITE_32:
+		/* if protection is enabled */
+		if (((cdb[10] >> 5) & 0x7) == 1)
+			return scsi_trace_rw32(p, cdb, len);
+		/* fall through */
+	default:
+		return scsi_trace_misc(p, cdb, len);
+	}
+}
Quoted 2 lines

It is not a requirement that a 32-byte READ/WRITE request must have PROTECT set. So that if statement is bogus.

Yes. I agree that the if statement is not necessary here. I'll fix it. Thanks for having your time for the review.

Kei