2005-11-21 08:27:10

by Anders Karlsson

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

Morning,

I am getting loads of these:

Nov 21 08:10:19 lenin kernel: [17304475.764000] arq->state: 4
Nov 21 08:10:19 lenin kernel: [17304475.764000] Badness in
as_insert_request at drivers/block/as-iosched.c:1519
Nov 21 08:10:19 lenin kernel: [17304475.764000]
[as_insert_request+109/464] as_insert_request+0x6d/0x1d0
Nov 21 08:10:19 lenin kernel: [17304475.764000]
[__elv_add_request+155/224] __elv_add_request+0x9b/0xe0
Nov 21 08:10:19 lenin kernel: [17304475.764000]
[elv_add_request+43/64] elv_add_request+0x2b/0x40
Nov 21 08:10:19 lenin kernel: [17304475.764000]
[blk_execute_rq_nowait+69/96] blk_execute_rq_nowait+0x45/0x60
Nov 21 08:10:19 lenin kernel: [17304475.764000]
[blk_execute_rq+123/224] blk_execute_rq+0x7b/0xe0
Nov 21 08:10:19 lenin kernel: [17304475.764000]
[blk_end_sync_rq+0/48] blk_end_sync_rq+0x0/0x30
Nov 21 08:10:19 lenin kernel: [17304475.764000]
[bio_phys_segments+39/48] bio_phys_segments+0x27/0x30
Nov 21 08:10:19 lenin kernel: [17304475.764000]
[blk_rq_bio_prep+133/176] blk_rq_bio_prep+0x85/0xb0
Nov 21 08:10:19 lenin kernel: [17304475.764000]
[cdrom_read_cdda_bpc+403/512] cdrom_read_cdda_bpc+0x193/0x200
Nov 21 08:10:19 lenin kernel: [17304475.764000]
[cdrom_read_cdda+91/192] cdrom_read_cdda+0x5b/0xc0
Nov 21 08:10:19 lenin kernel: [17304475.764000] [mmc_ioctl+2098/2784]
mmc_ioctl+0x832/0xae0
Nov 21 08:10:19 lenin kernel: [17304475.764000]
[__wake_up_common+67/112] __wake_up_common+0x43/0x70
Nov 21 08:10:19 lenin kernel: [17304475.764000]
[scsi_cmd_ioctl+191/1328] scsi_cmd_ioctl+0xbf/0x530
Nov 21 08:10:19 lenin kernel: [17304475.764000]
[n_tty_receive_buf+225/3888] n_tty_receive_buf+0xe1/0xf30
Nov 21 08:10:19 lenin kernel: [17304475.764000]
[log_wait_commit+202/256] log_wait_commit+0xca/0x100
Nov 21 08:10:19 lenin kernel: [17304475.764000]
[fast_clear_page+10/80] fast_clear_page+0xa/0x50
Nov 21 08:10:19 lenin kernel: [17304475.764000]
[buffered_rmqueue+398/480] buffered_rmqueue+0x18e/0x1e0
Nov 21 08:10:19 lenin kernel: [17304475.764000]
[generic_ide_ioctl+60/1408] generic_ide_ioctl+0x3c/0x580
Nov 21 08:10:19 lenin kernel: [17304475.764000]
[cdrom_ioctl+230/3536] cdrom_ioctl+0xe6/0xdd0
Nov 21 08:10:20 lenin kernel: [17304475.764000] [pty_write+103/128]
pty_write+0x67/0x80
Nov 21 08:10:20 lenin kernel: [17304475.764000] [idecd_ioctl+133/160]
idecd_ioctl+0x85/0xa0
Nov 21 08:10:20 lenin kernel: [17304475.764000]
[blkdev_ioctl+304/432] blkdev_ioctl+0x130/0x1b0
Nov 21 08:10:20 lenin kernel: [17304475.764000] [block_ioctl+43/48]
block_ioctl+0x2b/0x30
Nov 21 08:10:20 lenin kernel: [17304475.764000] [do_ioctl+50/144]
do_ioctl+0x32/0x90
Nov 21 08:10:20 lenin kernel: [17304475.764000] [vfs_ioctl+96/496]
vfs_ioctl+0x60/0x1f0
Nov 21 08:10:20 lenin kernel: [17304475.764000] [sys_ioctl+136/160]
sys_ioctl+0x88/0xa0
Nov 21 08:10:20 lenin kernel: [17304475.764000]
[sysenter_past_esp+84/117] sysenter_past_esp+0x54/0x75

