Question about Request Sense case in scsi_lib.c

Question about Request Sense case in scsi_lib.c

[Dave Olien]

I'm having some odd behavior with my multipath fibre channel system.
I'm running 2.6.9-rc3, and have a Qlogic 2300 dual ported controller,
routed through two brocade switches to two IBM FastT200 disk arrays.

The FastT200 are configured as JBOD. Each array has 10 disks.  Each FastT200
is dual ported, configured in "active-active" mode.  So, I have
four paths to each physical disk, 80 paths total.

Doing just simple IO (dd if=/dev/zero of=/dev/sdX bs=1M) on all 20 at once
drives gives me occasional messages of the form:

Incorrect number of segments after building list
counted 31, received 30
req nr_sec 1024, cur_nr_sec 8

this is from the code in scsi_init_io() function in scsi_lib.c

I traced this to scsi_io_completion(), to the scsi_requeue_command() at
the bottom of this code.

			if ((cmd->sense_buffer[2] & 0xf) == UNIT_ATTENTION) {
                                if (cmd->device->removable) {
                                        /* detected disc change.  set a bit
                                         * and quietly refuse further access.
                                         */
                                        cmd->device->changed = 1;
                                        cmd = scsi_end_request(cmd, 0,
                                                        this_count, 1);
                                        return;
                                } else {
                                        /*
                                        * Must have been a power glitch, or a
                                        * bus reset.  Could not have been a
                                        * media change, so we just retry the
                                        * request and see what happens.
                                        */
                                        scsi_requeue_command(q, cmd);
                                        return;
                                }
			}


My system hits this scsi_requeue_command() case a lot (maybe 1 in 1000 writes),
and of these I occasionally get the error messages in the requeue.

Can anyone explain why I might be getting the "bus reset" in my
request sense data?  I'll later look into the requeued commands that
fail, to understand what's going on there.

Thanks!
Dave Olien

Re: Question about Request Sense case in scsi_lib.c

[Tim Pepper]

On Mon, 11 Oct 2004 17:00:58 -0700, Dave Olien <dmo@osdl.org> wrote:
> I'm having some odd behavior with my multipath fibre channel system.
> I'm running 2.6.9-rc3, and have a Qlogic 2300 dual ported controller,
> routed through two brocade switches to two IBM FastT200 disk arrays.
>
> The FastT200 are configured as JBOD. Each array has 10 disks.  Each FastT200
> is dual ported, configured in "active-active" mode.

I thought on FAStT's while there are dual-active controllers, for a
given lun they weren't active-active, but rather active-passive with
either manual or automatic volume transfer.  Assuming automatic volume
transfer is on and you send IOs to both controllers simultaneously you
would ping-pong the cache, drive IO rates lower and possibly see that
manifest itself in interesting behaviour in the linux scsi stack.
With manual volume transfer you should get IO errors from the
controller which is not active or preferred for the given lun.  Maybe
somebody involved with their RDAC multipathing driver follows this
list and can comment on their intentions for the 2.6 kernel and dm
multipathing.

Re: Question about Request Sense case in scsi_lib.c

[Dave Olien]

Tim,

Thanks for the feedback.  Yes, Automatic volume transfer is on, and I
was expecting there'd be poor performance as a result.  I just
didn't expect to get IO errors.  The odd thing is that the "bus reset"
leads to the SCSI request being requeued.  But every once in a while,
the requeue fails with errors and the request is failed.  I'll look at
these cases a little more closely, try to understand why the requeues fail.

I think the dm multipathing software will soon have hooks to
support manual volume transfer in these situations.

Dave

On Tue, Oct 12, 2004 at 09:29:30AM -0700, Tim Pepper wrote:
> I thought on FAStT's while there are dual-active controllers, for a
> given lun they weren't active-active, but rather active-passive with
> either manual or automatic volume transfer.  Assuming automatic volume
> transfer is on and you send IOs to both controllers simultaneously you
> would ping-pong the cache, drive IO rates lower and possibly see that
> manifest itself in interesting behaviour in the linux scsi stack. 
> With manual volume transfer you should get IO errors from the
> controller which is not active or preferred for the given lun.  Maybe
> somebody involved with their RDAC multipathing driver follows this
> list and can comment on their intentions for the 2.6 kernel and dm
> multipathing.

Re: Question about Request Sense case in scsi_lib.c

[James Bottomley]

On Tue, 2004-10-12 at 11:59, Dave Olien wrote:
> Thanks for the feedback.  Yes, Automatic volume transfer is on, and I
> was expecting there'd be poor performance as a result.  I just
> didn't expect to get IO errors.  The odd thing is that the "bus reset"
> leads to the SCSI request being requeued.  But every once in a while,
> the requeue fails with errors and the request is failed.  I'll look at
> these cases a little more closely, try to understand why the requeues fail.

Hang on a minute ... if you're ping pong'ing the drives using AVT, those
transfers take time to achieve.  The device is probably returning UNIT
ATTENTION, NOT_READY while the transfer is in progress.  This is
probably the source of the requeue.

As for the error, I still don't understand that, but it looks like
something went wrong in setting up or tearing down the dma mapping, so
that it was incorrectly described when this happened a second time.

James

Re: Question about Request Sense case in scsi_lib.c

[Dave Olien]

James,

