[RFC][PATCH] Add a flight data recorder for scsi commands

[RFC][PATCH] Add a flight data recorder for scsi commands

[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).

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 <joern@logfs.org>
---
 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(+)

diff --git a/drivers/scsi/scsi.c b/drivers/scsi/scsi.c
index a884f13..54168bb 100644
--- a/drivers/scsi/scsi.c
+++ b/drivers/scsi/scsi.c
@@ -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);
 	}
diff --git a/drivers/scsi/scsi_error.c b/drivers/scsi/scsi_error.c
index 0dfae50..829cb74 100644
--- a/drivers/scsi/scsi_error.c
+++ b/drivers/scsi/scsi_error.c
@@ -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);
 
diff --git a/drivers/scsi/scsi_scan.c b/drivers/scsi/scsi_scan.c
index db89445..85dbae4 100644
--- a/drivers/scsi/scsi_scan.c
+++ b/drivers/scsi/scsi_scan.c
@@ -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 */
diff --git a/include/scsi/scsi_device.h b/include/scsi/scsi_device.h
index bafc41c..00b7e9b 100644
--- a/include/scsi/scsi_device.h
+++ b/include/scsi/scsi_device.h
@@ -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;
@@ -222,6 +234,7 @@ struct scsi_device {
 	struct scsi_dh_data	*scsi_dh_data;
 	enum scsi_device_state sdev_state;
 	struct ratelimit_state	sdev_ratelimit;
+	struct fdr_ring		fdr;
 	unsigned long		sdev_data[0];
 } __attribute__((aligned(sizeof(unsigned long))));
 
-- 
1.7.10.4
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [RFC][PATCH] Add a flight data recorder for scsi commands

[Nicholas A. Bellinger]

On Tue, 2013-08-27 at 18:17 -0400, Jörn Engel 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.
> 
> 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.

So that said, this logic should be disabled (by default) with some
manner of sysfs attribute in /sys/class/scsi_device (or some other
mechanism) that allows it to be enabled/disabled on a per struct
scsi_device basis.

I imagine that is already on your TODO, but given the gaping hole in
SCSI performance vs. raw block that scsi-mq is attempting to address, I
just wanted to make sure.  ;)

Thanks,

--nab

> 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 <joern@logfs.org>
> ---
>  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(+)
> 
> diff --git a/drivers/scsi/scsi.c b/drivers/scsi/scsi.c
> index a884f13..54168bb 100644
> --- a/drivers/scsi/scsi.c
> +++ b/drivers/scsi/scsi.c
> @@ -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);
>  	}
> diff --git a/drivers/scsi/scsi_error.c b/drivers/scsi/scsi_error.c
> index 0dfae50..829cb74 100644
> --- a/drivers/scsi/scsi_error.c
> +++ b/drivers/scsi/scsi_error.c
> @@ -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);
>  
> diff --git a/drivers/scsi/scsi_scan.c b/drivers/scsi/scsi_scan.c
> index db89445..85dbae4 100644
> --- a/drivers/scsi/scsi_scan.c
> +++ b/drivers/scsi/scsi_scan.c
> @@ -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 */
> diff --git a/include/scsi/scsi_device.h b/include/scsi/scsi_device.h
> index bafc41c..00b7e9b 100644
> --- a/include/scsi/scsi_device.h
> +++ b/include/scsi/scsi_device.h
> @@ -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;
> @@ -222,6 +234,7 @@ struct scsi_device {
>  	struct scsi_dh_data	*scsi_dh_data;
>  	enum scsi_device_state sdev_state;
>  	struct ratelimit_state	sdev_ratelimit;
> +	struct fdr_ring		fdr;
>  	unsigned long		sdev_data[0];
>  } __attribute__((aligned(sizeof(unsigned long))));
>  


--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [RFC][PATCH] Add a flight data recorder for scsi commands

[Jörn Engel]

On Tue, 27 August 2013 22:09:19 -0700, Nicholas A. Bellinger wrote:
> On Tue, 2013-08-27 at 18:17 -0400, Jörn Engel 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.
> > 
> > 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.

Agreed.  It shouldn't be too hard to replace the spin_lock with
cmpxchg, maybe even rcu.  And for the common case, one could reuse the
old buffer, getting rid of kmalloc overhead as well.

For the time being I will likely skip the work and see whether the
existing patch actually catches something useful.  First prove the
quick hack to be useful, then optimize the hell out of it.

Jörn

--
No art, however minor, demands less than total dedication if you want
to excel in it.
-- Leon Battista Alberti
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [RFC][PATCH] Add a flight data recorder for scsi commands

