Re: linux-next: Tree for July 11

Re: linux-next: Tree for July 11

[Rafael J. Wysocki]

On Friday, 11 of July 2008, Stephen Rothwell wrote:
> Hi all,
> 
> Changes since next-20080710:
> 
> New tree: voltage
> 
> The tip-core tree lost its conflict against Linus' tree.
> 
> The sched tree gained a conflict against Linus' tree.
> 
> The x86 tree gained conflicts against the ftrace and driver-core trees.
> 
> The ide tree lost its 2 conflicts against Linus' tree.
> 
> The rr tree gained a runtime bug fix patch (which Rusty tells me will not
> be needed for long).
> 
> The firmware tree gained a conflict against the usb tree that required the
> reverting of one of its commits) but also lost a conflict against Linus'
> tree.
> 
> The kmemcheck tree gained a conflict against the x86 tree.
> 
> The ttydev tree had two patches fail to apply which I removed.
> 
> I have also applied the following patches for known problems:
> 
> 	sparc64: sysdev API change fallout
> 	s390: fix compile error due to smp_call_function
> 
> This patch is no longer needed:
> 	linux-next: zero based percpu build error on s390
> 
> ----------------------------------------------------------------------------

With this tree I see two problems.  The first one is this:

=============================================
[ INFO: possible recursive locking detected ]
2.6.26-rc9-next #44
---------------------------------------------
swapper/1 is trying to acquire lock:
 (&queue->lock){-...}, at: [<ffffffff80483067>] qdisc_lock_tree+0x27/0x30

but task is already holding lock:
 (&queue->lock){-...}, at: [<ffffffff8048305f>] qdisc_lock_tree+0x1f/0x30

other info that might help us debug this:
3 locks held by swapper/1:
 #0:  (net_mutex){--..}, at: [<ffffffff8046e482>] register_pernet_device+0x22/0x70
 #1:  (rtnl_mutex){--..}, at: [<ffffffff8047bac2>] rtnl_lock+0x12/0x20
 #2:  (&queue->lock){-...}, at: [<ffffffff8048305f>] qdisc_lock_tree+0x1f/0x30

stack backtrace:
Pid: 1, comm: swapper Not tainted 2.6.26-rc9-next #44

Call Trace:
 [<ffffffff80263a4e>] __lock_acquire+0xb7e/0x1280
 [<ffffffff802641a7>] lock_acquire+0x57/0x80
 [<ffffffff80483067>] ? qdisc_lock_tree+0x27/0x30
 [<ffffffff80500c65>] _spin_lock+0x25/0x40
 [<ffffffff80483067>] qdisc_lock_tree+0x27/0x30
 [<ffffffff804830b1>] dev_init_scheduler+0x11/0x70
 [<ffffffff8047193b>] register_netdevice+0x1fb/0x370
 [<ffffffff80471af4>] register_netdev+0x44/0x60
 [<ffffffff806f18f7>] loopback_net_init+0x47/0x90
 [<ffffffff806f12c0>] ? firmware_class_init+0x0/0x90
 [<ffffffff806f1890>] ? loopback_init+0x0/0x20
 [<ffffffff8046e3e8>] register_pernet_operations+0x18/0x20
 [<ffffffff8046e491>] register_pernet_device+0x31/0x70
 [<ffffffff806f18a0>] loopback_init+0x10/0x20
 [<ffffffff806caa48>] kernel_init+0x128/0x310
 [<ffffffff8026297f>] ? trace_hardirqs_on_caller+0xbf/0x150
 [<ffffffff80262a1d>] ? trace_hardirqs_on+0xd/0x10
 [<ffffffff80500f9b>] ? _spin_unlock_irq+0x2b/0x40
 [<ffffffff80500830>] ? trace_hardirqs_on_thunk+0x3a/0x3f
 [<ffffffff8026297f>] ? trace_hardirqs_on_caller+0xbf/0x150
 [<ffffffff8020c6d9>] child_rip+0xa/0x11
 [<ffffffff8020bd0f>] ? restore_args+0x0/0x30
 [<ffffffff806ca920>] ? kernel_init+0x0/0x310
 [<ffffffff8020c6cf>] ? child_rip+0x0/0x11

and the second one is the following:

WARNING: at /home/rafael/src/linux-next/include/linux/blkdev.h:447 blk_plug_device+0x9b/0xb0()
Modules linked in: snd_hda_intel ohci1394 ieee1394 snd_pcm rtc_cmos sr_mod rtc_core floppy snd_timer wmi button cdrom rtc_lib serio_raw sky2 snd_page_alloc snd_hwdep snd evdev joydev sg soundcore raid456 async_xor async_memcpy async_tx xor raid0 usbhid ff_memless ehci_hcd ohci_hcd sd_mod edd raid1 ext3 jbd fan pata_marvell pata_atiixp thermal processor
Pid: 2244, comm: kjournald Not tainted 2.6.26-rc9-next #44