I flipped the drive (LG GSA4167B DVD±RW) into udma2 mode, enabled udma
and started reading from an audio disc with cdparanoia. I had to abort
the read (^C in shell where running cdparanoia) and noticed the system
became slower for a while. When checking the system logs, I spotted
these stacktraces.

System is a Asus A7V600 box, the DVD drive hangs off the primary
internal IDE bus. discs are attached to a siimage PCI card.

root@lenin:~# /usr/src/linux/scripts/ver_linux
If some fields are empty or look unusual you may have an old version.
Compare to the current minimal requirements in Documentation/Changes.

Linux lenin 2.6.14 #1 Fri Nov 18 05:27:31 GMT 2005 i686 GNU/Linux

Gnu C 4.0.2
Gnu make 3.80
binutils 2.16.1
util-linux 2.12p
mount 2.12p
module-init-tools 3.2-pre7
e2fsprogs 1.38
jfsutils 1.1.8
reiserfsprogs 3.6.19
reiser4progs 1.0.4
xfsprogs 2.6.28
pcmcia-cs 3.2.5
PPP 2.4.3
Linux C Library 2.3.5
Dynamic linker (ldd) 2.3.5
Procps 3.2.5
Net-tools 1.60
Console-tools 0.2.3
Sh-utils 5.2.1
udev 060
Modules Loaded nls_cp437 isofs nls_utf8 udf nvidia rfcomm
l2cap pktcdvd capability commoncap video thermal processor fan button
container ac battery analog hci_usb bluetooth usblp usbhid usb_storage
snd_seq_dummy snd_seq_oss snd_seq_midi snd_seq_midi_event snd_seq
snd_via82xx gameport snd_ac97_codec snd_ac97_bus snd_pcm_oss
snd_mixer_oss snd_pcm snd_timer snd_page_alloc snd_mpu401_uart
snd_rawmidi snd_seq_device snd soundcore ipt_MASQUERADE ehci_hcd
iptable_nat ip_nat ipt_REJECT ipt_multiport ipt_state ip6table_filter
ip6_tables ipv6 iptable_filter ip_tables ip_conntrack_tftp
ip_conntrack_proto_sctp ip_conntrack_pptp ip_conntrack_netbios_ns
ip_conntrack_irc ip_conntrack_ftp ip_conntrack_amanda ip_conntrack
uhci_hcd usbcore generic sk98lin via_agp agpgart tsdev it87 hwmon_vid
eeprom i2c_isa i2c_viapro i2c_core psmouse mousedev ide_generic unix

Kernel config is attached.

Is this something that is known and fixed in later kernels?


--
Anders Karlsson <[email protected]>


Attachments:
(No filename) (5.03 kB)
config-2.6.14 (48.39 kB)
Download all attachments

2005-11-21 08:35:41

by Brice Goglin

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

Anders Karlsson wrote:

