Re: Crash in ext3 while extracting 2.6.11 (on 2.6.11-rc5-something)
Hello,
> On Thu, Mar 03, 2005 at 02:10:04PM +0100, Jan Kara wrote:
> > Hello,
> >
> > >I've noticed that 2.6.11 is released, so I run (flawlessly) 'bk pull',
> > > and now I'm trying to export tree from 'bk' by doing 'bk export -tplain
> > > /tmp/linux-2.6.11'. Unfortunately I tried it twice, and twice it died
> > > with same crash in log_do_checkpoint (see below). Anybody has a clue
> > > what it could be? When I hit alt-sysrq-s, sync takes about 10 seconds,
> > > so box had to have lots of disk caches dirtied when crash occured.
> > >
> > > Box is dual opteron rev cg, kernel has enabled all possible debug
> > > options. Problem seems to occur on 2.6.11-rc4-something too, it just
> > > begins with crash in ext3_inode_dirty because I have rc4-something built
> > > without memory poisoning (probably).
> > >
> > > I've not noticed any other problems, and it was possible to extract
> > > 2.6.11-rc5-something on Monday with 2.6.11-rc4-something, which crashes
> > > now too. I'll run 'fsck -f', maybe it will help things a bit...
> > >
> > > Bootdata ok (command line is BOOT_IMAGE=Linux ro root=801 ramdisk=0
> > > console=tty0 console=ttyS0,115200 nmi_watchdog=2 psmouse_noext=1 verbose)
> > > Linux version 2.6.11-rc5-2065-64 ([EMAIL PROTECTED]) (gcc version 3.3.3
> > > (Debian 20040401)) #1 SMP Mon Feb 28 22:15:10 CET 2005
> > >
> > > stack segment: [1] PREEMPT SMP
> > > CPU 0
> > I don't see here a reason why the machine crashed (some NULL pointer
> > deref or what...). It would be useful to know it. Also could you run
> > gdb on vmlinux a find out where exactly in the function the oops
> > occured?
>
> It died because of dereferencing RBP which contained memory poisoning
> signature:
>
> 0x801d9996 : lock btsl $0x13,0x0(%rbp)
>
> apparently x86-64 generates #SS for %rbp non-canonical addresses too, like
> i386 does with %ebp segment overruns.
>
> Crash occured in bit_spin_trylock called by jbd_trylock_bh_state from
> log_do_checkpoint
> (fs/jbd/checkpoint.c:636), because jh2bh (jh->b_bh) returned poisoned pattern
> - apparently somebody else freed journal_head while we were holding pointer
> to it. No idea how it happened.
could you try applying attached patch and reproducing the problem? If
it is really oops because bh was set to NULL when freeing journal head
then the patch should catch it and write the place where we freed the
journal head...
Thanks
Honza
diff -rupX /home/jack/.kerndiffexclude linux-2.6.11/fs/jbd/checkpoint.c
linux-2.6.11-jhdebug/fs/jbd/checkpoint.c
--- linux-2.6.11/fs/jbd/checkpoint.c2005-03-03 18:58:29.0 +0100
+++ linux-2.6.11-jhdebug/fs/jbd/checkpoint.c2005-03-03 19:53:04.0
+0100
@@ -59,7 +59,7 @@ static int __try_to_free_cp_buf(struct j
JBUFFER_TRACE(jh, "remove from checkpoint list");
__journal_remove_checkpoint(jh);
jbd_unlock_bh_state(bh);
- journal_remove_journal_head(bh);
+ journal_remove_journal_head(bh, "__try_to_free_cp_buf");
BUFFER_TRACE(bh, "release");
__brelse(bh);
ret = 1;
@@ -182,7 +182,7 @@ static int __cleanup_transaction(journal
BUFFER_TRACE(bh, "remove from checkpoint");
__journal_remove_checkpoint(jh);
jbd_unlock_bh_state(bh);
- journal_remove_journal_head(bh);
+ journal_remove_journal_head(bh,
"__cleanup_transaction");
__brelse(bh);
ret = 1;
} else {
diff -rupX /home/jack/.kerndiffexclude linux-2.6.11/fs/jbd/commit.c
linux-2.6.11-jhdebug/fs/jbd/commit.c
--- linux-2.6.11/fs/jbd/commit.c2005-03-03 18:58:29.0 +0100
+++ linux-2.6.11-jhdebug/fs/jbd/commit.c2005-03-03 19:57:38.0
+0100
@@ -286,7 +286,7 @@ write_out_data:
goto write_out_data;
__journal_unfile_buffer(jh);
jbd_unlock_bh_state(bh);
- journal_remove_journal_head(bh);
+ journal_remove_journal_head(bh,
"commit_transaction_1");
put_bh(bh);
if (lock_need_resched(&journal->j_list_lock)) {
spin_unlock(&journal->j_list_lock);
@@ -327,7 +327,7 @@ write_out_data:
if (buffer_jbd(bh) && jh->b_jlist == BJ_Locked) {
__journal_unfile_buffer(jh);
jbd_unlock_bh_state(bh);
- journal_remove_journal_head(bh);
+ journal_remove_journal_head(bh, "commit_transaction_2");
put_bh(bh);
Re: Crash in ext3 while extracting 2.6.11 (on 2.6.11-rc5-something)
> > On Thu, Mar 03, 2005 at 02:10:04PM +0100, Jan Kara wrote: > > It died because of dereferencing RBP which contained memory poisoning > > signature: > > > > 0x801d9996 : lock btsl $0x13,0x0(%rbp) > > > > apparently x86-64 generates #SS for %rbp non-canonical addresses too, like > > i386 does with %ebp segment overruns. > > > > Crash occured in bit_spin_trylock called by jbd_trylock_bh_state from > > log_do_checkpoint (fs/jbd/checkpoint.c:636), because jh2bh (jh->b_bh) > > returned poisoned pattern - apparently somebody else freed journal_head > > while we were holding pointer to it. No idea how it happened. > > > > > Anyway I was briefly reading the code in log_do_checkpoint() and two > > > things are not clear to me - are we guaranteed that > > > transaction->t_checkpoint_list is non-empty (the code relies on that)? > > > Another thing is - __flush_buffer() can sleep. Cannot someone change > > > the t_checkpoint_list while we are sleeping? We are protected only by > > > the j_checkpoint_sem and that only protects us against other > > > log_do_checkpoint() calls. > > > > Code apparently believes that if __flush_buffer() sleeps then it returns > > 1. > Yes, I see that all the buffer heads will be processed. But I'm not > sure whether someone cannot come while we are sleeping and release the > journal_head next_jh points too (actually it seems that such thing is > happening). I'll have a look what could cause such nasty thing... Sorry, you were right that the test with 'retry' should handle this case also correctly. It must be something else. Honza -- Jan Kara <[EMAIL PROTECTED]> SuSE CR Labs - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: Crash in ext3 while extracting 2.6.11 (on 2.6.11-rc5-something)
> On Thu, Mar 03, 2005 at 02:10:04PM +0100, Jan Kara wrote:
> > Hello,
> >
> > >I've noticed that 2.6.11 is released, so I run (flawlessly) 'bk pull',
> > > and now I'm trying to export tree from 'bk' by doing 'bk export -tplain
> > > /tmp/linux-2.6.11'. Unfortunately I tried it twice, and twice it died
> > > with same crash in log_do_checkpoint (see below). Anybody has a clue
> > > what it could be? When I hit alt-sysrq-s, sync takes about 10 seconds,
> > > so box had to have lots of disk caches dirtied when crash occured.
> > >
> > > Box is dual opteron rev cg, kernel has enabled all possible debug
> > > options. Problem seems to occur on 2.6.11-rc4-something too, it just
> > > begins with crash in ext3_inode_dirty because I have rc4-something built
> > > without memory poisoning (probably).
> > >
> > > I've not noticed any other problems, and it was possible to extract
> > > 2.6.11-rc5-something on Monday with 2.6.11-rc4-something, which crashes
> > > now too. I'll run 'fsck -f', maybe it will help things a bit...
> > >
> > > Bootdata ok (command line is BOOT_IMAGE=Linux ro root=801 ramdisk=0
> > > console=tty0 console=ttyS0,115200 nmi_watchdog=2 psmouse_noext=1 verbose)
> > > Linux version 2.6.11-rc5-2065-64 ([EMAIL PROTECTED]) (gcc version 3.3.3
> > > (Debian 20040401)) #1 SMP Mon Feb 28 22:15:10 CET 2005
> > >
> > > stack segment: [1] PREEMPT SMP
> > > CPU 0
> > I don't see here a reason why the machine crashed (some NULL pointer
> > deref or what...). It would be useful to know it. Also could you run
> > gdb on vmlinux a find out where exactly in the function the oops
> > occured?
>
> It died because of dereferencing RBP which contained memory poisoning
> signature:
>
> 0x801d9996 : lock btsl $0x13,0x0(%rbp)
>
> apparently x86-64 generates #SS for %rbp non-canonical addresses too, like
> i386 does with %ebp segment overruns.
>
> Crash occured in bit_spin_trylock called by jbd_trylock_bh_state from
> log_do_checkpoint (fs/jbd/checkpoint.c:636), because jh2bh (jh->b_bh)
> returned poisoned pattern - apparently somebody else freed journal_head
> while we were holding pointer to it. No idea how it happened.
>
> > Anyway I was briefly reading the code in log_do_checkpoint() and two
> > things are not clear to me - are we guaranteed that
> > transaction->t_checkpoint_list is non-empty (the code relies on that)?
> > Another thing is - __flush_buffer() can sleep. Cannot someone change
> > the t_checkpoint_list while we are sleeping? We are protected only by
> > the j_checkpoint_sem and that only protects us against other
> > log_do_checkpoint() calls.
>
> Code apparently believes that if __flush_buffer() sleeps then it returns
> 1.
Yes, I see that all the buffer heads will be processed. But I'm not
sure whether someone cannot come while we are sleeping and release the
journal_head next_jh points too (actually it seems that such thing is
happening). I'll have a look what could cause such nasty thing...
Honza
> > > Modules linked in: ipx p8022 psnap llc esp6 ah6 ipcomp esp4 ah4 xfrm_user
> > > wp512 tea sha512 michael_mic md4 khazad cast6 cast5 arc4 anubis nfsd
> > > exportfs lockd sunrpc i810_audio ac97_codec soundcore deflate
> > > zlib_deflate zlib_inflate twofish serpent aes blowfish des sha256 sha1
> > > crypto_null af_key capability commoncap w83627hf_wdt md5 ipv6 ide_disk
> > > ide_cd floppy budget_ci tda1004x budget_core dvb_core saa7146
> > > ttpci_eeprom stv0299 i2c_amd756 hw_random i2c_amd8111 amd74xx eth1394
> > > usblp usb_storage ide_core tg3 usbhid ohci1394 ieee1394 tvaudio bttv
> > > tuner video_buf firmware_class v4l2_common btcx_risc tveeprom videodev
> > > ohci_hcd usbcore
> > > Pid: 7703, comm: syslogd Not tainted 2.6.11-rc5-2065-64
> > > RIP: 0010:[] {log_do_checkpoint+246}
> > > RSP: :81007ba819d8 EFLAGS: 00010213
> > > RAX: 81007ba81fd8 RBX: 8100710d12a8 RCX:
> > > RDX: RSI: 006b RDI: 0001
> > > RBP: 6b6b6b6b6b6b6b6b R08: R09: 8100710b2778
> > > R10: 0001 R11: R12: 6b6b6b6b6b6b6b6b
> > > R13: 810070f67a88 R14: 81003fee9120 R15: 81003fee92c4
> > > FS: () GS:805c0300(005b)
> > > knlGS:556c12a0
> > > CS: 0010 DS: 002b ES: 002b CR0: 8005003b
> > > CR2: 556f9d9c CR3: 7bd6e000 CR4: 06e0
> > > Process syslogd (pid: 7703, threadinfo 81007ba8, task
> > > 81003dde2780)
> > > Stack: 81007ba81a38 0020211c80168187 81003bb36208
> > > 000b
> > >81007e4b1698 81007e4b1628 81007e4b15b8
> > > 81007d8c8318
> > >810070f53f58 81007dfb0f58
> > > Call Trace:{__log_wait_for_space+178}
> > > {start_this_handle+1059}
> > >{radix_tree_gang_lookup_tag+77}
> > > {check_poison_obj+48}
> > >
Re: Crash in ext3 while extracting 2.6.11 (on 2.6.11-rc5-something)
On Thu, Mar 03, 2005 at 02:10:04PM +0100, Jan Kara wrote:
> Hello,
>
> >I've noticed that 2.6.11 is released, so I run (flawlessly) 'bk pull',
> > and now I'm trying to export tree from 'bk' by doing 'bk export -tplain
> > /tmp/linux-2.6.11'. Unfortunately I tried it twice, and twice it died
> > with same crash in log_do_checkpoint (see below). Anybody has a clue
> > what it could be? When I hit alt-sysrq-s, sync takes about 10 seconds,
> > so box had to have lots of disk caches dirtied when crash occured.
> >
> > Box is dual opteron rev cg, kernel has enabled all possible debug
> > options. Problem seems to occur on 2.6.11-rc4-something too, it just
> > begins with crash in ext3_inode_dirty because I have rc4-something built
> > without memory poisoning (probably).
> >
> > I've not noticed any other problems, and it was possible to extract
> > 2.6.11-rc5-something on Monday with 2.6.11-rc4-something, which crashes
> > now too. I'll run 'fsck -f', maybe it will help things a bit...
> >
> > Bootdata ok (command line is BOOT_IMAGE=Linux ro root=801 ramdisk=0
> > console=tty0 console=ttyS0,115200 nmi_watchdog=2 psmouse_noext=1 verbose)
> > Linux version 2.6.11-rc5-2065-64 ([EMAIL PROTECTED]) (gcc version 3.3.3
> > (Debian 20040401)) #1 SMP Mon Feb 28 22:15:10 CET 2005
> >
> > stack segment: [1] PREEMPT SMP
> > CPU 0
> I don't see here a reason why the machine crashed (some NULL pointer
> deref or what...). It would be useful to know it. Also could you run
> gdb on vmlinux a find out where exactly in the function the oops
> occured?
It died because of dereferencing RBP which contained memory poisoning
signature:
0x801d9996 : lock btsl $0x13,0x0(%rbp)
apparently x86-64 generates #SS for %rbp non-canonical addresses too, like
i386 does with %ebp segment overruns.
Crash occured in bit_spin_trylock called by jbd_trylock_bh_state from
log_do_checkpoint
(fs/jbd/checkpoint.c:636), because jh2bh (jh->b_bh) returned poisoned pattern
- apparently somebody else freed journal_head while we were holding pointer
to it. No idea how it happened.
> Anyway I was briefly reading the code in log_do_checkpoint() and two
> things are not clear to me - are we guaranteed that
> transaction->t_checkpoint_list is non-empty (the code relies on that)?
> Another thing is - __flush_buffer() can sleep. Cannot someone change
> the t_checkpoint_list while we are sleeping? We are protected only by
> the j_checkpoint_sem and that only protects us against other
> log_do_checkpoint() calls.
Code apparently believes that if __flush_buffer() sleeps then it returns
1.
Petr
> > Modules linked in: ipx p8022 psnap llc esp6 ah6 ipcomp esp4 ah4 xfrm_user
> > wp512 tea sha512 michael_mic md4 khazad cast6 cast5 arc4 anubis nfsd
> > exportfs lockd sunrpc i810_audio ac97_codec soundcore deflate zlib_deflate
> > zlib_inflate twofish serpent aes blowfish des sha256 sha1 crypto_null
> > af_key capability commoncap w83627hf_wdt md5 ipv6 ide_disk ide_cd floppy
> > budget_ci tda1004x budget_core dvb_core saa7146 ttpci_eeprom stv0299
> > i2c_amd756 hw_random i2c_amd8111 amd74xx eth1394 usblp usb_storage ide_core
> > tg3 usbhid ohci1394 ieee1394 tvaudio bttv tuner video_buf firmware_class
> > v4l2_common btcx_risc tveeprom videodev ohci_hcd usbcore
> > Pid: 7703, comm: syslogd Not tainted 2.6.11-rc5-2065-64
> > RIP: 0010:[] {log_do_checkpoint+246}
> > RSP: :81007ba819d8 EFLAGS: 00010213
> > RAX: 81007ba81fd8 RBX: 8100710d12a8 RCX:
> > RDX: RSI: 006b RDI: 0001
> > RBP: 6b6b6b6b6b6b6b6b R08: R09: 8100710b2778
> > R10: 0001 R11: R12: 6b6b6b6b6b6b6b6b
> > R13: 810070f67a88 R14: 81003fee9120 R15: 81003fee92c4
> > FS: () GS:805c0300(005b) knlGS:556c12a0
> > CS: 0010 DS: 002b ES: 002b CR0: 8005003b
> > CR2: 556f9d9c CR3: 7bd6e000 CR4: 06e0
> > Process syslogd (pid: 7703, threadinfo 81007ba8, task
> > 81003dde2780)
> > Stack: 81007ba81a38 0020211c80168187 81003bb36208 000b
> >81007e4b1698 81007e4b1628 81007e4b15b8 81007d8c8318
> >810070f53f58 81007dfb0f58
> > Call Trace:{__log_wait_for_space+178}
> > {start_this_handle+1059}
> >{radix_tree_gang_lookup_tag+77}
> > {check_poison_obj+48}
> >{poison_obj+70} {new_handle+20}
> >{dbg_redzone1+37}
> > {new_handle+20}
> >{cache_alloc_debugcheck_after+280}
> >{journal_start+168}
> > {ext3_dirty_inode+54}
> >{__mark_inode_dirty+52}
> > {inode_update_time+188}
> >{pipe_writev+1311}
> > {compat_do_readv_writev+403}
> >{pipe_write+0} {_spin_lock+27}
> >{_spin_unlock+64}
> > {compat_sys_writev+115}
> >{ia32_sysret+0}
> >
> > Code: f0 0f ba 6d 00 13
Re: Crash in ext3 while extracting 2.6.11 (on 2.6.11-rc5-something)
Hello,
>I've noticed that 2.6.11 is released, so I run (flawlessly) 'bk pull',
> and now I'm trying to export tree from 'bk' by doing 'bk export -tplain
> /tmp/linux-2.6.11'. Unfortunately I tried it twice, and twice it died
> with same crash in log_do_checkpoint (see below). Anybody has a clue
> what it could be? When I hit alt-sysrq-s, sync takes about 10 seconds,
> so box had to have lots of disk caches dirtied when crash occured.
>
> Box is dual opteron rev cg, kernel has enabled all possible debug
> options. Problem seems to occur on 2.6.11-rc4-something too, it just
> begins with crash in ext3_inode_dirty because I have rc4-something built
> without memory poisoning (probably).
>
> I've not noticed any other problems, and it was possible to extract
> 2.6.11-rc5-something on Monday with 2.6.11-rc4-something, which crashes
> now too. I'll run 'fsck -f', maybe it will help things a bit...
>
> Bootdata ok (command line is BOOT_IMAGE=Linux ro root=801 ramdisk=0
> console=tty0 console=ttyS0,115200 nmi_watchdog=2 psmouse_noext=1 verbose)
> Linux version 2.6.11-rc5-2065-64 ([EMAIL PROTECTED]) (gcc version 3.3.3
> (Debian 20040401)) #1 SMP Mon Feb 28 22:15:10 CET 2005
>
> stack segment: [1] PREEMPT SMP
> CPU 0
I don't see here a reason why the machine crashed (some NULL pointer
deref or what...). It would be useful to know it. Also could you run
gdb on vmlinux a find out where exactly in the function the oops
occured?
Anyway I was briefly reading the code in log_do_checkpoint() and two
things are not clear to me - are we guaranteed that
transaction->t_checkpoint_list is non-empty (the code relies on that)?
Another thing is - __flush_buffer() can sleep. Cannot someone change
the t_checkpoint_list while we are sleeping? We are protected only by
the j_checkpoint_sem and that only protects us against other
log_do_checkpoint() calls.
Honza
> Modules linked in: ipx p8022 psnap llc esp6 ah6 ipcomp esp4 ah4 xfrm_user
> wp512 tea sha512 michael_mic md4 khazad cast6 cast5 arc4 anubis nfsd exportfs
> lockd sunrpc i810_audio ac97_codec soundcore deflate zlib_deflate
> zlib_inflate twofish serpent aes blowfish des sha256 sha1 crypto_null af_key
> capability commoncap w83627hf_wdt md5 ipv6 ide_disk ide_cd floppy budget_ci
> tda1004x budget_core dvb_core saa7146 ttpci_eeprom stv0299 i2c_amd756
> hw_random i2c_amd8111 amd74xx eth1394 usblp usb_storage ide_core tg3 usbhid
> ohci1394 ieee1394 tvaudio bttv tuner video_buf firmware_class v4l2_common
> btcx_risc tveeprom videodev ohci_hcd usbcore
> Pid: 7703, comm: syslogd Not tainted 2.6.11-rc5-2065-64
> RIP: 0010:[] {log_do_checkpoint+246}
> RSP: :81007ba819d8 EFLAGS: 00010213
> RAX: 81007ba81fd8 RBX: 8100710d12a8 RCX:
> RDX: RSI: 006b RDI: 0001
> RBP: 6b6b6b6b6b6b6b6b R08: R09: 8100710b2778
> R10: 0001 R11: R12: 6b6b6b6b6b6b6b6b
> R13: 810070f67a88 R14: 81003fee9120 R15: 81003fee92c4
> FS: () GS:805c0300(005b) knlGS:556c12a0
> CS: 0010 DS: 002b ES: 002b CR0: 8005003b
> CR2: 556f9d9c CR3: 7bd6e000 CR4: 06e0
> Process syslogd (pid: 7703, threadinfo 81007ba8, task
> 81003dde2780)
> Stack: 81007ba81a38 0020211c80168187 81003bb36208 000b
>81007e4b1698 81007e4b1628 81007e4b15b8 81007d8c8318
>810070f53f58 81007dfb0f58
> Call Trace:{__log_wait_for_space+178}
> {start_this_handle+1059}
>{radix_tree_gang_lookup_tag+77}
> {check_poison_obj+48}
>{poison_obj+70} {new_handle+20}
>{dbg_redzone1+37} {new_handle+20}
>{cache_alloc_debugcheck_after+280}
>{journal_start+168}
> {ext3_dirty_inode+54}
>{__mark_inode_dirty+52}
> {inode_update_time+188}
>{pipe_writev+1311}
> {compat_do_readv_writev+403}
>{pipe_write+0} {_spin_lock+27}
>{_spin_unlock+64}
> {compat_sys_writev+115}
>{ia32_sysret+0}
>
> Code: f0 0f ba 6d 00 13 19 c0 85 c0 74 3b bf 01 00 00 00 e8 64 b0
> RIP {log_do_checkpoint+246} RSP
> <3>Debug: sleeping function called from invalid context at
> include/linux/rwsem.h:43
> in_atomic():1, irqs_disabled():0
>
> Call Trace:{__might_sleep+206}
> {profile_task_exit+41}
>{do_exit+28} {die+69}
>{do_trap+331}
> {do_stack_segment+175}
>{stack_segment+125}
> {log_do_checkpoint+246}
>
> note: syslogd[7703] exited with preempt_count 2
> scheduling while atomic: syslogd/0x1002/7703
>
> Call Trace:{schedule+125}
> {avc_has_perm+90}
>{_spin_lock+27} {__mod_timer+303}
>{cond_resched+47}
> {ext3_statfs+111}
>{vfs_statfs+95}
> {check_free_space+110}
>{do_acct_process+26}
> {acct_process+104}
>{do_exit+293} {die+69}
>{d