Call Trace:
 [<ffffffff8023d37f>] warn_on_slowpath+0x5f/0x80
 [<ffffffff80220030>] ? hpet_unregister_irq_handler+0x0/0x30
 [<ffffffff8022a8ae>] ? kmemcheck_mark_initialized+0xe/0x10
 [<ffffffff802b97fb>] ? kmemcheck_slab_alloc+0x2b/0x50
 [<ffffffff802b8610>] ? kmem_cache_alloc+0xc0/0x140
 [<ffffffff80291921>] ? mempool_alloc_slab+0x11/0x20
 [<ffffffff80291a8b>] ? mempool_alloc+0x5b/0x140
 [<ffffffff803575db>] blk_plug_device+0x9b/0xb0
 [<ffffffff80453d9f>] bitmap_startwrite+0xbf/0x1b0
 [<ffffffff802e87e4>] ? bio_alloc_bioset+0x54/0xb0
 [<ffffffffa004eafa>] make_request+0x39a/0x810 [raid1]
 [<ffffffff80291a8b>] ? mempool_alloc+0x5b/0x140
 [<ffffffff80291a8b>] ? mempool_alloc+0x5b/0x140
 [<ffffffff8035682d>] generic_make_request+0x17d/0x2b0
 [<ffffffff803581dc>] submit_bio+0x6c/0xf0
 [<ffffffff802e3c60>] submit_bh+0xf0/0x130
 [<ffffffffa001cce0>] journal_commit_transaction+0xa40/0x1000 [jbd]
 [<ffffffff80248504>] ? try_to_del_timer_sync+0x44/0x90
 [<ffffffffa0020967>] kjournald+0xe7/0x250 [jbd]
 [<ffffffff80254350>] ? autoremove_wake_function+0x0/0x40
 [<ffffffffa0020880>] ? kjournald+0x0/0x250 [jbd]
 [<ffffffff80253efd>] kthread+0x4d/0x80
 [<ffffffff8020c6d9>] child_rip+0xa/0x11
 [<ffffffff80500f9b>] ? _spin_unlock_irq+0x2b/0x40
 [<ffffffff8020bd0f>] ? restore_args+0x0/0x30
 [<ffffffff80254052>] ? kthreadd+0x122/0x1a0
 [<ffffffff80253eb0>] ? kthread+0x0/0x80
 [<ffffffff8020c6cf>] ? child_rip+0x0/0x11

---[ end trace d63b767d1ed7d78a ]---

Full dmesg output is at: http://www.sisk.pl/kernel/debug/20080711/dmesg-1.log

Thanks,
Rafael

Re: linux-next: Tree for July 11

[Vegard Nossum]

On Sat, Jul 12, 2008 at 8:51 PM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> and the second one is the following:
>
> WARNING: at /home/rafael/src/linux-next/include/linux/blkdev.h:447 blk_plug_device+0x9b/0xb0()
> Modules linked in: snd_hda_intel ohci1394 ieee1394 snd_pcm rtc_cmos sr_mod rtc_core floppy snd_timer wmi button cdrom rtc_lib serio_raw sky2 snd_page_alloc snd_hwdep snd evdev joydev sg soundcore raid456 async_xor async_memcpy async_tx xor raid0 usbhid ff_memless ehci_hcd ohci_hcd sd_mod edd raid1 ext3 jbd fan pata_marvell pata_atiixp thermal processor
> Pid: 2244, comm: kjournald Not tainted 2.6.26-rc9-next #44
>
> Call Trace:
>  [<ffffffff8023d37f>] warn_on_slowpath+0x5f/0x80
>  [<ffffffff80220030>] ? hpet_unregister_irq_handler+0x0/0x30
>  [<ffffffff8022a8ae>] ? kmemcheck_mark_initialized+0xe/0x10
>  [<ffffffff802b97fb>] ? kmemcheck_slab_alloc+0x2b/0x50
>  [<ffffffff802b8610>] ? kmem_cache_alloc+0xc0/0x140
>  [<ffffffff80291921>] ? mempool_alloc_slab+0x11/0x20
>  [<ffffffff80291a8b>] ? mempool_alloc+0x5b/0x140
>  [<ffffffff803575db>] blk_plug_device+0x9b/0xb0
>  [<ffffffff80453d9f>] bitmap_startwrite+0xbf/0x1b0
>  [<ffffffff802e87e4>] ? bio_alloc_bioset+0x54/0xb0
>  [<ffffffffa004eafa>] make_request+0x39a/0x810 [raid1]
>  [<ffffffff80291a8b>] ? mempool_alloc+0x5b/0x140
>  [<ffffffff80291a8b>] ? mempool_alloc+0x5b/0x140
>  [<ffffffff8035682d>] generic_make_request+0x17d/0x2b0
>  [<ffffffff803581dc>] submit_bio+0x6c/0xf0
>  [<ffffffff802e3c60>] submit_bh+0xf0/0x130
>  [<ffffffffa001cce0>] journal_commit_transaction+0xa40/0x1000 [jbd]
>  [<ffffffff80248504>] ? try_to_del_timer_sync+0x44/0x90
>  [<ffffffffa0020967>] kjournald+0xe7/0x250 [jbd]
>  [<ffffffff80254350>] ? autoremove_wake_function+0x0/0x40
>  [<ffffffffa0020880>] ? kjournald+0x0/0x250 [jbd]
>  [<ffffffff80253efd>] kthread+0x4d/0x80
>  [<ffffffff8020c6d9>] child_rip+0xa/0x11
>  [<ffffffff80500f9b>] ? _spin_unlock_irq+0x2b/0x40
>  [<ffffffff8020bd0f>] ? restore_args+0x0/0x30
>  [<ffffffff80254052>] ? kthreadd+0x122/0x1a0
>  [<ffffffff80253eb0>] ? kthread+0x0/0x80
>  [<ffffffff8020c6cf>] ? child_rip+0x0/0x11