>Morning,
>
>I am getting loads of these:
>
>Nov 21 08:10:19 lenin kernel: [17304475.764000] arq->state: 4
>Nov 21 08:10:19 lenin kernel: [17304475.764000] Badness in
>as_insert_request at drivers/block/as-iosched.c:1519
>Nov 21 08:10:19 lenin kernel: [17304475.764000]
>[as_insert_request+109/464] as_insert_request+0x6d/0x1d0
>Nov 21 08:10:19 lenin kernel: [17304475.764000]
>[__elv_add_request+155/224] __elv_add_request+0x9b/0xe0
>Nov 21 08:10:19 lenin kernel: [17304475.764000]
>[elv_add_request+43/64] elv_add_request+0x2b/0x40
>Nov 21 08:10:19 lenin kernel: [17304475.764000]
>[blk_execute_rq_nowait+69/96] blk_execute_rq_nowait+0x45/0x60
>Nov 21 08:10:19 lenin kernel: [17304475.764000]
>[blk_execute_rq+123/224] blk_execute_rq+0x7b/0xe0
>Nov 21 08:10:19 lenin kernel: [17304475.764000]
>[blk_end_sync_rq+0/48] blk_end_sync_rq+0x0/0x30
>Nov 21 08:10:19 lenin kernel: [17304475.764000]
>[bio_phys_segments+39/48] bio_phys_segments+0x27/0x30
>Nov 21 08:10:19 lenin kernel: [17304475.764000]
>[blk_rq_bio_prep+133/176] blk_rq_bio_prep+0x85/0xb0
>Nov 21 08:10:19 lenin kernel: [17304475.764000]
>[cdrom_read_cdda_bpc+403/512] cdrom_read_cdda_bpc+0x193/0x200
>Nov 21 08:10:19 lenin kernel: [17304475.764000]
>[cdrom_read_cdda+91/192] cdrom_read_cdda+0x5b/0xc0
>Nov 21 08:10:19 lenin kernel: [17304475.764000] [mmc_ioctl+2098/2784]
>mmc_ioctl+0x832/0xae0
>Nov 21 08:10:19 lenin kernel: [17304475.764000]
>[__wake_up_common+67/112] __wake_up_common+0x43/0x70
>Nov 21 08:10:19 lenin kernel: [17304475.764000]
>[scsi_cmd_ioctl+191/1328] scsi_cmd_ioctl+0xbf/0x530
>Nov 21 08:10:19 lenin kernel: [17304475.764000]
>[n_tty_receive_buf+225/3888] n_tty_receive_buf+0xe1/0xf30
>Nov 21 08:10:19 lenin kernel: [17304475.764000]
>[log_wait_commit+202/256] log_wait_commit+0xca/0x100
>Nov 21 08:10:19 lenin kernel: [17304475.764000]
>[fast_clear_page+10/80] fast_clear_page+0xa/0x50
>Nov 21 08:10:19 lenin kernel: [17304475.764000]
>[buffered_rmqueue+398/480] buffered_rmqueue+0x18e/0x1e0
>Nov 21 08:10:19 lenin kernel: [17304475.764000]
>[generic_ide_ioctl+60/1408] generic_ide_ioctl+0x3c/0x580
>Nov 21 08:10:19 lenin kernel: [17304475.764000]
>[cdrom_ioctl+230/3536] cdrom_ioctl+0xe6/0xdd0
>Nov 21 08:10:20 lenin kernel: [17304475.764000] [pty_write+103/128]
>pty_write+0x67/0x80
>Nov 21 08:10:20 lenin kernel: [17304475.764000] [idecd_ioctl+133/160]
>idecd_ioctl+0x85/0xa0
>Nov 21 08:10:20 lenin kernel: [17304475.764000]
>[blkdev_ioctl+304/432] blkdev_ioctl+0x130/0x1b0
>Nov 21 08:10:20 lenin kernel: [17304475.764000] [block_ioctl+43/48]
>block_ioctl+0x2b/0x30
>Nov 21 08:10:20 lenin kernel: [17304475.764000] [do_ioctl+50/144]
>do_ioctl+0x32/0x90
>Nov 21 08:10:20 lenin kernel: [17304475.764000] [vfs_ioctl+96/496]
>vfs_ioctl+0x60/0x1f0
>Nov 21 08:10:20 lenin kernel: [17304475.764000] [sys_ioctl+136/160]
>sys_ioctl+0x88/0xa0
>Nov 21 08:10:20 lenin kernel: [17304475.764000]
>[sysenter_past_esp+84/117] sysenter_past_esp+0x54/0x75
>
>I flipped the drive (LG GSA4167B DVD?RW) into udma2 mode, enabled udma
>and started reading from an audio disc with cdparanoia. I had to abort
>the read (^C in shell where running cdparanoia) and noticed the system
>became slower for a while. When checking the system logs, I spotted
>these stacktraces.
>
>

I reported a similar problem while ripping a CD with cdparanoia on
2.6.14 on a
thinkpad R52 (http://lkml.org/lkml/2005/11/10/286). But I didn't get any
answer.
I hope you will get some. Good luck :)

Brice

2005-11-21 14:54:18

by Jens Axboe

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

