In last week's ext4 concall I mentioned that I'd seen five consecutive failures
of xfstest generic/068 on an ext4 file system mounted with data=journal while
doing dev branch testing on a Pandaboard. Similar failures of generic/068 on
filesystems mounted with data=journal have been visible for some time with
mainline kernels on both x86-64 and ARM in about 10% of the tests run. (That
was still the case for my x86-64 runs on this dev kernel.)
Because we'd like a dependable reproducer to help find a fix for these failures,
I ran a larger number of trials on the Pandaboard using the same dev kernel
to see if we really had one. Unfortunately, the failure rate for this larger
sample set was 40% rather than 100%. The failure rate did still appear to be
elevated as compared to 3.10 on ARM.
More recent runs of generic/068 on a dev kernel from Friday failed at
about a 30% rate in the same test scenario on the Pandaboard and at the
same statement in the jbd2 code.
As requested, the last commit for the initial dev kernel:
74039f20b5 - ext4: remove ext4_ioend_wait()
The last commit for Friday's dev kernel:
a1edc9ea52 - jbd2: fix theoretical race in jbd2__journal_restart
Configuration for SUT:
Pandaboard ES, 2 ARM cores, 1 GB memory, 1 SATA III disk attached via USB 2.0
on which three 5 GB test file systems were located. e2fsprogs master branch,
1.43 WIP.
Stack trace excerpt from original dev kernel on Pandaboard:
kernel BUG at fs/jbd2/transaction.c:2156!
Internal error: Oops - BUG: 0 [#1] SMP ARM
Modules linked in:
CPU: 1 PID: 30272 Comm: fstest Not tainted 3.10.0-rc2-13849-g74039f2 #1
task: ed184140 ti: ec4c4000 task.ti: ec4c4000
PC is at jbd2_journal_invalidatepage+0x3cc/0x3f4
LR is at jbd2_journal_invalidatepage+0x208/0x3f4
pc : [<c01f926c>] lr : [<c01f90a8>] psr: 00000113
sp : ec4c5b88 ip : 00000000 fp : ec4c5bd4
r10: ecb58f88 r9 : 00200000 r8 : 00001000
r7 : ecb58f88 r6 : 00000000 r5 : ecb58f88 r4 : 00001000
r3 : 00000002 r2 : 0071c025 r1 : ecb58f88 r0 : 00000000
Flags: nzcv IRQs on FIQs on Mode SVC_32 ISA ARM Segment user
Control: 10c5387d Table: a77c804a DAC: 00000015
Process fstest (pid: 30272, stack limit = 0xec4c4240)
[<c01f926c>] (jbd2_journal_invalidatepage+0x3cc/0x3f4)
[<c01aab88>] (__ext4_journalled_invalidatepage+0x70/0xac)
[<c01abdb0>] (ext4_journalled_invalidatepage+0x18/0x34)
[<c00e355c>] (truncate_inode_page+0xbc/0xc4)
[<c00e36a4>] (truncate_inode_pages_range+0x140/0x47c)
[<c00e3abc>] (truncate_inode_pages+0x28/0x30)
[<c00e3b34>] (truncate_pagecache+0x70/0x90)
[<c01b04ac>] (ext4_setattr+0x40c/0x688)
[<c012df14>] (notify_change+0x1e8/0x334)
[<c0112368>] (do_truncate+0x84/0xa8)
[<c0121c7c>] (do_last.isra.28+0x634/0xba8)
[<c01222ac>] (path_openat+0xbc/0x498)
[<c01229a4>] (do_filp_open+0x3c/0x90)
[<c0113358>] (do_sys_open+0xf4/0x180)
[<c0113410>] (SyS_open+0x2c/0x30)
And another problem - when I ran generic/068 on an ext4 file system mounted with
data=journal using an x86-64 VM using Friday's dev kernel, the kernel BUGed
about 10% of the time as usual at fs/jbd2/transaction.c: 2133. However, it
also failed about 40% of the time in a way it didn't on the Pandaboard.
Retesting on x86-64 running 3.10-rc6, I was able to get the same failure but
at a lower rate of between 10 and 20%. (This may not bode well for trying to
reproduce the transaction.c BUG() on a physical x86-64 as we discussed in
the call.)
Here's an excerpt from that stack trace:
kernel BUG at fs/buffer.c:2956!
invalid opcode: 0000 [#1] SMP
Modules linked in: kvm_intel kvm microcode snd_hda_intel psmouse serio_raw snd_hda_codec snd_hwdep snd_pcm snd_timer snd soundcore snd_page_alloc virtio_balloon i2c_piix4 mac_hid lp parport f\
CPU: 0 PID: 3644 Comm: fstest Not tainted 3.10.0-rc6-ext4testing #1
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2007
task: ffff88003bbb9fb0 ti: ffff88003d23c000 task.ti: ffff88003d23c000
RIP: 0010:[<ffffffff811b8bca>] [<ffffffff811b8bca>] _submit_bh+0x17a/0x200
RSP: 0000:ffff88003d23d878 EFLAGS: 00010246
RAX: 000000000011c005 RBX: ffff88003b4f4f70 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffff88003b4f4f70 RDI: 0000000000000411
RBP: ffff88003d23d898 R08: 0000000000000004 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000411
R13: ffff88003d23d964 R14: ffff8800256b1800 R15: ffff88003b4f4f70
FS: 00007fcb7c652700(0000) GS:ffff88003fc00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fcb7c5e6000 CR3: 0000000036847000 CR4: 00000000000006f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Stack:
ffff88003b4f4f70 0000000000000411 ffff88003d23d964 ffff8800256b1800
ffff88003d23d8a8 ffffffff811b8c60 ffff88003d23d8c8 ffffffff811ba015
0000000000000001 ffff8800256b1b48 ffff88003d23d928 ffffffff8127932d
Call Trace:
[<ffffffff811b8c60>] submit_bh+0x10/0x20
[<ffffffff811ba015>] write_dirty_buffer+0x55/0x80
[<ffffffff8127932d>] __flush_batch+0x4d/0xa0
[<ffffffff81279b7f>] jbd2_log_do_checkpoint+0x27f/0x480
[<ffffffff81279e27>] __jbd2_log_wait_for_space+0xa7/0x1d0
[<ffffffff81273f70>] start_this_handle+0x2d0/0x550
[<ffffffff81178f2a>] ? kmem_cache_alloc+0x13a/0x140
[<ffffffff81274457>] jbd2__journal_start+0xf7/0x1d0
[<ffffffff8122cbf0>] ? ext4_dirty_inode+0x30/0x70
[<ffffffff81252bf2>] __ext4_journal_start_sb+0x82/0x150
[<ffffffff8122cbf0>] ext4_dirty_inode+0x30/0x70
[<ffffffff811b0942>] __mark_inode_dirty+0xe2/0x2b0
[<ffffffff811a10e1>] update_time+0x81/0xc0
[<ffffffff811a5662>] ? mnt_clone_write+0x12/0x30
[<ffffffff811a11b8>] file_update_time+0x98/0xf0
[<ffffffff8112a8aa>] ? find_get_page+0x9a/0xf0
[<ffffffff8122ce10>] ext4_page_mkwrite+0x60/0x450
[<ffffffff8114e84e>] __do_fault+0xde/0x470
[<ffffffff8115149f>] handle_pte_fault+0x8f/0x890
[<ffffffff811524a0>] handle_mm_fault+0x210/0x300
[<ffffffff816cfecf>] __do_page_fault+0x18f/0x510
[<ffffffff81070a63>] ? up_write+0x23/0x40
[<ffffffff811452e4>] ? vm_mmap_pgoff+0xb4/0xe0
[<ffffffff816cc5c9>] ? retint_swapgs+0xe/0x13
[<ffffffff813493ad>] ? trace_hardirqs_off_thunk+0x3a/0x3c
[<ffffffff816d025e>] do_page_fault+0xe/0x10
[<ffffffff816cc7e2>] page_fault+0x22/0x30
Thanks,
Eric