BUG: scheduling while atomic, new libata code

BUG: scheduling while atomic, new libata code

[Jon Smirl]

Got this is my logs, no idea what triggered it. Using 2.6.20-rc2
I have one PATA and one SATA HD on ICH5 and two PATA CDROM
All using the new libata drivers

 BUG: scheduling while atomic: hald-addon-stor/0x20000000/5170
  [schedule+1529/2816] __sched_text_start+0x5f9/0xb00
  [blk_done_softirq+88/112] blk_done_softirq+0x58/0x70
  [__do_softirq+114/224] __do_softirq+0x72/0xe0
  [do_IRQ+69/128] do_IRQ+0x45/0x80
  [reschedule_interrupt+40/48] reschedule_interrupt+0x28/0x30
  [__cond_resched+22/64] __cond_resched+0x16/0x40
  [cond_resched+35/48] cond_resched+0x23/0x30
  [__reacquire_kernel_lock+28/60] __reacquire_kernel_lock+0x1c/0x3c
  [schedule+1577/2816] __sched_text_start+0x629/0xb00
  [scsi_done+0/32] scsi_done+0x0/0x20
  [ata_scsi_translate+154/320] ata_scsi_translate+0x9a/0x140
  [scsi_request_fn+542/800] scsi_request_fn+0x21e/0x320
  [__cond_resched+22/64] __cond_resched+0x16/0x40
  [cond_resched+35/48] cond_resched+0x23/0x30
  [wait_for_completion+15/192] wait_for_completion+0xf/0xc0
  [blk_execute_rq_nowait+91/160] blk_execute_rq_nowait+0x5b/0xa0
  [cfq_set_request+0/896] cfq_set_request+0x0/0x380
  [cfq_set_request+508/896] cfq_set_request+0x1fc/0x380
  [blk_execute_rq+124/224] blk_execute_rq+0x7c/0xe0
  [blk_end_sync_rq+0/48] blk_end_sync_rq+0x0/0x30
  [cfq_set_request+0/896] cfq_set_request+0x0/0x380
  [elv_set_request+28/64] elv_set_request+0x1c/0x40
  [get_request+289/624] get_request+0x121/0x270
  [get_request_wait+39/288] get_request_wait+0x27/0x120
  [scsi_execute+217/256] scsi_execute+0xd9/0x100
  [pg0+944853162/1069057024] sr_do_ioctl+0x7a/0x240 [sr_mod]
  [__wake_up+56/80] __wake_up+0x38/0x50
  [pg0+944854258/1069057024] sr_drive_status+0x62/0x80 [sr_mod]
  [pg0+945482260/1069057024] cdrom_ioctl+0x514/0xde0 [cdrom]
  [__mark_inode_dirty+52/400] __mark_inode_dirty+0x34/0x190
  [touch_atime+158/272] touch_atime+0x9e/0x110
  [pg0+944852851/1069057024] sr_block_ioctl+0x53/0xb0 [sr_mod]
  [blkdev_driver_ioctl+109/128] blkdev_driver_ioctl+0x6d/0x80
  [blkdev_ioctl+751/2000] blkdev_ioctl+0x2ef/0x7d0
  [kobject_get+15/32] kobject_get+0xf/0x20
  [get_disk+57/112] get_disk+0x39/0x70
  [exact_lock+7/16] exact_lock+0x7/0x10
  [kobject_get+15/32] kobject_get+0xf/0x20
  [pg0+944849884/1069057024] sr_block_open+0x5c/0xa0 [sr_mod]
  [blkdev_open+0/112] blkdev_open+0x0/0x70
  [do_open+439/656] do_open+0x1b7/0x290
  [blkdev_open+0/112] blkdev_open+0x0/0x70
  [blkdev_open+48/112] blkdev_open+0x30/0x70
  [__dentry_open+353/448] __dentry_open+0x161/0x1c0
  [nameidata_to_filp+53/64] nameidata_to_filp+0x35/0x40
  [do_filp_open+75/96] do_filp_open+0x4b/0x60
  [block_ioctl+24/32] block_ioctl+0x18/0x20
  [block_ioctl+0/32] block_ioctl+0x0/0x20
  [do_ioctl+43/144] do_ioctl+0x2b/0x90
  [vfs_ioctl+92/672] vfs_ioctl+0x5c/0x2a0
  [sys_ioctl+114/144] sys_ioctl+0x72/0x90
  [sysenter_past_esp+95/133] sysenter_past_esp+0x5f/0x85
  =======================

