Re: Re: EXT4 panic at jbd2_journal_put_journal_head() in 3.9+

Re: Re: EXT4 panic at jbd2_journal_put_journal_head() in 3.9+

[EUNBONG SONG]

> Can you give us the full crash message, (i.e., the panic, the BUG,
> WARN, the registers, etc.), and not the stack trace?

>                       - Ted

Hi, Ted
Actually i try to find the crash point. And i confirmed crash point is in __journal_remove_journal_head() function.
I added some debug code and i found  J_ASSERT_JH is failed for jh->b_transaction. 
My source tree has some modifications only for MIPS architecture. I don't think it does not affect to ext4 operation. 
Also I confirmed the problem is not reproduced before merge 149b306089b88e186942a8d6647028ae6683aaf9.

149b306089b88e186942a8d6647028ae6683aaf9 Merge tag 'ext4_for_linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tytso/ext4

My full crash messages are as follows.

Iozone: Performance Test of File I/O
                Version $Revision: 3.397 $
                Compiled for 64 bit mode.
                Build: linux-powerpc64

        Contributors:William Norcott, Don Capps, Isom Crawford, Kirby Collins
                     Al Slater, Scott Rhine, Mike Wisner, Ken Goss
                     Steve Landherr, Brad Smith, Mark Kelly, Dr. Alain CYR,
                     Randy Dunlap, Mark Montague, Dan Million, Gavin Brebner,
                     Jean-Marc Zucconi, Jeff Blomberg, Benny Halevy, Dave Boone,
                     Erik Habbinga, Kris Strecker, Walter Wong, Joshua Roo[  233.458766] CPU: 3 PID: 1535 Comm: iozone Not tainted 3.9.0+ #81
t,
                     Fabrice Bacchella, Zhenghua Xue, Qin Li, Darre[  233.470132] Stack :n Sawyer.
                     Ben England.

        Run began: Sun Dec 10  ffffffff8101143808:38:24 2000

        Record Size 64 KB
        File size set to 5120 KB
 a80000008b64b000       SYNC Mode.
        Command line used: iozone -l 20 -u 20 -r 64k -s 5 0000000000000003m -o -F /user/f1 /user/f2 /user/f3 /user/f4 /user/f5 /user/f6 /u ffffffff80292470ser/f7 /user/f8 /user/f9 /user/f10 /user/f11 /user/f12 /user/f13
          /user/f14 /user/f15 /user/f16 /user/f17 /user/f18 /user/f19 /us 0000000000000000er/f20
        Output is in Kbytes/sec
        Time Resolution = 0.000001 se ffffffff80fa0000conds.
        Processor cache size set to 1024 Kbytes.
        Processor ca 000000000000001fche line size set to 32 bytes.
        File stride size set to 17 * re ffffffff80293728cord size.
        Min process = 20
        Max process = 20
        Throughput
         test with 20 processes
        Each process writes a 5120 Kbyte file i 0000000000000000n 64 Kbyte records
 0000000000000000 ffffffff81080000 ffffffff81080000
          ffffffff80e2abf0 ffffffff80f8f9f7 a8000002017a0db8 0000000000000020
          0000000000000003 0000000000000020 a80000020025f968 ffffffff810f0000
          a80000020025f770 ffffffff806ee88c a80000020025f588 ffffffff80290994
          000000007ef10087 ffffffff80293b58 000000000000000a ffffffff80e2abf0
          0000000000000003 a80000020025f4b0 00000002017a10f8 ffffffff805e68b4
          0000000000000000 0000000000000000 0000000000000000 0000000000000000
          0000000000000000 ffffffff80272418 0000000000000000 0000000000000000
          ...
