Add a flight data recorder for scsi commands

Here is a fun patch in an early state. Essentially I want to trace scsi commands, which has already been done long ago. The problem I have is that I care about all the scsi commands for one particular device - without knowing in advance which device it will be. Once I know the device in question, I want to dump the last X commands.

The existing tracing is covering all commands to all devices. So either I have to oversize my trace buffer and dump way too much, or I will miss the stuff I am interested in most of the time. Hence my per-device trace buffer (called fdr to avoid namespace collisions).

Steven, is there some magic 2-line patch that would also give me what I want without having to reinvent all your infrastructure and doing such a bad job?

Jörn

--
It is better to die of hunger having lived without grief and fear, than to live with a troubled spirit amid abundance.
-- Epictetus

And dump the fdr whenever we run into a timeout. If the timeout is caused by a crashed target and the target crash is triggered by a weird command sent by us, we might want to know which commands we send out.

Signed-off-by Joern Engel <[email protected]>

---
 drivers/scsi/scsi.c        |   31 +++++++++++++++++++++++++++++++
 drivers/scsi/scsi_error.c  |   38 ++++++++++++++++++++++++++++++++++++++
 drivers/scsi/scsi_scan.c   |    1 +
 include/scsi/scsi_device.h |   13 +++++++++++++
 4 files changed, 83 insertions(+)

drivers/scsi/scsi.c +31 -0

index a884f13..54168bb 100644
@@ -647,6 +647,36 @@ void scsi_cmd_get_serial(struct Scsi_Host *host, struct scsi_cmnd *cmd)
 }
 EXPORT_SYMBOL(scsi_cmd_get_serial);
 
+static void fdr_add(struct fdr_ring *ring, struct fdr_entry *entry)
+{
+	struct fdr_entry *old;
+	unsigned long flags;
+	int index;
+
+	spin_lock_irqsave(&ring->fdr_lock, flags);
+	index = ring->last_entry + 1;
+	if (index >= ARRAY_SIZE(ring->entry))
+		index = 0;
+	old = ring->entry[index];
+	ring->entry[index] = entry;
+	ring->last_entry = index;
+	spin_unlock_irqrestore(&ring->fdr_lock, flags);
+	kfree(old);
+}
+
+static void fdr_scsi_cmd(struct scsi_cmnd *cmd)
+{
+	struct fdr_entry *new;
+
+	new = kmalloc(sizeof(*new) + cmd->cmd_len, GFP_KERNEL);
+	if (!new)
+		return;
+	new->ts_nsec = local_clock();
+	new->size = cmd->cmd_len;
+	memcpy(new->data, cmd->cmnd, new->size);
+	fdr_add(&cmd->device->fdr, new);
+}
+
 /**
  * scsi_dispatch_command - Dispatch a command to the low-level driver.
  * @cmd: command block we are dispatching.

@@ -747,6 +777,7 @@ int scsi_dispatch_cmd(struct scsi_cmnd *cmd)
 		scsi_done(cmd);
 	} else {
 		trace_scsi_dispatch_cmd_start(cmd);
+		fdr_scsi_cmd(cmd);
 		cmd->scsi_done = scsi_done;
 		rtn = host->hostt->queuecommand(host, cmd);
 	}

drivers/scsi/scsi_error.c +38 -0

index 0dfae50..829cb74 100644
@@ -132,6 +132,41 @@ static void queue_for_eh(struct Scsi_Host *shost, struct scsi_cmnd *scmd)
 	schedule_work(&scmd->abort_work);
 }
 
+static void scsi_fdr_dump(struct fdr_entry *entry)
+{
+	char buf[64 + 8 + 2];
+	unsigned long ts = entry->ts_nsec;
+	unsigned long rem_nsec;
+
+	rem_nsec = do_div(ts, 1000000000);
+	hex_dump_to_buffer(entry->data, entry->size, 32, 8, buf, sizeof(buf), 0);
+	pr_info("%6lu.%06lu: %s\n", ts, rem_nsec, buf);
+}
+
+static void fdr_dump(struct fdr_ring *ring, void (*dump) (struct fdr_entry * entry))
+{
+	struct fdr_entry *entry;
+	unsigned long flags;
+	int i;
+
+	spin_lock_irqsave(&ring->fdr_lock, flags);
+	for (i = ring->last_entry + 1; i < ARRAY_SIZE(ring->entry); i++) {
+		entry = ring->entry[i];
+		ring->entry[i] = NULL;
+		if (entry)
+			dump(entry);
+		kfree(entry);
+	}
+	for (i = 0; i < ring->last_entry; i++) {
+		entry = ring->entry[i];
+		ring->entry[i] = NULL;
+		if (entry)
+			dump(entry);
+		kfree(entry);
+	}
+	spin_unlock_irqrestore(&ring->fdr_lock, flags);
+}
+
 /**
  * scsi_times_out - Timeout function for normal scsi commands.
  * @req:	request that is timing out.

@@ -148,6 +183,9 @@ enum blk_eh_timer_return scsi_times_out(struct request *req)
 	enum blk_eh_timer_return rtn = BLK_EH_NOT_HANDLED;
 	struct Scsi_Host *host = scmd->device->host;
 
+	sdev_printk(KERN_INFO, scmd->device, "dumping cdb recorder\n");
+	fdr_dump(&scmd->device->fdr, scsi_fdr_dump);
+
 	trace_scsi_dispatch_cmd_timeout(scmd);
 	scsi_log_completion(scmd, TIMEOUT_ERROR);
 

drivers/scsi/scsi_scan.c +1 -0

index db89445..85dbae4 100644
@@ -252,6 +252,7 @@ static struct scsi_device *scsi_alloc_sdev(struct scsi_target *starget,
 	INIT_LIST_HEAD(&sdev->starved_entry);
 	INIT_LIST_HEAD(&sdev->event_list);
 	spin_lock_init(&sdev->list_lock);
+	spin_lock_init(&sdev->fdr.fdr_lock);
 	INIT_WORK(&sdev->event_work, scsi_evt_thread);
 	INIT_WORK(&sdev->requeue_work, scsi_requeue_run_queue);
 	/* Limit scsi messages per device */