Hm, even though there's kmemcheck in the stacktrace, I think it's
unrelated. Probably it's just a call that returned and the addresses
were left on the stack. You can also see that the warning clearly
comes from blkdev.h, and since kmemcheck does *not* call into any
blkdev stuff, those stacktrace entries must be just left-overs, as is
also indicated by the unreliable mark, so although those are wrong in
certain circumstances, I don't think they are in this case.

The warning comes from here:

static inline int queue_flag_test_and_set(unsigned int flag,
                                          struct request_queue *q)
{
        WARN_ON_ONCE(!queue_is_locked(q));

I'll add Jens Axboe to Cc.

Thanks for the heads-up!


Vegard

-- 
"The animistic metaphor of the bug that maliciously sneaked in while
the programmer was not looking is intellectually dishonest as it
disguises that the error is the programmer's own creation."
	-- E. W. Dijkstra, EWD1036

Re: linux-next: Tree for July 11

[Arjan van de Ven]

On Sat, 12 Jul 2008 21:21:38 +0200
"Vegard Nossum" <vegard.nossum-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org> wrote:

> >  [<ffffffff8023d37f>] warn_on_slowpath+0x5f/0x80
> >  [<ffffffff80220030>] ? hpet_unregister_irq_handler+0x0/0x30
> >  [<ffffffff8022a8ae>] ? kmemcheck_mark_initialized+0xe/0x10
> >  [<ffffffff802b97fb>] ? kmemcheck_slab_alloc+0x2b/0x50
> >  [<ffffffff802b8610>] ? kmem_cache_alloc+0xc0/0x140
> >  [<ffffffff80291921>] ? mempool_alloc_slab+0x11/0x20
> >  [<ffffffff80291a8b>] ? mempool_alloc+0x5b/0x140
> >  [<ffffffff803575db>] blk_plug_device+0x9b/0xb0
> >  [<ffffffff80453d9f>] bitmap_startwrite+0xbf/0x1b0
> >  [<ffffffff802e87e4>] ? bio_alloc_bioset+0x54/0xb0
> >  [<ffffffffa004eafa>] make_request+0x39a/0x810 [raid1]
> >  [<ffffffff80291a8b>] ? mempool_alloc+0x5b/0x140
> >  [<ffffffff80291a8b>] ? mempool_alloc+0x5b/0x140
> >  [<ffffffff8035682d>] generic_make_request+0x17d/0x2b0
> >  [<ffffffff803581dc>] submit_bio+0x6c/0xf0
> Hm, even though there's kmemcheck in the stacktrace, I think it's
> unrelated. Probably it's just a call that returned and the addresses
> were left on the stack. 

more than "probably".. that's what the "?" in the trace is for ;)

Re: linux-next: Tree for July 11

[Rafael J. Wysocki]

On Saturday, 12 of July 2008, Vegard Nossum wrote:
> On Sat, Jul 12, 2008 at 8:51 PM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> > and the second one is the following:
> >
> > WARNING: at /home/rafael/src/linux-next/include/linux/blkdev.h:447 blk_plug_device+0x9b/0xb0()
> > Modules linked in: snd_hda_intel ohci1394 ieee1394 snd_pcm rtc_cmos sr_mod rtc_core floppy snd_timer wmi button cdrom rtc_lib serio_raw sky2 snd_page_alloc snd_hwdep snd evdev joydev sg soundcore raid456 async_xor async_memcpy async_tx xor raid0 usbhid ff_memless ehci_hcd ohci_hcd sd_mod edd raid1 ext3 jbd fan pata_marvell pata_atiixp thermal processor
> > Pid: 2244, comm: kjournald Not tainted 2.6.26-rc9-next #44
> >
> > Call Trace:
> >  [<ffffffff8023d37f>] warn_on_slowpath+0x5f/0x80
> >  [<ffffffff80220030>] ? hpet_unregister_irq_handler+0x0/0x30
> >  [<ffffffff8022a8ae>] ? kmemcheck_mark_initialized+0xe/0x10
> >  [<ffffffff802b97fb>] ? kmemcheck_slab_alloc+0x2b/0x50
> >  [<ffffffff802b8610>] ? kmem_cache_alloc+0xc0/0x140
> >  [<ffffffff80291921>] ? mempool_alloc_slab+0x11/0x20
> >  [<ffffffff80291a8b>] ? mempool_alloc+0x5b/0x140
> >  [<ffffffff803575db>] blk_plug_device+0x9b/0xb0
> >  [<ffffffff80453d9f>] bitmap_startwrite+0xbf/0x1b0
> >  [<ffffffff802e87e4>] ? bio_alloc_bioset+0x54/0xb0
> >  [<ffffffffa004eafa>] make_request+0x39a/0x810 [raid1]
> >  [<ffffffff80291a8b>] ? mempool_alloc+0x5b/0x140
> >  [<ffffffff80291a8b>] ? mempool_alloc+0x5b/0x140
> >  [<ffffffff8035682d>] generic_make_request+0x17d/0x2b0
> >  [<ffffffff803581dc>] submit_bio+0x6c/0xf0
> >  [<ffffffff802e3c60>] submit_bh+0xf0/0x130
> >  [<ffffffffa001cce0>] journal_commit_transaction+0xa40/0x1000 [jbd]
> >  [<ffffffff80248504>] ? try_to_del_timer_sync+0x44/0x90
> >  [<ffffffffa0020967>] kjournald+0xe7/0x250 [jbd]
> >  [<ffffffff80254350>] ? autoremove_wake_function+0x0/0x40
> >  [<ffffffffa0020880>] ? kjournald+0x0/0x250 [jbd]
> >  [<ffffffff80253efd>] kthread+0x4d/0x80
> >  [<ffffffff8020c6d9>] child_rip+0xa/0x11
> >  [<ffffffff80500f9b>] ? _spin_unlock_irq+0x2b/0x40
> >  [<ffffffff8020bd0f>] ? restore_args+0x0/0x30
> >  [<ffffffff80254052>] ? kthreadd+0x122/0x1a0
> >  [<ffffffff80253eb0>] ? kthread+0x0/0x80
> >  [<ffffffff8020c6cf>] ? child_rip+0x0/0x11
> 
> Hm, even though there's kmemcheck in the stacktrace, I think it's
> unrelated. Probably it's just a call that returned and the addresses
> were left on the stack. You can also see that the warning clearly
> comes from blkdev.h, and since kmemcheck does *not* call into any
> blkdev stuff, those stacktrace entries must be just left-overs, as is
> also indicated by the unreliable mark, so although those are wrong in
> certain circumstances, I don't think they are in this case.
> 
> The warning comes from here:
> 
> static inline int queue_flag_test_and_set(unsigned int flag,
>                                           struct request_queue *q)
> {
>         WARN_ON_ONCE(!queue_is_locked(q));
> 
> I'll add Jens Axboe to Cc.

Yeah, good idea. :-)

It turns out that this happened before, but I've been overlooking it.  This is
a trace from the Friday's linux-next:

------------[ cut here ]------------
WARNING: at /home/rafael/src/linux-next/include/linux/blkdev.h:447 blk_plug_device+0x9b/0xb0()
Modules linked in: rtc_cmos snd_hda_intel rtc_core snd_pcm sr_mod floppy snd_timer snd_page_alloc rtc_lib ohci1394 serio_raw cdrom ieee1394 snd_hwdep snd soundcore sky2 button wmi joydev evdev sg raid456 async_xor async_memcpy async_tx xor raid0 usbhid ff_memless ehci_hcd sd_mod ohci_hcd edd raid1 ext3 jbd fan pata_marvell pata_atiixp thermal processor
Pid: 2275, comm: kjournald Not tainted 2.6.26-rc9-next #40

Call Trace:
 [<ffffffff8023cf9f>] warn_on_slowpath+0x5f/0x80
 [<ffffffff80220030>] ? hpet_rtc_interrupt+0x100/0x380
 [<ffffffff80263327>] ? __lock_acquire+0x8b7/0x1280
 [<ffffffff80291461>] ? mempool_alloc_slab+0x11/0x20
 [<ffffffff8035735b>] blk_plug_device+0x9b/0xb0
 [<ffffffff8045377f>] bitmap_startwrite+0xbf/0x1b0
 [<ffffffff802e8254>] ? bio_alloc_bioset+0x54/0xb0
 [<ffffffffa004eafa>] make_request+0x39a/0x810 [raid1]
 [<ffffffff802915cb>] ? mempool_alloc+0x5b/0x140
 [<ffffffff802915cb>] ? mempool_alloc+0x5b/0x140
 [<ffffffff803565ad>] generic_make_request+0x17d/0x2b0
 [<ffffffff80357f5c>] submit_bio+0x6c/0xf0
 [<ffffffff802e36d0>] submit_bh+0xf0/0x130
 [<ffffffffa001cce0>] journal_commit_transaction+0xa40/0x1000 [jbd]
 [<ffffffff802480d4>] ? try_to_del_timer_sync+0x44/0x90
 [<ffffffffa0020967>] kjournald+0xe7/0x250 [jbd]
 [<ffffffff80253ef0>] ? autoremove_wake_function+0x0/0x40
 [<ffffffffa0020880>] ? kjournald+0x0/0x250 [jbd]
 [<ffffffff80253a9d>] kthread+0x4d/0x80
 [<ffffffff8020c6b9>] child_rip+0xa/0x11
 [<ffffffff8020bcef>] ? restore_args+0x0/0x30
 [<ffffffff80253a50>] ? kthread+0x0/0x80
 [<ffffffff8020c6af>] ? child_rip+0x0/0x11

---[ end trace bd85cedf792d0f08 ]---

and the full dmesg is here: http://www.sisk.pl/kernel/debug/20080709/dmesg-1.log

Thanks,
Rafael

Re: linux-next: Tree for July 11: WARNING: at /home/rafael/src/linux-next/include/linux/blkdev.h:447

[Rafael J. Wysocki]

On Saturday, 12 of July 2008, Rafael J. Wysocki wrote:
> On Saturday, 12 of July 2008, Vegard Nossum wrote:
> > On Sat, Jul 12, 2008 at 8:51 PM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> > > and the second one is the following:
[--snip--]
> 
> It turns out that this happened before, but I've been overlooking it.  This is
> a trace from the Friday's linux-next:
> 
> ------------[ cut here ]------------
> WARNING: at /home/rafael/src/linux-next/include/linux/blkdev.h:447 blk_plug_device+0x9b/0xb0()
> Modules linked in: rtc_cmos snd_hda_intel rtc_core snd_pcm sr_mod floppy snd_timer snd_page_alloc rtc_lib ohci1394 serio_raw cdrom ieee1394 snd_hwdep snd soundcore sky2 button wmi joydev evdev sg raid456 async_xor async_memcpy async_tx xor raid0 usbhid ff_memless ehci_hcd sd_mod ohci_hcd edd raid1 ext3 jbd fan pata_marvell pata_atiixp thermal processor
> Pid: 2275, comm: kjournald Not tainted 2.6.26-rc9-next #40
> 
> Call Trace:
>  [<ffffffff8023cf9f>] warn_on_slowpath+0x5f/0x80
>  [<ffffffff80220030>] ? hpet_rtc_interrupt+0x100/0x380
>  [<ffffffff80263327>] ? __lock_acquire+0x8b7/0x1280
>  [<ffffffff80291461>] ? mempool_alloc_slab+0x11/0x20
>  [<ffffffff8035735b>] blk_plug_device+0x9b/0xb0
>  [<ffffffff8045377f>] bitmap_startwrite+0xbf/0x1b0
>  [<ffffffff802e8254>] ? bio_alloc_bioset+0x54/0xb0
>  [<ffffffffa004eafa>] make_request+0x39a/0x810 [raid1]
>  [<ffffffff802915cb>] ? mempool_alloc+0x5b/0x140
>  [<ffffffff802915cb>] ? mempool_alloc+0x5b/0x140
>  [<ffffffff803565ad>] generic_make_request+0x17d/0x2b0
>  [<ffffffff80357f5c>] submit_bio+0x6c/0xf0
>  [<ffffffff802e36d0>] submit_bh+0xf0/0x130
>  [<ffffffffa001cce0>] journal_commit_transaction+0xa40/0x1000 [jbd]
>  [<ffffffff802480d4>] ? try_to_del_timer_sync+0x44/0x90
>  [<ffffffffa0020967>] kjournald+0xe7/0x250 [jbd]
>  [<ffffffff80253ef0>] ? autoremove_wake_function+0x0/0x40
>  [<ffffffffa0020880>] ? kjournald+0x0/0x250 [jbd]
>  [<ffffffff80253a9d>] kthread+0x4d/0x80
>  [<ffffffff8020c6b9>] child_rip+0xa/0x11
>  [<ffffffff8020bcef>] ? restore_args+0x0/0x30
>  [<ffffffff80253a50>] ? kthread+0x0/0x80
>  [<ffffffff8020c6af>] ? child_rip+0x0/0x11
> 
> ---[ end trace bd85cedf792d0f08 ]---
> 

This has now made it into the Linus' tree:

------------[ cut here ]------------
WARNING: at /home/rafael/src/linux-2.6/include/linux/blkdev.h:447 blk_plug_device+0x9b/0xb0()
Modules linked in: rtc_cmos rtc_core sr_mod rtc_lib snd_hda_intel cdrom floppy snd_pcm snd_timer serio_raw snd_page_alloc ohci1394 snd_hwdep ieee1394 sky2 snd soundcore joydev button wmi evdev sg raid456 async_xor async_memcpy async_tx xor raid0 usbhid ff_memless ehci_hcd ohci_hcd sd_mod edd raid1 ext3 jbd fan pata_marvell pata_atiixp thermal processor
Pid: 2264, comm: kjournald Not tainted 2.6.26-git #203

Call Trace:
 [<ffffffff8023aadf>] warn_on_slowpath+0x5f/0x80
 [<ffffffff80261075>] ? __lock_acquire+0x8d5/0x1290
 [<ffffffff8028991b>] ? mempool_alloc+0x5b/0x140
 [<ffffffff8034e43b>] blk_plug_device+0x9b/0xb0
 [<ffffffff8044727f>] bitmap_startwrite+0xbf/0x1b0
 [<ffffffff802dff44>] ? bio_alloc_bioset+0x54/0xb0
 [<ffffffffa004ea9c>] make_request+0x39c/0x810 [raid1]
 [<ffffffff8028991b>] ? mempool_alloc+0x5b/0x140
 [<ffffffff8028991b>] ? mempool_alloc+0x5b/0x140
 [<ffffffff8034d68d>] generic_make_request+0x17d/0x2b0
 [<ffffffff8034f03c>] submit_bio+0x6c/0xf0
 [<ffffffff802db3c0>] submit_bh+0xf0/0x130
 [<ffffffffa001cce0>] journal_commit_transaction+0xa40/0x1000 [jbd]
 [<ffffffff80245c74>] ? try_to_del_timer_sync+0x44/0x90
 [<ffffffffa0020947>] kjournald+0xe7/0x250 [jbd]
 [<ffffffff80251a60>] ? autoremove_wake_function+0x0/0x40
 [<ffffffffa0020860>] ? kjournald+0x0/0x250 [jbd]
 [<ffffffff8025160d>] kthread+0x4d/0x80
 [<ffffffff8020c6c9>] child_rip+0xa/0x11
 [<ffffffff8020bcff>] ? restore_args+0x0/0x30
 [<ffffffff802515c0>] ? kthread+0x0/0x80
 [<ffffffff8020c6bf>] ? child_rip+0x0/0x11

---[ end trace a367ac91f145af0b ]---

dmesg: http://www.sisk.pl/kernel/debug/mainline/a3cf859321486f69506326146ab3e2fd15c05c3f/dmesg-M3A32-MVP.log
config: http://www.sisk.pl/kernel/debug/mainline/a3cf859321486f69506326146ab3e2fd15c05c3f/M3A32-MVP-config

Thanks,
Rafael

Re: linux-next: Tree for July 11: WARNING: at /home/rafael/src/linux-next/include/linux/blkdev.h:447

[Andrew Morton]

On Thu, 17 Jul 2008 01:02:15 +0200
"Rafael J. Wysocki" <rjw@sisk.pl> wrote:

> On Saturday, 12 of July 2008, Rafael J. Wysocki wrote:
> > On Saturday, 12 of July 2008, Vegard Nossum wrote:
> > > On Sat, Jul 12, 2008 at 8:51 PM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> > > > and the second one is the following:
> [--snip--]
> > 
> > It turns out that this happened before, but I've been overlooking it.  This is
> > a trace from the Friday's linux-next:
> > 
> > ------------[ cut here ]------------
> > WARNING: at /home/rafael/src/linux-next/include/linux/blkdev.h:447 blk_plug_device+0x9b/0xb0()
> > Modules linked in: rtc_cmos snd_hda_intel rtc_core snd_pcm sr_mod floppy snd_timer snd_page_alloc rtc_lib ohci1394 serio_raw cdrom ieee1394 snd_hwdep snd soundcore sky2 button wmi joydev evdev sg raid456 async_xor async_memcpy async_tx xor raid0 usbhid ff_memless ehci_hcd sd_mod ohci_hcd edd raid1 ext3 jbd fan pata_marvell pata_atiixp thermal processor
> > Pid: 2275, comm: kjournald Not tainted 2.6.26-rc9-next #40
> > 
> > Call Trace:
> >  [<ffffffff8023cf9f>] warn_on_slowpath+0x5f/0x80
> >  [<ffffffff80220030>] ? hpet_rtc_interrupt+0x100/0x380
> >  [<ffffffff80263327>] ? __lock_acquire+0x8b7/0x1280
> >  [<ffffffff80291461>] ? mempool_alloc_slab+0x11/0x20
> >  [<ffffffff8035735b>] blk_plug_device+0x9b/0xb0
> >  [<ffffffff8045377f>] bitmap_startwrite+0xbf/0x1b0
> >  [<ffffffff802e8254>] ? bio_alloc_bioset+0x54/0xb0
> >  [<ffffffffa004eafa>] make_request+0x39a/0x810 [raid1]
> >  [<ffffffff802915cb>] ? mempool_alloc+0x5b/0x140
> >  [<ffffffff802915cb>] ? mempool_alloc+0x5b/0x140
> >  [<ffffffff803565ad>] generic_make_request+0x17d/0x2b0
> >  [<ffffffff80357f5c>] submit_bio+0x6c/0xf0
> >  [<ffffffff802e36d0>] submit_bh+0xf0/0x130
> >  [<ffffffffa001cce0>] journal_commit_transaction+0xa40/0x1000 [jbd]
> >  [<ffffffff802480d4>] ? try_to_del_timer_sync+0x44/0x90
> >  [<ffffffffa0020967>] kjournald+0xe7/0x250 [jbd]
> >  [<ffffffff80253ef0>] ? autoremove_wake_function+0x0/0x40
> >  [<ffffffffa0020880>] ? kjournald+0x0/0x250 [jbd]
> >  [<ffffffff80253a9d>] kthread+0x4d/0x80
> >  [<ffffffff8020c6b9>] child_rip+0xa/0x11
> >  [<ffffffff8020bcef>] ? restore_args+0x0/0x30
> >  [<ffffffff80253a50>] ? kthread+0x0/0x80
> >  [<ffffffff8020c6af>] ? child_rip+0x0/0x11
> > 
> > ---[ end trace bd85cedf792d0f08 ]---
> > 
> 
> This has now made it into the Linus' tree:

Why does this happen :(

> ------------[ cut here ]------------
> WARNING: at /home/rafael/src/linux-2.6/include/linux/blkdev.h:447 blk_plug_device+0x9b/0xb0()
> Modules linked in: rtc_cmos rtc_core sr_mod rtc_lib snd_hda_intel cdrom floppy snd_pcm snd_timer serio_raw snd_page_alloc ohci1394 snd_hwdep ieee1394 sky2 snd soundcore joydev button wmi evdev sg raid456 async_xor async_memcpy async_tx xor raid0 usbhid ff_memless ehci_hcd ohci_hcd sd_mod edd raid1 ext3 jbd fan pata_marvell pata_atiixp thermal processor
> Pid: 2264, comm: kjournald Not tainted 2.6.26-git #203
> 
> Call Trace:
>  [<ffffffff8023aadf>] warn_on_slowpath+0x5f/0x80
>  [<ffffffff80261075>] ? __lock_acquire+0x8d5/0x1290
>  [<ffffffff8028991b>] ? mempool_alloc+0x5b/0x140
>  [<ffffffff8034e43b>] blk_plug_device+0x9b/0xb0
>  [<ffffffff8044727f>] bitmap_startwrite+0xbf/0x1b0
>  [<ffffffff802dff44>] ? bio_alloc_bioset+0x54/0xb0
>  [<ffffffffa004ea9c>] make_request+0x39c/0x810 [raid1]
>  [<ffffffff8028991b>] ? mempool_alloc+0x5b/0x140
>  [<ffffffff8028991b>] ? mempool_alloc+0x5b/0x140
>  [<ffffffff8034d68d>] generic_make_request+0x17d/0x2b0
>  [<ffffffff8034f03c>] submit_bio+0x6c/0xf0
>  [<ffffffff802db3c0>] submit_bh+0xf0/0x130
>  [<ffffffffa001cce0>] journal_commit_transaction+0xa40/0x1000 [jbd]
>  [<ffffffff80245c74>] ? try_to_del_timer_sync+0x44/0x90
>  [<ffffffffa0020947>] kjournald+0xe7/0x250 [jbd]
>  [<ffffffff80251a60>] ? autoremove_wake_function+0x0/0x40
>  [<ffffffffa0020860>] ? kjournald+0x0/0x250 [jbd]
>  [<ffffffff8025160d>] kthread+0x4d/0x80
>  [<ffffffff8020c6c9>] child_rip+0xa/0x11
>  [<ffffffff8020bcff>] ? restore_args+0x0/0x30
>  [<ffffffff802515c0>] ? kthread+0x0/0x80
>  [<ffffffff8020c6bf>] ? child_rip+0x0/0x11
> 
> ---[ end trace a367ac91f145af0b ]---
> 

a) that's a real bug.  ->queue_flags requires queue_lock coverage
   for the nonatomic bitops and without that we have ghastly subtle
   races.

b) queue_is_locked() is wrong.  On CONFIG_PREEMPT=y, CONFIG_SMP=n
   kernels we *require* that preemption be disabled via
   spin_lock(queue_lock) but that function fails to handle this case
   correctly.