[Bart Van Assche]

On 08/28/13 00:17, Jörn Engel 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.
>
> 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.

Best regards,

Bart.

--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [RFC][PATCH] Add a flight data recorder for scsi commands

[Jörn Engel]

On Wed, 28 August 2013 14:45:14 +0200, Bart Van Assche wrote:
> 
> 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.

Wireshark would be great if there was a reproducable testcase and a
developer could sit down for an afternoon and collect some traces.
But how would you deal with rare cases that require around a year to
reproduce per device and only matter when dealing with many devices?

Jörn

--
Data expands to fill the space available for storage.
-- Parkinson's Law
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [RFC][PATCH] Add a flight data recorder for scsi commands

[Steven Rostedt]

On Tue, 27 Aug 2013 18:03:25 -0400
Jörn Engel <joern@logfs.org> 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.

cd /sys/kernel/debug/tracing
mkdir instances/myscsi
echo 'channel==0 && id==0 && lun==0' > \
  instances/myscsi/events/scsi/scsi_dispatch_cmd_done/filter
echo 1 > instance/myscsi/events/scsi/scsi_dispatch_cmd_done/enable
cat instances/myscsi/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 10/10   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
          <idle>-0     [000] d.h3  8173.344559: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=68117912 txlen=8 protect=0 raw=28 00 04 0f 65 98 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
          <idle>-0     [001] d.h3  8173.347743: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=68351144 txlen=8 protect=0 raw=28 00 04 12 f4 a8 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
          <idle>-0     [000] d.h3  8174.810108: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=61301272 txlen=8 protect=0 raw=28 00 03 a7 62 18 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
          <idle>-0     [001] d.h3  8174.822038: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=48718352 txlen=8 protect=0 raw=28 00 02 e7 62 10 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
          <idle>-0     [002] d.h3  8174.827439: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0 prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=56582672 txlen=8 protect=0 raw=28 00 03 5f 62 10 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
          <idle>-0     [003] d.h3  8174.835280: scsi_dispatch_cmd_done:
          host_no=0 channel=0 id=0 lun=0 data_sgl=1 prot_sgl=0
          prot_op=SCSI_PROT_NORMAL cmnd=(READ_10 lba=82010640 txl

Is that something you are talking about?

-- Steve



> 
> 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
> 
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [RFC][PATCH] Add a flight data recorder for scsi commands

[Jörn Engel]

On Tue, 27 August 2013 19:54:22 -0400, Steven Rostedt wrote:
> On Tue, 27 Aug 2013 18:03:25 -0400
> Jörn Engel <joern@logfs.org> 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.

"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.  

Jörn

--
If you're willing to restrict the flexibility of your approach,
you can almost always do something better.
-- John Carmack
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [RFC][PATCH] Add a flight data recorder for scsi commands

[Steven Rostedt]

On Tue, 27 Aug 2013 18:41:47 -0400
Jörn Engel <joern@logfs.org> wrote:

> On Tue, 27 August 2013 19:54:22 -0400, Steven Rostedt wrote:
> > On Tue, 27 Aug 2013 18:03:25 -0400
> > Jörn Engel <joern@logfs.org> 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.
> 
> "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.  

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.

Basically, on boot, you can make a separate buffer for each device, and
have a different filter for those events to save to each specific
buffer.


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.

You can also create your own ring buffer with ring_buffer_alloc(), and
get a lockless ring buffer as well. All of ftrace is built with lego
blocks, so the infrastructure is there even if the general utility
isn't exactly what you are looking for.

-- Steve
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [RFC][PATCH] Add a flight data recorder for scsi commands

[Jörn Engel]

On Tue, 27 August 2013 20:34:43 -0400, Steven Rostedt wrote:
> On Tue, 27 Aug 2013 18:41:47 -0400
> Jörn Engel <joern@logfs.org> wrote:
> > 
> > "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.  
> 
> Are you sure about that?

When it comes to my mental shortcomings, I am quite sure about their
existence. ;)

> 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.

That does look fairly neat and doable.  I am not sure about the
performance overhead, though.  Would this translate into one big
switch or, for large systems, hundreds of "if (some_filter)" lines.
The latter would likely be noticeable overhead.

> 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.

Hmm.  I will ponder that idea for a bit.  If we can come up with
something merge-worthy, that would be great.  If not, I will simply
carry my existing patch and not make anyone else pay the cost for it.

Jörn

--
The wise man seeks everything in himself; the ignorant man tries to get
everything from somebody else.
-- unknown
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html