[BUG] XFS crash using Realtime Preemption patch

[BUG] XFS crash using Realtime Preemption patch

[Nathaniel W. Filardo]

Hello all.

Using 2.6.10-rc3-mm1-V0.7.33-04 and TCFQ ver 17, I get the following crash 
while trying to sync the portage tree, though the system seems stable 
under interactive load (read: an rm command went OK prior to this crash).

Machine is a 933MHz transmeta laptop with IDE disk.

Any more information you need?
--nwf;

kernel BUG at kernel/rt.c:1210!
invalid operand: 0000 [#1]
PREEMPT
Modules linked in: hostap_pci hostap uhci_hcd rtc eth1394 ohci1394 
ieee1394 pcmc
ia 8139too mii yenta_socket pcmcia_core belkin_sa usbserial ehci_hcd 
i2c_core oh
ci_hcd usbcore tun crc32
CPU:    0
EIP:    0060:[<c01308ac>]    Not tainted VLI
EFLAGS: 00010286   (2.6.10-rc3-mm1-V0.7.33-04-tcfq17)
EIP is at up_write+0x8c/0xa0
eax: 00000019   ebx: c5693284   ecx: 00000000   edx: 00000000
esi: c56931f4   edi: c5ba8814   ebp: 00000000   esp: ce003d1c
ds: 007b   es: 007b   ss: 0068   preempt: 00000001
Process emerge (pid: 19312, threadinfo=ce003000 task=ce7ff470)
Stack: c0357cdb c035a116 000004ba 00000000 ce003000 d47c64b0 00000008 
c01d2d5c
        c56931f4 d47c64b0 c01d728c ce003d68 ce003d6c 00000000 00000000 
d6c3c96c
        00000000 d6c3cc00 00000002 c4eb7000 cb02e5e0 c5ba8814 cf67511c 
d6c3cc00
Call Trace:
  [<c01d2d5c>] xfs_iunlock+0x7c/0xa0 (32)
  [<c01d728c>] xfs_iflush+0x1cc/0x440 (12)
  [<c01d85a0>] xfs_inode_item_push+0x10/0x20 (60)
  [<c01ebd0a>] xfs_trans_push_ail+0x1aa/0x1e0 (8)
  [<c01ddadd>] xlog_grant_push_ail+0x14d/0x180 (68)
  [<c01dc9fc>] xfs_log_reserve+0x9c/0xc0 (60)
  [<c01f7569>] kmem_zone_alloc+0x39/0xa0 (8)
  [<c01ea89a>] xfs_trans_reserve+0x8a/0x1e0 (20)
  [<c01d56f6>] xfs_itruncate_finish+0x1a6/0x390 (40)
  [<c01ecd6b>] xfs_trans_ijoin+0x2b/0x80 (96)
  [<c01f266a>] xfs_inactive+0x3ea/0x4c0 (20)
  [<c0144f30>] truncate_inode_pages_range+0x100/0x350 (20)
  [<c02023e0>] vn_rele+0x50/0xe0 (24)
  [<c0202467>] vn_rele+0xd7/0xe0 (24)
  [<c017154a>] dput+0x8a/0x2a0 (4)
  [<c0200bbf>] linvfs_clear_inode+0xf/0x20 (20)
  [<c01738d8>] clear_inode+0x158/0x160 (8)
  [<c0145197>] truncate_inode_pages+0x17/0x20 (12)
  [<c017483f>] generic_delete_inode+0xef/0x110 (12)
  [<c013100a>] atomic_dec_and_spin_lock+0x1a/0x70 (8)
  [<c01749f7>] iput+0x57/0x90 (16)
  [<c016a5a1>] sys_unlink+0xc1/0x120 (24)
  [<c0102fb3>] syscall_call+0x7/0xb (84)
Code: 08 e8 d9 a7 fe ff e8 b4 34 fd ff eb a6 c7 04 24 db 7c 35 c0 b8 ba 04 
00 00
  89 44 24 08 b8 16 a1 35 c0 89 44 24 04 e8 b4 a7 fe ff <0f> 0b ba 04 16 a1 
35 c0
  eb 85 8d 76 00 8d bc 27 00 00 00 00 83

Re: [BUG] XFS crash using Realtime Preemption patch

[Ingo Molnar]

* Nathaniel W. Filardo <nwf@andrew.cmu.edu> wrote:

> Hello all.
> 
> Using 2.6.10-rc3-mm1-V0.7.33-04 and TCFQ ver 17, I get the following
> crash while trying to sync the portage tree, though the system seems
> stable under interactive load (read: an rm command went OK prior to
> this crash).
> 
> Machine is a 933MHz transmeta laptop with IDE disk.
> 
> Any more information you need?
> --nwf;
> 
> kernel BUG at kernel/rt.c:1210!

Seems like an XFS bug at first sight. The BUG() means that an up_write()
was done while a down_read() was active for the lock. Does XFS really do
this? Initialization/destruction bugs can possibly cause such messages
too.

Here's the call sequence:

> EIP is at up_write+0x8c/0xa0
>  [<c01d2d5c>] xfs_iunlock+0x7c/0xa0 (32)
>  [<c01d728c>] xfs_iflush+0x1cc/0x440 (12)
>  [<c01d85a0>] xfs_inode_item_push+0x10/0x20 (60)
>  [<c01ebd0a>] xfs_trans_push_ail+0x1aa/0x1e0 (8)
>  [<c01ddadd>] xlog_grant_push_ail+0x14d/0x180 (68)
>  [<c01dc9fc>] xfs_log_reserve+0x9c/0xc0 (60)
>  [<c01f7569>] kmem_zone_alloc+0x39/0xa0 (8)
>  [<c01ea89a>] xfs_trans_reserve+0x8a/0x1e0 (20)
>  [<c01d56f6>] xfs_itruncate_finish+0x1a6/0x390 (40)
>  [<c01ecd6b>] xfs_trans_ijoin+0x2b/0x80 (96)
>  [<c01f266a>] xfs_inactive+0x3ea/0x4c0 (20)
>  [<c0144f30>] truncate_inode_pages_range+0x100/0x350 (20)
>  [<c02023e0>] vn_rele+0x50/0xe0 (24)
>  [<c0202467>] vn_rele+0xd7/0xe0 (24)
>  [<c017154a>] dput+0x8a/0x2a0 (4)
>  [<c0200bbf>] linvfs_clear_inode+0xf/0x20 (20)
>  [<c01738d8>] clear_inode+0x158/0x160 (8)
>  [<c0145197>] truncate_inode_pages+0x17/0x20 (12)
>  [<c017483f>] generic_delete_inode+0xef/0x110 (12)
>  [<c013100a>] atomic_dec_and_spin_lock+0x1a/0x70 (8)
>  [<c01749f7>] iput+0x57/0x90 (16)
>  [<c016a5a1>] sys_unlink+0xc1/0x120 (24)
>  [<c0102fb3>] syscall_call+0x7/0xb (84)

Re: [BUG] XFS crash using Realtime Preemption patch

[Nathaniel W. Filardo]

On Tue, 21 Dec 2004, Ingo Molnar wrote:

>
> * Nathaniel W. Filardo <nwf@andrew.cmu.edu> wrote:
>
>> Hello all.
>>
>> Using 2.6.10-rc3-mm1-V0.7.33-04 and TCFQ ver 17, I get the following
>> crash while trying to sync the portage tree, though the system seems
>> stable under interactive load (read: an rm command went OK prior to
>> this crash).
>>
>> Machine is a 933MHz transmeta laptop with IDE disk.
>>
>> Any more information you need?
>> --nwf;
>>
>> kernel BUG at kernel/rt.c:1210!
>
> Seems like an XFS bug at first sight. The BUG() means that an up_write()
> was done while a down_read() was active for the lock. Does XFS really do
> this? Initialization/destruction bugs can possibly cause such messages
> too.

>From what I can make of the XFS code, it looks fine.  Somebody's either 
being horribly rude to memory (stomp) or there's some other issue... 
sadly, the machine is a laptop and thus nigh on impossible to get any real 
debugging out of.

I don't *think* it's memory issues as it's pretty reproducable and is 
exactly the same every time I've tried.

Open to suggestions.

--nwf;

> Here's the call sequence:
>
>> EIP is at up_write+0x8c/0xa0
>>  [<c01d2d5c>] xfs_iunlock+0x7c/0xa0 (32)

fs/xfs/linux-2.6/mrlock.h: mrunlock( mrlock_t *mrp )
 	Switches behavior based on mr_writer flag as to whether to
 	up_read or up_write.  Since we're taking the up_write branch,
 	we should look for where a down_read was called.  This can
 	come through via a mraccessf or mrtryaccess.

 	  if (mrp->mr_writer) {
 	    mrp->mr_writer = 0;
 	    up_write(&mrp->mr_lock);
 	  } else {
 	    up_read(&mrp->mr_lock);
 	  }

fs/xfs/xfs_iget.c
 	calls mrunlock() inlined - see abov
 		on ip->i_lock and/or ip->i_iolock, based on flags

>>  [<c01d728c>] xfs_iflush+0x1cc/0x440 (12)

fs/xfs/xfs_inode.c
 	ASSERT's that ip->i_lock is already taken, so we're probably
 	chasing after that one.

>>  [<c01d85a0>] xfs_inode_item_push+0x10/0x20 (60)

fs/xfs/xfs_inode_item.c
 	ASSERT's that lock is already taken

>>  [<c01ebd0a>] xfs_trans_push_ail+0x1aa/0x1e0 (8)

fs/xfs/xfs_trans_ail.c
 	through IOP_TRYLOCK (maps to xfs_inode_item_trylock)
 	through xfs_ilock_nowait (SHARED)
 	locks both ip->i_lock and ip->i_iolock through mrtryaccess()

Re: [BUG] XFS crash using Realtime Preemption patch

[Nathan Scott]

On Tue, Dec 21, 2004 at 11:40:43AM +0100, Ingo Molnar wrote:
> 
> * Nathaniel W. Filardo <nwf@andrew.cmu.edu> wrote:
> 
> > Hello all.
> > 
> > Using 2.6.10-rc3-mm1-V0.7.33-04 and TCFQ ver 17, I get the following
> > crash while trying to sync the portage tree, though the system seems
> > stable under interactive load (read: an rm command went OK prior to
> > this crash).
> > 
> > Machine is a 933MHz transmeta laptop with IDE disk.
> > 
> > Any more information you need?
> > --nwf;
> > 
> > kernel BUG at kernel/rt.c:1210!
> 
> Seems like an XFS bug at first sight. The BUG() means that an up_write()
> was done while a down_read() was active for the lock. Does XFS really do
> this?

That should definately not happen.  Something has gone wrong in
mrlock.h if so - or it could be the incore xfs_inode has been
trampled on, and the mrlock writer state has become inappropriately
set.. that would cause the wrong branch to be taken and we'd end
up with the situation you've described here.

cheers.

-- 
Nathan

Re: [BUG] XFS crash using Realtime Preemption patch

[Nathaniel W. Filardo]

I added
         BUG_ON( (mrp->mr_writer != 0) && (mrp->mr_writer != 1) );
to mrlock.h : mrunlock() to see if it was corruption and got the following 
instead.  It's a similar call pathway, but somewhat different.

kernel BUG at kernel/rt.c:1210!
invalid operand: 0000 [#1]
PREEMPT
Modules linked in: uhci_hcd rtc eth1394 ohci1394 ieee1394 pcmcia 
hostap_pci hostap 8139too mii yenta_socket pcmcia_core ehci_hcd 
i2c_ali15x3 i2c_core ohci_hcd usbcore tun crc32
CPU:    0
EIP:    0060:[<c01308ac>]    Not tainted VLI
EFLAGS: 00010286   (2.6.10-rc3-mm1-V0.7.33-04-tcfq17)
EIP is at up_write+0x8c/0xa0
eax: 00000019   ebx: d039171c   ecx: 00000000   edx: 00000000
esi: 00000008   edi: d039168c   ebp: 00000000   esp: cf8a6cdc
ds: 007b   es: 007b   ss: 0068   preempt: 00000001
Process rm (pid: 8661, threadinfo=cf8a6000 task=d5014370)
Stack: c0357dbb c035a1f6 000004ba c0130ddf 00000010 00000286 d039171c 
c01d2d8c
        cf8a6000 d038dec8 d020bb44 d039168c d038dec8 d020bb44 c01d735c 
cf8a6d38
        cf8a6d3c 00000000 00000000 d6c3eb4c 00000000 d6c3ec00 00000002 
c7af1700
Call Trace:
  [<c0130ddf>] down_trylock+0x1f/0xb0 (16)
  [<c01d2d8c>] xfs_iunlock+0x6c/0x130 (16)
  [<c01d735c>] xfs_iflush+0x1cc/0x440 (28)
  [<c01d8670>] xfs_inode_item_push+0x10/0x20 (60)
  [<c01ebdda>] xfs_trans_push_ail+0x1aa/0x1e0 (8)
  [<c01ddbad>] xlog_grant_push_ail+0x14d/0x180 (68)
  [<c01dcacc>] xfs_log_reserve+0x9c/0xc0 (60)
  [<c01f7639>] kmem_zone_alloc+0x39/0xa0 (8)
  [<c01ea96a>] xfs_trans_reserve+0x8a/0x1e0 (20)
  [<c01aed86>] xfs_bmap_finish+0xc6/0x170 (40)
  [<c01d589a>] xfs_itruncate_finish+0x27a/0x390 (48)
  [<c01ece3b>] xfs_trans_ijoin+0x2b/0x80 (96)
  [<c01f273a>] xfs_inactive+0x3ea/0x4c0 (20)
  [<c02024b0>] vn_rele+0x50/0xe0 (44)
  [<c0202537>] vn_rele+0xd7/0xe0 (24)
  [<c017154a>] dput+0x8a/0x2a0 (4)
  [<c0200c8f>] linvfs_clear_inode+0xf/0x20 (20)
  [<c01738d8>] clear_inode+0x158/0x160 (8)
  [<c017483f>] generic_delete_inode+0xef/0x110 (24)
  [<c013100a>] atomic_dec_and_spin_lock+0x1a/0x70 (8)
  [<c01749f7>] iput+0x57/0x90 (16)
  [<c016a5a1>] sys_unlink+0xc1/0x120 (24)
  [<c0102fb3>] syscall_call+0x7/0xb (84)
Code: 08 e8 d9 a7 fe ff e8 b4 34 fd ff eb a6 c7 04 24 bb 7d 35 c0 b8 ba 04 
00 00 89 44 24 08 b8 f6 a1 35 c0 89 44 24 04 e8 b4 a7 fe ff <0f> 0b ba 04 
f6 a1 35 c0 eb 85 8d 76 00 8d bc 27 00 00 00 00 83

--nwf;

On Wed, 22 Dec 2004, Nathan Scott wrote:

> On Tue, Dec 21, 2004 at 11:40:43AM +0100, Ingo Molnar wrote:
>>
>> * Nathaniel W. Filardo <nwf@andrew.cmu.edu> wrote:
>>
>>> Hello all.
>>>
>>> Using 2.6.10-rc3-mm1-V0.7.33-04 and TCFQ ver 17, I get the following
>>> crash while trying to sync the portage tree, though the system seems
>>> stable under interactive load (read: an rm command went OK prior to
>>> this crash).
>>>
>>> Machine is a 933MHz transmeta laptop with IDE disk.
>>>
>>> Any more information you need?
>>> --nwf;
>>>
>>> kernel BUG at kernel/rt.c:1210!
>>
>> Seems like an XFS bug at first sight. The BUG() means that an up_write()
>> was done while a down_read() was active for the lock. Does XFS really do
>> this?
>
> That should definately not happen.  Something has gone wrong in
> mrlock.h if so - or it could be the incore xfs_inode has been
> trampled on, and the mrlock writer state has become inappropriately
> set.. that would cause the wrong branch to be taken and we'd end
> up with the situation you've described here.
>
> cheers.
>
> --
> Nathan
>
>

Re: [BUG] XFS crash using Realtime Preemption patch

[Nathan Scott]

On Wed, Dec 22, 2004 at 02:50:20AM -0500, Nathaniel W. Filardo wrote:
> I added
>          BUG_ON( (mrp->mr_writer != 0) && (mrp->mr_writer != 1) );
> to mrlock.h : mrunlock() to see if it was corruption and got the following 

Good thinkin.

> instead.  It's a similar call pathway, but somewhat different.

Thats exactly the same call path right?  There is no call to
down_trylock from xfs_iunlock (goes directly to up_write) so
I think that must just be leftover stack junk, and we should
assume the path was xfs_iunlock->(inline)mrunlock->up_write,
which means your BUG_ON didn't trigger... (put a printk of the
value there, maybe we'll get lucky and get some recognisable
hex pattern).

> kernel BUG at kernel/rt.c:1210!
> invalid operand: 0000 [#1]
> PREEMPT
> Modules linked in: uhci_hcd rtc eth1394 ohci1394 ieee1394 pcmcia 
> hostap_pci hostap 8139too mii yenta_socket pcmcia_core ehci_hcd 
> i2c_ali15x3 i2c_core ohci_hcd usbcore tun crc32
> CPU:    0
> EIP:    0060:[<c01308ac>]    Not tainted VLI
> EFLAGS: 00010286   (2.6.10-rc3-mm1-V0.7.33-04-tcfq17)
> EIP is at up_write+0x8c/0xa0
> eax: 00000019   ebx: d039171c   ecx: 00000000   edx: 00000000
> esi: 00000008   edi: d039168c   ebp: 00000000   esp: cf8a6cdc
> ds: 007b   es: 007b   ss: 0068   preempt: 00000001
> Process rm (pid: 8661, threadinfo=cf8a6000 task=d5014370)
> Stack: c0357dbb c035a1f6 000004ba c0130ddf 00000010 00000286 d039171c 
> c01d2d8c
>         cf8a6000 d038dec8 d020bb44 d039168c d038dec8 d020bb44 c01d735c 
> cf8a6d38
>         cf8a6d3c 00000000 00000000 d6c3eb4c 00000000 d6c3ec00 00000002 
> c7af1700
> Call Trace:
>   [<c0130ddf>] down_trylock+0x1f/0xb0 (16)
>   [<c01d2d8c>] xfs_iunlock+0x6c/0x130 (16)
>   [<c01d735c>] xfs_iflush+0x1cc/0x440 (28)

-- 
Nathan

Re: [BUG] XFS crash using Realtime Preemption patch

[Nathaniel W. Filardo]

On Thu, 23 Dec 2004, Nathan Scott wrote:

> On Wed, Dec 22, 2004 at 02:50:20AM -0500, Nathaniel W. Filardo wrote:
>> I added
>>          BUG_ON( (mrp->mr_writer != 0) && (mrp->mr_writer != 1) );
>> to mrlock.h : mrunlock() to see if it was corruption and got the following
>
> Good thinkin.
>
>> instead.  It's a similar call pathway, but somewhat different.
>
> Thats exactly the same call path right?  There is no call to
> down_trylock from xfs_iunlock (goes directly to up_write) so
> I think that must just be leftover stack junk, and we should
> assume the path was xfs_iunlock->(inline)mrunlock->up_write,
> which means your BUG_ON didn't trigger... (put a printk of the
> value there, maybe we'll get lucky and get some recognisable
> hex pattern).

If the BUG_ON didn't trigger, we shouldn't get a recognisable hex pattern 
- we'll get a 1 or a 0 every time, yes?

I'll believe that it's the same trace.  I changed the value for mr_writer
in a writer state from 1 to 128 (leaving readers as 0) and got the same 
dump, which means that the new
 	BUG_ON( (mrp->mr_writer != 0) && (mrp->mr_writer != 128 ) );
didn't fire.  So I don't think it's memory corruption unless my RAM is 
psychic. =)

