Badness in as_completed_request in 2.6.0-test5-bk3

Badness in as_completed_request in 2.6.0-test5-bk3

[Ludovico Gardenghi]

[I'm very sorry if this message appears 2 or 3 times, but I sent it once
with a @despammed.com address; their DNS appears to be down in this
period so vger.kernel.org didn't accept my mail.]

Hello.

I've read about this error and that it should have been patched in
2.6.0-test5-bk3.

I tried it because I got a lot of them with 2.6.0-test5 while removing
lots of files (i.e. while starting sn at boot time), but I got the same error
messages with 2.6.0-test5-bk3; moreover, i had also some "attempt to
access beyond end of device" errors while trying to read a file from the
same partition. Here are the messages:

Badness in as_completed_request at drivers/block/as-iosched.c:906
Call Trace:
 [as_completed_request+413/416] as_completed_request+0x19d/0x1a0
 [elv_completed_request+31/48] elv_completed_request+0x1f/0x30
 [__blk_put_request+60/192] __blk_put_request+0x3c/0xc0
 [end_that_request_last+82/160] end_that_request_last+0x52/0xa0
 [ide_end_request+219/336] ide_end_request+0xdb/0x150
 [ide_dmaq_complete+85/208] ide_dmaq_complete+0x55/0xd0
 [ide_dmaq_intr+59/144] ide_dmaq_intr+0x3b/0x90
 [ide_intr+234/400] ide_intr+0xea/0x190
 [ide_dmaq_intr+0/144] ide_dmaq_intr+0x0/0x90
 [handle_IRQ_event+58/112] handle_IRQ_event+0x3a/0x70
 [do_IRQ+145/304] do_IRQ+0x91/0x130
 [rest_init+0/96] _stext+0x0/0x60
 [common_interrupt+24/32] common_interrupt+0x18/0x20
 [rest_init+0/96] _stext+0x0/0x60
 [default_idle+35/48] default_idle+0x23/0x30
 [cpu_idle+44/64] cpu_idle+0x2c/0x40
 [start_kernel+337/352] start_kernel+0x151/0x160
 [unknown_bootoption+0/256] unknown_bootoption+0x0/0x100

Badness in as_completed_request at drivers/block/as-iosched.c:906
Call Trace:
 [as_completed_request+413/416] as_completed_request+0x19d/0x1a0
 [elv_completed_request+31/48] elv_completed_request+0x1f/0x30
 [__blk_put_request+60/192] __blk_put_request+0x3c/0xc0
 [end_that_request_last+82/160] end_that_request_last+0x52/0xa0
 [ide_end_request+219/336] ide_end_request+0xdb/0x150
 [ide_dmaq_complete+85/208] ide_dmaq_complete+0x55/0xd0
 [ide_dmaq_intr+59/144] ide_dmaq_intr+0x3b/0x90
 [ide_intr+234/400] ide_intr+0xea/0x190
 [ide_dmaq_intr+0/144] ide_dmaq_intr+0x0/0x90
 [handle_IRQ_event+58/112] handle_IRQ_event+0x3a/0x70
 [do_IRQ+145/304] do_IRQ+0x91/0x130
 [common_interrupt+24/32] common_interrupt+0x18/0x20
 [journal_add_journal_head+228/256] journal_add_journal_head+0xe4/0x100
 [journal_get_undo_access+21/320] journal_get_undo_access+0x15/0x140
 [ext3_free_blocks+432/1264] ext3_free_blocks+0x1b0/0x4f0
 [ext3_free_data+152/336] ext3_free_data+0x98/0x150
 [ext3_truncate+1444/1536] ext3_truncate+0x5a4/0x600
 [ext3_mark_iloc_dirty+40/64] ext3_mark_iloc_dirty+0x28/0x40
 [journal_start+169/208] journal_start+0xa9/0xd0
 [__ext3_journal_stop+36/80] __ext3_journal_stop+0x24/0x50
 [start_transaction+35/96] start_transaction+0x23/0x60
 [ext3_delete_inode+198/272] ext3_delete_inode+0xc6/0x110
 [ext3_put_inode+19/48] ext3_put_inode+0x13/0x30
 [ext3_delete_inode+0/272] ext3_delete_inode+0x0/0x110
 [generic_delete_inode+106/272] generic_delete_inode+0x6a/0x110
 [ext3_put_inode+19/48] ext3_put_inode+0x13/0x30
 [iput+98/128] iput+0x62/0x80
 [sys_unlink+272/320] sys_unlink+0x110/0x140
 [syscall_call+7/11] syscall_call+0x7/0xb


And:

attempt to access beyond end of device
hda7: rw=0, want=3699666016, limit=9992367
attempt to access beyond end of device
hda7: rw=0, want=1817182208, limit=9992367
attempt to access beyond end of device
hda7: rw=0, want=4294958280, limit=9992367
attempt to access beyond end of device
hda7: rw=0, want=1487072352, limit=9992367
attempt to access beyond end of device
hda7: rw=0, want=1242071648, limit=9992367
attempt to access beyond end of device
hda7: rw=0, want=4294960784, limit=9992367
attempt to access beyond end of device
hda7: rw=0, want=3706055712, limit=9992367
[...]

My mainboard has a VIA controller (Asus A7V8X) and the hard disk is a IBM
180GXP with Tagged Command Queueing enabled and a default queue length
of 8. I haven't tried disabling TCQ, but it seemed to work up to
2.6.0-test4 (although with 2.6.0-test4 I experienced some data
"swapping" between files while accessing lots of them concurrently).

Ludovico
-- 
<dunadan@libero.it>              garden (irc.freenode.net) ICQ: 64483080
GPG ID: 07F89BB8              Jabber: garden@jabber.students.cs.unibo.it
-- This is signature nr. 1226

Re: Badness in as_completed_request in 2.6.0-test5-bk3

[Nick Piggin]

Ludovico Gardenghi wrote:

>[I'm very sorry if this message appears 2 or 3 times, but I sent it once
>with a @despammed.com address; their DNS appears to be down in this
>period so vger.kernel.org didn't accept my mail.]
>
>Hello.
>
>I've read about this error and that it should have been patched in
>2.6.0-test5-bk3.
>
>I tried it because I got a lot of them with 2.6.0-test5 while removing
>lots of files (i.e. while starting sn at boot time), but I got the same error
>messages with 2.6.0-test5-bk3; moreover, i had also some "attempt to
>access beyond end of device" errors while trying to read a file from the
>same partition. Here are the messages:
>

Hi Ludovico,

Thanks for the report. The AS messages should be harmless. The warn
statement is an incorrect assertion (I'm actually surprised the only
reports of it are IDE TCQ). It should not be the cause of the attempt
to access beyond the end of device messages.

I think IDE TCQ is not 100% stable at the moment (Jens?) and you have
to do things like ensure only one drive on the cable (not a master and
slave). Your best option is to turn TCQ off. You could try booting with
the argument elevator=deadline, however. That would fix it if it were
an AS problem.

Re: Badness in as_completed_request in 2.6.0-test5-bk3

[Rene Rask]

I'm not subscribed to the list so please cc me if you have questions.

>Try disabling TCQ, I don't think it is very stable for IDE drives.

I'm getting these messages with a 3ware 7500-12 card as well even though
it is a scsi card.
I'm using kernel 2.6-test5-bk6 and copying files files an nfs mount to
the local 3ware disks ( 6 200 GB disks in hardware RAID5).

Dmesg output:

Badness in as_completed_request at drivers/block/as-iosched.c:906
Call Trace:
 [<c020b460>] as_completed_request+0x190/0x1a0
 [<c020382f>] elv_completed_request+0x1f/0x30
 [<c0205c7c>] __blk_put_request+0x3c/0xc0
 [<c0206cc9>] end_that_request_last+0x59/0xf0
 [<f88519ed>] scsi_end_request+0xbd/0xf0 [scsi_mod]
 [<f8851d5c>] scsi_io_completion+0x18c/0x520 [scsi_mod]
 [<f882dbc7>] sd_rw_intr+0x87/0x300 [sd_mod]
 [<f884cbb4>] scsi_finish_command+0x84/0xe0 [scsi_mod]
 [<c010d508>] do_IRQ+0xc8/0x150
 [<f884c9af>] scsi_softirq+0xef/0x230 [scsi_mod]
 [<c010b73c>] common_interrupt+0x18/0x20
 [<c0125b93>] do_softirq+0xd3/0xe0
 [<f8a8cf27>] xprt_prepare_transmit+0x77/0xe0 [sunrpc]
 [<f8a8adca>] call_transmit+0x2a/0xb0 [sunrpc]
 [<f8a8ed27>] __rpc_execute+0x217/0x310 [sunrpc]
 [<c011fbd0>] autoremove_wake_function+0x0/0x50
 [<f8ab7ed2>] nfs_pagein_one+0xa2/0xf0 [nfs]
 [<f8ab7f6e>] nfs_pagein_list+0x4e/0x80 [nfs]
 [<f8ab8468>] nfs_readpages+0x98/0xa0 [nfs]
 [<f8ab8300>] readpage_async_filler+0x0/0xd0 [nfs]
 [<c01439a8>] read_pages+0x178/0x190
 [<c0141909>] __alloc_pages+0x99/0x330
 [<c02517b4>] kfree_skbmem+0x24/0x30
 [<c0143c80>] do_page_cache_readahead+0xf0/0x150
 [<c0143e25>] page_cache_readahead+0x145/0x180
 [<c013d88c>] do_generic_mapping_read+0xdc/0x500
 [<c013dcb0>] file_read_actor+0x0/0xf0
 [<c013df92>] __generic_file_aio_read+0x1f2/0x230
 [<c013dcb0>] file_read_actor+0x0/0xf0
 [<c013e02a>] generic_file_aio_read+0x5a/0x80
 [<f8ab0cc1>] nfs_file_read+0x91/0xe0 [nfs]
 [<c015d28b>] do_sync_read+0x8b/0xc0
 [<c01b5789>] inode_has_perm+0x69/0xa0
 [<c01b7b01>] selinux_file_permission+0x141/0x180
 [<c015d3a0>] vfs_read+0xe0/0x150
 [<c010b73c>] common_interrupt+0x18/0x20
 [<c015d662>] sys_read+0x42/0x70
 [<c010ad7d>] sysenter_past_esp+0x52/0x71
 
Badness in as_completed_request at drivers/block/as-iosched.c:906
Call Trace:
 [<c020b460>] as_completed_request+0x190/0x1a0
 [<c020382f>] elv_completed_request+0x1f/0x30
 [<c0205c7c>] __blk_put_request+0x3c/0xc0
 [<c0206cc9>] end_that_request_last+0x59/0xf0
 [<f88519ed>] scsi_end_request+0xbd/0xf0 [scsi_mod]
 [<f8851d5c>] scsi_io_completion+0x18c/0x520 [scsi_mod]
 [<f882dbc7>] sd_rw_intr+0x87/0x300 [sd_mod]
 [<f884f39a>] scsi_delete_timer+0x1a/0x70 [scsi_mod]
 [<f884cbb4>] scsi_finish_command+0x84/0xe0 [scsi_mod]
 [<f884c9af>] scsi_softirq+0xef/0x230 [scsi_mod]
 [<c0125b93>] do_softirq+0xd3/0xe0
 [<c010d547>] do_IRQ+0x107/0x150
 [<c0108930>] default_idle+0x0/0x40
 [<c010b73c>] common_interrupt+0x18/0x20
 [<c0108930>] default_idle+0x0/0x40
 [<c010895a>] default_idle+0x2a/0x40
 [<c01089e7>] cpu_idle+0x37/0x40
 [<c0105000>] rest_init+0x0/0x50
 [<c03848d7>] start_kernel+0x197/0x1d0
 [<c0384450>] unknown_bootoption+0x0/0x100

This is just the first 2 after a reboot. The logs are filled with these
now.

Cheers
Rene < rene AT grain dk >

Re: Badness in as_completed_request in 2.6.0-test5-bk3

[Nick Piggin]

Rene Rask wrote:

>I'm not subscribed to the list so please cc me if you have questions.
>
>
>>Try disabling TCQ, I don't think it is very stable for IDE drives.
>>
>
>I'm getting these messages with a 3ware 7500-12 card as well even though
>it is a scsi card.
>I'm using kernel 2.6-test5-bk6 and copying files files an nfs mount to
>the local 3ware disks ( 6 200 GB disks in hardware RAID5).
>

No hangs though?

Re: Badness in as_completed_request in 2.6.0-test5-bk3

[Rene Rask]

On Sun, 2003-09-21 at 03:35, Nick Piggin wrote:
> Rene Rask wrote:
> 
> >I'm not subscribed to the list so please cc me if you have questions.
> >
> >
> >>Try disabling TCQ, I don't think it is very stable for IDE drives.
> >>
> >
> >I'm getting these messages with a 3ware 7500-12 card as well even though
> >it is a scsi card.
> >I'm using kernel 2.6-test5-bk6 and copying files files an nfs mount to
> >the local 3ware disks ( 6 200 GB disks in hardware RAID5).
> >
> 
> No hangs though?
> 

No permanent hangs. If I "cat 4GB_file > /dev/null" I can't seem to stop
that process fast. If I kill it and wait a long time it will eventually
die.

I have copied 700 GB from another server with no other problems than
those log messages. 

Re: Badness in as_completed_request in 2.6.0-test5-bk3

[Ludovico Gardenghi]

In article <wpjF.63v.17@gated-at.bofh.it> you wrote:

> Try disabling TCQ, I don't think it is very stable for IDE drives.

I tried, and now everything seems fine (both Badness and end-of-disk).

I'll try and see if that strange file corruption still happens or if
it was linked to the TCQ support.

Thanks.

Ludovico
-- 
<dunadan@libero.it>              garden (irc.freenode.net) ICQ: 64483080
GPG ID: 07F89BB8              Jabber: garden@jabber.students.cs.unibo.it
-- This is signature nr. 1230

Badness in as_completed_request in 2.6.0-test5-bk3

[Ludovico Gardenghi]

[I hope this message doesn't appear 2 times]

Hello.

I've read about this error and that it should have been patched in
2.6.0-test5-bk3.

I tried it because I got a lot of them with 2.6.0-test5 while removing
lots of files (i.e. while starting sn at boot time), but I got the same error
messages with 2.6.0-test5-bk3; moreover, i had also some "attempt to
access beyond end of device" errors while trying to read a file from the
same partition. Here are the messages:

Badness in as_completed_request at drivers/block/as-iosched.c:906
Call Trace:
 [as_completed_request+413/416] as_completed_request+0x19d/0x1a0
 [elv_completed_request+31/48] elv_completed_request+0x1f/0x30
 [__blk_put_request+60/192] __blk_put_request+0x3c/0xc0
 [end_that_request_last+82/160] end_that_request_last+0x52/0xa0
 [ide_end_request+219/336] ide_end_request+0xdb/0x150
 [ide_dmaq_complete+85/208] ide_dmaq_complete+0x55/0xd0
 [ide_dmaq_intr+59/144] ide_dmaq_intr+0x3b/0x90
 [ide_intr+234/400] ide_intr+0xea/0x190
 [ide_dmaq_intr+0/144] ide_dmaq_intr+0x0/0x90
 [handle_IRQ_event+58/112] handle_IRQ_event+0x3a/0x70
 [do_IRQ+145/304] do_IRQ+0x91/0x130
 [rest_init+0/96] _stext+0x0/0x60
 [common_interrupt+24/32] common_interrupt+0x18/0x20
 [rest_init+0/96] _stext+0x0/0x60
 [default_idle+35/48] default_idle+0x23/0x30
 [cpu_idle+44/64] cpu_idle+0x2c/0x40
 [start_kernel+337/352] start_kernel+0x151/0x160
 [unknown_bootoption+0/256] unknown_bootoption+0x0/0x100

Badness in as_completed_request at drivers/block/as-iosched.c:906
Call Trace:
 [as_completed_request+413/416] as_completed_request+0x19d/0x1a0
 [elv_completed_request+31/48] elv_completed_request+0x1f/0x30
 [__blk_put_request+60/192] __blk_put_request+0x3c/0xc0
 [end_that_request_last+82/160] end_that_request_last+0x52/0xa0
 [ide_end_request+219/336] ide_end_request+0xdb/0x150
 [ide_dmaq_complete+85/208] ide_dmaq_complete+0x55/0xd0
 [ide_dmaq_intr+59/144] ide_dmaq_intr+0x3b/0x90
 [ide_intr+234/400] ide_intr+0xea/0x190
 [ide_dmaq_intr+0/144] ide_dmaq_intr+0x0/0x90
 [handle_IRQ_event+58/112] handle_IRQ_event+0x3a/0x70
 [do_IRQ+145/304] do_IRQ+0x91/0x130
 [common_interrupt+24/32] common_interrupt+0x18/0x20
 [journal_add_journal_head+228/256] journal_add_journal_head+0xe4/0x100
 [journal_get_undo_access+21/320] journal_get_undo_access+0x15/0x140
 [ext3_free_blocks+432/1264] ext3_free_blocks+0x1b0/0x4f0
 [ext3_free_data+152/336] ext3_free_data+0x98/0x150
 [ext3_truncate+1444/1536] ext3_truncate+0x5a4/0x600
 [ext3_mark_iloc_dirty+40/64] ext3_mark_iloc_dirty+0x28/0x40
 [journal_start+169/208] journal_start+0xa9/0xd0
 [__ext3_journal_stop+36/80] __ext3_journal_stop+0x24/0x50
 [start_transaction+35/96] start_transaction+0x23/0x60
 [ext3_delete_inode+198/272] ext3_delete_inode+0xc6/0x110
 [ext3_put_inode+19/48] ext3_put_inode+0x13/0x30
 [ext3_delete_inode+0/272] ext3_delete_inode+0x0/0x110
 [generic_delete_inode+106/272] generic_delete_inode+0x6a/0x110
 [ext3_put_inode+19/48] ext3_put_inode+0x13/0x30
 [iput+98/128] iput+0x62/0x80
 [sys_unlink+272/320] sys_unlink+0x110/0x140
 [syscall_call+7/11] syscall_call+0x7/0xb


And:

attempt to access beyond end of device
hda7: rw=0, want=3699666016, limit=9992367
attempt to access beyond end of device
hda7: rw=0, want=1817182208, limit=9992367
attempt to access beyond end of device
hda7: rw=0, want=4294958280, limit=9992367
attempt to access beyond end of device
hda7: rw=0, want=1487072352, limit=9992367
attempt to access beyond end of device
hda7: rw=0, want=1242071648, limit=9992367
attempt to access beyond end of device
hda7: rw=0, want=4294960784, limit=9992367
attempt to access beyond end of device
hda7: rw=0, want=3706055712, limit=9992367
[...]

My mainboard has a VIA controller (Asus A7V8X) and the hard disk is a IBM
180GXP with Tagged Command Queueing enabled and a default queue length
of 8. I haven't tried disabling TCQ, but it seemed to work up to
2.6.0-test4 (although with 2.6.0-test4 I experienced some data
"swapping" between files while accessing lots of them concurrently).

Ludovico
-- 
<dunadan@despammed.com>          garden (irc.freenode.net) ICQ: 64483080
GPG ID: 07F89BB8              Jabber: garden@jabber.students.cs.unibo.it
-- This is signature nr. 1226

Re: Badness in as_completed_request in 2.6.0-test5-bk3

[Nick Piggin]

Ludovico Gardenghi wrote:

>[I hope this message doesn't appear 2 times]
>
>Hello.
>
>I've read about this error and that it should have been patched in
>2.6.0-test5-bk3.
>
>I tried it because I got a lot of them with 2.6.0-test5 while removing
>lots of files (i.e. while starting sn at boot time), but I got the same error
>messages with 2.6.0-test5-bk3; moreover, i had also some "attempt to
>access beyond end of device" errors while trying to read a file from the
>same partition. Here are the messages:
>

Hi Ludovico,
Thanks for the report. The warnings themselves are harmless. As long
as you aren't seeing the processes hanging on IO.

Try disabling TCQ, I don't think it is very stable for IDE drives.