On Tue, Oct 12, 2004 at 12:13:13PM -0500, James Bottomley wrote:
> 
> Hang on a minute ... if you're ping pong'ing the drives using AVT, those
> transfers take time to achieve.  The device is probably returning UNIT
> ATTENTION, NOT_READY while the transfer is in progress.  This is
> probably the source of the requeue.

	OK, This probably makes sense.  I'm going to see if I can
	get a theory of operations for this device somewhere.  I'd
	like to have a better understanding of how the device
	works and how long it takes to do these transfers.

> 
> As for the error, I still don't understand that, but it looks like
> something went wrong in setting up or tearing down the dma mapping, so
> that it was incorrectly described when this happened a second time.

	I'll dump out some more information about these cases, and
	see if we can analyze what's going on.
> 
> James
> 

Thanks!
Dave

Re: Question about Request Sense case in scsi_lib.c

[Patrick Mansfield]

On Tue, Oct 12, 2004 at 10:59:43AM -0700, Dave Olien wrote:
> 
> James,
> 
> On Tue, Oct 12, 2004 at 12:13:13PM -0500, James Bottomley wrote:
> > 
> > Hang on a minute ... if you're ping pong'ing the drives using AVT, those
> > transfers take time to achieve.  The device is probably returning UNIT
> > ATTENTION, NOT_READY while the transfer is in progress.  This is
> > probably the source of the requeue.
> 
> 	OK, This probably makes sense.  I'm going to see if I can
> 	get a theory of operations for this device somewhere.  I'd
> 	like to have a better understanding of how the device
> 	works and how long it takes to do these transfers.

I ran that way (use both controllers for one LUN while in AVT mode) a long
time ago, I don't know the timing, but performance was horrid. I can't
think of any reason to run that way, other than trying to duplicate this
bug ;-)

AFAIR the "transfer" is moving cached data from one controller of the disk
array to the other, but it must have some sort of synchronization method.

But try running with the scsi command completion logging on, it should
dump the full sense data.

You can run at this log level without generating extra IO (won't log the
logging), make sure you have CONFIG_SCSI_LOGGING on, and then use:

	sysctl -w dev.scsi.logging_level=0x1200

Or just use /proc/sys/dev/scsi/logging_level ...

Set back to zero to turn off logging:

	sysctl -w dev.scsi.logging_level=0

And you should get logging for non-zero scmd->result IO completions
(scmd->result is 2 meaning check condition in the below output) like this:

Oct 12 13:00:54 elm3b79 kernel: scsi <0:0:0:0> done SUCCESS        2 scsi0 : destination target 0, lun 0
Oct 12 13:00:54 elm3b79 kernel:         command = Inquiry 01 83 00 fe 00
Oct 12 13:00:54 elm3b79 kernel: Current sda: sense key Illegal Request
Oct 12 13:00:54 elm3b79 kernel: Additional sense: Invalid field in cdb

HTH ...

-- Patrick Mansfield

Re: Question about Request Sense case in scsi_lib.c

[Dave Olien]

Patrick,

Thanks for the pointer.  I'll see what SCSI logging reveals.

Yup, I'm definately not doing this hoping to measure performance.
I'm trying to understand better how my hardware is
working, and making sure it's working correctly.

A couple weeks ago, I had IO failures because of two flakey gbic's on
my fibre channel switches.  It took some effort to track those down
and replace them.  So now, I want to understand this new behavior
before moving on.

If there's a software bug triggered by these scsi command
requeue's, it's probably worth understanding that and fixing it.

Thanks!
Dave Olien

On Tue, Oct 12, 2004 at 01:13:17PM -0700, Patrick Mansfield wrote:
> 
> I ran that way (use both controllers for one LUN while in AVT mode) a long
> time ago, I don't know the timing, but performance was horrid. I can't
> think of any reason to run that way, other than trying to duplicate this
> bug ;-)
> 
> AFAIR the "transfer" is moving cached data from one controller of the disk
> array to the other, but it must have some sort of synchronization method.
> 
> But try running with the scsi command completion logging on, it should
> dump the full sense data.
> 
> You can run at this log level without generating extra IO (won't log the
> logging), make sure you have CONFIG_SCSI_LOGGING on, and then use:
> 
> 	sysctl -w dev.scsi.logging_level=0x1200
> 
> Or just use /proc/sys/dev/scsi/logging_level ...
> 
> Set back to zero to turn off logging:
> 
> 	sysctl -w dev.scsi.logging_level=0
> 
> And you should get logging for non-zero scmd->result IO completions
> (scmd->result is 2 meaning check condition in the below output) like this:
> 
> Oct 12 13:00:54 elm3b79 kernel: scsi <0:0:0:0> done SUCCESS        2 scsi0 : destination target 0, lun 0
> Oct 12 13:00:54 elm3b79 kernel:         command = Inquiry 01 83 00 fe 00
> Oct 12 13:00:54 elm3b79 kernel: Current sda: sense key Illegal Request
> Oct 12 13:00:54 elm3b79 kernel: Additional sense: Invalid field in cdb
> 
> HTH ...
> 
> -- Patrick Mansfield

Re: Question about Request Sense case in scsi_lib.c

[Douglas Gilbert]