-- 
Jon Smirl
jonsmirl@gmail.com

Re: BUG: scheduling while atomic, new libata code

[Randy Dunlap]

On Tue, 26 Dec 2006 20:47:31 -0500 Jon Smirl wrote:

> Got this is my logs, no idea what triggered it. Using 2.6.20-rc2
> I have one PATA and one SATA HD on ICH5 and two PATA CDROM
> All using the new libata drivers
> 
>  BUG: scheduling while atomic: hald-addon-stor/0x20000000/5170
>   [schedule+1529/2816] __sched_text_start+0x5f9/0xb00
>   [blk_done_softirq+88/112] blk_done_softirq+0x58/0x70
>   [__do_softirq+114/224] __do_softirq+0x72/0xe0
>   [do_IRQ+69/128] do_IRQ+0x45/0x80
>   [reschedule_interrupt+40/48] reschedule_interrupt+0x28/0x30
>   [__cond_resched+22/64] __cond_resched+0x16/0x40
>   [cond_resched+35/48] cond_resched+0x23/0x30
>   [__reacquire_kernel_lock+28/60] __reacquire_kernel_lock+0x1c/0x3c
>   [schedule+1577/2816] __sched_text_start+0x629/0xb00
>   [scsi_done+0/32] scsi_done+0x0/0x20
>   [ata_scsi_translate+154/320] ata_scsi_translate+0x9a/0x140
>   [scsi_request_fn+542/800] scsi_request_fn+0x21e/0x320
>   [__cond_resched+22/64] __cond_resched+0x16/0x40
>   [cond_resched+35/48] cond_resched+0x23/0x30
>   [wait_for_completion+15/192] wait_for_completion+0xf/0xc0
>   [blk_execute_rq_nowait+91/160] blk_execute_rq_nowait+0x5b/0xa0
>   [cfq_set_request+0/896] cfq_set_request+0x0/0x380
>   [cfq_set_request+508/896] cfq_set_request+0x1fc/0x380
>   [blk_execute_rq+124/224] blk_execute_rq+0x7c/0xe0
>   [blk_end_sync_rq+0/48] blk_end_sync_rq+0x0/0x30
>   [cfq_set_request+0/896] cfq_set_request+0x0/0x380
>   [elv_set_request+28/64] elv_set_request+0x1c/0x40
>   [get_request+289/624] get_request+0x121/0x270
>   [get_request_wait+39/288] get_request_wait+0x27/0x120
>   [scsi_execute+217/256] scsi_execute+0xd9/0x100
>   [pg0+944853162/1069057024] sr_do_ioctl+0x7a/0x240 [sr_mod]
>   [__wake_up+56/80] __wake_up+0x38/0x50
>   [pg0+944854258/1069057024] sr_drive_status+0x62/0x80 [sr_mod]
>   [pg0+945482260/1069057024] cdrom_ioctl+0x514/0xde0 [cdrom]
>   [__mark_inode_dirty+52/400] __mark_inode_dirty+0x34/0x190
>   [touch_atime+158/272] touch_atime+0x9e/0x110
>   [pg0+944852851/1069057024] sr_block_ioctl+0x53/0xb0 [sr_mod]
>   [blkdev_driver_ioctl+109/128] blkdev_driver_ioctl+0x6d/0x80
>   [blkdev_ioctl+751/2000] blkdev_ioctl+0x2ef/0x7d0
>   [kobject_get+15/32] kobject_get+0xf/0x20
>   [get_disk+57/112] get_disk+0x39/0x70
>   [exact_lock+7/16] exact_lock+0x7/0x10
>   [kobject_get+15/32] kobject_get+0xf/0x20
>   [pg0+944849884/1069057024] sr_block_open+0x5c/0xa0 [sr_mod]
>   [blkdev_open+0/112] blkdev_open+0x0/0x70
>   [do_open+439/656] do_open+0x1b7/0x290
>   [blkdev_open+0/112] blkdev_open+0x0/0x70
>   [blkdev_open+48/112] blkdev_open+0x30/0x70
>   [__dentry_open+353/448] __dentry_open+0x161/0x1c0
>   [nameidata_to_filp+53/64] nameidata_to_filp+0x35/0x40
>   [do_filp_open+75/96] do_filp_open+0x4b/0x60
>   [block_ioctl+24/32] block_ioctl+0x18/0x20
>   [block_ioctl+0/32] block_ioctl+0x0/0x20
>   [do_ioctl+43/144] do_ioctl+0x2b/0x90
>   [vfs_ioctl+92/672] vfs_ioctl+0x5c/0x2a0
>   [sys_ioctl+114/144] sys_ioctl+0x72/0x90
>   [sysenter_past_esp+95/133] sysenter_past_esp+0x5f/0x85
>   =======================