On Mon, Nov 21 2005, Brice Goglin wrote:
> Anders Karlsson wrote:
>
> >Morning,
> >
> >I am getting loads of these:
> >
> >Nov 21 08:10:19 lenin kernel: [17304475.764000] arq->state: 4
> >Nov 21 08:10:19 lenin kernel: [17304475.764000] Badness in
> >as_insert_request at drivers/block/as-iosched.c:1519
> >Nov 21 08:10:19 lenin kernel: [17304475.764000]
> >[as_insert_request+109/464] as_insert_request+0x6d/0x1d0
> >Nov 21 08:10:19 lenin kernel: [17304475.764000]
> >[__elv_add_request+155/224] __elv_add_request+0x9b/0xe0
> >Nov 21 08:10:19 lenin kernel: [17304475.764000]
> >[elv_add_request+43/64] elv_add_request+0x2b/0x40
> >Nov 21 08:10:19 lenin kernel: [17304475.764000]
> >[blk_execute_rq_nowait+69/96] blk_execute_rq_nowait+0x45/0x60
> >Nov 21 08:10:19 lenin kernel: [17304475.764000]
> >[blk_execute_rq+123/224] blk_execute_rq+0x7b/0xe0
> >Nov 21 08:10:19 lenin kernel: [17304475.764000]
> >[blk_end_sync_rq+0/48] blk_end_sync_rq+0x0/0x30
> >Nov 21 08:10:19 lenin kernel: [17304475.764000]
> >[bio_phys_segments+39/48] bio_phys_segments+0x27/0x30
> >Nov 21 08:10:19 lenin kernel: [17304475.764000]
> >[blk_rq_bio_prep+133/176] blk_rq_bio_prep+0x85/0xb0
> >Nov 21 08:10:19 lenin kernel: [17304475.764000]
> >[cdrom_read_cdda_bpc+403/512] cdrom_read_cdda_bpc+0x193/0x200
> >Nov 21 08:10:19 lenin kernel: [17304475.764000]
> >[cdrom_read_cdda+91/192] cdrom_read_cdda+0x5b/0xc0
> >Nov 21 08:10:19 lenin kernel: [17304475.764000] [mmc_ioctl+2098/2784]
> >mmc_ioctl+0x832/0xae0
> >Nov 21 08:10:19 lenin kernel: [17304475.764000]
> >[__wake_up_common+67/112] __wake_up_common+0x43/0x70
> >Nov 21 08:10:19 lenin kernel: [17304475.764000]
> >[scsi_cmd_ioctl+191/1328] scsi_cmd_ioctl+0xbf/0x530
> >Nov 21 08:10:19 lenin kernel: [17304475.764000]
> >[n_tty_receive_buf+225/3888] n_tty_receive_buf+0xe1/0xf30
> >Nov 21 08:10:19 lenin kernel: [17304475.764000]
> >[log_wait_commit+202/256] log_wait_commit+0xca/0x100
> >Nov 21 08:10:19 lenin kernel: [17304475.764000]
> >[fast_clear_page+10/80] fast_clear_page+0xa/0x50
> >Nov 21 08:10:19 lenin kernel: [17304475.764000]
> >[buffered_rmqueue+398/480] buffered_rmqueue+0x18e/0x1e0
> >Nov 21 08:10:19 lenin kernel: [17304475.764000]
> >[generic_ide_ioctl+60/1408] generic_ide_ioctl+0x3c/0x580
> >Nov 21 08:10:19 lenin kernel: [17304475.764000]
> >[cdrom_ioctl+230/3536] cdrom_ioctl+0xe6/0xdd0
> >Nov 21 08:10:20 lenin kernel: [17304475.764000] [pty_write+103/128]
> >pty_write+0x67/0x80
> >Nov 21 08:10:20 lenin kernel: [17304475.764000] [idecd_ioctl+133/160]
> >idecd_ioctl+0x85/0xa0
> >Nov 21 08:10:20 lenin kernel: [17304475.764000]
> >[blkdev_ioctl+304/432] blkdev_ioctl+0x130/0x1b0
> >Nov 21 08:10:20 lenin kernel: [17304475.764000] [block_ioctl+43/48]
> >block_ioctl+0x2b/0x30
> >Nov 21 08:10:20 lenin kernel: [17304475.764000] [do_ioctl+50/144]
> >do_ioctl+0x32/0x90
> >Nov 21 08:10:20 lenin kernel: [17304475.764000] [vfs_ioctl+96/496]
> >vfs_ioctl+0x60/0x1f0
> >Nov 21 08:10:20 lenin kernel: [17304475.764000] [sys_ioctl+136/160]
> >sys_ioctl+0x88/0xa0
> >Nov 21 08:10:20 lenin kernel: [17304475.764000]
> >[sysenter_past_esp+84/117] sysenter_past_esp+0x54/0x75
> >
> >I flipped the drive (LG GSA4167B DVD?RW) into udma2 mode, enabled udma
> >and started reading from an audio disc with cdparanoia. I had to abort
> >the read (^C in shell where running cdparanoia) and noticed the system
> >became slower for a while. When checking the system logs, I spotted
> >these stacktraces.
> >
> >
>
> I reported a similar problem while ripping a CD with cdparanoia on
> 2.6.14 on a
> thinkpad R52 (http://lkml.org/lkml/2005/11/10/286). But I didn't get any
> answer.
> I hope you will get some. Good luck :)

Oops, just responded to you, here is the similar report from yesterday:

http://lkml.org/lkml/2005/11/20/119

--
Jens Axboe