James Bottomley wrote:
> On Tue, 2004-10-12 at 11:59, Dave Olien wrote:
> 
>>Thanks for the feedback.  Yes, Automatic volume transfer is on, and I
>>was expecting there'd be poor performance as a result.  I just
>>didn't expect to get IO errors.  The odd thing is that the "bus reset"
>>leads to the SCSI request being requeued.  But every once in a while,
>>the requeue fails with errors and the request is failed.  I'll look at
>>these cases a little more closely, try to understand why the requeues fail.
> 
> 
> Hang on a minute ... if you're ping pong'ing the drives using AVT, those
> transfers take time to achieve.  The device is probably returning UNIT
> ATTENTION, NOT_READY while the transfer is in progress.  This is
> probably the source of the requeue.

UNIT ATTENTION and NOT READY are both sense keys so a
device can't yield both on one command. However you may be
on the right track as there is an ever increasing number of
reasons a device could issue a UNIT ATTENTION. [See SPC-3
rev 21 and I believe these ASC codes (and all their associated
ASCQ codes) occur with a sense key of UNIT ATTENTION:
0x28, 0x29, 0x2a, 0x3f, 0x5b/0x1 and 0x5d.]

Unlikely in this case but a sense key of UNIT ATTENTION
(or perhaps RECOVERED ERROR)  with an additional sense
of "Hardware impending failure, seek error rate too high"
may slip by without even a log entry.

> As for the error, I still don't understand that, but it looks like
> something went wrong in setting up or tearing down the dma mapping, so
> that it was incorrectly described when this happened a second time.

I hope to address the code in the scsi_io_completion() error/warning
processing paths with the descriptor_sense cleanup. There seems to
be a missing scsi_print_sense() call on the UNIT ATTENTION path.

Dave, does your log show a bus error (ASC/ASCQ=0x29/0x2) has occurred?

Doug Gilbert

Re: Question about Request Sense case in scsi_lib.c

[Dave Olien]

Here's what seeing out of the SCSI log:

        command = Write (10) 00 00 00 84 00 00 04 00 00
Current sdx: sense key Unit Attention
ASC=8b ASCQ= 2
P<6>scsi <2:0:2:3> done SUCCESS        2 scsi2 : destination target 2, lun 3
        command = Write (10) 00 00 00 88 00 00 04 00 00
Current sdx: sense key Unit Attention
ASC=8b ASCQ= 2
P<6>scsi <2:0:2:0> done SUCCESS        2 scsi2 : destination target 2, lun 0
        command = Write (10) 00 00 00 00 48 00 04 00 00
Current sdu: sense key Unit Attention
ASC=8b ASCQ= 2
P<3>Incorrect number of segments after building list
counted 11, received 5
req nr_sec 1024, cur_nr_sec 8


On Wed, Oct 13, 2004 at 12:10:21PM +1000, Douglas Gilbert wrote:
> UNIT ATTENTION and NOT READY are both sense keys so a
> device can't yield both on one command. However you may be
> on the right track as there is an ever increasing number of
> reasons a device could issue a UNIT ATTENTION. [See SPC-3
> rev 21 and I believe these ASC codes (and all their associated
> ASCQ codes) occur with a sense key of UNIT ATTENTION:
> 0x28, 0x29, 0x2a, 0x3f, 0x5b/0x1 and 0x5d.]
> 
> Unlikely in this case but a sense key of UNIT ATTENTION
> (or perhaps RECOVERED ERROR)  with an additional sense
> of "Hardware impending failure, seek error rate too high"
> may slip by without even a log entry.
> 
> >As for the error, I still don't understand that, but it looks like
> >something went wrong in setting up or tearing down the dma mapping, so
> >that it was incorrectly described when this happened a second time.
> 
> I hope to address the code in the scsi_io_completion() error/warning
> processing paths with the descriptor_sense cleanup. There seems to
> be a missing scsi_print_sense() call on the UNIT ATTENTION path.
> 
> Dave, does your log show a bus error (ASC/ASCQ=0x29/0x2) has occurred?
> 
> Doug Gilbert

Re: Question about Request Sense case in scsi_lib.c

['Dave Olien']

Yanling,

Your reply makes sense.  So, the controller fails SCSI commands
with this sense key while it is transferring a volume.

Are the failed commands only for the volume that is being
transferred, or will it fail any command queued to that
controller while it is doing a transfer.

Now, on to figuring out why some of these requeued commands
fail the requeue.

Thanks!
Dave

On Wed, Oct 13, 2004 at 01:15:40PM -0500, Qi, Yanling wrote:
> The check-condition (06h/8Bh/02h) is Engenio's vendor specific UA. It means
> "Quiescence Is In Progress" while transferring a volume from one controller
> to the other. When the volume transfer (cache sync and bookkeeping) is
> completed, the device server will start accept IO requests.
> 
> Yanling
> 

Re: Question about Request Sense case in scsi_lib.c

[James Bottomley]

On Wed, 2004-10-13 at 16:46, 'Dave Olien' wrote:
> Now, on to figuring out why some of these requeued commands
> fail the requeue.

Yes, I've been wondering that too ... either the second remap is wrong,
or something goes awry with the segment recount on a requeue.

In the unit attention, could you print out cmd->use_sg and
cmd->request->nr_phys_segments ... just to see what values got set up
the first time around, which might give a clue where to look for the
problem.

James

Re: Question about Request Sense case in scsi_lib.c

['Dave Olien']

Sure, I'll get on it right away.

Dave