include/scsi/scsi_device.h +12 -0

index bafc41c..00b7e9b 100644
@@ -97,6 +97,18 @@ enum scsi_err_inj_duration {
 };
 #endif /* CONFIG_SCSI_ERROR_INJECTOR */
 
+struct fdr_entry {
+	unsigned long ts_nsec;
+	u32 size;
+	u8 data[0];
+};
+
+struct fdr_ring {
+	spinlock_t fdr_lock;
+	int last_entry;
+	struct fdr_entry *entry[1000];
+};
+
 struct scsi_device {
 	struct Scsi_Host *host;
 	struct request_queue *request_queue;

Quoted 11 lines · Jörn Engel

Here is a fun patch in an early state. Essentially I want to trace scsi commands, which has already been done long ago. The problem I have is that I care about all the scsi commands for one particular device - without knowing in advance which device it will be. Once I know the device in question, I want to dump the last X commands.

The existing tracing is covering all commands to all devices. So either I have to oversize my trace buffer and dump way too much, or I will miss the stuff I am interested in most of the time. Hence my per-device trace buffer (called fdr to avoid namespace collisions).

Sounds like a useful idea..

However, it adds another kmalloc + spin_lock -> spin_unlock in the fast path for each struct scsi_cmnd I/O dispatch, which is exactly what the scsi-mq prototype code is trying to avoid at all costs.

Here is a fun patch in an early state. Essentially I want to trace scsi commands, which has already been done long ago. The problem I have is that I care about all the scsi commands for one particular device - without knowing in advance which device it will be. Once I know the device in question, I want to dump the last X commands.

The existing tracing is covering all commands to all devices. So either I have to oversize my trace buffer and dump way too much, or I will miss the stuff I am interested in most of the time. Hence my per-device trace buffer (called fdr to avoid namespace collisions).

Isn't this facility something that overlaps with what Wireshark can already do today ? Wireshark can already capture SCSI traces for several transport types (iSCSI, USB, ...). For other transports, e.g. FC, I'd prefer to see Wireshark being extended instead of adding more SCSI tracing mechanisms in the SCSI core.

Here is a fun patch in an early state. Essentially I want to trace scsi commands, which has already been done long ago. The problem I have is that I care about all the scsi commands for one particular device - without knowing in advance which device it will be. Once I know the device in question, I want to dump the last X commands.

The existing tracing is covering all commands to all devices. So either I have to oversize my trace buffer and dump way too much, or I will miss the stuff I am interested in most of the time. Hence my per-device trace buffer (called fdr to avoid namespace collisions).

Steven, is there some magic 2-line patch that would also give me what I want without having to reinvent all your infrastructure and doing such a bad job?

Jörn

Quoted 5 lines · On Tue, 27 Aug 2013 18:03:25 -0400 Jörn Engel <[email protected]> wrote:

Here is a fun patch in an early state. Essentially I want to trace scsi commands, which has already been done long ago. The problem I have is that I care about all the scsi commands for one particular device - without knowing in advance which device it will be. Once I know the device in question, I want to dump the last X commands.

Is the device passed to the trace point? If so, you can add a filter on that device. You can even create a separate buffer to just trace that device.

Quoted 9 lines · Steven Rostedt

Quoted 5 lines · On Tue, 27 Aug 2013 18:03:25 -0400 Jörn Engel <[email protected]> wrote:

Here is a fun patch in an early state. Essentially I want to trace scsi commands, which has already been done long ago. The problem I have is that I care about all the scsi commands for one particular device - without knowing in advance which device it will be. Once I know the device in question, I want to dump the last X commands.

Quoted 3 lines

Is the device passed to the trace point? If so, you can add a filter on that device. You can even create a separate buffer to just trace that device.

"without knowing in advance which device it will be"

I have to trace all devices, because I don't know the interesting one ahead of time. And after the fact, I only care about one device. So having per-device trace buffers seems to be The Right Approach(tm).

And having multiple trace buffers is where I cannot easily make my problem fit your infrastructure.

Quoted 3 lines · On Tue, 27 Aug 2013 18:41:47 -0400 Jörn Engel <[email protected]> wrote:

"without knowing in advance which device it will be"

Quoted 6 lines

I have to trace all devices, because I don't know the interesting one ahead of time. And after the fact, I only care about one device. So having per-device trace buffers seems to be The Right Approach(tm).

And having multiple trace buffers is where I cannot easily make my problem fit your infrastructure.

Are you sure about that?

Note, I'm not sure you want this as something
in production systems to always have on boot, for that, we can modify things a little to help you there. But other than that you can do:

for each device d
mkdir /sys/kernel/debug/tracing/instances/scsi-$d cd /sys/kernel/debug/tracing/instances/scsi-$d echo $filter > events/scsi/*/filter
echo 1 > events/scsi/*/enable
done

The above is a script like pseudo code, just to convey the idea, not something to put in verbatim.

Now, this may still not be what you want, but at a minimum, I would not add another hook like you did with the fdr_scsi_cmd(cmd). You know you can hook to the tracepoint directly.

	register_trace_scsi_dispatch_cmd_start(fdr_scsi_cmd, NULL);

static void fdr_scsi_cmd(void *data, struct scsi_cmnd *cmd)

{
	[...]
}

Once you call that register function, the tracepoint will call the function you registered when the tracepoint is hit.