Can you apply and test the patch here:
  http://lkml.org/lkml/2006/12/26/62
and let us know if that fixes the BUG, please.


---
~Randy

Re: BUG: scheduling while atomic, new libata code

[Jon Smirl]

On 12/26/06, Randy Dunlap <randy.dunlap@oracle.com> wrote:
> Can you apply and test the patch here:
>   http://lkml.org/lkml/2006/12/26/62
> and let us know if that fixes the BUG, please.

I am running with the patch and haven't hit the BUG. But I wasn't
hitting it very often without the patch so it may take a while to know
if there is a difference.

-- 
Jon Smirl
jonsmirl@gmail.com

Re: BUG: scheduling while atomic, new libata code

[Jon Smirl]

Still getting the bug with patch applied.


BUG: scheduling while atomic: hald-addon-stor/0x20000000/5078
 [<c02b0289>] __sched_text_start+0x5f9/0xb00
 [<c024a623>] net_rx_action+0xb3/0x180
 [<c01210f2>] __do_softirq+0x72/0xe0
 [<c0105205>] do_IRQ+0x45/0x80
 [<c0103aab>] common_interrupt+0x23/0x28
 [<c0117696>] __cond_resched+0x16/0x40
 [<c02b07b3>] cond_resched+0x23/0x30
 [<c02b225c>] __reacquire_kernel_lock+0x1c/0x3c
 [<c02b02b9>] __sched_text_start+0x629/0xb00
 [<c02b086e>] wait_for_completion+0x8e/0xc0
 [<c0117650>] default_wake_function+0x0/0x10
 [<c01b321c>] blk_execute_rq+0x7c/0xe0
 [<c0117696>] __cond_resched+0x16/0x40
 [<c02b07b3>] cond_resched+0x23/0x30
 [<c0161a36>] kmem_cache_zalloc+0x76/0x90
 [<c02181fd>] scsi_execute_req+0x3d/0xf0
 [<c01b6ce9>] sg_io+0x2a9/0x340
 [<c0218306>] scsi_test_unit_ready+0x56/0xa0
 [<f8986132>] sr_media_change+0x52/0x220 [sr_mod]
 [<c0103ad8>] reschedule_interrupt+0x28/0x30
 [<f8986320>] sr_block_media_changed+0x0/0x10 [sr_mod]
 [<f89f508d>] media_changed+0x5d/0xa0 [cdrom]
 [<c01883ac>] check_disk_change+0x1c/0x80
 [<f89f9432>] cdrom_open+0x152/0xa90 [cdrom]
 [<c0218306>] scsi_test_unit_ready+0x56/0xa0
 [<c0175619>] __d_lookup+0x89/0x100
 [<c0175b85>] dput+0xb5/0x130
 [<c016ba75>] do_lookup+0x65/0x190
 [<f8972540>] ext3_permission+0x0/0x10 [ext3]
 [<c0175b85>] dput+0xb5/0x130
 [<c016dc6a>] __link_path_walk+0xc1a/0xc90
 [<c017828e>] touch_atime+0x9e/0x110
 [<c0179b5b>] mntput_no_expire+0x1b/0x80
 [<c016dd45>] link_path_walk+0x65/0xc0
 [<c01323fe>] hrtimer_cancel+0xe/0x20
 [<c0132539>] hrtimer_nanosleep+0x49/0x110
 [<c01bdf3f>] kobject_get+0xf/0x20
 [<c01b5ce9>] get_disk+0x39/0x70
 [<c01b5d27>] exact_lock+0x7/0x10
 [<c01bdf3f>] kobject_get+0xf/0x20
 [<f89863dc>] sr_block_open+0x5c/0xa0 [sr_mod]
 [<c0188e70>] blkdev_open+0x0/0x70
 [<c0188bc9>] do_open+0x1e9/0x290
 [<c0188e70>] blkdev_open+0x0/0x70
 [<c0188ea0>] blkdev_open+0x30/0x70
 [<c016307a>] __dentry_open+0xba/0x1c0
 [<c0163235>] nameidata_to_filp+0x35/0x40
 [<c016328b>] do_filp_open+0x4b/0x60
 [<c01323fe>] hrtimer_cancel+0xe/0x20
 [<c0132539>] hrtimer_nanosleep+0x49/0x110
 [<c01632ea>] do_sys_open+0x4a/0xe0
 [<c01633bc>] sys_open+0x1c/0x20
 [<c010309a>] sysenter_past_esp+0x5f/0x85
 =======================