On Wed, Oct 13, 2004 at 04:56:25PM -0500, James Bottomley wrote:
> On Wed, 2004-10-13 at 16:46, 'Dave Olien' wrote:
> > Now, on to figuring out why some of these requeued commands
> > fail the requeue.
> 
> Yes, I've been wondering that too ... either the second remap is wrong,
> or something goes awry with the segment recount on a requeue.
> 
> In the unit attention, could you print out cmd->use_sg and
> cmd->request->nr_phys_segments ... just to see what values got set up
> the first time around, which might give a clue where to look for the
> problem.
> 
> James
> 

Re: Question about Request Sense case in scsi_lib.c

[Douglas Gilbert]

Qi, Yanling wrote:
> The check-condition (06h/8Bh/02h) is Engenio's vendor specific UA. It 
> means "Quiescence Is In Progress" while transferring a volume from one 
> controller to the other. When the volume transfer (cache sync and 
> bookkeeping) is completed, the device server will start accept IO requests.
> 
> Yanling

Thanks for that information.

So in the future when we print a SK/ASC/ASCQ sequence to log
we should note:
   a) if (asc >= 0x80) then it is vendor specific
   b) if (ascq >= 0x80) then it is a vendor specific qualification
      of a standard asc value

That should alert diligent users to look at the vendor's product
manual or to contact the vendor.

Doug Gilbert

> -----Original Message-----
> From: linux-scsi-owner@vger.kernel.org
> [mailto:linux-scsi-owner@vger.kernel.org]On Behalf Of Dave Olien
> Sent: Wednesday, October 13, 2004 12:57 PM
> To: Douglas Gilbert
> Cc: James Bottomley; Tim Pepper; SCSI Mailing List
> Subject: Re: Question about Request Sense case in scsi_lib.c
> 
> 
> 
> Here's what seeing out of the SCSI log:
> 
>         command = Write (10) 00 00 00 84 00 00 04 00 00
> Current sdx: sense key Unit Attention
> ASC=8b ASCQ= 2
> P<6>scsi <2:0:2:3> done SUCCESS        2 scsi2 : destination target 2, 
> lun 3
>         command = Write (10) 00 00 00 88 00 00 04 00 00
> Current sdx: sense key Unit Attention
> ASC=8b ASCQ= 2
> P<6>scsi <2:0:2:0> done SUCCESS        2 scsi2 : destination target 2, 
> lun 0
>         command = Write (10) 00 00 00 00 48 00 04 00 00
> Current sdu: sense key Unit Attention
> ASC=8b ASCQ= 2
> P<3>Incorrect number of segments after building list
> counted 11, received 5
> req nr_sec 1024, cur_nr_sec 8
> 
> 
> On Wed, Oct 13, 2004 at 12:10:21PM +1000, Douglas Gilbert wrote:
>  > UNIT ATTENTION and NOT READY are both sense keys so a
>  > device can't yield both on one command. However you may be
>  > on the right track as there is an ever increasing number of
>  > reasons a device could issue a UNIT ATTENTION. [See SPC-3
>  > rev 21 and I believe these ASC codes (and all their associated
>  > ASCQ codes) occur with a sense key of UNIT ATTENTION:
>  > 0x28, 0x29, 0x2a, 0x3f, 0x5b/0x1 and 0x5d.]
>  >
>  > Unlikely in this case but a sense key of UNIT ATTENTION
>  > (or perhaps RECOVERED ERROR)  with an additional sense
>  > of "Hardware impending failure, seek error rate too high"
>  > may slip by without even a log entry.
>  >
>  > >As for the error, I still don't understand that, but it looks like
>  > >something went wrong in setting up or tearing down the dma mapping, so
>  > >that it was incorrectly described when this happened a second time.
>  >
>  > I hope to address the code in the scsi_io_completion() error/warning
>  > processing paths with the descriptor_sense cleanup. There seems to
>  > be a missing scsi_print_sense() call on the UNIT ATTENTION path.
>  >
>  > Dave, does your log show a bus error (ASC/ASCQ=0x29/0x2) has occurred?
>  >
>  > Doug Gilbert
> -
> 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: Question about Request Sense case in scsi_lib.c

[Lan Tran]

Don't know if this will help or hinder, but I was also getting the
same error for a multipathing block layer driver  we have been working
on:

Incorrect number of segments after building list
counted 2, received 1
req nr_sec 0, cur_nr_sec 8

And it was due to the fact that when a bio is sent down to the
mid-layer, it would come back with another bio chained to it, so when
the original bio was retried, the  number of segments that were mapped
(i.e. 2, one from each bio) did not match the value stored in
cmd->use_sg (i.e. 1).  I still haven't figured out why chained bios
from indepedent IO requests are returned from the mid-layer ... but
may be a similar issue you're seeing here?

Lan