c) WARN_ON_ONCE() is pretty porky and if we want to retain those
   warnings in queue_flag_test_and_clear() and
   queue_flag_test_and_set() (which seems a good idea) then they should
   be uninlined.

2.6.27-rc1: WARNING: at /home/rafael/src/linux-next/include/linux/blkdev.h:447

[Rafael J. Wysocki]

On Thursday, 17 of July 2008, Rafael J. Wysocki wrote:
> On Saturday, 12 of July 2008, Rafael J. Wysocki wrote:
> > On Saturday, 12 of July 2008, Vegard Nossum wrote:
> > > On Sat, Jul 12, 2008 at 8:51 PM, Rafael J. Wysocki <rjw-KKrjLPT3xs0@public.gmane.org> wrote:
> > > > and the second one is the following:
> [--snip--]
> > 
> > It turns out that this happened before, but I've been overlooking it.  This is
> > a trace from the Friday's linux-next:
> > 
> > ------------[ cut here ]------------
> > WARNING: at /home/rafael/src/linux-next/include/linux/blkdev.h:447 blk_plug_device+0x9b/0xb0()
> > Modules linked in: rtc_cmos snd_hda_intel rtc_core snd_pcm sr_mod floppy snd_timer snd_page_alloc rtc_lib ohci1394 serio_raw cdrom ieee1394 snd_hwdep snd soundcore sky2 button wmi joydev evdev sg raid456 async_xor async_memcpy async_tx xor raid0 usbhid ff_memless ehci_hcd sd_mod ohci_hcd edd raid1 ext3 jbd fan pata_marvell pata_atiixp thermal processor
> > Pid: 2275, comm: kjournald Not tainted 2.6.26-rc9-next #40
> > 
> > Call Trace:
> >  [<ffffffff8023cf9f>] warn_on_slowpath+0x5f/0x80
> >  [<ffffffff80220030>] ? hpet_rtc_interrupt+0x100/0x380
> >  [<ffffffff80263327>] ? __lock_acquire+0x8b7/0x1280
> >  [<ffffffff80291461>] ? mempool_alloc_slab+0x11/0x20
> >  [<ffffffff8035735b>] blk_plug_device+0x9b/0xb0
> >  [<ffffffff8045377f>] bitmap_startwrite+0xbf/0x1b0
> >  [<ffffffff802e8254>] ? bio_alloc_bioset+0x54/0xb0
> >  [<ffffffffa004eafa>] make_request+0x39a/0x810 [raid1]
> >  [<ffffffff802915cb>] ? mempool_alloc+0x5b/0x140
> >  [<ffffffff802915cb>] ? mempool_alloc+0x5b/0x140
> >  [<ffffffff803565ad>] generic_make_request+0x17d/0x2b0
> >  [<ffffffff80357f5c>] submit_bio+0x6c/0xf0
> >  [<ffffffff802e36d0>] submit_bh+0xf0/0x130
> >  [<ffffffffa001cce0>] journal_commit_transaction+0xa40/0x1000 [jbd]
> >  [<ffffffff802480d4>] ? try_to_del_timer_sync+0x44/0x90
> >  [<ffffffffa0020967>] kjournald+0xe7/0x250 [jbd]
> >  [<ffffffff80253ef0>] ? autoremove_wake_function+0x0/0x40
> >  [<ffffffffa0020880>] ? kjournald+0x0/0x250 [jbd]
> >  [<ffffffff80253a9d>] kthread+0x4d/0x80
> >  [<ffffffff8020c6b9>] child_rip+0xa/0x11
> >  [<ffffffff8020bcef>] ? restore_args+0x0/0x30
> >  [<ffffffff80253a50>] ? kthread+0x0/0x80
> >  [<ffffffff8020c6af>] ? child_rip+0x0/0x11
> > 
> > ---[ end trace bd85cedf792d0f08 ]---
> > 
> 
> This has now made it into the Linus' tree:
> 
> ------------[ cut here ]------------
> WARNING: at /home/rafael/src/linux-2.6/include/linux/blkdev.h:447 blk_plug_device+0x9b/0xb0()
> Modules linked in: rtc_cmos rtc_core sr_mod rtc_lib snd_hda_intel cdrom floppy snd_pcm snd_timer serio_raw snd_page_alloc ohci1394 snd_hwdep ieee1394 sky2 snd soundcore joydev button wmi evdev sg raid456 async_xor async_memcpy async_tx xor raid0 usbhid ff_memless ehci_hcd ohci_hcd sd_mod edd raid1 ext3 jbd fan pata_marvell pata_atiixp thermal processor
> Pid: 2264, comm: kjournald Not tainted 2.6.26-git #203
> 
> Call Trace:
>  [<ffffffff8023aadf>] warn_on_slowpath+0x5f/0x80
>  [<ffffffff80261075>] ? __lock_acquire+0x8d5/0x1290
>  [<ffffffff8028991b>] ? mempool_alloc+0x5b/0x140
>  [<ffffffff8034e43b>] blk_plug_device+0x9b/0xb0
>  [<ffffffff8044727f>] bitmap_startwrite+0xbf/0x1b0
>  [<ffffffff802dff44>] ? bio_alloc_bioset+0x54/0xb0
>  [<ffffffffa004ea9c>] make_request+0x39c/0x810 [raid1]
>  [<ffffffff8028991b>] ? mempool_alloc+0x5b/0x140
>  [<ffffffff8028991b>] ? mempool_alloc+0x5b/0x140
>  [<ffffffff8034d68d>] generic_make_request+0x17d/0x2b0
>  [<ffffffff8034f03c>] submit_bio+0x6c/0xf0
>  [<ffffffff802db3c0>] submit_bh+0xf0/0x130
>  [<ffffffffa001cce0>] journal_commit_transaction+0xa40/0x1000 [jbd]
>  [<ffffffff80245c74>] ? try_to_del_timer_sync+0x44/0x90
>  [<ffffffffa0020947>] kjournald+0xe7/0x250 [jbd]
>  [<ffffffff80251a60>] ? autoremove_wake_function+0x0/0x40
>  [<ffffffffa0020860>] ? kjournald+0x0/0x250 [jbd]
>  [<ffffffff8025160d>] kthread+0x4d/0x80
>  [<ffffffff8020c6c9>] child_rip+0xa/0x11
>  [<ffffffff8020bcff>] ? restore_args+0x0/0x30
>  [<ffffffff802515c0>] ? kthread+0x0/0x80
>  [<ffffffff8020c6bf>] ? child_rip+0x0/0x11
> 
> ---[ end trace a367ac91f145af0b ]---

