2.6.25-rc6: kernel BUG at fs/sysfs/file.c:89

2.6.25-rc6: kernel BUG at fs/sysfs/file.c:89

[Christian Kujau]

Hi,

while attempting to test the patch which should fix the dm-crypt hang[0], 
I applied the diff to -rc6. After rebooting I increased disk i/o and 
shortly after the box rebooted - I noticed this earlier with -rc5 too, but 
had no debug messages at hand. Well, the box is running again and tar(1) 
is reading with 32MB/s for some time now - but is not rebooting, which is 
good :)
(I changed kernel.panic and kernel.panic_on_oops to zero).
However, it's printing stuff like this:

[ 2632.423419] ------------[ cut here ]------------
[ 2632.423762] kernel BUG at fs/sysfs/file.c:89!
[ 2632.424089] invalid opcode: 0000 [#1] 
[ 2632.424398] Modules linked in: sha256_generic act_police sch_ingress cls_u32 sch_sfq sch_cbq ipt_ULOG x_tables nfsd lockd nfs_acl auth_rpcgss exportfs tun sunrpc fuse twofish_i586 twofish_common eeprom w83l785ts asb100 hwmon_vid usb_storage zd1211rw firmware_class mac80211 i2c_nforce2 snd_intel8x0 snd_ac97_codec i2c_core cfg80211 ac97_bus snd_pcm snd_timer snd soundcore snd_page_alloc
[ 2632.426407] 
[ 2632.426651] Pid: 10297, comm: tar Not tainted (2.6.25-rc6 #3)
[ 2632.427019] EIP: 0060:[<c01a8add>] EFLAGS: 00010212 CPU: 0
[ 2632.427386] EIP is at sysfs_read_file+0xdd/0xf0
[ 2632.427717] EAX: 00000001 EBX: f5691f00 ECX: 00000003 EDX: f7ca1e70
[ 2632.428100] ESI: 00001000 EDI: f7ca1ed0 EBP: f5691f14 ESP: f6f3ff54
[ 2632.428482]  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
[ 2632.428758] Process tar (pid: 10297, ti=f6f3f000 task=f6290d60 task.ti=f6f3f000)
[ 2632.428921] Stack: c0164ff7 f5ca6000 00001000 0866ce00 c0550d50 f7d8fab8 f776b180 0866ce00 
[ 2632.429174]        c01a8a00 00001000 c016868d f6f3ffa0 00000003 f776b180 fffffff7 0866ce00 
[ 2632.429430]        f6f3f000 c0168a91 f6f3ffa0 00000000 00000000 00000000 00000003 00001000 
[ 2632.429688] Call Trace:
[ 2632.429884]  [<c0164ff7>] kmem_cache_free+0xa7/0xf0
[ 2632.430023]  [<c01a8a00>] sysfs_read_file+0x0/0xf0
[ 2632.430159]  [<c016868d>] vfs_read+0x9d/0x140
[ 2632.430333]  [<c0168a91>] sys_read+0x41/0x70
[ 2632.430657]  [<c0102dee>] sysenter_past_esp+0x5f/0xa5
[ 2632.431006]  =======================
[ 2632.431308] Code: 18 89 f0 5b 5e 5f 5d c3 be ed ff ff ff eb e8 b8 d0 00 00 00 be f4 ff ff ff e8 e0 31 fa ff 85 c0 89 43 0c 0f 85 6d ff ff ff eb cc <0f> 0b 90 eb fd 8d b4 26 00 00 00 00 8d bc 27 00 00 00 00 83 ec 
[ 2632.432467] EIP: [<c01a8add>] sysfs_read_file+0xdd/0xf0 SS:ESP 0068:f6f3ff54
[ 2632.432630] ---[ end trace 9959fa4f11f46a8e ]---

Please see the full dmesg and .config: http://nerdbynature.de/bits/2.6.25-rc6/

Thanks,
Christian.

[0] http://lkml.org/lkml/2008/3/17/214
-- 
BOFH excuse #197:

I'm sorry a pentium won't do, you need an SGI to connect with us.

Re: 2.6.25-rc6: kernel BUG at fs/sysfs/file.c:89

[Rafael J. Wysocki]

On Friday, 21 of March 2008, Christian Kujau wrote:
> Hi,

Hi,

> while attempting to test the patch which should fix the dm-crypt hang[0], 
> I applied the diff to -rc6. After rebooting I increased disk i/o and 
> shortly after the box rebooted - I noticed this earlier with -rc5 too, but 
> had no debug messages at hand. Well, the box is running again and tar(1) 
> is reading with 32MB/s for some time now - but is not rebooting, which is 
> good :)
> (I changed kernel.panic and kernel.panic_on_oops to zero).
> However, it's printing stuff like this:

This looks worrisome (some experts added to the CC list).

> [ 2632.423419] ------------[ cut here ]------------
> [ 2632.423762] kernel BUG at fs/sysfs/file.c:89!
> [ 2632.424089] invalid opcode: 0000 [#1] 
> [ 2632.424398] Modules linked in: sha256_generic act_police sch_ingress cls_u32 sch_sfq sch_cbq ipt_ULOG x_tables nfsd lockd nfs_acl auth_rpcgss exportfs tun sunrpc fuse twofish_i586 twofish_common eeprom w83l785ts asb100 hwmon_vid usb_storage zd1211rw firmware_class mac80211 i2c_nforce2 snd_intel8x0 snd_ac97_codec i2c_core cfg80211 ac97_bus snd_pcm snd_timer snd soundcore snd_page_alloc
> [ 2632.426407] 
> [ 2632.426651] Pid: 10297, comm: tar Not tainted (2.6.25-rc6 #3)
> [ 2632.427019] EIP: 0060:[<c01a8add>] EFLAGS: 00010212 CPU: 0
> [ 2632.427386] EIP is at sysfs_read_file+0xdd/0xf0
> [ 2632.427717] EAX: 00000001 EBX: f5691f00 ECX: 00000003 EDX: f7ca1e70
> [ 2632.428100] ESI: 00001000 EDI: f7ca1ed0 EBP: f5691f14 ESP: f6f3ff54
> [ 2632.428482]  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
> [ 2632.428758] Process tar (pid: 10297, ti=f6f3f000 task=f6290d60 task.ti=f6f3f000)
> [ 2632.428921] Stack: c0164ff7 f5ca6000 00001000 0866ce00 c0550d50 f7d8fab8 f776b180 0866ce00 
> [ 2632.429174]        c01a8a00 00001000 c016868d f6f3ffa0 00000003 f776b180 fffffff7 0866ce00 
> [ 2632.429430]        f6f3f000 c0168a91 f6f3ffa0 00000000 00000000 00000000 00000003 00001000 
> [ 2632.429688] Call Trace:
> [ 2632.429884]  [<c0164ff7>] kmem_cache_free+0xa7/0xf0
> [ 2632.430023]  [<c01a8a00>] sysfs_read_file+0x0/0xf0
> [ 2632.430159]  [<c016868d>] vfs_read+0x9d/0x140
> [ 2632.430333]  [<c0168a91>] sys_read+0x41/0x70
> [ 2632.430657]  [<c0102dee>] sysenter_past_esp+0x5f/0xa5
> [ 2632.431006]  =======================
> [ 2632.431308] Code: 18 89 f0 5b 5e 5f 5d c3 be ed ff ff ff eb e8 b8 d0 00 00 00 be f4 ff ff ff e8 e0 31 fa ff 85 c0 89 43 0c 0f 85 6d ff ff ff eb cc <0f> 0b 90 eb fd 8d b4 26 00 00 00 00 8d bc 27 00 00 00 00 83 ec 
> [ 2632.432467] EIP: [<c01a8add>] sysfs_read_file+0xdd/0xf0 SS:ESP 0068:f6f3ff54
> [ 2632.432630] ---[ end trace 9959fa4f11f46a8e ]---
> 
> Please see the full dmesg and .config: http://nerdbynature.de/bits/2.6.25-rc6/
> 
> Thanks,
> Christian.
> 
> [0] http://lkml.org/lkml/2008/3/17/214



-- 
"Premature optimization is the root of all evil." - Donald Knuth

Re: 2.6.25-rc6: kernel BUG at fs/sysfs/file.c:89

[Andrew Morton]

On Sat, 22 Mar 2008 02:26:34 +0100 "Rafael J. Wysocki" <rjw@sisk.pl> wrote:

> On Friday, 21 of March 2008, Christian Kujau wrote:
> > Hi,
> 
> Hi,
> 
> > while attempting to test the patch which should fix the dm-crypt hang[0], 
> > I applied the diff to -rc6. After rebooting I increased disk i/o and 
> > shortly after the box rebooted - I noticed this earlier with -rc5 too, but 
> > had no debug messages at hand. Well, the box is running again and tar(1) 
> > is reading with 32MB/s for some time now - but is not rebooting, which is 
> > good :)
> > (I changed kernel.panic and kernel.panic_on_oops to zero).
> > However, it's printing stuff like this:
> 
> This looks worrisome (some experts added to the CC list).
> 
> > [ 2632.423419] ------------[ cut here ]------------
> > [ 2632.423762] kernel BUG at fs/sysfs/file.c:89!
> > [ 2632.424089] invalid opcode: 0000 [#1] 
> > [ 2632.424398] Modules linked in: sha256_generic act_police sch_ingress cls_u32 sch_sfq sch_cbq ipt_ULOG x_tables nfsd lockd nfs_acl auth_rpcgss exportfs tun sunrpc fuse twofish_i586 twofish_common eeprom w83l785ts asb100 hwmon_vid usb_storage zd1211rw firmware_class mac80211 i2c_nforce2 snd_intel8x0 snd_ac97_codec i2c_core cfg80211 ac97_bus snd_pcm snd_timer snd soundcore snd_page_alloc
> > [ 2632.426407] 
> > [ 2632.426651] Pid: 10297, comm: tar Not tainted (2.6.25-rc6 #3)
> > [ 2632.427019] EIP: 0060:[<c01a8add>] EFLAGS: 00010212 CPU: 0
> > [ 2632.427386] EIP is at sysfs_read_file+0xdd/0xf0
> > [ 2632.427717] EAX: 00000001 EBX: f5691f00 ECX: 00000003 EDX: f7ca1e70
> > [ 2632.428100] ESI: 00001000 EDI: f7ca1ed0 EBP: f5691f14 ESP: f6f3ff54
> > [ 2632.428482]  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
> > [ 2632.428758] Process tar (pid: 10297, ti=f6f3f000 task=f6290d60 task.ti=f6f3f000)
> > [ 2632.428921] Stack: c0164ff7 f5ca6000 00001000 0866ce00 c0550d50 f7d8fab8 f776b180 0866ce00 
> > [ 2632.429174]        c01a8a00 00001000 c016868d f6f3ffa0 00000003 f776b180 fffffff7 0866ce00 
> > [ 2632.429430]        f6f3f000 c0168a91 f6f3ffa0 00000000 00000000 00000000 00000003 00001000 
> > [ 2632.429688] Call Trace:
> > [ 2632.429884]  [<c0164ff7>] kmem_cache_free+0xa7/0xf0
> > [ 2632.430023]  [<c01a8a00>] sysfs_read_file+0x0/0xf0
> > [ 2632.430159]  [<c016868d>] vfs_read+0x9d/0x140
> > [ 2632.430333]  [<c0168a91>] sys_read+0x41/0x70
> > [ 2632.430657]  [<c0102dee>] sysenter_past_esp+0x5f/0xa5
> > [ 2632.431006]  =======================
> > [ 2632.431308] Code: 18 89 f0 5b 5e 5f 5d c3 be ed ff ff ff eb e8 b8 d0 00 00 00 be f4 ff ff ff e8 e0 31 fa ff 85 c0 89 43 0c 0f 85 6d ff ff ff eb cc <0f> 0b 90 eb fd 8d b4 26 00 00 00 00 8d bc 27 00 00 00 00 83 ec 
> > [ 2632.432467] EIP: [<c01a8add>] sysfs_read_file+0xdd/0xf0 SS:ESP 0068:f6f3ff54
> > [ 2632.432630] ---[ end trace 9959fa4f11f46a8e ]---
> > 
> > Please see the full dmesg and .config: http://nerdbynature.de/bits/2.6.25-rc6/

Is MD (ie: raid) in use?

If so, the below (already merged) patch should fix this crash.

If this patch does not fix it then please apply this debug patch:

http://userweb.kernel.org/~akpm/mmotm/broken-out/gregkh-driver-driver-core-debug-for-bad-dev_attr_show-return-value.patch

then rerun the test.

Greg/Kay:

- why is this BUG_ON now triggering for people?

- we're killing people's machines.  Can we switch it to a
  WARN_ON()+fix-up-the-mess?


From: NeilBrown <neilb@suse.de>

Exposing the binary blob which is the md 'super-block' via sysfs
doesn't really fit with the sysfs model, and since commit

   8118a859dc7abd873193986c77a8d9bdb877adc8

it doesn't actually work at all (as the size of the blob is often one page).

(akpm: as in, fs/sysfs/file.c:fill_read_buffer() goes BUG)

So just remove it altogether.  It isn't really useful.

Signed-off-by: Neil Brown <neilb@suse.de>
Signed-off-by: Andrew Morton <akpm@linux-foundation.org>
---

 drivers/md/md.c |   12 ------------
 1 file changed, 12 deletions(-)

diff -puN drivers/md/md.c~md-remove-the-super-sysfs-attribute-from-devices-in-an-md-array drivers/md/md.c
--- a/drivers/md/md.c~md-remove-the-super-sysfs-attribute-from-devices-in-an-md-array
+++ a/drivers/md/md.c
@@ -1864,17 +1864,6 @@ static struct rdev_sysfs_entry rdev_stat
 __ATTR(state, S_IRUGO|S_IWUSR, state_show, state_store);
 
 static ssize_t
-super_show(mdk_rdev_t *rdev, char *page)
-{
-	if (rdev->sb_loaded && rdev->sb_size) {
-		memcpy(page, page_address(rdev->sb_page), rdev->sb_size);
-		return rdev->sb_size;
-	} else
-		return 0;
-}
-static struct rdev_sysfs_entry rdev_super = __ATTR_RO(super);
-
-static ssize_t
 errors_show(mdk_rdev_t *rdev, char *page)
 {
 	return sprintf(page, "%d\n", atomic_read(&rdev->corrected_errors));
@@ -2060,7 +2049,6 @@ __ATTR(size, S_IRUGO|S_IWUSR, rdev_size_
 
 static struct attribute *rdev_default_attrs[] = {
 	&rdev_state.attr,
-	&rdev_super.attr,
 	&rdev_errors.attr,
 	&rdev_slot.attr,
 	&rdev_offset.attr,
_

Re: 2.6.25-rc6: kernel BUG at fs/sysfs/file.c:89

[Greg KH]

On Fri, Mar 21, 2008 at 10:26:06PM -0700, Andrew Morton wrote:
> On Sat, 22 Mar 2008 02:26:34 +0100 "Rafael J. Wysocki" <rjw@sisk.pl> wrote:
> 
> > On Friday, 21 of March 2008, Christian Kujau wrote:
> > > Hi,
> > 
> > Hi,
> > 
> > > while attempting to test the patch which should fix the dm-crypt hang[0], 
> > > I applied the diff to -rc6. After rebooting I increased disk i/o and 
> > > shortly after the box rebooted - I noticed this earlier with -rc5 too, but 
> > > had no debug messages at hand. Well, the box is running again and tar(1) 
> > > is reading with 32MB/s for some time now - but is not rebooting, which is 
> > > good :)
> > > (I changed kernel.panic and kernel.panic_on_oops to zero).
> > > However, it's printing stuff like this:
> > 
> > This looks worrisome (some experts added to the CC list).
> > 
> > > [ 2632.423419] ------------[ cut here ]------------
> > > [ 2632.423762] kernel BUG at fs/sysfs/file.c:89!
> > > [ 2632.424089] invalid opcode: 0000 [#1] 
> > > [ 2632.424398] Modules linked in: sha256_generic act_police sch_ingress cls_u32 sch_sfq sch_cbq ipt_ULOG x_tables nfsd lockd nfs_acl auth_rpcgss exportfs tun sunrpc fuse twofish_i586 twofish_common eeprom w83l785ts asb100 hwmon_vid usb_storage zd1211rw firmware_class mac80211 i2c_nforce2 snd_intel8x0 snd_ac97_codec i2c_core cfg80211 ac97_bus snd_pcm snd_timer snd soundcore snd_page_alloc
> > > [ 2632.426407] 
> > > [ 2632.426651] Pid: 10297, comm: tar Not tainted (2.6.25-rc6 #3)
> > > [ 2632.427019] EIP: 0060:[<c01a8add>] EFLAGS: 00010212 CPU: 0
> > > [ 2632.427386] EIP is at sysfs_read_file+0xdd/0xf0
> > > [ 2632.427717] EAX: 00000001 EBX: f5691f00 ECX: 00000003 EDX: f7ca1e70
> > > [ 2632.428100] ESI: 00001000 EDI: f7ca1ed0 EBP: f5691f14 ESP: f6f3ff54
> > > [ 2632.428482]  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
> > > [ 2632.428758] Process tar (pid: 10297, ti=f6f3f000 task=f6290d60 task.ti=f6f3f000)
> > > [ 2632.428921] Stack: c0164ff7 f5ca6000 00001000 0866ce00 c0550d50 f7d8fab8 f776b180 0866ce00 
> > > [ 2632.429174]        c01a8a00 00001000 c016868d f6f3ffa0 00000003 f776b180 fffffff7 0866ce00 
> > > [ 2632.429430]        f6f3f000 c0168a91 f6f3ffa0 00000000 00000000 00000000 00000003 00001000 
> > > [ 2632.429688] Call Trace:
> > > [ 2632.429884]  [<c0164ff7>] kmem_cache_free+0xa7/0xf0
> > > [ 2632.430023]  [<c01a8a00>] sysfs_read_file+0x0/0xf0
> > > [ 2632.430159]  [<c016868d>] vfs_read+0x9d/0x140
> > > [ 2632.430333]  [<c0168a91>] sys_read+0x41/0x70
> > > [ 2632.430657]  [<c0102dee>] sysenter_past_esp+0x5f/0xa5
> > > [ 2632.431006]  =======================
> > > [ 2632.431308] Code: 18 89 f0 5b 5e 5f 5d c3 be ed ff ff ff eb e8 b8 d0 00 00 00 be f4 ff ff ff e8 e0 31 fa ff 85 c0 89 43 0c 0f 85 6d ff ff ff eb cc <0f> 0b 90 eb fd 8d b4 26 00 00 00 00 8d bc 27 00 00 00 00 83 ec 
> > > [ 2632.432467] EIP: [<c01a8add>] sysfs_read_file+0xdd/0xf0 SS:ESP 0068:f6f3ff54
> > > [ 2632.432630] ---[ end trace 9959fa4f11f46a8e ]---
> > > 
> > > Please see the full dmesg and .config: http://nerdbynature.de/bits/2.6.25-rc6/
> 
> Is MD (ie: raid) in use?
> 
> If so, the below (already merged) patch should fix this crash.
> 
> If this patch does not fix it then please apply this debug patch:
> 
> http://userweb.kernel.org/~akpm/mmotm/broken-out/gregkh-driver-driver-core-debug-for-bad-dev_attr_show-return-value.patch
> 
> then rerun the test.
> 
> Greg/Kay:
> 
> - why is this BUG_ON now triggering for people?

Someone is overflowing the sysfs buffer now, it's only a PAGE_SIZE big,
which should be fine for a simple one-value-per-file system.

> - we're killing people's machines.  Can we switch it to a
>   WARN_ON()+fix-up-the-mess?

The patch above does just that, it's queued up for .26, but I have no
objection to add it now if you want.

thanks,

greg k-h

Re: 2.6.25-rc6: kernel BUG at fs/sysfs/file.c:89

[Andrew Morton]

On Fri, 21 Mar 2008 23:20:25 -0700 Greg KH <greg@kroah.com> wrote:

> > - we're killing people's machines.  Can we switch it to a
> >   WARN_ON()+fix-up-the-mess?
> 
> The patch above does just that, it's queued up for .26, but I have no
> objection to add it now if you want.

It'd be best to do so, I think.

Upsides: we get more debug info and we might save people's machines

Downsides: ???

Re: 2.6.25-rc6: kernel BUG at fs/sysfs/file.c:89

[Greg KH]

On Fri, Mar 21, 2008 at 11:26:32PM -0700, Andrew Morton wrote:
> On Fri, 21 Mar 2008 23:20:25 -0700 Greg KH <greg@kroah.com> wrote:
> 
> > > - we're killing people's machines.  Can we switch it to a
> > >   WARN_ON()+fix-up-the-mess?
> > 
> > The patch above does just that, it's queued up for .26, but I have no
> > objection to add it now if you want.
> 
> It'd be best to do so, I think.
> 
> Upsides: we get more debug info and we might save people's machines
> 
> Downsides: ???

Ok, I'll move it up the stack to send to Linus on Monday.

thanks,

greg k-h

Re: 2.6.25-rc6: kernel BUG at fs/sysfs/file.c:89

[Christian Kujau]

On Fri, 21 Mar 2008, ext Andrew Morton wrote:
> Is MD (ie: raid) in use?

Yes, indeed. LUKS/dm-crypt on top of raid-1:

> If so, the below (already merged) patch should fix this crash.
> If this patch does not fix it then please apply this debug patch:
> http://userweb.kernel.org/~akpm/mmotm/broken-out/gregkh-driver-driver-core-debug-for-bad-dev_attr_show-return-value.patch
> then rerun the test.

Ah, sorry, I misread your post: I applied the aforementioned dm-crypt 
patch[0] and Greg's debug patch and got quite nasty SCSI errors, leading 
to a complete lockup. I'll try again and only apply Neil's patch...stay tuned...

Thanks,
Christian.

[0] http://lkml.org/lkml/2008/3/17/214
[0] http://nerdbynature.de/bits/2.6.25-rc6/fill_read_buffer.log
-- 
BOFH excuse #197:

I'm sorry a pentium won't do, you need an SGI to connect with us.

Re: 2.6.25-rc6: kernel BUG at fs/sysfs/file.c:89

[Christian Kujau]

On Sat, 22 Mar 2008, Christian Kujau wrote:
>> If so, the below (already merged) patch should fix this crash.
>> If this patch does not fix it then please apply this debug patch:
>> http://userweb.kernel.org/~akpm/mmotm/broken-out/gregkh-driver-driver-core-debug-for-bad-dev_attr_show-return-value.patch
>> then rerun the test.
>
> Ah, sorry, I misread your post: I applied the aforementioned dm-crypt 
> patch[0] and Greg's debug patch and got quite nasty SCSI errors, leading to a 
> complete lockup. I'll try again and only apply Neil's patch...stay tuned...

Hm, this was strange: I applied Neil's patch (and the dm-crypt patch) on 
2.6.25-rc6 and I kept getting SCSI errors (and lockups) when doing "tar 
-cf - | dd of=/dev/null" - which I did to generate disk I/O.

Doing the same as a normal user, nothing bad happened (except a
"possible circular locking dependency" warning, copied below) and the box 
is still up & running for a few hours now, with a constant read of ~30MB/s
across (md-)disks (running tar, rsync). So all in all I'm very happy, 
because with these two patches applied, 2.6.25-rc seems to be usable 
again.

Of course, it'd be interesting to know where the scsi errors come from, 
but that's another story I guess...

Thanks to all involved,
Christian.

[ 4657.715881] =======================================================
[ 4657.716512] [ INFO: possible circular locking dependency detected ]
[ 4657.716895] 2.6.25-rc6 #5
[ 4657.717170] -------------------------------------------------------
[ 4657.717552] rsync/14184 is trying to acquire lock:
[ 4657.717892]  (iprune_mutex){--..}, at: [<c017b672>] shrink_icache_memory+0x72/0x220
[ 4657.718239] 
[ 4657.718239] but task is already holding lock:
[ 4657.718463]  (&(&ip->i_iolock)->mr_lock){----}, at: [<c027a766>] xfs_ilock+0x96/0xb0
[ 4657.718714] 
[ 4657.718715] which lock already depends on the new lock.
[ 4657.718716] 
[ 4657.719047] 
[ 4657.719047] the existing dependency chain (in reverse order) is:
[ 4657.719291] 
[ 4657.719292] -> #1 (&(&ip->i_iolock)->mr_lock){----}:
[ 4657.719526]        [<c01369f4>] add_lock_to_list+0x44/0xc0
[ 4657.719779]        [<c0139486>] __lock_acquire+0xc26/0x10b0
[ 4657.720142]        [<c027a766>] xfs_ilock+0x96/0xb0
[ 4657.720483]        [<c013826d>] mark_held_locks+0x3d/0x70
[ 4657.720483]        [<c013996e>] lock_acquire+0x5e/0x80
[ 4657.720483]        [<c027a766>] xfs_ilock+0x96/0xb0
[ 4657.720483]        [<c012fc81>] down_write_nested+0x41/0x60
[ 4657.720483]        [<c027a766>] xfs_ilock+0x96/0xb0
[ 4657.720483]        [<c027a766>] xfs_ilock+0x96/0xb0
[ 4657.720483]        [<c027a8fa>] xfs_ireclaim+0x1a/0x60
[ 4657.720483]        [<c02987b3>] xfs_finish_reclaim+0x53/0x1a0
[ 4657.720483]        [<c02a7c6e>] xfs_fs_clear_inode+0x5e/0x90
[ 4657.720483]        [<c017b279>] clear_inode+0xa9/0x130
[ 4657.720483]        [<c017ac40>] destroy_inode+0x20/0x40
[ 4657.720483]        [<c017b55a>] dispose_list+0x1a/0xc0
[ 4657.720483]        [<c017b7e2>] shrink_icache_memory+0x1e2/0x220
[ 4657.720483]        [<c0150211>] shrink_slab+0x101/0x160
[ 4657.720483]        [<c01507a8>] kswapd+0x298/0x3f0
[ 4657.720483]        [<c014f140>] isolate_pages_global+0x0/0x60
[ 4657.720483]        [<c012c710>] autoremove_wake_function+0x0/0x40
[ 4657.720483]        [<c01383bc>] trace_hardirqs_on+0x9c/0x110
[ 4657.720483]        [<c0150510>] kswapd+0x0/0x3f0
[ 4657.720483]        [<c012c442>] kthread+0x42/0x70
[ 4657.720483]        [<c012c400>] kthread+0x0/0x70
[ 4657.720483]        [<c0103a1f>] kernel_thread_helper+0x7/0x18
[ 4657.720483]        [<ffffffff>] 0xffffffff
[ 4657.720483] 
[ 4657.720483] -> #0 (iprune_mutex){--..}:
[ 4657.720483]        [<c0136c80>] print_circular_bug_entry+0x40/0x50
[ 4657.720483]        [<c0139287>] __lock_acquire+0xa27/0x10b0
[ 4657.720483]        [<c01389ef>] __lock_acquire+0x18f/0x10b0
[ 4657.720483]        [<c013996e>] lock_acquire+0x5e/0x80
[ 4657.720483]        [<c017b672>] shrink_icache_memory+0x72/0x220
[ 4657.720483]        [<c043e2f9>] mutex_lock_nested+0x89/0x240
[ 4657.720483]        [<c017b672>] shrink_icache_memory+0x72/0x220
[ 4657.720483]        [<c017b672>] shrink_icache_memory+0x72/0x220
[ 4657.720483]        [<c017b672>] shrink_icache_memory+0x72/0x220
[ 4657.720483]        [<c0150131>] shrink_slab+0x21/0x160
[ 4657.720483]        [<c0150211>] shrink_slab+0x101/0x160
[ 4657.720483]        [<c01503c2>] try_to_free_pages+0x152/0x230
[ 4657.720483]        [<c014f140>] isolate_pages_global+0x0/0x60
[ 4657.720483]        [<c014ba3b>] __alloc_pages+0x14b/0x370
[ 4657.720483]        [<c043fa20>] _read_unlock_irq+0x20/0x30
[ 4657.720483]        [<c01466e1>] __grab_cache_page+0x81/0xc0
[ 4657.720483]        [<c01897d6>] block_write_begin+0x76/0xe0
[ 4657.720483]        [<c029ed56>] xfs_vm_write_begin+0x46/0x50
[ 4657.720483]        [<c029f5a0>] xfs_get_blocks+0x0/0x30
[ 4657.720483]        [<c0147377>] generic_file_buffered_write+0x117/0x650
[ 4657.720483]        [<c01846c3>] __mark_inode_dirty+0x53/0x180
[ 4657.720483]        [<c043f6b9>] _spin_lock+0x29/0x40
[ 4657.720483]        [<c01846c3>] __mark_inode_dirty+0x53/0x180
[ 4657.720483]        [<c02a74ac>] xfs_write+0x7ac/0x8a0
[ 4657.720483]        [<c0174ba1>] core_sys_select+0x21/0x350
[ 4657.720483]        [<c02a339c>] xfs_file_aio_write+0x5c/0x70
[ 4657.720483]        [<c0167cd5>] do_sync_write+0xd5/0x120
[ 4657.720483]        [<c012c710>] autoremove_wake_function+0x0/0x40
[ 4657.720483]        [<c019d0b5>] dnotify_parent+0x35/0x90
[ 4657.720483]        [<c0167c00>] do_sync_write+0x0/0x120
[ 4657.720483]        [<c016854f>] vfs_write+0x9f/0x140
[ 4657.720483]        [<c0168b01>] sys_write+0x41/0x70
[ 4657.720483]        [<c0102dee>] sysenter_past_esp+0x5f/0xa5
[ 4657.720483]        [<ffffffff>] 0xffffffff
[ 4657.720483] 
[ 4657.720483] other info that might help us debug this:
[ 4657.720483] 
[ 4657.720483] 3 locks held by rsync/14184:
[ 4657.720483]  #0:  (&sb->s_type->i_mutex_key#12){--..}, at: [<c02a70f9>] xfs_write+0x3f9/0x8a0
[ 4657.720483]  #1:  (&(&ip->i_iolock)->mr_lock){----}, at: [<c027a766>] xfs_ilock+0x96/0xb0
[ 4657.720483]  #2:  (shrinker_rwsem){----}, at: [<c0150131>] shrink_slab+0x21/0x160
[ 4657.720483] 
[ 4657.720483] stack backtrace:
[ 4657.720483] Pid: 14184, comm: rsync Not tainted 2.6.25-rc6 #5
[ 4657.720483]  [<c0137502>] print_circular_bug_tail+0x72/0x80
[ 4657.720483]  [<c0139287>] __lock_acquire+0xa27/0x10b0
[ 4657.720483]  [<c01389ef>] __lock_acquire+0x18f/0x10b0
[ 4657.720483]  [<c013996e>] lock_acquire+0x5e/0x80
[ 4657.720483]  [<c017b672>] shrink_icache_memory+0x72/0x220
[ 4657.720483]  [<c043e2f9>] mutex_lock_nested+0x89/0x240
[ 4657.720483]  [<c017b672>] shrink_icache_memory+0x72/0x220
[ 4657.720483]  [<c017b672>] shrink_icache_memory+0x72/0x220
[ 4657.720483]  [<c017b672>] shrink_icache_memory+0x72/0x220
[ 4657.720483]  [<c0150131>] shrink_slab+0x21/0x160
[ 4657.720483]  [<c0150211>] shrink_slab+0x101/0x160
[ 4657.720483]  [<c01503c2>] try_to_free_pages+0x152/0x230
[ 4657.720483]  [<c014f140>] isolate_pages_global+0x0/0x60
[ 4657.720483]  [<c014ba3b>] __alloc_pages+0x14b/0x370
[ 4657.720483]  [<c043fa20>] _read_unlock_irq+0x20/0x30
[ 4657.720483]  [<c01466e1>] __grab_cache_page+0x81/0xc0
[ 4657.720483]  [<c01897d6>] block_write_begin+0x76/0xe0
[ 4657.720483]  [<c029ed56>] xfs_vm_write_begin+0x46/0x50
[ 4657.720483]  [<c029f5a0>] xfs_get_blocks+0x0/0x30
[ 4657.720483]  [<c0147377>] generic_file_buffered_write+0x117/0x650
[ 4657.720483]  [<c01846c3>] __mark_inode_dirty+0x53/0x180
[ 4657.720483]  [<c043f6b9>] _spin_lock+0x29/0x40
[ 4657.720483]  [<c01846c3>] __mark_inode_dirty+0x53/0x180
[ 4657.720483]  [<c02a74ac>] xfs_write+0x7ac/0x8a0
[ 4657.720483]  [<c0174ba1>] core_sys_select+0x21/0x350
[ 4657.720483]  [<c02a339c>] xfs_file_aio_write+0x5c/0x70
[ 4657.720483]  [<c0167cd5>] do_sync_write+0xd5/0x120
[ 4657.720483]  [<c012c710>] autoremove_wake_function+0x0/0x40
[ 4657.720483]  [<c019d0b5>] dnotify_parent+0x35/0x90
[ 4657.720483]  [<c0167c00>] do_sync_write+0x0/0x120
[ 4657.720483]  [<c016854f>] vfs_write+0x9f/0x140
[ 4657.720483]  [<c0168b01>] sys_write+0x41/0x70
[ 4657.720483]  [<c0102dee>] sysenter_past_esp+0x5f/0xa5
[ 4657.720483]  =======================

-- 
BOFH excuse #197:

I'm sorry a pentium won't do, you need an SGI to connect with us.

Re: 2.6.25-rc6: kernel BUG at fs/sysfs/file.c:89

[Andrew Morton]

On Sat, 22 Mar 2008 22:54:51 +0100 (CET) Christian Kujau <lists@nerdbynature.de> wrote:

> On Sat, 22 Mar 2008, Christian Kujau wrote:
> >> If so, the below (already merged) patch should fix this crash.
> >> If this patch does not fix it then please apply this debug patch:
> >> http://userweb.kernel.org/~akpm/mmotm/broken-out/gregkh-driver-driver-core-debug-for-bad-dev_attr_show-return-value.patch
> >> then rerun the test.
> >
> > Ah, sorry, I misread your post: I applied the aforementioned dm-crypt 
> > patch[0] and Greg's debug patch and got quite nasty SCSI errors, leading to a 
> > complete lockup. I'll try again and only apply Neil's patch...stay tuned...
> 
> Hm, this was strange: I applied Neil's patch (and the dm-crypt patch) on 
> 2.6.25-rc6 and I kept getting SCSI errors (and lockups) when doing "tar 
> -cf - | dd of=/dev/null" - which I did to generate disk I/O.

Please send all the details about this, retaining all cc's.

Re: 2.6.25-rc6: kernel BUG at fs/sysfs/file.c:89

[Christian Kujau]

On Sat, 22 Mar 2008, Andrew Morton wrote:
>> Hm, this was strange: I applied Neil's patch (and the dm-crypt patch) on
>> 2.6.25-rc6 and I kept getting SCSI errors (and lockups) when doing "tar
>> -cf - | dd of=/dev/null" - which I did to generate disk I/O.
>
> Please send all the details about this, retaining all cc's.

Hm, reproducing seems easy, but as nothings get written to disk or to the 
remote syslog server anymore, I don't have any error messages - yet.

C.
-- 
BOFH excuse #93:

Feature not yet implemented

Re: 2.6.25-rc6: kernel BUG at fs/sysfs/file.c:89

[Andrew Morton]

On Sat, 22 Mar 2008 22:54:51 +0100 (CET) Christian Kujau <lists@nerdbynature.de> wrote:

> On Sat, 22 Mar 2008, Christian Kujau wrote:
> >> If so, the below (already merged) patch should fix this crash.
> >> If this patch does not fix it then please apply this debug patch:
> >> http://userweb.kernel.org/~akpm/mmotm/broken-out/gregkh-driver-driver-core-debug-for-bad-dev_attr_show-return-value.patch
> >> then rerun the test.
> >
> > Ah, sorry, I misread your post: I applied the aforementioned dm-crypt 
> > patch[0] and Greg's debug patch and got quite nasty SCSI errors, leading to a 
> > complete lockup. I'll try again and only apply Neil's patch...stay tuned...
> 
> Hm, this was strange: I applied Neil's patch (and the dm-crypt patch) on 
> 2.6.25-rc6 and I kept getting SCSI errors (and lockups) when doing "tar 
> -cf - | dd of=/dev/null" - which I did to generate disk I/O.
> 
> Doing the same as a normal user, nothing bad happened (except a
> "possible circular locking dependency" warning, copied below) and the box 
> is still up & running for a few hours now, with a constant read of ~30MB/s
> across (md-)disks (running tar, rsync). So all in all I'm very happy, 
> because with these two patches applied, 2.6.25-rc seems to be usable 
> again.
> 
> Of course, it'd be interesting to know where the scsi errors come from, 
> but that's another story I guess...
> 
> Thanks to all involved,
> Christian.
> 
> [ 4657.715881] =======================================================
> [ 4657.716512] [ INFO: possible circular locking dependency detected ]
> [ 4657.716895] 2.6.25-rc6 #5
> [ 4657.717170] -------------------------------------------------------
> [ 4657.717552] rsync/14184 is trying to acquire lock:
> [ 4657.717892]  (iprune_mutex){--..}, at: [<c017b672>] shrink_icache_memory+0x72/0x220
> [ 4657.718239] 
> [ 4657.718239] but task is already holding lock:
> [ 4657.718463]  (&(&ip->i_iolock)->mr_lock){----}, at: [<c027a766>] xfs_ilock+0x96/0xb0
> [ 4657.718714] 
> [ 4657.718715] which lock already depends on the new lock.
> [ 4657.718716] 
> [ 4657.719047] 
> [ 4657.719047] the existing dependency chain (in reverse order) is:
> [ 4657.719291] 
> [ 4657.719292] -> #1 (&(&ip->i_iolock)->mr_lock){----}:
> [ 4657.719526]        [<c01369f4>] add_lock_to_list+0x44/0xc0
> [ 4657.719779]        [<c0139486>] __lock_acquire+0xc26/0x10b0
> [ 4657.720142]        [<c027a766>] xfs_ilock+0x96/0xb0
> [ 4657.720483]        [<c013826d>] mark_held_locks+0x3d/0x70
> [ 4657.720483]        [<c013996e>] lock_acquire+0x5e/0x80
> [ 4657.720483]        [<c027a766>] xfs_ilock+0x96/0xb0
> [ 4657.720483]        [<c012fc81>] down_write_nested+0x41/0x60
> [ 4657.720483]        [<c027a766>] xfs_ilock+0x96/0xb0
> [ 4657.720483]        [<c027a766>] xfs_ilock+0x96/0xb0
> [ 4657.720483]        [<c027a8fa>] xfs_ireclaim+0x1a/0x60
> [ 4657.720483]        [<c02987b3>] xfs_finish_reclaim+0x53/0x1a0
> [ 4657.720483]        [<c02a7c6e>] xfs_fs_clear_inode+0x5e/0x90
> [ 4657.720483]        [<c017b279>] clear_inode+0xa9/0x130
> [ 4657.720483]        [<c017ac40>] destroy_inode+0x20/0x40
> [ 4657.720483]        [<c017b55a>] dispose_list+0x1a/0xc0
> [ 4657.720483]        [<c017b7e2>] shrink_icache_memory+0x1e2/0x220
> [ 4657.720483]        [<c0150211>] shrink_slab+0x101/0x160
> [ 4657.720483]        [<c01507a8>] kswapd+0x298/0x3f0
> [ 4657.720483]        [<c014f140>] isolate_pages_global+0x0/0x60
> [ 4657.720483]        [<c012c710>] autoremove_wake_function+0x0/0x40
> [ 4657.720483]        [<c01383bc>] trace_hardirqs_on+0x9c/0x110
> [ 4657.720483]        [<c0150510>] kswapd+0x0/0x3f0
> [ 4657.720483]        [<c012c442>] kthread+0x42/0x70
> [ 4657.720483]        [<c012c400>] kthread+0x0/0x70
> [ 4657.720483]        [<c0103a1f>] kernel_thread_helper+0x7/0x18
> [ 4657.720483]        [<ffffffff>] 0xffffffff
> [ 4657.720483] 
> [ 4657.720483] -> #0 (iprune_mutex){--..}:
> [ 4657.720483]        [<c0136c80>] print_circular_bug_entry+0x40/0x50
> [ 4657.720483]        [<c0139287>] __lock_acquire+0xa27/0x10b0
> [ 4657.720483]        [<c01389ef>] __lock_acquire+0x18f/0x10b0
> [ 4657.720483]        [<c013996e>] lock_acquire+0x5e/0x80
> [ 4657.720483]        [<c017b672>] shrink_icache_memory+0x72/0x220
> [ 4657.720483]        [<c043e2f9>] mutex_lock_nested+0x89/0x240
> [ 4657.720483]        [<c017b672>] shrink_icache_memory+0x72/0x220
> [ 4657.720483]        [<c017b672>] shrink_icache_memory+0x72/0x220
> [ 4657.720483]        [<c017b672>] shrink_icache_memory+0x72/0x220
> [ 4657.720483]        [<c0150131>] shrink_slab+0x21/0x160
> [ 4657.720483]        [<c0150211>] shrink_slab+0x101/0x160
> [ 4657.720483]        [<c01503c2>] try_to_free_pages+0x152/0x230
> [ 4657.720483]        [<c014f140>] isolate_pages_global+0x0/0x60
> [ 4657.720483]        [<c014ba3b>] __alloc_pages+0x14b/0x370
> [ 4657.720483]        [<c043fa20>] _read_unlock_irq+0x20/0x30
> [ 4657.720483]        [<c01466e1>] __grab_cache_page+0x81/0xc0
> [ 4657.720483]        [<c01897d6>] block_write_begin+0x76/0xe0
> [ 4657.720483]        [<c029ed56>] xfs_vm_write_begin+0x46/0x50
> [ 4657.720483]        [<c029f5a0>] xfs_get_blocks+0x0/0x30
> [ 4657.720483]        [<c0147377>] generic_file_buffered_write+0x117/0x650
> [ 4657.720483]        [<c01846c3>] __mark_inode_dirty+0x53/0x180
> [ 4657.720483]        [<c043f6b9>] _spin_lock+0x29/0x40
> [ 4657.720483]        [<c01846c3>] __mark_inode_dirty+0x53/0x180
> [ 4657.720483]        [<c02a74ac>] xfs_write+0x7ac/0x8a0
> [ 4657.720483]        [<c0174ba1>] core_sys_select+0x21/0x350
> [ 4657.720483]        [<c02a339c>] xfs_file_aio_write+0x5c/0x70
> [ 4657.720483]        [<c0167cd5>] do_sync_write+0xd5/0x120
> [ 4657.720483]        [<c012c710>] autoremove_wake_function+0x0/0x40
> [ 4657.720483]        [<c019d0b5>] dnotify_parent+0x35/0x90
> [ 4657.720483]        [<c0167c00>] do_sync_write+0x0/0x120
> [ 4657.720483]        [<c016854f>] vfs_write+0x9f/0x140
> [ 4657.720483]        [<c0168b01>] sys_write+0x41/0x70
> [ 4657.720483]        [<c0102dee>] sysenter_past_esp+0x5f/0xa5
> [ 4657.720483]        [<ffffffff>] 0xffffffff
> [ 4657.720483] 
> [ 4657.720483] other info that might help us debug this:
> [ 4657.720483] 
> [ 4657.720483] 3 locks held by rsync/14184:
> [ 4657.720483]  #0:  (&sb->s_type->i_mutex_key#12){--..}, at: [<c02a70f9>] xfs_write+0x3f9/0x8a0
> [ 4657.720483]  #1:  (&(&ip->i_iolock)->mr_lock){----}, at: [<c027a766>] xfs_ilock+0x96/0xb0
> [ 4657.720483]  #2:  (shrinker_rwsem){----}, at: [<c0150131>] shrink_slab+0x21/0x160
> [ 4657.720483] 
> [ 4657.720483] stack backtrace:
> [ 4657.720483] Pid: 14184, comm: rsync Not tainted 2.6.25-rc6 #5
> [ 4657.720483]  [<c0137502>] print_circular_bug_tail+0x72/0x80
> [ 4657.720483]  [<c0139287>] __lock_acquire+0xa27/0x10b0
> [ 4657.720483]  [<c01389ef>] __lock_acquire+0x18f/0x10b0
> [ 4657.720483]  [<c013996e>] lock_acquire+0x5e/0x80
> [ 4657.720483]  [<c017b672>] shrink_icache_memory+0x72/0x220
> [ 4657.720483]  [<c043e2f9>] mutex_lock_nested+0x89/0x240
> [ 4657.720483]  [<c017b672>] shrink_icache_memory+0x72/0x220
> [ 4657.720483]  [<c017b672>] shrink_icache_memory+0x72/0x220
> [ 4657.720483]  [<c017b672>] shrink_icache_memory+0x72/0x220
> [ 4657.720483]  [<c0150131>] shrink_slab+0x21/0x160
> [ 4657.720483]  [<c0150211>] shrink_slab+0x101/0x160
> [ 4657.720483]  [<c01503c2>] try_to_free_pages+0x152/0x230
> [ 4657.720483]  [<c014f140>] isolate_pages_global+0x0/0x60
> [ 4657.720483]  [<c014ba3b>] __alloc_pages+0x14b/0x370
> [ 4657.720483]  [<c043fa20>] _read_unlock_irq+0x20/0x30
> [ 4657.720483]  [<c01466e1>] __grab_cache_page+0x81/0xc0
> [ 4657.720483]  [<c01897d6>] block_write_begin+0x76/0xe0
> [ 4657.720483]  [<c029ed56>] xfs_vm_write_begin+0x46/0x50
> [ 4657.720483]  [<c029f5a0>] xfs_get_blocks+0x0/0x30
> [ 4657.720483]  [<c0147377>] generic_file_buffered_write+0x117/0x650
> [ 4657.720483]  [<c01846c3>] __mark_inode_dirty+0x53/0x180
> [ 4657.720483]  [<c043f6b9>] _spin_lock+0x29/0x40
> [ 4657.720483]  [<c01846c3>] __mark_inode_dirty+0x53/0x180
> [ 4657.720483]  [<c02a74ac>] xfs_write+0x7ac/0x8a0
> [ 4657.720483]  [<c0174ba1>] core_sys_select+0x21/0x350
> [ 4657.720483]  [<c02a339c>] xfs_file_aio_write+0x5c/0x70
> [ 4657.720483]  [<c0167cd5>] do_sync_write+0xd5/0x120
> [ 4657.720483]  [<c012c710>] autoremove_wake_function+0x0/0x40
> [ 4657.720483]  [<c019d0b5>] dnotify_parent+0x35/0x90
> [ 4657.720483]  [<c0167c00>] do_sync_write+0x0/0x120
> [ 4657.720483]  [<c016854f>] vfs_write+0x9f/0x140
> [ 4657.720483]  [<c0168b01>] sys_write+0x41/0x70
> [ 4657.720483]  [<c0102dee>] sysenter_past_esp+0x5f/0xa5
> [ 4657.720483]  =======================
> 

That's an XFS bug.

To clarify, I believe you are running

	2.6.25-rc6
plus	http://lkml.org/lkml/2008/3/22/8
plus	some dm-crypt patch?

Re: 2.6.25-rc6: kernel BUG at fs/sysfs/file.c:89

[Christian Kujau]

On Sat, 22 Mar 2008, Andrew Morton wrote:
> That's an XFS bug.
> To clarify, I believe you are running
>
> 	2.6.25-rc6
> plus	http://lkml.org/lkml/2008/3/22/8

Yes, Neil's patch you posted in this message.

> plus	some dm-crypt patch?

The dm-crypt patch is http://lkml.org/lkml/2008/3/17/214

Thanks,
Christian.
-- 
BOFH excuse #93:

Feature not yet implemented