On Thu, 14 Oct 2004 10:30:28 +1000, Douglas Gilbert <dougg@torque.net> wrote:
> Qi, Yanling wrote:
> > The check-condition (06h/8Bh/02h) is Engenio's vendor specific UA. It
> > means "Quiescence Is In Progress" while transferring a volume from one
> > controller to the other. When the volume transfer (cache sync and
> > bookkeeping) is completed, the device server will start accept IO requests.
> >
> > Yanling
> 
> Thanks for that information.
> 
> So in the future when we print a SK/ASC/ASCQ sequence to log
> we should note:
>    a) if (asc >= 0x80) then it is vendor specific
>    b) if (ascq >= 0x80) then it is a vendor specific qualification
>       of a standard asc value
> 
> That should alert diligent users to look at the vendor's product
> manual or to contact the vendor.
> 
> Doug Gilbert
> 
> 
> 
> > -----Original Message-----
> > From: linux-scsi-owner@vger.kernel.org
> > [mailto:linux-scsi-owner@vger.kernel.org]On Behalf Of Dave Olien
> > Sent: Wednesday, October 13, 2004 12:57 PM
> > To: Douglas Gilbert
> > Cc: James Bottomley; Tim Pepper; SCSI Mailing List
> > Subject: Re: Question about Request Sense case in scsi_lib.c
> >
> >
> >
> > Here's what seeing out of the SCSI log:
> >
> >         command = Write (10) 00 00 00 84 00 00 04 00 00
> > Current sdx: sense key Unit Attention
> > ASC=8b ASCQ= 2
> > P<6>scsi <2:0:2:3> done SUCCESS        2 scsi2 : destination target 2,
> > lun 3
> >         command = Write (10) 00 00 00 88 00 00 04 00 00
> > Current sdx: sense key Unit Attention
> > ASC=8b ASCQ= 2
> > P<6>scsi <2:0:2:0> done SUCCESS        2 scsi2 : destination target 2,
> > lun 0
> >         command = Write (10) 00 00 00 00 48 00 04 00 00
> > Current sdu: sense key Unit Attention
> > ASC=8b ASCQ= 2
> > P<3>Incorrect number of segments after building list
> > counted 11, received 5
> > req nr_sec 1024, cur_nr_sec 8
> >
> >
> > On Wed, Oct 13, 2004 at 12:10:21PM +1000, Douglas Gilbert wrote:
> >  > UNIT ATTENTION and NOT READY are both sense keys so a
> >  > device can't yield both on one command. However you may be
> >  > on the right track as there is an ever increasing number of
> >  > reasons a device could issue a UNIT ATTENTION. [See SPC-3
> >  > rev 21 and I believe these ASC codes (and all their associated
> >  > ASCQ codes) occur with a sense key of UNIT ATTENTION:
> >  > 0x28, 0x29, 0x2a, 0x3f, 0x5b/0x1 and 0x5d.]
> >  >
> >  > Unlikely in this case but a sense key of UNIT ATTENTION
> >  > (or perhaps RECOVERED ERROR)  with an additional sense
> >  > of "Hardware impending failure, seek error rate too high"
> >  > may slip by without even a log entry.
> >  >
> >  > >As for the error, I still don't understand that, but it looks like
> >  > >something went wrong in setting up or tearing down the dma mapping, so
> >  > >that it was incorrectly described when this happened a second time.
> >  >
> >  > I hope to address the code in the scsi_io_completion() error/warning
> >  > processing paths with the descriptor_sense cleanup. There seems to
> >  > be a missing scsi_print_sense() call on the UNIT ATTENTION path.
> >  >
> >  > Dave, does your log show a bus error (ASC/ASCQ=0x29/0x2) has occurred?
> >  >
> >  > Doug Gilbert
> > -
> > 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
> >
> 
> 
> 
> -
> 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: Question about Request Sense case in scsi_lib.c

[James Bottomley]

On Thu, 2004-10-14 at 01:49, Lan Tran wrote:
> And it was due to the fact that when a bio is sent down to the
> mid-layer, it would come back with another bio chained to it, so when
> the original bio was retried, the  number of segments that were mapped
> (i.e. 2, one from each bio) did not match the value stored in
> cmd->use_sg (i.e. 1).

This sounds a bit unlikely, since the SCSI layer never deals with bios
per se, it merely maps a request (which is a collection of bios).  What
was the evidence that this was happening?

I can see the reverse being true: the scsi request is partially complete
when requeued, so some of the bios are fully complete and somehow this
causes a miscalculation in the segments.  However, the miscalculation
has to be that we undercount the number of needed request slots, and
this looks hard to do.

>  I still haven't figured out why chained bios
> from indepedent IO requests are returned from the mid-layer ... but
> may be a similar issue you're seeing here?

It sounds similar.  The problem seems to be in requeuing somehow.  I'm
going to dig out my old requeueing simulator and see if I can reproduce
it.

James

Re: Question about Request Sense case in scsi_lib.c

['Dave Olien']

James,

Sorry this took so long.  Here's I think the information you're asking for.
Just to make sure I'm not overlooking something...  I'm doing
IO on the /dev/sda, /dev/sdb, etc. devices.  I DO have multipath
software installed, and there ARE multipath dm devices present, but since
I'm doing IO only through the lower level devices, not the dm devices,
I've been assuming that the dm device is not in play here.

However, I want to point out, I get A LOT MORE of these types of
errors when I do IO through the multipath device.  I thought it made
sense though to track down the lower level error first.

If you think it could be an issue, I can go back and deconfigure
the dm device and try this again.

In the data below, the "comp cmd" strings are being printed out in
the scsi_io_completion() routine, as part of the unit attention
sense key parsing.  The first hex value is the address of the scsi_cmnd
structure.  The rest are pretty obvious.  I decided to print good_bytes
on the chance that these IO's maybe were partial completions.

The "Incorrect number of segments" string of course is the source of our
concern.  I added the address of the scsi_cmnd to the end of this string,
to make sure it corresponds to the same command that got the sense key.

