[2.6.14.2] Badness in as_insert_request at drivers/block/as-iosched.c:1519

[2.6.14.2] Badness in as_insert_request at drivers/block/as-iosched.c:1519

[Luca]

Hi,
while playing an audio CD with XMMS using digital audio extraction the
kernel started flooding my logs (syslog writes my kernel logs synchronously)
with the following message:

 cdrom: dropping to single frame dma
 arq->state: 4
 Badness in as_insert_request at drivers/block/as-iosched.c:1519
  [<c0104027>] dump_stack+0x17/0x20
  [<c0263b2c>] as_insert_request+0x5c/0x160
  [<c025aa0a>] __elv_add_request+0x8a/0xc0
  [<c025aa75>] elv_add_request+0x35/0x70
  [<c025dc4b>] blk_execute_rq_nowait+0x3b/0x50
  [<c025dcda>] blk_execute_rq+0x7a/0xb0
  [<c028daad>] cdrom_read_cdda_bpc+0x14d/0x1b0
  [<c028db68>] cdrom_read_cdda+0x58/0xc0
  [<c028f025>] mmc_ioctl+0x735/0x930
  [<c028e5c2>] cdrom_ioctl+0x9f2/0xca0
  [<c028aabe>] idecd_ioctl+0x5e/0x70
  [<c025ffa5>] blkdev_driver_ioctl+0x45/0x80
  [<c0260157>] blkdev_ioctl+0x177/0x180
  [<c0162a7b>] block_ioctl+0x1b/0x30
  [<c016cf74>] do_ioctl+0x74/0x90
  [<c016d109>] vfs_ioctl+0x59/0x1c0
  [<c016d2a9>] sys_ioctl+0x39/0x60
  [<c01031a5>] syscall_call+0x7/0xb

This happens both with my DVD unit and the CD/RW unit. The cause may be
a couple of skratches on the disk (my portable cd player is happy with
it though) and the drives behave fine with other audio disks. In the
dmesg there isn't any other error related to the cd (i.e. no medium
errors...)

As workaround I'm using noop scheduler for the unit...

Luca
-- 
Home: http://kronoz.cjb.net
K.R.O.N.O.S
Kinetic Replicant Optimized for Nocturnal Observation and Sabotage

Re: [2.6.14.2] Badness in as_insert_request at drivers/block/as-iosched.c:1519

[Jens Axboe]

On Sun, Nov 20 2005, Luca wrote:
> Hi,
> while playing an audio CD with XMMS using digital audio extraction the
> kernel started flooding my logs (syslog writes my kernel logs synchronously)
> with the following message:
> 
>  cdrom: dropping to single frame dma
>  arq->state: 4
>  Badness in as_insert_request at drivers/block/as-iosched.c:1519
>   [<c0104027>] dump_stack+0x17/0x20
>   [<c0263b2c>] as_insert_request+0x5c/0x160
>   [<c025aa0a>] __elv_add_request+0x8a/0xc0
>   [<c025aa75>] elv_add_request+0x35/0x70
>   [<c025dc4b>] blk_execute_rq_nowait+0x3b/0x50
>   [<c025dcda>] blk_execute_rq+0x7a/0xb0
>   [<c028daad>] cdrom_read_cdda_bpc+0x14d/0x1b0

This is actually the 'as' request state detection being a little to
anxious, I think. The cdrom layer reuses the same request several times
instead of allocating/freeing it inside the loop, and 'as' barfs if the
request state isn't 'fresh' when it first sees the request after it has
completed once.

This should work around the issue in the cdrom layer, even though it
isn't actually buggy.

> This happens both with my DVD unit and the CD/RW unit. The cause may be
> a couple of skratches on the disk (my portable cd player is happy with
> it though) and the drives behave fine with other audio disks. In the
> dmesg there isn't any other error related to the cd (i.e. no medium
> errors...)

It just so happens to trigger there, because then you drop into single
frame dma mode which will iterate the loop several times per request
(which then exposes the bug).

> As workaround I'm using noop scheduler for the unit...

That'll do fine as well, of course.

diff --git a/drivers/cdrom/cdrom.c b/drivers/cdrom/cdrom.c
index 1539603..7540d27 100644
--- a/drivers/cdrom/cdrom.c
+++ b/drivers/cdrom/cdrom.c
@@ -2089,7 +2089,7 @@ static int cdrom_read_cdda_bpc(struct cd
 			       int lba, int nframes)
 {
 	request_queue_t *q = cdi->disk->queue;
-	struct request *rq;
+	struct request *rq = NULL;
 	struct bio *bio;
 	unsigned int len;
 	int nr, ret = 0;
@@ -2097,13 +2097,13 @@ static int cdrom_read_cdda_bpc(struct cd
 	if (!q)
 		return -ENXIO;
 
-	rq = blk_get_request(q, READ, GFP_KERNEL);
-	if (!rq)
-		return -ENOMEM;
-
 	cdi->last_sense = 0;
 
 	while (nframes) {
+		rq = blk_get_request(q, READ, GFP_KERNEL);
+		if (!rq)
+			return -ENOMEM;
+
 		nr = nframes;
 		if (cdi->cdda_method == CDDA_BPC_SINGLE)
 			nr = 1;
@@ -2151,9 +2151,13 @@ static int cdrom_read_cdda_bpc(struct cd
 		nframes -= nr;
 		lba += nr;
 		ubuf += len;
+		blk_put_request(rq);
+		rq = NULL;
 	}
 
-	blk_put_request(rq);
+	if (rq)
+		blk_put_request(rq);
+
 	return ret;
 }
 

-- 
Jens Axboe

Re: [2.6.14.2] Badness in as_insert_request at drivers/block/as-iosched.c:1519

[Luca]

Il Sun, Nov 20, 2005 at 10:27:12PM +0100, Jens Axboe ha scritto: 
> On Sun, Nov 20 2005, Luca wrote:
> > Hi,
> > while playing an audio CD with XMMS using digital audio extraction the
> > kernel started flooding my logs (syslog writes my kernel logs synchronously)
> > with the following message:
> > 
> >  cdrom: dropping to single frame dma
> >  arq->state: 4
> >  Badness in as_insert_request at drivers/block/as-iosched.c:1519
> >   [<c0104027>] dump_stack+0x17/0x20
> >   [<c0263b2c>] as_insert_request+0x5c/0x160
> >   [<c025aa0a>] __elv_add_request+0x8a/0xc0
> >   [<c025aa75>] elv_add_request+0x35/0x70
> >   [<c025dc4b>] blk_execute_rq_nowait+0x3b/0x50
> >   [<c025dcda>] blk_execute_rq+0x7a/0xb0
> >   [<c028daad>] cdrom_read_cdda_bpc+0x14d/0x1b0
> 
> This is actually the 'as' request state detection being a little to
> anxious, I think. The cdrom layer reuses the same request several times
> instead of allocating/freeing it inside the loop, and 'as' barfs if the
> request state isn't 'fresh' when it first sees the request after it has
> completed once.
> 
> This should work around the issue in the cdrom layer, even though it
> isn't actually buggy.
[...]
> diff --git a/drivers/cdrom/cdrom.c b/drivers/cdrom/cdrom.c
> index 1539603..7540d27 100644
> --- a/drivers/cdrom/cdrom.c
> +++ b/drivers/cdrom/cdrom.c
[patch]

Thanks, with your patch the warning is gone.

Luca
-- 
Home: http://kronoz.cjb.net
Pare che gli uomini facciano l'amore di continuo e le donne solo
raramente. Ci dev'essere qualcuno che bara.