[  233.604041] Call Trace:
[  233.606495] [<ffffffff80272418>] show_stack+0x68/0x80
[  233.611550] [<ffffffff805e68b4>] cdr_event_handler+0x604/0xbf8
[  233.617384] [<ffffffff805e7648>] cdr_event_die+0xd0/0x150
[  233.622784] [<ffffffff802bd42c>] notifier_call_chain+0x5c/0xa8
[  233.628619] [<ffffffff802bdb04>] __atomic_notifier_call_chain+0x3c/0x58
[  233.635233] [<ffffffff802bdb68>] notify_die+0x38/0x48
[  233.640285] [<ffffffff80271c48>] do_trap_or_bp+0x48/0x1a8
[  233.645684] [<ffffffff8026c764>] resume_userspace_check+0x0/0x10
[  233.651695] [<ffffffff80460b64>] jbd2_journal_put_journal_head+0xcc/0x250
[  233.658484] [<ffffffff8045a1b4>] jbd2_journal_get_write_access+0x3c/0x58
[  233.665188] [<ffffffff804348a8>] __ext4_journal_get_write_access+0x58/0xa0
[  233.672064] [<ffffffff80410344>] ext4_reserve_inode_write+0x84/0xb0
[  233.678331] [<ffffffff804103ac>] ext4_mark_inode_dirty+0x3c/0x1e0
[  233.684424] [<ffffffff80410590>] ext4_dirty_inode+0x40/0x70
[  233.689998] [<ffffffff80392258>] __mark_inode_dirty+0x48/0x238
[  233.695832] [<ffffffff803828f4>] update_time+0xb4/0x100
[  233.701058] [<ffffffff803829f0>] file_update_time+0xb0/0x108
[  233.706718] [<ffffffff8031eb98>] __generic_file_aio_write+0x180/0x380
[  233.713158] [<ffffffff8031edf8>] generic_file_aio_write+0x60/0xc0
[  233.719252] [<ffffffff8040af54>] ext4_file_write+0x6c/0x468
[  233.724827] [<ffffffff80366cbc>] do_sync_write+0x84/0xe8
[  233.730139] [<ffffffff80368700>] vfs_write+0xe0/0x1e0
[  233.735191] [<ffffffff803688f8>] SyS_write+0x50/0xc0
[  233.740157] [<ffffffff80274864>] handle_sys64+0x44/0x64

Thanks. 

Re: Re: EXT4 panic at jbd2_journal_put_journal_head() in 3.9+

[Tony Luck]