comp cmd cfa9d8a0 good_bytes 0 nr_phys_req 5 use_sg 10
Incorrect number of segments after building list cmd cfa9d8a0
counted 10, received 5
req nr_sec 1024, cur_nr_sec 8
Buffer I/O error on device sda, logical block 5489
lost page write due to I/O error on sda
Buffer I/O error on device sda, logical block 5490
lost page write due to I/O error on sda
Buffer I/O error on device sda, logical block 5491
lost page write due to I/O error on sda
Buffer I/O error on device sda, logical block 5492
lost page write due to I/O error on sda
Buffer I/O error on device sda, logical block 5493
lost page write due to I/O error on sda
Buffer I/O error on device sda, logical block 5494
lost page write due to I/O error on sda
Buffer I/O error on device sda, logical block 5495
lost page write due to I/O error on sda
Buffer I/O error on device sda, logical block 5496
lost page write due to I/O error on sda
Buffer I/O error on device sda, logical block 5497
lost page write due to I/O error on sda
Buffer I/O error on device sda, logical block 5498
lost page write due to I/O error on sda
comp cmd cfa9d480 good_bytes 0 nr_phys_req 10 use_sg 12
Incorrect number of segments after building list cmd cfa9d480
counted 12, received 10
req nr_sec 1024, cur_nr_sec 8
comp cmd cfa9d8a0 good_bytes 0 nr_phys_req 80 use_sg 80
comp cmd cfa9da00 good_bytes 0 nr_phys_req 107 use_sg 107
comp cmd cfa9d060 good_bytes 0 nr_phys_req 105 use_sg 105
comp cmd c6181e80 good_bytes 0 nr_phys_req 114 use_sg 114
comp cmd cfda4b40 good_bytes 0 nr_phys_req 112 use_sg 112
comp cmd cfda45c0 good_bytes 0 nr_phys_req 108 use_sg 108
comp cmd cfda49e0 good_bytes 0 nr_phys_req 106 use_sg 106
comp cmd cfda4880 good_bytes 0 nr_phys_req 114 use_sg 114
comp cmd cfda4460 good_bytes 0 nr_phys_req 112 use_sg 112
comp cmd cfa9d5e0 good_bytes 0 nr_phys_req 116 use_sg 116
comp cmd cfa9db60 good_bytes 0 nr_phys_req 114 use_sg 114
comp cmd cfda4040 good_bytes 0 nr_phys_req 93 use_sg 93
comp cmd cfa9d1c0 good_bytes 0 nr_phys_req 97 use_sg 97
comp cmd cfa9dcc0 good_bytes 0 nr_phys_req 18 use_sg 22
Incorrect number of segments after building list cmd cfa9dcc0
counted 22, received 18
req nr_sec 1024, cur_nr_sec 8
comp cmd cfda4300 good_bytes 0 nr_phys_req 68 use_sg 69
Incorrect number of segments after building list cmd cfda4300
counted 69, received 68
req nr_sec 1024, cur_nr_sec 8
comp cmd cfa9d320 good_bytes 0 nr_phys_req 80 use_sg 80
comp cmd cfa9d8a0 good_bytes 0 nr_phys_req 80 use_sg 80
comp cmd cfa9da00 good_bytes 0 nr_phys_req 107 use_sg 107
comp cmd cfa9d060 good_bytes 0 nr_phys_req 105 use_sg 105
comp cmd c6181e80 good_bytes 0 nr_phys_req 114 use_sg 114
comp cmd cfda4b40 good_bytes 0 nr_phys_req 112 use_sg 112
comp cmd cfda45c0 good_bytes 0 nr_phys_req 108 use_sg 108
comp cmd cfda49e0 good_bytes 0 nr_phys_req 106 use_sg 106
comp cmd cfda4880 good_bytes 0 nr_phys_req 114 use_sg 114
comp cmd cfda4460 good_bytes 0 nr_phys_req 112 use_sg 112
comp cmd cfa9d5e0 good_bytes 0 nr_phys_req 116 use_sg 116
comp cmd cfa9db60 good_bytes 0 nr_phys_req 114 use_sg 114
comp cmd cfda4040 good_bytes 0 nr_phys_req 93 use_sg 93
comp cmd cfa9d1c0 good_bytes 0 nr_phys_req 97 use_sg 97
comp cmd cfa9d480 good_bytes 0 nr_phys_req 105 use_sg 105
comp cmd cdfbc300 good_bytes 0 nr_phys_req 19 use_sg 20
Incorrect number of segments after building list cmd cdfbc300
counted 20, received 19
req nr_sec 1024, cur_nr_sec 8


and so on... I have more if you like...

On Wed, Oct 13, 2004 at 04:56:25PM -0500, James Bottomley wrote:
> In the unit attention, could you print out cmd->use_sg and
> cmd->request->nr_phys_segments ... just to see what values got set up
> the first time around, which might give a clue where to look for the
> problem.
> 
> James
> 
> 
> -
> 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: Question about Request Sense case in scsi_lib.c

[James Bottomley]

On Thu, 2004-10-14 at 12:52, 'Dave Olien' wrote:
> comp cmd cfa9d8a0 good_bytes 0 nr_phys_req 5 use_sg 10
> Incorrect number of segments after building list cmd cfa9d8a0
> counted 10, received 5
> req nr_sec 1024, cur_nr_sec 8
> Buffer I/O error on device sda, logical block 5489

Well, I managed to create a test rig that randomly rejects commands with
UNIT ATTENTION (and QUEUE FULL just for good measure).  So far I've seen
this condition once so it looks like you have the better ability to
reproduce.