This also happens in 2.6.27-rc1:

------------[ cut here ]------------
WARNING: at /home/rafael/src/linux-2.6/include/linux/blkdev.h:447 blk_plug_device+0x9b/0xb0()
Modules linked in: snd_hda_intel snd_pcm rtc_cmos rtc_core sr_mod snd_timer floppy rtc_lib snd_page_alloc ohci1394 snd_hwdep snd cdrom ieee1394 serio_raw soundcore sky2 wmi button joydev evdev sg raid456 async_xor async_memcpy async_tx xor raid0 usbhid ff_memless ehci_hcd ohci_hcd sd_mod crc_t10dif edd raid1 ext3 jbd fan pata_marvell pata_atiixp thermal processor
Pid: 2268, comm: kjournald Not tainted 2.6.27-rc1-git #211

Call Trace:
 [<ffffffff8023af5f>] warn_on_slowpath+0x5f/0x80
 [<ffffffff802af8e3>] ? cache_alloc_debugcheck_after+0xc3/0x1f0
 [<ffffffff80260d75>] ? __lock_acquire+0x865/0xef0
 [<ffffffff8034fc7b>] blk_plug_device+0x9b/0xb0
 [<ffffffff8044d5bf>] bitmap_startwrite+0xbf/0x1b0
 [<ffffffff802dfd84>] ? bio_alloc_bioset+0x54/0xb0
 [<ffffffffa004f8ed>] make_request+0x39d/0x810 [raid1]
 [<ffffffff8028979b>] ? mempool_alloc+0x5b/0x140
 [<ffffffff8028979b>] ? mempool_alloc+0x5b/0x140
 [<ffffffff8034ecce>] generic_make_request+0x17e/0x2b0
 [<ffffffff8034ee6c>] submit_bio+0x6c/0xf0
 [<ffffffff802dbeb0>] submit_bh+0xf0/0x130
 [<ffffffffa001de35>] journal_commit_transaction+0xa75/0x1040 [jbd]
 [<ffffffff802456d4>] ? try_to_del_timer_sync+0x44/0x90
 [<ffffffffa0021167>] kjournald+0xe7/0x250 [jbd]
 [<ffffffff80251740>] ? autoremove_wake_function+0x0/0x40
 [<ffffffffa0021080>] ? kjournald+0x0/0x250 [jbd]
 [<ffffffff8025125d>] kthread+0x4d/0x80
 [<ffffffff8020c6d9>] child_rip+0xa/0x11
 [<ffffffff8020bd0f>] ? restore_args+0x0/0x30
 [<ffffffff80251210>] ? kthread+0x0/0x80
 [<ffffffff8020c6cf>] ? child_rip+0x0/0x11

---[ end trace e8b3210386e976bd ]---

dmesg: http://www.sisk.pl/kernel/debug/mainline/2.6.27-rc1/dmesg-M3A32-MVP.log
config: http://www.sisk.pl/kernel/debug/mainline/2.6.27-rc1/config-M3A32-MVP

Thanks,
Rafael