[-- Attachment #1: Type: text/plain, Size: 892 bytes --]

I think I have the same (or highly similar) thing happening on ia64.

Similarities: seeing assertions fail for b_transaction
Differences: I only have ext3 filesystems mounted, no ext4

See attached trace.  I'm pretty certain that the highly unhelpful

    bugcheck! 0 [1]

comes from the

        J_ASSERT_JH(jh, jh->b_transaction == NULL);

from disassembling __journal_remove_journal_head(). The instruction
pointer <a0000001003d6690> points to the 2nd "break" instruction
in the function.

The problem shows up after 30 minutes to a couple of hours of stress (kernel
builds with "make -j32").

I'm pretty sure this problem didn't occur in plain v3.9 (it can run for
a full 24 hours).

Trying to bisect - but it takes a while to be convinced that a good kernel
is actually good (since I don't have a clear picture of how long to run
before deciding that the bug isn't going to show)

-Tony

[-- Attachment #2: bug --]
[-- Type: application/octet-stream, Size: 5312 bytes --]

Welcome to SUSE Linux Enterprise Server 11 SP1  (ia64) - Kernel 3.9.0-generic-smp-10996-g0f47c94 (ttyS0).


linux-bxb1 login: ld[16310]: bugcheck! 0 [1]
Modules linked in: nfs dns_resolver lockd sunrpc binfmt_misc loop sr_mod dm_mod usb_storage ehci_pci sg button usbhid uhci_hcd ehci_hcd usbcore usb_common fan processor thermal thermal_sys

CPU: 29 PID: 16310 Comm: ld Not tainted 3.9.0-generic-smp-10996-g0f47c94 #16
Hardware name: Supermicro I8QBH/I8QBH, BIOS I8QBH 15.006.004RAS 2010/05/10
task: e000000316e50000 ti: e000000316e50e10 task.ti: e000000316e50e10
psr : 0000101008526038 ifs : 800000000000038a ip  : [<a0000001003d6690>]    Not tainted (3.9.0-generic-smp-10996-g0f47c94)
ip is at __journal_remove_journal_head+0x530/0x6c0
unat: 0000000000000000 pfs : 000000000000038a rsc : 0000000000000003
rnat: 0000000000000000 bsps: 0000000000000000 pr  : 59519aa665a99555
ldrs: 0000000000000000 ccv : 0000000000000006 fpsr: 0009804c8a70033f
csd : 0000000000000000 ssd : 0000000000000000
b0  : a0000001003d6690 b6  : a00000010057fac0 b7  : a0000001000103f0
f6  : 000000000000000000000 f7  : 1003e00000001370f632a
f8  : 1003e0044b82fa09b5a53 f9  : 1003e000001f1c8973a6a
f10 : 1003e8eaf481679c5af3e f11 : 1003e000000000000009b
r1  : a00000010179d490 r2  : 0000000000000007 r3  : a00000010159e058
r8  : 0000000000000024 r9  : 0000000000000001 r10 : e0000000018409c8
r11 : 0000000000000001 r12 : e000000316e5fbc0 r13 : e000000316e50000
r14 : 0000000000000006 r15 : 0000000000000007 r16 : 0000000000000000
r17 : e000000001880000 r18 : fffffffffffc0428 r19 : fffffffffffc09c8
r20 : 0000001008522038 r21 : 0000000000004000 r22 : 8200000000240038
r23 : 0000000000000039 r24 : 0000000000000039 r25 : 0000000000000031
r26 : 0000000000000002 r27 : 8200000000240038 r28 : 00000000000002dc
r29 : 00000000000002db r30 : 0000000000010068 r31 : 0000000000000038

Call Trace:
 [<a000000100015d20>] show_stack+0x80/0xa0
                                sp=e000000316e5f780 bsp=e000000316e51b60
 [<a000000100016380>] show_regs+0x640/0x920
                                sp=e000000316e5f950 bsp=e000000316e51b08
 [<a000000100041540>] die+0x1a0/0x2e0
                                sp=e000000316e5f960 bsp=e000000316e51ac8
 [<a0000001000416d0>] die_if_kernel+0x50/0x80
                                sp=e000000316e5f960 bsp=e000000316e51a98
 [<a0000001000429f0>] ia64_bad_break+0x3d0/0x6e0
                                sp=e000000316e5f960 bsp=e000000316e51a70
 [<a00000010000be60>] ia64_native_leave_kernel+0x0/0x270
                                sp=e000000316e5f9f0 bsp=e000000316e51a70
 [<a0000001003d6690>] __journal_remove_journal_head+0x530/0x6c0
                                sp=e000000316e5fbc0 bsp=e000000316e51a20
 [<a0000001003d69c0>] journal_put_journal_head+0x1a0/0x260
                                sp=e000000316e5fbc0 bsp=e000000316e519f0
 [<a0000001003cb9d0>] journal_get_undo_access+0x330/0x3e0
                                sp=e000000316e5fbc0 bsp=e000000316e519a0
 [<a0000001003a3e10>] __ext3_journal_get_undo_access+0x30/0xa0
                                sp=e000000316e5fbc0 bsp=e000000316e51968
 [<a000000100379a90>] ext3_try_to_allocate_with_rsv+0x70/0x720
                                sp=e000000316e5fbc0 bsp=e000000316e518c0
 [<a00000010037a460>] ext3_new_blocks+0x320/0xd60
                                sp=e000000316e5fbe0 bsp=e000000316e517d0
 [<a000000100384bd0>] ext3_alloc_branch+0x90/0x8e0
                                sp=e000000316e5fc00 bsp=e000000316e51720
 [<a000000100386360>] ext3_get_blocks_handle+0xf40/0xfe0
                                sp=e000000316e5fc30 bsp=e000000316e51690
 [<a000000100386590>] ext3_get_block+0x190/0x200
                                sp=e000000316e5fcb0 bsp=e000000316e51628
 [<a000000100289f80>] __block_write_begin+0x560/0xb00
                                sp=e000000316e5fcb0 bsp=e000000316e51538
 [<a00000010038a070>] ext3_write_begin+0x110/0x420
                                sp=e000000316e5fcd0 bsp=e000000316e51458
 [<a0000001001660c0>] generic_perform_write+0x120/0x4e0
                                sp=e000000316e5fce0 bsp=e000000316e51390
 [<a000000100166510>] generic_file_buffered_write+0x90/0xe0
                                sp=e000000316e5fcf0 bsp=e000000316e51338
 [<a00000010016b720>] __generic_file_aio_write+0x440/0x720
                                sp=e000000316e5fd10 bsp=e000000316e512c8
 [<a00000010016ba90>] generic_file_aio_write+0x90/0x1a0
                                sp=e000000316e5fd30 bsp=e000000316e51270
 [<a0000001002186f0>] do_sync_write+0x130/0x240
                                sp=e000000316e5fd30 bsp=e000000316e51218
 [<a00000010021abe0>] vfs_write+0x200/0x400
                                sp=e000000316e5fe20 bsp=e000000316e511c0
 [<a00000010021afb0>] SyS_write+0x90/0xe0
                                sp=e000000316e5fe20 bsp=e000000316e51148
 [<a00000010000bce0>] ia64_ret_from_syscall+0x0/0x20
                                sp=e000000316e5fe30 bsp=e000000316e51148
 [<a000000000040720>] __kernel_syscall_via_break+0x0/0x20
                                sp=e000000316e60000 bsp=e000000316e51148
Disabling lock debugging due to kernel taint
INFO: rcu_sched self-detected stall on CPUINFO: rcu_sched self-detected stall on CPU { 30}  (t=5250 jiffies g=208324 c=208323 q=7602)

Re: Re: EXT4 panic at jbd2_journal_put_journal_head() in 3.9+

[Dmitry Monakhov]

On Fri, 10 May 2013 10:27:58 -0700, Tony Luck <tony.luck@gmail.com> wrote:
Non-text part: multipart/mixed
> I think I have the same (or highly similar) thing happening on ia64.
What was page_size and fsblock size?
> 
> Similarities: seeing assertions fail for b_transaction
> Differences: I only have ext3 filesystems mounted, no ext4
> 
> See attached trace.  I'm pretty certain that the highly unhelpful
> 
>     bugcheck! 0 [1]
> 
> comes from the
> 
>         J_ASSERT_JH(jh, jh->b_transaction == NULL);
> 
> from disassembling __journal_remove_journal_head(). The instruction
> pointer <a0000001003d6690> points to the 2nd "break" instruction
> in the function.
> 
> The problem shows up after 30 minutes to a couple of hours of stress (kernel
> builds with "make -j32").
I cant reproduce this one yet.
But changes {ext3,jbd} are minimal
#git log --oneline v3.9.. fs/{ext3,jbd}
5af43c2 Merge branch 'akpm' (incoming from Andrew)
a27bb33 aio: don't include aio.h in sched.h
4385bab make blkdev_put() return void
14a9e5c Merge branch 'for_linus' of git://git.kernel.org/pub/scm/linux/kernel/git/jack/linux-fs
e760040 fs/buffer.c: remove unnecessary init operation after allocating buffer_head.
713685111 mm: make snapshotting pages for stable writes a per-bio
operation
8bb9da9 jbd: use kmem_cache_zalloc for allocating journal head
e162b2f jbd: use kmem_cache_zalloc instead of kmem_cache_alloc/memset
e678a4f jbd: don't wait (forever) for stale tid caused by wraparound
e643692 ext3: fix data=journal fast mount/umount hang

So looks very strange..
I have ia64 and now I work on reproduction.
> 
> I'm pretty sure this problem didn't occur in plain v3.9 (it can run for
> a full 24 hours).
> 
> Trying to bisect - but it takes a while to be convinced that a good kernel
> is actually good (since I don't have a clear picture of how long to run
> before deciding that the bug isn't going to show)
> 
> -Tony
Attachment: bug (application/octet-stream)

Re: Re: EXT4 panic at jbd2_journal_put_journal_head() in 3.9+

[Tony Luck]

On Sat, May 11, 2013 at 12:52 AM, Dmitry Monakhov <dmonakhov@openvz.org> wrote:.
> What was page_size and fsblock size?

CONFIG_IA64_PAGE_SIZE_64KB=y

fsblock size is whatever is the default for SLES11SP2 on ia64 - which
tool will tell me?

My git bisect finally competed and points the a finger at:

bisect> git bisect good
ae4647fb7654676fc44a97e86eb35f9f06b99f66 is first bad commit
commit ae4647fb7654676fc44a97e86eb35f9f06b99f66
Author: Jan Kara <jack@suse.cz>
Date:   Fri Apr 12 00:03:42 2013 -0400

    jbd2: reduce journal_head size

    Remove unused t_cow_tid field (ext4 copy-on-write support doesn't seem
    to be happening) and change b_modified and b_jlist to bitfields thus
    saving 8 bytes in the structure.

    Signed-off-by: Jan Kara <jack@suse.cz>
    Signed-off-by: "Theodore Ts'o" <tytso@mit.edu>
    Reviewed-by: Zheng Liu <wenqing.lz@taobao.com>

:040000 040000 c39ece4341894b3daf84764ba425a87ffb90fe50
d4e8d9185c2a1b740c235ca8ed05d496a442fce3 M      include

-Tony

Re: Re: EXT4 panic at jbd2_journal_put_journal_head() in 3.9+

[EUNBONG SONG]

> Hi,

> Bitfields are likely to be implemented using read-modify-write semantics.
> Modifications of either b_jlist or b_jmodified must be done under lock
> since they share same uint. I guess this lock is missing somewhere.

Hi, I agree with you.  b_jlist and b_jmodified share the same unit.
I think they are separated. 
Thanks. 

Re: Re: EXT4 panic at jbd2_journal_put_journal_head() in 3.9+

[EUNBONG SONG]

Hi,
I have some problem to boot with 3.10-rc1.  So i will test with e0fd9affeb64088eff407dfc98bbd3a5c17ea479.
The commit message is as follow.
commit e0fd9affeb64088eff407dfc98bbd3a5c17ea479
Merge: 3d15b79 ea9627c
Author: Linus Torvalds <torvalds@linux-foundation.org>
Date:   Wed May 8 15:29:48 2013 -0700

    Merge tag 'rdma-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/roland/infiniband


Usually, the problem was reproduced in 30 seconds in my board. 
I will test only revert ae4647fb7654676fc44a97e86eb35f9f06b99f66(jbd2: reduce journal_head size) and 
i will let you know the test result. 

Thanks.

Re: Re: EXT4 panic at jbd2_journal_put_journal_head() in 3.9+

[Zheng Liu]

On Sun, May 12, 2013 at 07:04:45PM -0700, Tony Luck wrote:
> On Sat, May 11, 2013 at 12:52 AM, Dmitry Monakhov <dmonakhov@openvz.org> wrote:.
> > What was page_size and fsblock size?
> 
> CONFIG_IA64_PAGE_SIZE_64KB=y
> 
> fsblock size is whatever is the default for SLES11SP2 on ia64 - which
> tool will tell me?
> 
> My git bisect finally competed and points the a finger at:
> 
> bisect> git bisect good
> ae4647fb7654676fc44a97e86eb35f9f06b99f66 is first bad commit
> commit ae4647fb7654676fc44a97e86eb35f9f06b99f66
> Author: Jan Kara <jack@suse.cz>
> Date:   Fri Apr 12 00:03:42 2013 -0400
> 
>     jbd2: reduce journal_head size
> 
>     Remove unused t_cow_tid field (ext4 copy-on-write support doesn't seem
>     to be happening) and change b_modified and b_jlist to bitfields thus
>     saving 8 bytes in the structure.
> 
>     Signed-off-by: Jan Kara <jack@suse.cz>
>     Signed-off-by: "Theodore Ts'o" <tytso@mit.edu>
>     Reviewed-by: Zheng Liu <wenqing.lz@taobao.com>
> 
> :040000 040000 c39ece4341894b3daf84764ba425a87ffb90fe50
> d4e8d9185c2a1b740c235ca8ed05d496a442fce3 M      include

Hi all,

First of all I couldn't reproduce this regression in my sand box.  So
the following speculation is only my guess.  I suspect that the commit
(ae4647fb) isn't root cause.  It just uncover a potential bug that has
been there for a long time.  I look at the code, and found two
suspicious stuff in jbd2.  The first one is in do_get_write_access().
In this function we forgot to lock bh state when we check b_jlist ==
BJ_Shadow.  I generate a patch to fix it, and I really think it is the
root cause.  Further, in __journal_remove_journal_head() we check
b_jlist == BJ_None.  But, when this function is called, bh state won't
be locked sometimes.  So I suspect this is why we hit a BUG in
jbd2_journal_put_journal_head().  But I don't have a good solution to
fix this until now because I don't know whether we need to lock bh state
here, or maybe we should remove this assertation.

So, generally, Tony, Eunbong, could you please try the following patch?

Thanks in advance,
                                                - Zheng


Subject: [PATCH] jbd2: lock bh state when check b_jlist == BJ_Shadow

From: Zheng Liu <wenqing.lz@taobao.com>

When we try to check b_jlist's value we need to lock bh state.  But in
do_get_write_access when we check b_jlist == BJ_Shadow we won't lock bh
state.  So fix it.

Signed-off-by: Zheng Liu <wenqing.lz@taobao.com>
---
 fs/jbd2/transaction.c | 14 ++++++++------
 1 file changed, 8 insertions(+), 6 deletions(-)

diff --git a/fs/jbd2/transaction.c b/fs/jbd2/transaction.c
index 10f524c..a800513 100644
--- a/fs/jbd2/transaction.c
+++ b/fs/jbd2/transaction.c
@@ -761,16 +761,18 @@ repeat:
 			wqh = bit_waitqueue(&bh->b_state, BH_Unshadow);
 
 			JBUFFER_TRACE(jh, "on shadow: sleep");
-			jbd_unlock_bh_state(bh);
 			/* commit wakes up all shadow buffers after IO */
-			for ( ; ; ) {
-				prepare_to_wait(wqh, &wait.wait,
-						TASK_UNINTERRUPTIBLE);
+			do {
 				if (jh->b_jlist != BJ_Shadow)
 					break;
+				prepare_to_wait(wqh, &wait.wait,
+						TASK_UNINTERRUPTIBLE);
+				jbd_unlock_bh_state(bh);
 				schedule();
-			}
-			finish_wait(wqh, &wait.wait);
+				finish_wait(wqh, &wait.wait);
+				jbd_lock_bh_state(bh);
+			} while (1);
+			jbd_unlock_bh_state(bh);
 			goto repeat;
 		}
 
-- 
1.7.12.rc2.18.g61b472e