-- 
Jon Smirl
jonsmirl@gmail.com

Re: BUG: scheduling while atomic, new libata code

[Arnd Bergmann]

On Thursday 28 December 2006 03:16, Jon Smirl wrote:
> BUG: scheduling while atomic: hald-addon-stor/0x20000000/5078
>  [<c02b0289>] __sched_text_start+0x5f9/0xb00
>  [<c024a623>] net_rx_action+0xb3/0x180
>  [<c01210f2>] __do_softirq+0x72/0xe0
>  [<c0105205>] do_IRQ+0x45/0x80

This doesn't seem to be related to libata at all. Like your
first trace, you call schedule from a softirq context, which
is always atomic.
The only place where I can imagine this happening is the
local_irq_enable() in there, which can be defined in different
ways.
Are you running with paravirt_ops, CONFIG_TRACE_IRQFLAGS_SUPPORT
and/or kernel preemption enabled?

	Arnd <><

Re: BUG: scheduling while atomic, new libata code

[Jon Smirl]

On 12/28/06, Arnd Bergmann <arnd@arndb.de> wrote:
> On Thursday 28 December 2006 03:16, Jon Smirl wrote:
> > BUG: scheduling while atomic: hald-addon-stor/0x20000000/5078
> > [<c02b0289>] __sched_text_start+0x5f9/0xb00
> > [<c024a623>] net_rx_action+0xb3/0x180
> > [<c01210f2>] __do_softirq+0x72/0xe0
> > [<c0105205>] do_IRQ+0x45/0x80
>
> This doesn't seem to be related to libata at all. Like your
> first trace, you call schedule from a softirq context, which
> is always atomic.
> The only place where I can imagine this happening is the
> local_irq_enable() in there, which can be defined in different
> ways.
> Are you running with paravirt_ops, CONFIG_TRACE_IRQFLAGS_SUPPORT
> and/or kernel preemption enabled?

This is set, although I don't recall setting it.
CONFIG_TRACE_IRQFLAGS_SUPPORT=y

# CONFIG_PREEMPT_NONE is not set
CONFIG_PREEMPT_VOLUNTARY=y
# CONFIG_PREEMPT is not set
CONFIG_PREEMPT_BKL=y

Another odd thing I'm doing is simultaneously using a wired and
wireless net at the same time.

>
>         Arnd <><
>


-- 
Jon Smirl
jonsmirl@gmail.com

Re: BUG: scheduling while atomic, new libata code

[Jon Smirl]

On 12/28/06, Arnd Bergmann <arnd@arndb.de> wrote:
> On Thursday 28 December 2006 03:16, Jon Smirl wrote:
> > BUG: scheduling while atomic: hald-addon-stor/0x20000000/5078
> > [<c02b0289>] __sched_text_start+0x5f9/0xb00
> > [<c024a623>] net_rx_action+0xb3/0x180
> > [<c01210f2>] __do_softirq+0x72/0xe0
> > [<c0105205>] do_IRQ+0x45/0x80
>
> This doesn't seem to be related to libata at all. Like your
> first trace, you call schedule from a softirq context, which
> is always atomic.
> The only place where I can imagine this happening is the
> local_irq_enable() in there, which can be defined in different
> ways.
> Are you running with paravirt_ops, CONFIG_TRACE_IRQFLAGS_SUPPORT
> and/or kernel preemption enabled?

Forgot this,
# CONFIG_PARAVIRT is not set

CPU is 2.8Mhz P4, no virtualization capabilities.

>
>         Arnd <><
>


-- 
Jon Smirl
jonsmirl@gmail.com