What happens is that nr_phys_segments is being reduced *after* the
sgtable is allocated the first time (otherwise there would be an
Incorrect segments message for its initial mapping).  Why this is
happening, I still can't fathom.

James

Re: Question about Request Sense case in scsi_lib.c

[James Bottomley]

OK, I caught it with actual data this time

If you analyse my trace you see that blk_rq_map_sg() is insisting on a
phys segment size of no more than 65536 bytes (which gives it 11
segments since some are bigger than this).  However, an exact count of
the number of phys segments without this boundary would yield 5, which
is exactly the figure we get.

I theorise that the initial request had nr_phys_segments pretty high, so
it mapped OK.  Then later we trigger a recount somehow using
blk_recalc_rq_segments() which drops it to 5

Therefore it seems to me that the problem occurs because
blk_recalc_rq_segment size is failing to respect the queueu
max_segment_size (which is set to 65536 by default).

James

REQUEUE: doing a reinsertion of request c37dc270, use_sg=11, nr_phys_segments=5, nr_hw_segments=128

 FOUND FAILING CASE
after recalc_rq_segments nr_phys_segments=5, nr_hw_segments=128

SG SEGMENTS FROM cmd ARE:
0: 0x008e7000-0x008f7000 [65536]
1: 0x008f7000-0x00903000 [49152]
2: 0x00904000-0x00914000 [65536]
3: 0x00914000-0x00919000 [20480]
4: 0x0091a000-0x0091e000 [16384]
5: 0x0091f000-0x0092f000 [65536]
6: 0x0092f000-0x0093f000 [65536]
7: 0x0093f000-0x0094f000 [65536]
8: 0x0094f000-0x00958000 [36864]
9: 0x00959000-0x00969000 [65536]
10: 0x00969000-0x0096b000 [8192]