It looks like it might be a buggy attempt to upgrade a reader lock to a 
writer, or a more general failure of the locking semantics...  Is the 
former possible along this path?

>> kernel BUG at kernel/rt.c:1210!
>> invalid operand: 0000 [#1]
>> PREEMPT
>> Modules linked in: uhci_hcd rtc eth1394 ohci1394 ieee1394 pcmcia
>> hostap_pci hostap 8139too mii yenta_socket pcmcia_core ehci_hcd
>> i2c_ali15x3 i2c_core ohci_hcd usbcore tun crc32
>> CPU:    0
>> EIP:    0060:[<c01308ac>]    Not tainted VLI
>> EFLAGS: 00010286   (2.6.10-rc3-mm1-V0.7.33-04-tcfq17)
>> EIP is at up_write+0x8c/0xa0
>> eax: 00000019   ebx: d039171c   ecx: 00000000   edx: 00000000
>> esi: 00000008   edi: d039168c   ebp: 00000000   esp: cf8a6cdc
>> ds: 007b   es: 007b   ss: 0068   preempt: 00000001
>> Process rm (pid: 8661, threadinfo=cf8a6000 task=d5014370)
>> Stack: c0357dbb c035a1f6 000004ba c0130ddf 00000010 00000286 d039171c
>> c01d2d8c
>>         cf8a6000 d038dec8 d020bb44 d039168c d038dec8 d020bb44 c01d735c
>> cf8a6d38
>>         cf8a6d3c 00000000 00000000 d6c3eb4c 00000000 d6c3ec00 00000002
>> c7af1700
>> Call Trace:
>>   [<c0130ddf>] down_trylock+0x1f/0xb0 (16)
>>   [<c01d2d8c>] xfs_iunlock+0x6c/0x130 (16)
>>   [<c01d735c>] xfs_iflush+0x1cc/0x440 (28)
>
> --
> Nathan
>
>

Re: [BUG] XFS crash using Realtime Preemption patch

[Nathan Scott]

On Thu, Dec 23, 2004 at 10:27:32PM -0500, Nathaniel W. Filardo wrote:
> If the BUG_ON didn't trigger, we shouldn't get a recognisable hex pattern 
> - we'll get a 1 or a 0 every time, yes?

Of course, you're right - sorry, my brains switched off.  I'll
take a look in the new year if you don't figure it out before
I get back. :)  The only other thought I had was perhaps the
writer field assignment is getting reordered around the atual
lock, may need some judicious use of memory barriers in there;
that needs some details analysis though.

cheers.

-- 
Nathan