bio0, seg0: 0x008e7000-0x008e8000 [4096]
bio1, seg0: 0x008e8000-0x008e9000 [4096]
bio2, seg0: 0x008e9000-0x008ea000 [4096]
bio3, seg0: 0x008ea000-0x008eb000 [4096]
bio4, seg0: 0x008eb000-0x008ec000 [4096]
bio5, seg0: 0x008ec000-0x008ed000 [4096]
bio6, seg0: 0x008ed000-0x008ee000 [4096]
bio7, seg0: 0x008ee000-0x008ef000 [4096]
bio8, seg0: 0x008ef000-0x008f0000 [4096]
bio9, seg0: 0x008f0000-0x008f1000 [4096]
bio10, seg0: 0x008f1000-0x008f2000 [4096]
bio11, seg0: 0x008f2000-0x008f3000 [4096]
bio12, seg0: 0x008f3000-0x008f4000 [4096]
bio13, seg0: 0x008f4000-0x008f5000 [4096]
bio14, seg0: 0x008f5000-0x008f6000 [4096]
bio15, seg0: 0x008f6000-0x008f7000 [4096]
bio16, seg0: 0x008f7000-0x008f8000 [4096]
bio17, seg0: 0x008f8000-0x008f9000 [4096]
bio18, seg0: 0x008f9000-0x008fa000 [4096]
bio19, seg0: 0x008fa000-0x008fb000 [4096]
bio20, seg0: 0x008fb000-0x008fc000 [4096]
bio21, seg0: 0x008fc000-0x008fd000 [4096]
bio22, seg0: 0x008fd000-0x008fe000 [4096]
bio23, seg0: 0x008fe000-0x008ff000 [4096]
bio24, seg0: 0x008ff000-0x00900000 [4096]
bio25, seg0: 0x00900000-0x00901000 [4096]
bio26, seg0: 0x00901000-0x00902000 [4096]
bio27, seg0: 0x00902000-0x00903000 [4096]
bio28, seg0: 0x00904000-0x00905000 [4096]
bio29, seg0: 0x00905000-0x00906000 [4096]
bio30, seg0: 0x00906000-0x00907000 [4096]
bio31, seg0: 0x00907000-0x00908000 [4096]
bio32, seg0: 0x00908000-0x00909000 [4096]
bio33, seg0: 0x00909000-0x0090a000 [4096]
bio34, seg0: 0x0090a000-0x0090b000 [4096]
bio35, seg0: 0x0090b000-0x0090c000 [4096]
bio36, seg0: 0x0090c000-0x0090d000 [4096]
bio37, seg0: 0x0090d000-0x0090e000 [4096]
bio38, seg0: 0x0090e000-0x0090f000 [4096]
bio39, seg0: 0x0090f000-0x00910000 [4096]
bio40, seg0: 0x00910000-0x00911000 [4096]
bio41, seg0: 0x00911000-0x00912000 [4096]
bio42, seg0: 0x00912000-0x00913000 [4096]
bio43, seg0: 0x00913000-0x00914000 [4096]
bio44, seg0: 0x00914000-0x00915000 [4096]
bio45, seg0: 0x00915000-0x00916000 [4096]
bio46, seg0: 0x00916000-0x00917000 [4096]
bio47, seg0: 0x00917000-0x00918000 [4096]
bio48, seg0: 0x00918000-0x00919000 [4096]
bio49, seg0: 0x0091a000-0x0091b000 [4096]
bio50, seg0: 0x0091b000-0x0091c000 [4096]
bio51, seg0: 0x0091c000-0x0091d000 [4096]
bio52, seg0: 0x0091d000-0x0091e000 [4096]
bio53, seg0: 0x0091f000-0x00920000 [4096]
bio54, seg0: 0x00920000-0x00921000 [4096]
bio55, seg0: 0x00921000-0x00922000 [4096]
bio56, seg0: 0x00922000-0x00923000 [4096]
bio57, seg0: 0x00923000-0x00924000 [4096]
bio58, seg0: 0x00924000-0x00925000 [4096]
bio59, seg0: 0x00925000-0x00926000 [4096]
bio60, seg0: 0x00926000-0x00927000 [4096]
bio61, seg0: 0x00927000-0x00928000 [4096]
bio62, seg0: 0x00928000-0x00929000 [4096]
bio63, seg0: 0x00929000-0x0092a000 [4096]
bio64, seg0: 0x0092a000-0x0092b000 [4096]
bio65, seg0: 0x0092b000-0x0092c000 [4096]
bio66, seg0: 0x0092c000-0x0092d000 [4096]
bio67, seg0: 0x0092d000-0x0092e000 [4096]
bio68, seg0: 0x0092e000-0x0092f000 [4096]
bio69, seg0: 0x0092f000-0x00930000 [4096]
bio70, seg0: 0x00930000-0x00931000 [4096]
bio71, seg0: 0x00931000-0x00932000 [4096]
bio72, seg0: 0x00932000-0x00933000 [4096]
bio73, seg0: 0x00933000-0x00934000 [4096]
bio74, seg0: 0x00934000-0x00935000 [4096]
bio75, seg0: 0x00935000-0x00936000 [4096]
bio76, seg0: 0x00936000-0x00937000 [4096]
bio77, seg0: 0x00937000-0x00938000 [4096]
bio78, seg0: 0x00938000-0x00939000 [4096]
bio79, seg0: 0x00939000-0x0093a000 [4096]
bio80, seg0: 0x0093a000-0x0093b000 [4096]
bio81, seg0: 0x0093b000-0x0093c000 [4096]
bio82, seg0: 0x0093c000-0x0093d000 [4096]
bio83, seg0: 0x0093d000-0x0093e000 [4096]
bio84, seg0: 0x0093e000-0x0093f000 [4096]
bio85, seg0: 0x0093f000-0x00940000 [4096]
bio86, seg0: 0x00940000-0x00941000 [4096]
bio87, seg0: 0x00941000-0x00942000 [4096]
bio88, seg0: 0x00942000-0x00943000 [4096]
bio89, seg0: 0x00943000-0x00944000 [4096]
bio90, seg0: 0x00944000-0x00945000 [4096]
bio91, seg0: 0x00945000-0x00946000 [4096]
bio92, seg0: 0x00946000-0x00947000 [4096]
bio93, seg0: 0x00947000-0x00948000 [4096]
bio94, seg0: 0x00948000-0x00949000 [4096]
bio95, seg0: 0x00949000-0x0094a000 [4096]
bio96, seg0: 0x0094a000-0x0094b000 [4096]
bio97, seg0: 0x0094b000-0x0094c000 [4096]
bio98, seg0: 0x0094c000-0x0094d000 [4096]
bio99, seg0: 0x0094d000-0x0094e000 [4096]
bio100, seg0: 0x0094e000-0x0094f000 [4096]
bio101, seg0: 0x0094f000-0x00950000 [4096]
bio102, seg0: 0x00950000-0x00951000 [4096]
bio103, seg0: 0x00951000-0x00952000 [4096]
bio104, seg0: 0x00952000-0x00953000 [4096]
bio105, seg0: 0x00953000-0x00954000 [4096]
bio106, seg0: 0x00954000-0x00955000 [4096]
bio107, seg0: 0x00955000-0x00956000 [4096]
bio108, seg0: 0x00956000-0x00957000 [4096]
bio109, seg0: 0x00957000-0x00958000 [4096]
bio110, seg0: 0x00959000-0x0095a000 [4096]
bio111, seg0: 0x0095a000-0x0095b000 [4096]
bio112, seg0: 0x0095b000-0x0095c000 [4096]
bio113, seg0: 0x0095c000-0x0095d000 [4096]
bio114, seg0: 0x0095d000-0x0095e000 [4096]
bio115, seg0: 0x0095e000-0x0095f000 [4096]
bio116, seg0: 0x0095f000-0x00960000 [4096]
bio117, seg0: 0x00960000-0x00961000 [4096]
bio118, seg0: 0x00961000-0x00962000 [4096]
bio119, seg0: 0x00962000-0x00963000 [4096]
bio120, seg0: 0x00963000-0x00964000 [4096]
bio121, seg0: 0x00964000-0x00965000 [4096]
bio122, seg0: 0x00965000-0x00966000 [4096]
bio123, seg0: 0x00966000-0x00967000 [4096]
bio124, seg0: 0x00967000-0x00968000 [4096]
bio125, seg0: 0x00968000-0x00969000 [4096]
bio126, seg0: 0x00969000-0x0096a000 [4096]
bio127, seg0: 0x0096a000-0x0096b000 [4096]
Incorrect number of segments after building list
counted 11, received 5
req nr_sec 1024, cur_nr_sec 8
nr_hw_segments = 128
segments now 5
slab error in cache_free_debugcheck(): cache `sgpool-8': double free, or memory outside object was overwritten