* crash in __jbd2_journal_file_buffer @ 2013-07-30 22:41 Sage Weil 2013-07-31 19:02 ` Jan Kara 0 siblings, 1 reply; 16+ messages in thread From: Sage Weil @ 2013-07-30 22:41 UTC (permalink / raw) To: linux-ext4 Hi everyone, Hit this on 3.10. Is this a known issue? Thanks- sage Stack traceback for pid 23944 0xffff8802206edeb0 23944 23840 1 2 R 0xffff8802206ee338 *ceph-osd ffff88020bf17b78 0000000000000018 ffffffff81267398 ffff8802256d40c0 ffff88020b5a1230 ffff88020bf17bb8 ffffffff81325d9c ffff88020b5a1230 ffff8802256d40c0 ffff88020b5a1230 00000000698a8d24 ffff88020bf17be8 Call Trace: [<ffffffff81267398>] ? __jbd2_journal_file_buffer+0x188/0x260 [<ffffffff81325d9c>] ? do_raw_spin_lock+0x10c/0x150 [<ffffffff81268118>] ? do_get_write_access+0x448/0x650 [<ffffffff81213caf>] ? ext4_read_inode_bitmap+0x9f/0x5f0 [<ffffffff81167849>] ? kmem_cache_alloc+0x39/0x160 [<ffffffff81268490>] ? jbd2_journal_get_write_access+0x30/0x50 [<ffffffff81244d43>] ? __ext4_journal_get_write_access+0x43/0x90 [<ffffffff812143d7>] ? ext4_free_inode+0x1d7/0x5d0 [<ffffffff8121e601>] ? ext4_evict_inode+0x341/0x4d0 [<ffffffff8121b268>] ? ext4_mark_inode_dirty+0x88/0x230 [<ffffffff8121e610>] ? ext4_evict_inode+0x350/0x4d0 [<ffffffff8118a098>] ? evict+0xb8/0x1c0 [<ffffffff8118a9d5>] ? iput+0x105/0x190 [<ffffffff8117d341>] ? do_unlinkat+0x201/0x270 [<ffffffff8131e9be>] ? trace_hardirqs_on_thunk+0x3a/0x3f [<ffffffff81180356>] ? SyS_unlink+0x16/0x20 ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: crash in __jbd2_journal_file_buffer 2013-07-30 22:41 crash in __jbd2_journal_file_buffer Sage Weil @ 2013-07-31 19:02 ` Jan Kara 2013-08-09 17:36 ` Sage Weil 0 siblings, 1 reply; 16+ messages in thread From: Jan Kara @ 2013-07-31 19:02 UTC (permalink / raw) To: Sage Weil; +Cc: linux-ext4 Hello, On Tue 30-07-13 15:41:40, Sage Weil wrote: > Hit this on 3.10. Is this a known issue? No, I haven't seen it. Why did the kernel crash? Honza > > Thanks- > sage > > > Stack traceback for pid 23944 > 0xffff8802206edeb0 23944 23840 1 2 R 0xffff8802206ee338 > *ceph-osd > ffff88020bf17b78 0000000000000018 ffffffff81267398 ffff8802256d40c0 > ffff88020b5a1230 ffff88020bf17bb8 ffffffff81325d9c ffff88020b5a1230 > ffff8802256d40c0 ffff88020b5a1230 00000000698a8d24 ffff88020bf17be8 > Call Trace: > [<ffffffff81267398>] ? __jbd2_journal_file_buffer+0x188/0x260 > [<ffffffff81325d9c>] ? do_raw_spin_lock+0x10c/0x150 > [<ffffffff81268118>] ? do_get_write_access+0x448/0x650 > [<ffffffff81213caf>] ? ext4_read_inode_bitmap+0x9f/0x5f0 > [<ffffffff81167849>] ? kmem_cache_alloc+0x39/0x160 > [<ffffffff81268490>] ? jbd2_journal_get_write_access+0x30/0x50 > [<ffffffff81244d43>] ? __ext4_journal_get_write_access+0x43/0x90 > [<ffffffff812143d7>] ? ext4_free_inode+0x1d7/0x5d0 > [<ffffffff8121e601>] ? ext4_evict_inode+0x341/0x4d0 > [<ffffffff8121b268>] ? ext4_mark_inode_dirty+0x88/0x230 > [<ffffffff8121e610>] ? ext4_evict_inode+0x350/0x4d0 > [<ffffffff8118a098>] ? evict+0xb8/0x1c0 > [<ffffffff8118a9d5>] ? iput+0x105/0x190 > [<ffffffff8117d341>] ? do_unlinkat+0x201/0x270 > [<ffffffff8131e9be>] ? trace_hardirqs_on_thunk+0x3a/0x3f > [<ffffffff81180356>] ? SyS_unlink+0x16/0x20 > > -- > To unsubscribe from this list: send the line "unsubscribe linux-ext4" in > the body of a message to majordomo@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html -- Jan Kara <jack@suse.cz> SUSE Labs, CR ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: crash in __jbd2_journal_file_buffer 2013-07-31 19:02 ` Jan Kara @ 2013-08-09 17:36 ` Sage Weil 2013-08-09 21:24 ` Jan Kara 0 siblings, 1 reply; 16+ messages in thread From: Sage Weil @ 2013-08-09 17:36 UTC (permalink / raw) To: Jan Kara; +Cc: linux-ext4 Hi Jan, Sorry for the slow response; took a while for this to happen again. This time I'm keeping the machine sitting in kdb in case there is more information needed. <4>[19307.314449] ------------[ cut here ]------------ <4>[19307.319114] WARNING: at /srv/autobuild-ceph/gitbuilder.git/build/fs/jbd2/transaction.c:1237 jbd2_journal_dirty_metadata+0x1ba/0x260() <4>[19307.382324] CPU: 0 PID: 8877 Comm: ceph-osd Tainted: G W 3.10.0-ceph-00049-g68d04c9 #1 <4>[19307.391256] Hardware name: Dell Inc. PowerEdge R410/01V648, BIOS 1.6.3 02/07/2011 <4>[19307.398879] ffffffff81a1d3c8 ffff880214469928 ffffffff816311b0 ffff880214469968 <4>[19307.407572] ffffffff8103fae0 ffff880214469958 ffff880170a9dc30 ffff8802240fbe80 <4>[19307.415153] 0000000000000000 ffff88020b366000 ffff8802256e7510 ffff880214469978 <4>[19307.422633] Call Trace: <4>[19307.425209] [<ffffffff816311b0>] dump_stack+0x19/0x1b <4>[19307.430368] [<ffffffff8103fae0>] warn_slowpath_common+0x70/0xa0 <4>[19307.436502] [<ffffffff8103fb2a>] warn_slowpath_null+0x1a/0x20 <4>[19307.442356] [<ffffffff81267c2a>] jbd2_journal_dirty_metadata+0x1ba/0x260 <4>[19307.449271] [<ffffffff81245093>] __ext4_handle_dirty_metadata+0xa3/0x140 <4>[19307.456192] [<ffffffff812561f3>] ext4_xattr_release_block+0x103/0x1f0 <4>[19307.462742] [<ffffffff81256680>] ext4_xattr_block_set+0x1e0/0x910 <4>[19307.469049] [<ffffffff8125795b>] ext4_xattr_set_handle+0x38b/0x4a0 <4>[19307.475445] [<ffffffff810a319d>] ? trace_hardirqs_on+0xd/0x10 <4>[19307.481300] [<ffffffff81257b32>] ext4_xattr_set+0xc2/0x140 <4>[19307.486995] [<ffffffff81258547>] ext4_xattr_user_set+0x47/0x50 <4>[19307.492936] [<ffffffff811935ce>] generic_setxattr+0x6e/0x90 <4>[19307.498734] [<ffffffff81193ecb>] __vfs_setxattr_noperm+0x7b/0x1c0 <4>[19307.505049] [<ffffffff811940d4>] vfs_setxattr+0xc4/0xd0 <4>[19307.510380] [<ffffffff8119421e>] setxattr+0x13e/0x1e0 <4>[19307.515646] [<ffffffff811719c7>] ? __sb_start_write+0xe7/0x1b0 <4>[19307.521587] [<ffffffff8118f2e8>] ? mnt_want_write_file+0x28/0x60 <4>[19307.527812] [<ffffffff8118c65c>] ? fget_light+0x3c/0x130 <4>[19307.533230] [<ffffffff8118f2e8>] ? mnt_want_write_file+0x28/0x60 <4>[19307.539522] [<ffffffff8118f1f8>] ? __mnt_want_write+0x58/0x70 <4>[19307.545492] [<ffffffff811946be>] SyS_fsetxattr+0xbe/0x100 <4>[19307.551001] [<ffffffff816407c2>] system_call_fastpath+0x16/0x1b <4>[19307.557137] ---[ end trace 3e447f9462172c58 ]--- <2>[19307.561776] EXT4-fs error (device sda1) in ext4_handle_dirty_xattr_block:167: error 117 <3>[19307.570181] Aborting journal on device sda1-8. <2>[19307.604589] EXT4-fs (sda1): Remounting filesystem read-only <2>[19307.610273] EXT4-fs error (device sda1) in ext4_xattr_release_block:558: error 117 <0>[19307.623337] journal commit I/O error <0>[19307.623342] journal commit I/O error <0>[19307.623405] journal commit I/O error <0>[19307.623519] journal commit I/O error <2>[19307.623585] EXT4-fs error (device sda1): __ext4_journal_start_sb:62: Detected aborted journal <1>[19307.623642] BUG: unable to handle kernel NULL pointer dereference at 0000000000000010 <1>[19307.623649] IP: [<ffffffff81267c4a>] jbd2_journal_dirty_metadata+0x1da/0x260 <4>[19307.623653] PGD 20bc32067 PUD 2245fc067 PMD 0 <4>[19307.623657] Oops: 0000 [#1] SMP [dumpcommon]kdb> -bt Stack traceback for pid 8877 0xffff88020db7bf20 8877 8795 1 4 R 0xffff88020db7c3a8 *ceph-osd ffff880214469a08 0000000000000018 ffffffff81267ad0 ffffea000834d600 ffff880226c03300 ffffffff81256562 0000000000000282 ffff880214469a68 0000000000000000 00000000000011a5 ffffffff81825270 ffff8802256e7510 Call Trace: [<ffffffff81267ad0>] ? jbd2_journal_dirty_metadata+0x60/0x260 [<ffffffff81256562>] ? ext4_xattr_block_set+0xc2/0x910 [<ffffffff81245093>] ? __ext4_handle_dirty_metadata+0xa3/0x140 [<ffffffff8121aeee>] ? ext4_mark_iloc_dirty+0x40e/0x660 [<ffffffff81257835>] ? ext4_xattr_set_handle+0x265/0x4a0 [<ffffffff81257b32>] ? ext4_xattr_set+0xc2/0x140 [<ffffffff81258547>] ? ext4_xattr_user_set+0x47/0x50 [<ffffffff811935ce>] ? generic_setxattr+0x6e/0x90 [<ffffffff81193ecb>] ? __vfs_setxattr_noperm+0x7b/0x1c0 [<ffffffff811940d4>] ? vfs_setxattr+0xc4/0xd0 [<ffffffff8119421e>] ? setxattr+0x13e/0x1e0 [<ffffffff811719c7>] ? __sb_start_write+0xe7/0x1b0 [<ffffffff8118f2e8>] ? mnt_want_write_file+0x28/0x60 [<ffffffff8118c65c>] ? fget_light+0x3c/0x130 [<ffffffff8118f2e8>] ? mnt_want_write_file+0x28/0x60 [<ffffffff8118f1f8>] ? __mnt_want_write+0x58/0x70 [<ffffffff811946be>] ? SyS_fsetxattr+0xbe/0x100 [<ffffffff816407c2>] ? system_call_fastpath+0x16/0x1b The workload is a ceph-osd daemon, which tends to hammer pretty heavily on the xattr paths. I don't have a nice self-contained reproducer or anything since this is is falling out of our integration tests. Hopefully there is enough here (or that can be gleaned from kdb) that it is clear what is going on. It's v3.10 (plus some unrelated patches). Thanks! sage On Wed, 31 Jul 2013, Jan Kara wrote: > Hello, > > On Tue 30-07-13 15:41:40, Sage Weil wrote: > > Hit this on 3.10. Is this a known issue? > No, I haven't seen it. Why did the kernel crash? > > Honza > > > > Thanks- > > sage > > > > > > Stack traceback for pid 23944 > > 0xffff8802206edeb0 23944 23840 1 2 R 0xffff8802206ee338 > > *ceph-osd > > ffff88020bf17b78 0000000000000018 ffffffff81267398 ffff8802256d40c0 > > ffff88020b5a1230 ffff88020bf17bb8 ffffffff81325d9c ffff88020b5a1230 > > ffff8802256d40c0 ffff88020b5a1230 00000000698a8d24 ffff88020bf17be8 > > Call Trace: > > [<ffffffff81267398>] ? __jbd2_journal_file_buffer+0x188/0x260 > > [<ffffffff81325d9c>] ? do_raw_spin_lock+0x10c/0x150 > > [<ffffffff81268118>] ? do_get_write_access+0x448/0x650 > > [<ffffffff81213caf>] ? ext4_read_inode_bitmap+0x9f/0x5f0 > > [<ffffffff81167849>] ? kmem_cache_alloc+0x39/0x160 > > [<ffffffff81268490>] ? jbd2_journal_get_write_access+0x30/0x50 > > [<ffffffff81244d43>] ? __ext4_journal_get_write_access+0x43/0x90 > > [<ffffffff812143d7>] ? ext4_free_inode+0x1d7/0x5d0 > > [<ffffffff8121e601>] ? ext4_evict_inode+0x341/0x4d0 > > [<ffffffff8121b268>] ? ext4_mark_inode_dirty+0x88/0x230 > > [<ffffffff8121e610>] ? ext4_evict_inode+0x350/0x4d0 > > [<ffffffff8118a098>] ? evict+0xb8/0x1c0 > > [<ffffffff8118a9d5>] ? iput+0x105/0x190 > > [<ffffffff8117d341>] ? do_unlinkat+0x201/0x270 > > [<ffffffff8131e9be>] ? trace_hardirqs_on_thunk+0x3a/0x3f > > [<ffffffff81180356>] ? SyS_unlink+0x16/0x20 > > > > -- > > To unsubscribe from this list: send the line "unsubscribe linux-ext4" in > > the body of a message to majordomo@vger.kernel.org > > More majordomo info at http://vger.kernel.org/majordomo-info.html > -- > Jan Kara <jack@suse.cz> > SUSE Labs, CR > > ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: crash in __jbd2_journal_file_buffer 2013-08-09 17:36 ` Sage Weil @ 2013-08-09 21:24 ` Jan Kara 2013-08-09 22:11 ` Sage Weil 0 siblings, 1 reply; 16+ messages in thread From: Jan Kara @ 2013-08-09 21:24 UTC (permalink / raw) To: Sage Weil; +Cc: Jan Kara, linux-ext4 On Fri 09-08-13 10:36:37, Sage Weil wrote: > Hi Jan, > > Sorry for the slow response; took a while for this to happen again. This > time I'm keeping the machine sitting in kdb in case there is more > information needed. > > <4>[19307.314449] ------------[ cut here ]------------ > <4>[19307.319114] WARNING: at /srv/autobuild-ceph/gitbuilder.git/build/fs/jbd2/transaction.c:1237 jbd2_journal_dirty_metadata+0x1ba/0x260() > > <4>[19307.382324] CPU: 0 PID: 8877 Comm: ceph-osd Tainted: G W 3.10.0-ceph-00049-g68d04c9 #1 > <4>[19307.391256] Hardware name: Dell Inc. PowerEdge R410/01V648, BIOS 1.6.3 02/07/2011 > <4>[19307.398879] ffffffff81a1d3c8 ffff880214469928 ffffffff816311b0 ffff880214469968 > <4>[19307.407572] ffffffff8103fae0 ffff880214469958 ffff880170a9dc30 ffff8802240fbe80 > <4>[19307.415153] 0000000000000000 ffff88020b366000 ffff8802256e7510 ffff880214469978 > <4>[19307.422633] Call Trace: > <4>[19307.425209] [<ffffffff816311b0>] dump_stack+0x19/0x1b > <4>[19307.430368] [<ffffffff8103fae0>] warn_slowpath_common+0x70/0xa0 > <4>[19307.436502] [<ffffffff8103fb2a>] warn_slowpath_null+0x1a/0x20 > <4>[19307.442356] [<ffffffff81267c2a>] jbd2_journal_dirty_metadata+0x1ba/0x260 > <4>[19307.449271] [<ffffffff81245093>] __ext4_handle_dirty_metadata+0xa3/0x140 > <4>[19307.456192] [<ffffffff812561f3>] ext4_xattr_release_block+0x103/0x1f0 > <4>[19307.462742] [<ffffffff81256680>] ext4_xattr_block_set+0x1e0/0x910 > <4>[19307.469049] [<ffffffff8125795b>] ext4_xattr_set_handle+0x38b/0x4a0 > <4>[19307.475445] [<ffffffff810a319d>] ? trace_hardirqs_on+0xd/0x10 > <4>[19307.481300] [<ffffffff81257b32>] ext4_xattr_set+0xc2/0x140 > <4>[19307.486995] [<ffffffff81258547>] ext4_xattr_user_set+0x47/0x50 > <4>[19307.492936] [<ffffffff811935ce>] generic_setxattr+0x6e/0x90 > <4>[19307.498734] [<ffffffff81193ecb>] __vfs_setxattr_noperm+0x7b/0x1c0 > <4>[19307.505049] [<ffffffff811940d4>] vfs_setxattr+0xc4/0xd0 > <4>[19307.510380] [<ffffffff8119421e>] setxattr+0x13e/0x1e0 > <4>[19307.515646] [<ffffffff811719c7>] ? __sb_start_write+0xe7/0x1b0 > <4>[19307.521587] [<ffffffff8118f2e8>] ? mnt_want_write_file+0x28/0x60 > <4>[19307.527812] [<ffffffff8118c65c>] ? fget_light+0x3c/0x130 > <4>[19307.533230] [<ffffffff8118f2e8>] ? mnt_want_write_file+0x28/0x60 > <4>[19307.539522] [<ffffffff8118f1f8>] ? __mnt_want_write+0x58/0x70 > <4>[19307.545492] [<ffffffff811946be>] SyS_fsetxattr+0xbe/0x100 > <4>[19307.551001] [<ffffffff816407c2>] system_call_fastpath+0x16/0x1b > <4>[19307.557137] ---[ end trace 3e447f9462172c58 ]--- Hum, weird. So we returned EUCLEAN from jbd2_journal_dirty_metadata() meaning that buffer head passed in there didn't have journal head attached. However ext4_xattr_release_block() does call ext4_journal_get_write_access() for the bh before calling ext4_handle_dirty_xattr_block(). So we should have bh attached to the running transaction which also keeps journal head in place. > <2>[19307.561776] EXT4-fs error (device sda1) in ext4_handle_dirty_xattr_block:167: error 117 > <3>[19307.570181] Aborting journal on device sda1-8. > <2>[19307.604589] EXT4-fs (sda1): Remounting filesystem read-only > <2>[19307.610273] EXT4-fs error (device sda1) in ext4_xattr_release_block:558: error 117 > <0>[19307.623337] journal commit I/O error > <0>[19307.623342] journal commit I/O error > <0>[19307.623405] journal commit I/O error > <0>[19307.623519] journal commit I/O error > <2>[19307.623585] EXT4-fs error (device sda1): __ext4_journal_start_sb:62: Detected aborted journal > <1>[19307.623642] BUG: unable to handle kernel NULL pointer dereference at 0000000000000010 > <1>[19307.623649] IP: [<ffffffff81267c4a>] jbd2_journal_dirty_metadata+0x1da/0x260 Can you possibly disassemble where exactly did we crash in this function? Apparently we didn't properly handle the fact that the journal got aborted here. But I'm not sure what exactly failed. Honza > <4>[19307.623653] PGD 20bc32067 PUD 2245fc067 PMD 0 > <4>[19307.623657] Oops: 0000 [#1] SMP > [dumpcommon]kdb> -bt > > Stack traceback for pid 8877 > 0xffff88020db7bf20 8877 8795 1 4 R 0xffff88020db7c3a8 *ceph-osd > ffff880214469a08 0000000000000018 ffffffff81267ad0 ffffea000834d600 > ffff880226c03300 ffffffff81256562 0000000000000282 ffff880214469a68 > 0000000000000000 00000000000011a5 ffffffff81825270 ffff8802256e7510 > Call Trace: > [<ffffffff81267ad0>] ? jbd2_journal_dirty_metadata+0x60/0x260 > [<ffffffff81256562>] ? ext4_xattr_block_set+0xc2/0x910 > [<ffffffff81245093>] ? __ext4_handle_dirty_metadata+0xa3/0x140 > [<ffffffff8121aeee>] ? ext4_mark_iloc_dirty+0x40e/0x660 > [<ffffffff81257835>] ? ext4_xattr_set_handle+0x265/0x4a0 > [<ffffffff81257b32>] ? ext4_xattr_set+0xc2/0x140 > [<ffffffff81258547>] ? ext4_xattr_user_set+0x47/0x50 > [<ffffffff811935ce>] ? generic_setxattr+0x6e/0x90 > [<ffffffff81193ecb>] ? __vfs_setxattr_noperm+0x7b/0x1c0 > [<ffffffff811940d4>] ? vfs_setxattr+0xc4/0xd0 > [<ffffffff8119421e>] ? setxattr+0x13e/0x1e0 > [<ffffffff811719c7>] ? __sb_start_write+0xe7/0x1b0 > [<ffffffff8118f2e8>] ? mnt_want_write_file+0x28/0x60 > [<ffffffff8118c65c>] ? fget_light+0x3c/0x130 > [<ffffffff8118f2e8>] ? mnt_want_write_file+0x28/0x60 > [<ffffffff8118f1f8>] ? __mnt_want_write+0x58/0x70 > [<ffffffff811946be>] ? SyS_fsetxattr+0xbe/0x100 > [<ffffffff816407c2>] ? system_call_fastpath+0x16/0x1b > > > The workload is a ceph-osd daemon, which tends to hammer pretty heavily on > the xattr paths. I don't have a nice self-contained reproducer or > anything since this is is falling out of our integration tests. > Hopefully there is enough here (or that can be gleaned from kdb) that it > is clear what is going on. It's v3.10 (plus some unrelated patches). > > Thanks! > sage > > > > On Wed, 31 Jul 2013, Jan Kara wrote: > > Hello, > > > > On Tue 30-07-13 15:41:40, Sage Weil wrote: > > > Hit this on 3.10. Is this a known issue? > > No, I haven't seen it. Why did the kernel crash? > > > > Honza > > > > > > Thanks- > > > sage > > > > > > > > > Stack traceback for pid 23944 > > > 0xffff8802206edeb0 23944 23840 1 2 R 0xffff8802206ee338 > > > *ceph-osd > > > ffff88020bf17b78 0000000000000018 ffffffff81267398 ffff8802256d40c0 > > > ffff88020b5a1230 ffff88020bf17bb8 ffffffff81325d9c ffff88020b5a1230 > > > ffff8802256d40c0 ffff88020b5a1230 00000000698a8d24 ffff88020bf17be8 > > > Call Trace: > > > [<ffffffff81267398>] ? __jbd2_journal_file_buffer+0x188/0x260 > > > [<ffffffff81325d9c>] ? do_raw_spin_lock+0x10c/0x150 > > > [<ffffffff81268118>] ? do_get_write_access+0x448/0x650 > > > [<ffffffff81213caf>] ? ext4_read_inode_bitmap+0x9f/0x5f0 > > > [<ffffffff81167849>] ? kmem_cache_alloc+0x39/0x160 > > > [<ffffffff81268490>] ? jbd2_journal_get_write_access+0x30/0x50 > > > [<ffffffff81244d43>] ? __ext4_journal_get_write_access+0x43/0x90 > > > [<ffffffff812143d7>] ? ext4_free_inode+0x1d7/0x5d0 > > > [<ffffffff8121e601>] ? ext4_evict_inode+0x341/0x4d0 > > > [<ffffffff8121b268>] ? ext4_mark_inode_dirty+0x88/0x230 > > > [<ffffffff8121e610>] ? ext4_evict_inode+0x350/0x4d0 > > > [<ffffffff8118a098>] ? evict+0xb8/0x1c0 > > > [<ffffffff8118a9d5>] ? iput+0x105/0x190 > > > [<ffffffff8117d341>] ? do_unlinkat+0x201/0x270 > > > [<ffffffff8131e9be>] ? trace_hardirqs_on_thunk+0x3a/0x3f > > > [<ffffffff81180356>] ? SyS_unlink+0x16/0x20 > > > > > > -- > > > To unsubscribe from this list: send the line "unsubscribe linux-ext4" in > > > the body of a message to majordomo@vger.kernel.org > > > More majordomo info at http://vger.kernel.org/majordomo-info.html > > -- > > Jan Kara <jack@suse.cz> > > SUSE Labs, CR > > > > -- Jan Kara <jack@suse.cz> SUSE Labs, CR ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: crash in __jbd2_journal_file_buffer 2013-08-09 21:24 ` Jan Kara @ 2013-08-09 22:11 ` Sage Weil 2013-08-12 12:52 ` Jan Kara 0 siblings, 1 reply; 16+ messages in thread From: Sage Weil @ 2013-08-09 22:11 UTC (permalink / raw) To: Jan Kara; +Cc: linux-ext4 On Fri, 9 Aug 2013, Jan Kara wrote: > On Fri 09-08-13 10:36:37, Sage Weil wrote: > > Hi Jan, > > > > Sorry for the slow response; took a while for this to happen again. This > > time I'm keeping the machine sitting in kdb in case there is more > > information needed. > > > > <4>[19307.314449] ------------[ cut here ]------------ > > <4>[19307.319114] WARNING: at /srv/autobuild-ceph/gitbuilder.git/build/fs/jbd2/transaction.c:1237 jbd2_journal_dirty_metadata+0x1ba/0x260() > > > > <4>[19307.382324] CPU: 0 PID: 8877 Comm: ceph-osd Tainted: G W 3.10.0-ceph-00049-g68d04c9 #1 > > <4>[19307.391256] Hardware name: Dell Inc. PowerEdge R410/01V648, BIOS 1.6.3 02/07/2011 > > <4>[19307.398879] ffffffff81a1d3c8 ffff880214469928 ffffffff816311b0 ffff880214469968 > > <4>[19307.407572] ffffffff8103fae0 ffff880214469958 ffff880170a9dc30 ffff8802240fbe80 > > <4>[19307.415153] 0000000000000000 ffff88020b366000 ffff8802256e7510 ffff880214469978 > > <4>[19307.422633] Call Trace: > > <4>[19307.425209] [<ffffffff816311b0>] dump_stack+0x19/0x1b > > <4>[19307.430368] [<ffffffff8103fae0>] warn_slowpath_common+0x70/0xa0 > > <4>[19307.436502] [<ffffffff8103fb2a>] warn_slowpath_null+0x1a/0x20 > > <4>[19307.442356] [<ffffffff81267c2a>] jbd2_journal_dirty_metadata+0x1ba/0x260 > > <4>[19307.449271] [<ffffffff81245093>] __ext4_handle_dirty_metadata+0xa3/0x140 > > <4>[19307.456192] [<ffffffff812561f3>] ext4_xattr_release_block+0x103/0x1f0 > > <4>[19307.462742] [<ffffffff81256680>] ext4_xattr_block_set+0x1e0/0x910 > > <4>[19307.469049] [<ffffffff8125795b>] ext4_xattr_set_handle+0x38b/0x4a0 > > <4>[19307.475445] [<ffffffff810a319d>] ? trace_hardirqs_on+0xd/0x10 > > <4>[19307.481300] [<ffffffff81257b32>] ext4_xattr_set+0xc2/0x140 > > <4>[19307.486995] [<ffffffff81258547>] ext4_xattr_user_set+0x47/0x50 > > <4>[19307.492936] [<ffffffff811935ce>] generic_setxattr+0x6e/0x90 > > <4>[19307.498734] [<ffffffff81193ecb>] __vfs_setxattr_noperm+0x7b/0x1c0 > > <4>[19307.505049] [<ffffffff811940d4>] vfs_setxattr+0xc4/0xd0 > > <4>[19307.510380] [<ffffffff8119421e>] setxattr+0x13e/0x1e0 > > <4>[19307.515646] [<ffffffff811719c7>] ? __sb_start_write+0xe7/0x1b0 > > <4>[19307.521587] [<ffffffff8118f2e8>] ? mnt_want_write_file+0x28/0x60 > > <4>[19307.527812] [<ffffffff8118c65c>] ? fget_light+0x3c/0x130 > > <4>[19307.533230] [<ffffffff8118f2e8>] ? mnt_want_write_file+0x28/0x60 > > <4>[19307.539522] [<ffffffff8118f1f8>] ? __mnt_want_write+0x58/0x70 > > <4>[19307.545492] [<ffffffff811946be>] SyS_fsetxattr+0xbe/0x100 > > <4>[19307.551001] [<ffffffff816407c2>] system_call_fastpath+0x16/0x1b > > <4>[19307.557137] ---[ end trace 3e447f9462172c58 ]--- > Hum, weird. So we returned EUCLEAN from jbd2_journal_dirty_metadata() > meaning that buffer head passed in there didn't have journal head attached. > However ext4_xattr_release_block() does call > ext4_journal_get_write_access() for the bh before calling > ext4_handle_dirty_xattr_block(). So we should have bh attached to the > running transaction which also keeps journal head in place. > > > <2>[19307.561776] EXT4-fs error (device sda1) in ext4_handle_dirty_xattr_block:167: error 117 > > <3>[19307.570181] Aborting journal on device sda1-8. > > <2>[19307.604589] EXT4-fs (sda1): Remounting filesystem read-only > > <2>[19307.610273] EXT4-fs error (device sda1) in ext4_xattr_release_block:558: error 117 > > <0>[19307.623337] journal commit I/O error > > <0>[19307.623342] journal commit I/O error > > <0>[19307.623405] journal commit I/O error > > <0>[19307.623519] journal commit I/O error > > <2>[19307.623585] EXT4-fs error (device sda1): __ext4_journal_start_sb:62: Detected aborted journal > > <1>[19307.623642] BUG: unable to handle kernel NULL pointer dereference at 0000000000000010 > > <1>[19307.623649] IP: [<ffffffff81267c4a>] jbd2_journal_dirty_metadata+0x1da/0x260 > Can you possibly disassemble where exactly did we crash in this function? > Apparently we didn't properly handle the fact that the journal got aborted > here. But I'm not sure what exactly failed. Hrm, I'm having trouble getting from a bzImage back to something I can objdump with inline code, so this is a separate compile with the same .config that is hopefully right: jh->b_modified = 1; J_ASSERT_JH(jh, handle->h_buffer_credits > 0); 1e33: 0f 0b ud2 */ if (jh->b_transaction != transaction) { JBUFFER_TRACE(jh, "already on other transaction"); if (unlikely(jh->b_transaction != journal->j_committing_transaction)) { printk(KERN_EMERG "JBD: %s: " 1e35: 4d 85 c9 test %r9,%r9 1e38: 74 04 je 1e3e <jbd2_journal_dirty_metadata+0x1de> 1e3a: 41 8b 41 08 mov 0x8(%r9),%eax **here^^^ 1e3e: 45 31 c0 xor %r8d,%r8d 1e41: 48 85 c9 test %rcx,%rcx 1e44: 74 04 je 1e4a <jbd2_journal_dirty_metadata+0x1ea> 1e46: 44 8b 41 08 mov 0x8(%rcx),%r8d 1e4a: 48 8b 53 18 mov 0x18(%rbx),%rdx "jh->b_transaction (%llu, %p, %u) != " "journal->j_committing_transaction (%p, %u)", journal->j_devname, 1e4e: 49 8d b6 80 05 00 00 lea 0x580(%r14),%rsi */ if (jh->b_transaction != transaction) { JBUFFER_TRACE(jh, "already on other transaction"); if (unlikely(jh->b_transaction != journal->j_committing_transaction)) { printk(KERN_EMERG "JBD: %s: " 1e55: 89 04 24 mov %eax,(%rsp) 1e58: 48 c7 c7 00 00 00 00 mov $0x0,%rdi 1e5b: R_X86_64_32S .rodata.str1.8+0x160 1e5f: 31 c0 xor %eax,%eax 1e61: e8 00 00 00 00 callq 1e66 <jbd2_journal_dirty_metadata+0x206> 1e62: R_X86_64_PC32 printk-0x4 jh->b_transaction, jh->b_transaction ? jh->b_transaction->t_tid : 0, journal->j_committing_transaction, journal->j_committing_transaction ? journal->j_committing_transaction->t_tid : 0); ret = -EINVAL; 1e66: b8 ea ff ff ff mov $0xffffffea,%eax 1e6b: e9 a4 fe ff ff jmpq 1d14 <jbd2_journal_dirty_metadata+0xb4> } if (unlikely(jh->b_next_transaction != transaction)) { printk(KERN_EMERG "JBD: %s: " 1e70: 45 31 c0 xor %r8d,%r8d 1e73: 48 85 c9 test %rcx,%rcx 1e76: 41 8b 44 24 08 mov 0x8(%r12),%eax 1e7b: 74 04 je 1e81 <jbd2_journal_dirty_metadata+0x221> 1e7d: 44 8b 41 08 mov 0x8(%rcx),%r8d 1e81: 48 8b 53 18 mov 0x18(%rbx),%rdx "jh->b_next_transaction (%llu, %p, %u) != " "transaction (%p, %u)", journal->j_devname, 1e85: 49 8d b6 80 05 00 00 lea 0x580(%r14),%rsi journal->j_committing_transaction ? journal->j_committing_transaction->t_tid : 0); ret = -EINVAL; } if (unlikely(jh->b_next_transaction != transaction)) { printk(KERN_EMERG "JBD: %s: " 1e8c: 89 04 24 mov %eax,(%rsp) 1e8f: 4d 89 e1 mov %r12,%r9 1e92: 48 c7 c7 00 00 00 00 mov $0x0,%rdi 1e95: R_X86_64_32S .rodata.str1.8+0x1c0 1e99: 31 c0 xor %eax,%eax 1e9b: e8 00 00 00 00 callq 1ea0 <jbd2_journal_dirty_metadata+0x240> 1e9c: R_X86_64_PC32 printk-0x4 (unsigned long long) bh->b_blocknr, jh->b_next_transaction, jh->b_next_transaction ? jh->b_next_transaction->t_tid : 0, transaction, transaction->t_tid); ret = -EINVAL; 1ea0: b8 ea ff ff ff mov $0xffffffea,%eax 1ea5: e9 77 fe ff ff jmpq 1d21 <jbd2_journal_dirty_metadata+0xc1> * bit-based spin_unlock() */ static inline void bit_spin_unlock(int bitnum, unsigned long *addr) { #ifdef CONFIG_DEBUG_SPINLOCK BUG_ON(!test_bit(bitnum, addr)); 1eaa: e8 00 00 00 00 callq 1eaf <jbd2_journal_dirty_metadata+0x24f> 1eab: R_X86_64_PC32 .text.unlikely-0x4 * transaction's data buffer, ever. */ Registers are [4]kdb> rd ax: 0000000000000000 bx: ffff8801f57837b8 cx: 0000000000000000 dx: 000000000091c029 si: 000000000091c029 di: 0000000000000001 bp: ffff880214469a58 sp: ffff880214469a08 r8: ffff8801f57837b8 r9: 0000000000000008 r10: 0000000000000000 r11: 0000000000000000 r12: ffff8802256e7870 r13: ffff8801893c52a0 r14: ffff8802256e76c0 r15: ffff8802256e7510 ip: ffffffff81267c4a flags: 00010202 cs: 00000010 ss: 00000018 ds: 00000018 es: 00000018 fs: 00000018 gs: 00000018 journal == NULL? sage > > Honza > > > <4>[19307.623653] PGD 20bc32067 PUD 2245fc067 PMD 0 > > <4>[19307.623657] Oops: 0000 [#1] SMP > > [dumpcommon]kdb> -bt > > > > Stack traceback for pid 8877 > > 0xffff88020db7bf20 8877 8795 1 4 R 0xffff88020db7c3a8 *ceph-osd > > ffff880214469a08 0000000000000018 ffffffff81267ad0 ffffea000834d600 > > ffff880226c03300 ffffffff81256562 0000000000000282 ffff880214469a68 > > 0000000000000000 00000000000011a5 ffffffff81825270 ffff8802256e7510 > > Call Trace: > > [<ffffffff81267ad0>] ? jbd2_journal_dirty_metadata+0x60/0x260 > > [<ffffffff81256562>] ? ext4_xattr_block_set+0xc2/0x910 > > [<ffffffff81245093>] ? __ext4_handle_dirty_metadata+0xa3/0x140 > > [<ffffffff8121aeee>] ? ext4_mark_iloc_dirty+0x40e/0x660 > > [<ffffffff81257835>] ? ext4_xattr_set_handle+0x265/0x4a0 > > [<ffffffff81257b32>] ? ext4_xattr_set+0xc2/0x140 > > [<ffffffff81258547>] ? ext4_xattr_user_set+0x47/0x50 > > [<ffffffff811935ce>] ? generic_setxattr+0x6e/0x90 > > [<ffffffff81193ecb>] ? __vfs_setxattr_noperm+0x7b/0x1c0 > > [<ffffffff811940d4>] ? vfs_setxattr+0xc4/0xd0 > > [<ffffffff8119421e>] ? setxattr+0x13e/0x1e0 > > [<ffffffff811719c7>] ? __sb_start_write+0xe7/0x1b0 > > [<ffffffff8118f2e8>] ? mnt_want_write_file+0x28/0x60 > > [<ffffffff8118c65c>] ? fget_light+0x3c/0x130 > > [<ffffffff8118f2e8>] ? mnt_want_write_file+0x28/0x60 > > [<ffffffff8118f1f8>] ? __mnt_want_write+0x58/0x70 > > [<ffffffff811946be>] ? SyS_fsetxattr+0xbe/0x100 > > [<ffffffff816407c2>] ? system_call_fastpath+0x16/0x1b > > > > > > The workload is a ceph-osd daemon, which tends to hammer pretty heavily on > > the xattr paths. I don't have a nice self-contained reproducer or > > anything since this is is falling out of our integration tests. > > Hopefully there is enough here (or that can be gleaned from kdb) that it > > is clear what is going on. It's v3.10 (plus some unrelated patches). > > > > Thanks! > > sage > > > > > > > > On Wed, 31 Jul 2013, Jan Kara wrote: > > > Hello, > > > > > > On Tue 30-07-13 15:41:40, Sage Weil wrote: > > > > Hit this on 3.10. Is this a known issue? > > > No, I haven't seen it. Why did the kernel crash? > > > > > > Honza > > > > > > > > Thanks- > > > > sage > > > > > > > > > > > > Stack traceback for pid 23944 > > > > 0xffff8802206edeb0 23944 23840 1 2 R 0xffff8802206ee338 > > > > *ceph-osd > > > > ffff88020bf17b78 0000000000000018 ffffffff81267398 ffff8802256d40c0 > > > > ffff88020b5a1230 ffff88020bf17bb8 ffffffff81325d9c ffff88020b5a1230 > > > > ffff8802256d40c0 ffff88020b5a1230 00000000698a8d24 ffff88020bf17be8 > > > > Call Trace: > > > > [<ffffffff81267398>] ? __jbd2_journal_file_buffer+0x188/0x260 > > > > [<ffffffff81325d9c>] ? do_raw_spin_lock+0x10c/0x150 > > > > [<ffffffff81268118>] ? do_get_write_access+0x448/0x650 > > > > [<ffffffff81213caf>] ? ext4_read_inode_bitmap+0x9f/0x5f0 > > > > [<ffffffff81167849>] ? kmem_cache_alloc+0x39/0x160 > > > > [<ffffffff81268490>] ? jbd2_journal_get_write_access+0x30/0x50 > > > > [<ffffffff81244d43>] ? __ext4_journal_get_write_access+0x43/0x90 > > > > [<ffffffff812143d7>] ? ext4_free_inode+0x1d7/0x5d0 > > > > [<ffffffff8121e601>] ? ext4_evict_inode+0x341/0x4d0 > > > > [<ffffffff8121b268>] ? ext4_mark_inode_dirty+0x88/0x230 > > > > [<ffffffff8121e610>] ? ext4_evict_inode+0x350/0x4d0 > > > > [<ffffffff8118a098>] ? evict+0xb8/0x1c0 > > > > [<ffffffff8118a9d5>] ? iput+0x105/0x190 > > > > [<ffffffff8117d341>] ? do_unlinkat+0x201/0x270 > > > > [<ffffffff8131e9be>] ? trace_hardirqs_on_thunk+0x3a/0x3f > > > > [<ffffffff81180356>] ? SyS_unlink+0x16/0x20 > > > > > > > > -- > > > > To unsubscribe from this list: send the line "unsubscribe linux-ext4" in > > > > the body of a message to majordomo@vger.kernel.org > > > > More majordomo info at http://vger.kernel.org/majordomo-info.html > > > -- > > > Jan Kara <jack@suse.cz> > > > SUSE Labs, CR > > > > > > > -- > Jan Kara <jack@suse.cz> > SUSE Labs, CR > > ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: crash in __jbd2_journal_file_buffer 2013-08-09 22:11 ` Sage Weil @ 2013-08-12 12:52 ` Jan Kara [not found] ` <alpine.DEB.2.00.1308121106320.29150@cobra.newdream.net> 0 siblings, 1 reply; 16+ messages in thread From: Jan Kara @ 2013-08-12 12:52 UTC (permalink / raw) To: Sage Weil; +Cc: Jan Kara, linux-ext4 On Fri 09-08-13 15:11:05, Sage Weil wrote: > On Fri, 9 Aug 2013, Jan Kara wrote: > > On Fri 09-08-13 10:36:37, Sage Weil wrote: > > > Hi Jan, > > > > > > Sorry for the slow response; took a while for this to happen again. This > > > time I'm keeping the machine sitting in kdb in case there is more > > > information needed. > > > > > > <4>[19307.314449] ------------[ cut here ]------------ > > > <4>[19307.319114] WARNING: at /srv/autobuild-ceph/gitbuilder.git/build/fs/jbd2/transaction.c:1237 jbd2_journal_dirty_metadata+0x1ba/0x260() > > > > > > <4>[19307.382324] CPU: 0 PID: 8877 Comm: ceph-osd Tainted: G W 3.10.0-ceph-00049-g68d04c9 #1 > > > <4>[19307.391256] Hardware name: Dell Inc. PowerEdge R410/01V648, BIOS 1.6.3 02/07/2011 > > > <4>[19307.398879] ffffffff81a1d3c8 ffff880214469928 ffffffff816311b0 ffff880214469968 > > > <4>[19307.407572] ffffffff8103fae0 ffff880214469958 ffff880170a9dc30 ffff8802240fbe80 > > > <4>[19307.415153] 0000000000000000 ffff88020b366000 ffff8802256e7510 ffff880214469978 > > > <4>[19307.422633] Call Trace: > > > <4>[19307.425209] [<ffffffff816311b0>] dump_stack+0x19/0x1b > > > <4>[19307.430368] [<ffffffff8103fae0>] warn_slowpath_common+0x70/0xa0 > > > <4>[19307.436502] [<ffffffff8103fb2a>] warn_slowpath_null+0x1a/0x20 > > > <4>[19307.442356] [<ffffffff81267c2a>] jbd2_journal_dirty_metadata+0x1ba/0x260 > > > <4>[19307.449271] [<ffffffff81245093>] __ext4_handle_dirty_metadata+0xa3/0x140 > > > <4>[19307.456192] [<ffffffff812561f3>] ext4_xattr_release_block+0x103/0x1f0 > > > <4>[19307.462742] [<ffffffff81256680>] ext4_xattr_block_set+0x1e0/0x910 > > > <4>[19307.469049] [<ffffffff8125795b>] ext4_xattr_set_handle+0x38b/0x4a0 > > > <4>[19307.475445] [<ffffffff810a319d>] ? trace_hardirqs_on+0xd/0x10 > > > <4>[19307.481300] [<ffffffff81257b32>] ext4_xattr_set+0xc2/0x140 > > > <4>[19307.486995] [<ffffffff81258547>] ext4_xattr_user_set+0x47/0x50 > > > <4>[19307.492936] [<ffffffff811935ce>] generic_setxattr+0x6e/0x90 > > > <4>[19307.498734] [<ffffffff81193ecb>] __vfs_setxattr_noperm+0x7b/0x1c0 > > > <4>[19307.505049] [<ffffffff811940d4>] vfs_setxattr+0xc4/0xd0 > > > <4>[19307.510380] [<ffffffff8119421e>] setxattr+0x13e/0x1e0 > > > <4>[19307.515646] [<ffffffff811719c7>] ? __sb_start_write+0xe7/0x1b0 > > > <4>[19307.521587] [<ffffffff8118f2e8>] ? mnt_want_write_file+0x28/0x60 > > > <4>[19307.527812] [<ffffffff8118c65c>] ? fget_light+0x3c/0x130 > > > <4>[19307.533230] [<ffffffff8118f2e8>] ? mnt_want_write_file+0x28/0x60 > > > <4>[19307.539522] [<ffffffff8118f1f8>] ? __mnt_want_write+0x58/0x70 > > > <4>[19307.545492] [<ffffffff811946be>] SyS_fsetxattr+0xbe/0x100 > > > <4>[19307.551001] [<ffffffff816407c2>] system_call_fastpath+0x16/0x1b > > > <4>[19307.557137] ---[ end trace 3e447f9462172c58 ]--- > > Hum, weird. So we returned EUCLEAN from jbd2_journal_dirty_metadata() > > meaning that buffer head passed in there didn't have journal head attached. > > However ext4_xattr_release_block() does call > > ext4_journal_get_write_access() for the bh before calling > > ext4_handle_dirty_xattr_block(). So we should have bh attached to the > > running transaction which also keeps journal head in place. > > > > > <2>[19307.561776] EXT4-fs error (device sda1) in ext4_handle_dirty_xattr_block:167: error 117 > > > <3>[19307.570181] Aborting journal on device sda1-8. > > > <2>[19307.604589] EXT4-fs (sda1): Remounting filesystem read-only > > > <2>[19307.610273] EXT4-fs error (device sda1) in ext4_xattr_release_block:558: error 117 > > > <0>[19307.623337] journal commit I/O error > > > <0>[19307.623342] journal commit I/O error > > > <0>[19307.623405] journal commit I/O error > > > <0>[19307.623519] journal commit I/O error > > > <2>[19307.623585] EXT4-fs error (device sda1): __ext4_journal_start_sb:62: Detected aborted journal > > > <1>[19307.623642] BUG: unable to handle kernel NULL pointer dereference at 0000000000000010 > > > <1>[19307.623649] IP: [<ffffffff81267c4a>] jbd2_journal_dirty_metadata+0x1da/0x260 > > Can you possibly disassemble where exactly did we crash in this function? > > Apparently we didn't properly handle the fact that the journal got aborted > > here. But I'm not sure what exactly failed. > > Hrm, I'm having trouble getting from a bzImage back to something I can > objdump with inline code, so this is a separate compile with the same > .config that is hopefully right: > > jh->b_modified = 1; > J_ASSERT_JH(jh, handle->h_buffer_credits > 0); > 1e33: 0f 0b ud2 > */ > if (jh->b_transaction != transaction) { > JBUFFER_TRACE(jh, "already on other transaction"); > if (unlikely(jh->b_transaction != > journal->j_committing_transaction)) { > printk(KERN_EMERG "JBD: %s: " > 1e35: 4d 85 c9 test %r9,%r9 > 1e38: 74 04 je 1e3e <jbd2_journal_dirty_metadata+0x1de> > 1e3a: 41 8b 41 08 mov 0x8(%r9),%eax > **here^^^ > 1e3e: 45 31 c0 xor %r8d,%r8d > 1e41: 48 85 c9 test %rcx,%rcx > 1e44: 74 04 je 1e4a <jbd2_journal_dirty_metadata+0x1ea> > 1e46: 44 8b 41 08 mov 0x8(%rcx),%r8d > 1e4a: 48 8b 53 18 mov 0x18(%rbx),%rdx > "jh->b_transaction (%llu, %p, %u) != " > "journal->j_committing_transaction (%p, %u)", > journal->j_devname, > 1e4e: 49 8d b6 80 05 00 00 lea 0x580(%r14),%rsi > */ > if (jh->b_transaction != transaction) { > JBUFFER_TRACE(jh, "already on other transaction"); > if (unlikely(jh->b_transaction != > journal->j_committing_transaction)) { > printk(KERN_EMERG "JBD: %s: " > 1e55: 89 04 24 mov %eax,(%rsp) > 1e58: 48 c7 c7 00 00 00 00 mov $0x0,%rdi > 1e5b: R_X86_64_32S .rodata.str1.8+0x160 > 1e5f: 31 c0 xor %eax,%eax > 1e61: e8 00 00 00 00 callq 1e66 <jbd2_journal_dirty_metadata+0x206> > 1e62: R_X86_64_PC32 printk-0x4 > jh->b_transaction, > jh->b_transaction ? jh->b_transaction->t_tid : 0, > journal->j_committing_transaction, > journal->j_committing_transaction ? > journal->j_committing_transaction->t_tid : 0); > ret = -EINVAL; > 1e66: b8 ea ff ff ff mov $0xffffffea,%eax > 1e6b: e9 a4 fe ff ff jmpq 1d14 <jbd2_journal_dirty_metadata+0xb4> > } > if (unlikely(jh->b_next_transaction != transaction)) { > printk(KERN_EMERG "JBD: %s: " > 1e70: 45 31 c0 xor %r8d,%r8d > 1e73: 48 85 c9 test %rcx,%rcx > 1e76: 41 8b 44 24 08 mov 0x8(%r12),%eax > 1e7b: 74 04 je 1e81 <jbd2_journal_dirty_metadata+0x221> > 1e7d: 44 8b 41 08 mov 0x8(%rcx),%r8d > 1e81: 48 8b 53 18 mov 0x18(%rbx),%rdx > "jh->b_next_transaction (%llu, %p, %u) != " > "transaction (%p, %u)", > journal->j_devname, > 1e85: 49 8d b6 80 05 00 00 lea 0x580(%r14),%rsi > journal->j_committing_transaction ? > journal->j_committing_transaction->t_tid : 0); > ret = -EINVAL; > } > if (unlikely(jh->b_next_transaction != transaction)) { > printk(KERN_EMERG "JBD: %s: " > 1e8c: 89 04 24 mov %eax,(%rsp) > 1e8f: 4d 89 e1 mov %r12,%r9 > 1e92: 48 c7 c7 00 00 00 00 mov $0x0,%rdi > 1e95: R_X86_64_32S .rodata.str1.8+0x1c0 > 1e99: 31 c0 xor %eax,%eax > 1e9b: e8 00 00 00 00 callq 1ea0 <jbd2_journal_dirty_metadata+0x240> > 1e9c: R_X86_64_PC32 printk-0x4 > (unsigned long long) bh->b_blocknr, > jh->b_next_transaction, > jh->b_next_transaction ? > jh->b_next_transaction->t_tid : 0, > transaction, transaction->t_tid); > ret = -EINVAL; > 1ea0: b8 ea ff ff ff mov $0xffffffea,%eax > 1ea5: e9 77 fe ff ff jmpq 1d21 <jbd2_journal_dirty_metadata+0xc1> > * bit-based spin_unlock() > */ > static inline void bit_spin_unlock(int bitnum, unsigned long *addr) > { > #ifdef CONFIG_DEBUG_SPINLOCK > BUG_ON(!test_bit(bitnum, addr)); > 1eaa: e8 00 00 00 00 callq 1eaf <jbd2_journal_dirty_metadata+0x24f> > 1eab: R_X86_64_PC32 .text.unlikely-0x4 > * transaction's data buffer, ever. */ > > Registers are > > [4]kdb> rd > ax: 0000000000000000 bx: ffff8801f57837b8 cx: 0000000000000000 > dx: 000000000091c029 si: 000000000091c029 di: 0000000000000001 > bp: ffff880214469a58 sp: ffff880214469a08 r8: ffff8801f57837b8 > r9: 0000000000000008 r10: 0000000000000000 r11: 0000000000000000 > r12: ffff8802256e7870 r13: ffff8801893c52a0 r14: ffff8802256e76c0 > r15: ffff8802256e7510 ip: ffffffff81267c4a flags: 00010202 cs: 00000010 > ss: 00000018 ds: 00000018 es: 00000018 fs: 00000018 gs: 00000018 > > journal == NULL? Umm, r9 is 0x8 so it seems jh->b_transaction or journal->j_running_transaction was 8 (instead of NULL vs valid pointer) and thus we oopsed while looking at ->t_tid... Oh, I see where's the problem. __ext4_handle_dirty_metadata() will stop the handle if there's an error but caller really doesn't count with this and further uses freed handle. So at least the BUG part of the problem is clear now - I'll look into fixing that. But how did we pass bh without jh into jbd2_journal_dirty_metadata() still isn't clear to me. BTW, I see 'W' taint flag in the warning which means there was some warning before this one. What was that? Honza -- Jan Kara <jack@suse.cz> SUSE Labs, CR ^ permalink raw reply [flat|nested] 16+ messages in thread
[parent not found: <alpine.DEB.2.00.1308121106320.29150@cobra.newdream.net>]
* Re: crash in __jbd2_journal_file_buffer [not found] ` <alpine.DEB.2.00.1308121106320.29150@cobra.newdream.net> @ 2013-08-13 10:34 ` Jan Kara 2013-08-22 23:35 ` Sage Weil 0 siblings, 1 reply; 16+ messages in thread From: Jan Kara @ 2013-08-13 10:34 UTC (permalink / raw) To: Sage Weil; +Cc: Jan Kara, linux-ext4 [-- Attachment #1: Type: text/plain, Size: 542 bytes --] On Mon 12-08-13 11:13:06, Sage Weil wrote: > Full dmesg is attached. Hum, nothing interesting in there... > Our QA seems to hit this with some regularity. Let me know if there's > some combination of patches that would help shed more light! If they can run with attached debug patch it could maybe sched some more light. Please send also your System.map file together with the dmesg of the kernel when the crash happens so that I can map addresses to function names... Thanks! Honza -- Jan Kara <jack@suse.cz> SUSE Labs, CR [-- Attachment #2: 0001-jbd2-Debug-journal_head-additions-and-removals.patch --] [-- Type: text/x-patch, Size: 2139 bytes --] >From ae473a63b28ee1719cf47a637c73d9d163ddb4db Mon Sep 17 00:00:00 2001 From: Jan Kara <jack@suse.cz> Date: Tue, 13 Aug 2013 12:29:35 +0200 Subject: [PATCH] jbd2: Debug journal_head additions and removals Signed-off-by: Jan Kara <jack@suse.cz> --- fs/jbd2/journal.c | 4 ++++ fs/jbd2/transaction.c | 4 ++++ include/linux/buffer_head.h | 4 ++++ 3 files changed, 12 insertions(+) diff --git a/fs/jbd2/journal.c b/fs/jbd2/journal.c index 02c7ad9..227a1ab 100644 --- a/fs/jbd2/journal.c +++ b/fs/jbd2/journal.c @@ -2433,6 +2433,8 @@ repeat: bh->b_private = jh; jh->b_bh = bh; get_bh(bh); + bh->added_from = _RET_IP_; + bh->added_jiffies = jiffies; BUFFER_TRACE(bh, "added journal_head"); } jh->b_jcount++; @@ -2498,6 +2500,8 @@ void jbd2_journal_put_journal_head(struct journal_head *jh) --jh->b_jcount; if (!jh->b_jcount) { __journal_remove_journal_head(bh); + bh->removed_from = _RET_IP_; + bh->removed_jiffies = jiffies; jbd_unlock_bh_journal_head(bh); __brelse(bh); } else diff --git a/fs/jbd2/transaction.c b/fs/jbd2/transaction.c index 7aa9a32..aacd1cd 100644 --- a/fs/jbd2/transaction.c +++ b/fs/jbd2/transaction.c @@ -1275,6 +1275,10 @@ int jbd2_journal_dirty_metadata(handle_t *handle, struct buffer_head *bh) journal = transaction->t_journal; jh = jbd2_journal_grab_journal_head(bh); if (!jh) { + printk(KERN_ERR "Dirtying buffer without jh at %lu: state %lx," + "jh added from 0x%lx at %lu, removed from 0x%lx " + "at %lu\n", jiffies, bh->b_state, bh->removed_from, + bh->removed_jiffies, bh->added_from, bh->added_jiffies); ret = -EUCLEAN; goto out; } diff --git a/include/linux/buffer_head.h b/include/linux/buffer_head.h index 91fa9a9..f24073e 100644 --- a/include/linux/buffer_head.h +++ b/include/linux/buffer_head.h @@ -74,6 +74,10 @@ struct buffer_head { struct address_space *b_assoc_map; /* mapping this buffer is associated with */ atomic_t b_count; /* users using this buffer_head */ + unsigned long removed_from; + unsigned long removed_jiffies; + unsigned long added_from; + unsigned long added_jiffies; }; /* -- 1.8.1.4 ^ permalink raw reply related [flat|nested] 16+ messages in thread
* Re: crash in __jbd2_journal_file_buffer 2013-08-13 10:34 ` Jan Kara @ 2013-08-22 23:35 ` Sage Weil 2013-08-23 9:54 ` Jan Kara 2013-08-23 20:48 ` Jan Kara 0 siblings, 2 replies; 16+ messages in thread From: Sage Weil @ 2013-08-22 23:35 UTC (permalink / raw) To: Jan Kara; +Cc: linux-ext4 On Tue, 13 Aug 2013, Jan Kara wrote: > On Mon 12-08-13 11:13:06, Sage Weil wrote: > > Full dmesg is attached. > Hum, nothing interesting in there... > > > Our QA seems to hit this with some regularity. Let me know if there's > > some combination of patches that would help shed more light! > If they can run with attached debug patch it could maybe sched some more > light. Please send also your System.map file together with the dmesg of the > kernel when the crash happens so that I can map addresses to function > names... Thanks! Okay, finally hit it again: <6>[75193.192249] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro,user_xattr,user_xattr <3>[77877.426658] Dirtying buffer without jh at 4302720297: state 218c029,jh added from 0xffffffff8127ab1d at 4302720297, removed from 0xffffffff8127b5b0 at 4302720296 <4>[77877.441200] ------------[ cut here ]------------ <4>[77877.445845] WARNING: CPU: 7 PID: 26045 at /srv/autobuild-ceph/gitbuilder.git/build/fs/jbd2/transaction.c:1380 jbd2_journal_dirty_metadata+0x1f1/0x2e0() <4>[77877.497349] CPU: 7 PID: 26045 Comm: ceph-osd Not tainted 3.11.0-rc5-ceph-00061-g546140d #1 <4>[77877.505649] Hardware name: Dell Inc. PowerEdge R410/01V648, BIOS 1.6.3 02/07/2011 <4>[77877.513213] 0000000000000564 ffff880131ca1938 ffffffff81642d85 ffff8802272ef290 <4>[77877.520694] 0000000000000000 ffff880131ca1978 ffffffff8104985c ffff880131ca19a0 <4>[77877.528218] ffff88020f695aa0 0000000000000000 ffff880214c48b40 ffff88020be55000 <4>[77877.535756] Call Trace: <4>[77877.538279] [<ffffffff81642d85>] dump_stack+0x46/0x58 <4>[77877.543439] [<ffffffff8104985c>] warn_slowpath_common+0x8c/0xc0 <4>[77877.549548] [<ffffffff810498aa>] warn_slowpath_null+0x1a/0x20 <4>[77877.555413] [<ffffffff8127adb1>] jbd2_journal_dirty_metadata+0x1f1/0x2e0 <4>[77877.562288] [<ffffffff812578c3>] __ext4_handle_dirty_metadata+0xa3/0x140 <4>[77877.569155] [<ffffffff81268e23>] ext4_xattr_release_block+0x103/0x1f0 <4>[77877.575723] [<ffffffff812692b0>] ext4_xattr_block_set+0x1e0/0x910 <4>[77877.581990] [<ffffffff8126a58b>] ext4_xattr_set_handle+0x38b/0x4a0 <4>[77877.588335] [<ffffffff810af7cd>] ? trace_hardirqs_on+0xd/0x10 <4>[77877.594188] [<ffffffff8126a765>] ext4_xattr_set+0xc5/0x140 <4>[77877.599837] [<ffffffff8126b177>] ext4_xattr_user_set+0x47/0x50 <4>[77877.605779] [<ffffffff811a3fee>] generic_setxattr+0x6e/0x90 <4>[77877.611514] [<ffffffff811a48eb>] __vfs_setxattr_noperm+0x7b/0x1c0 <4>[77877.617773] [<ffffffff811a4af4>] vfs_setxattr+0xc4/0xd0 <4>[77877.623103] [<ffffffff811a4c3e>] setxattr+0x13e/0x1e0 <4>[77877.628317] [<ffffffff81181ec7>] ? __sb_start_write+0xe7/0x1b0 <4>[77877.634260] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 <4>[77877.640428] [<ffffffff8119cf0c>] ? fget_light+0x3c/0x130 <4>[77877.645847] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 <4>[77877.652015] [<ffffffff8119e902>] ? mnt_clone_write+0x12/0x30 <4>[77877.657897] [<ffffffff811a50de>] SyS_fsetxattr+0xbe/0x100 <4>[77877.663405] [<ffffffff81653782>] system_call_fastpath+0x16/0x1b <4>[77877.669488] ---[ end trace bb7933908cd5a32a ]--- <2>[77877.674126] EXT4-fs error (device sda1) in ext4_handle_dirty_xattr_block:167: error 117 <3>[77877.692983] Aborting journal on device sda1-8. <2>[77877.721561] EXT4-fs (sda1): Remounting filesystem read-only <0>[77877.721657] journal commit I/O error <0>[77877.721706] journal commit I/O error <0>[77877.721707] journal commit I/O error <2>[77877.727300] EXT4-fs error (device sda1): ext4_journal_check_start:56: Detected aborted journal <2>[77877.727338] EXT4-fs (sda1): Remounting filesystem read-only <2>[77877.727613] EXT4-fs error (device sda1): ext4_journal_check_start:56: Detected aborted journal <2>[77877.727618] EXT4-fs error (device sda1): ext4_journal_check_start:56: Detected aborted journal <2>[77877.727625] EXT4-fs error (device sda1): ext4_journal_check_start:56: Detected aborted journal <2>[77877.778239] EXT4-fs error (device sda1) in ext4_xattr_release_block:558: error 117 <3>[77877.786051] Dirtying buffer without jh at 4302720332: state 10c029,jh added from 0xffffffff8127eb88 at 4302720326, removed from 0xffffffff8127b5b0 at 4302720274 <4>[77877.800516] ------------[ cut here ]------------ <4>[77877.805156] WARNING: CPU: 7 PID: 26045 at /srv/autobuild-ceph/gitbuilder.git/build/fs/jbd2/transaction.c:1380 jbd2_journal_dirty_metadata+0x1f1/0x2e0() <4>[77877.856583] CPU: 7 PID: 26045 Comm: ceph-osd Tainted: G W 3.11.0-rc5-ceph-00061-g546140d #1 <4>[77877.865896] Hardware name: Dell Inc. PowerEdge R410/01V648, BIOS 1.6.3 02/07/2011 <4>[77877.873475] 0000000000000564 ffff880131ca19b8 ffffffff81642d85 ffff8802272ef290 <4>[77877.880954] 0000000000000000 ffff880131ca19f8 ffffffff8104985c ffff880131ca1a20 <4>[77877.888488] ffff8801c499be58 0000000000000000 ffff880029010000 ffff880029010c30 <4>[77877.895962] Call Trace: <4>[77877.898484] [<ffffffff81642d85>] dump_stack+0x46/0x58 <4>[77877.903643] [<ffffffff8104985c>] warn_slowpath_common+0x8c/0xc0 <4>[77877.909724] [<ffffffff810498aa>] warn_slowpath_null+0x1a/0x20 <4>[77877.915577] [<ffffffff8127adb1>] jbd2_journal_dirty_metadata+0x1f1/0x2e0 <4>[77877.922443] [<ffffffff810af7cd>] ? trace_hardirqs_on+0xd/0x10 <4>[77877.928353] [<ffffffff812578c3>] __ext4_handle_dirty_metadata+0xa3/0x140 <4>[77877.935165] [<ffffffff8122ca3e>] ext4_mark_iloc_dirty+0x40e/0x660 <4>[77877.941421] [<ffffffff8126a465>] ext4_xattr_set_handle+0x265/0x4a0 <4>[77877.947766] [<ffffffff8126a765>] ext4_xattr_set+0xc5/0x140 <4>[77877.953358] [<ffffffff8126b177>] ext4_xattr_user_set+0x47/0x50 <4>[77877.959354] [<ffffffff811a3fee>] generic_setxattr+0x6e/0x90 <4>[77877.965034] [<ffffffff811a48eb>] __vfs_setxattr_noperm+0x7b/0x1c0 <4>[77877.971289] [<ffffffff811a4af4>] vfs_setxattr+0xc4/0xd0 <4>[77877.976621] [<ffffffff811a4c3e>] setxattr+0x13e/0x1e0 <4>[77877.981837] [<ffffffff81181ec7>] ? __sb_start_write+0xe7/0x1b0 <4>[77877.987830] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 <4>[77877.993944] [<ffffffff8119cf0c>] ? fget_light+0x3c/0x130 <4>[77877.999417] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 <4>[77878.005530] [<ffffffff8119e902>] ? mnt_clone_write+0x12/0x30 <4>[77878.011349] [<ffffffff811a50de>] SyS_fsetxattr+0xbe/0x100 <4>[77878.016856] [<ffffffff81653782>] system_call_fastpath+0x16/0x1b <4>[77878.022941] ---[ end trace bb7933908cd5a32b ]--- [7]kdb> rd ax: ffff88020aadbf20 bx: ffff8800290100a0 cx: 0000000000000000 dx: ffff8800290100a0 si: ffff8800290100a0 di: ffff8800290100a0 bp: ffff880131ca1a28 sp: ffff880131ca1978 r8: 0000000000000002 r9: 0000000000000000 r10: 0000000000000001 r11: 0000000000000000 r12: ffff880029010000 r13: 0000000000000000 r14: ffff880029010c30 r15: 00000000ffffff8b ip: ffffffff81279f84 flags: 00010286 cs: 00000010 ss: 00000018 ds: 00000018 es: 00000018 fs: 00000018 gs: 00000018 [7]kdb> bt Stack traceback for pid 26045 0xffff88020aadbf20 26045 25958 1 7 R 0xffff88020aadc3a8 *ceph-osd ffff880131ca1978 0000000000000018 ffff880131ca1978 ffff880131ca1998 bb7933908cd5a32b 0000000000000000 0000000000000001 0000000000000002 0000000000000000 ffff880131ca19b8 0000000000000000 ffff880131ca19f8 Call Trace: [<ffffffff8104986f>] ? warn_slowpath_common+0x9f/0xc0 [<ffffffff81257308>] ? __ext4_journal_stop+0x78/0xa0 [<ffffffff812578dc>] ? __ext4_handle_dirty_metadata+0xbc/0x140 [<ffffffff8122ca3e>] ? ext4_mark_iloc_dirty+0x40e/0x660 [<ffffffff8126a465>] ? ext4_xattr_set_handle+0x265/0x4a0 [<ffffffff8126a765>] ? ext4_xattr_set+0xc5/0x140 [<ffffffff8126b177>] ? ext4_xattr_user_set+0x47/0x50 [<ffffffff811a3fee>] ? generic_setxattr+0x6e/0x90 [<ffffffff811a48eb>] ? __vfs_setxattr_noperm+0x7b/0x1c0 [<ffffffff811a4af4>] ? vfs_setxattr+0xc4/0xd0 [<ffffffff811a4c3e>] ? setxattr+0x13e/0x1e0 [<ffffffff81181ec7>] ? __sb_start_write+0xe7/0x1b0 [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 [<ffffffff8119cf0c>] ? fget_light+0x3c/0x130 [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 [<ffffffff8119e902>] ? mnt_clone_write+0x12/0x30 [<ffffffff811a50de>] ? SyS_fsetxattr+0xbe/0x100 [<ffffffff81653782>] ? system_call_fastpath+0x16/0x1b Let me know if there is anything else I can gather from this machine that will help! sage ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: crash in __jbd2_journal_file_buffer 2013-08-22 23:35 ` Sage Weil @ 2013-08-23 9:54 ` Jan Kara 2013-08-23 15:02 ` Sage Weil 2013-08-23 20:48 ` Jan Kara 1 sibling, 1 reply; 16+ messages in thread From: Jan Kara @ 2013-08-23 9:54 UTC (permalink / raw) To: Sage Weil; +Cc: linux-ext4 On Thu 22-08-13 16:35:15, Sage Weil wrote: > On Tue, 13 Aug 2013, Jan Kara wrote: > > On Mon 12-08-13 11:13:06, Sage Weil wrote: > > > Full dmesg is attached. > > Hum, nothing interesting in there... > > > > > Our QA seems to hit this with some regularity. Let me know if there's > > > some combination of patches that would help shed more light! > > If they can run with attached debug patch it could maybe sched some more > > light. Please send also your System.map file together with the dmesg of the > > kernel when the crash happens so that I can map addresses to function > > names... Thanks! > > Okay, finally hit it again: > > <6>[75193.192249] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro,user_xattr,user_xattr > <3>[77877.426658] Dirtying buffer without jh at 4302720297: state 218c029,jh added from 0xffffffff8127ab1d at 4302720297, removed from 0xffffffff8127b5b0 at 4302720296 Great! Can you please send me /proc/kallsyms from the machine? Honza > <4>[77877.441200] ------------[ cut here ]------------ > <4>[77877.445845] WARNING: CPU: 7 PID: 26045 at /srv/autobuild-ceph/gitbuilder.git/build/fs/jbd2/transaction.c:1380 jbd2_journal_dirty_metadata+0x1f1/0x2e0() > > <4>[77877.497349] CPU: 7 PID: 26045 Comm: ceph-osd Not tainted 3.11.0-rc5-ceph-00061-g546140d #1 > <4>[77877.505649] Hardware name: Dell Inc. PowerEdge R410/01V648, BIOS 1.6.3 02/07/2011 > <4>[77877.513213] 0000000000000564 ffff880131ca1938 ffffffff81642d85 ffff8802272ef290 > <4>[77877.520694] 0000000000000000 ffff880131ca1978 ffffffff8104985c ffff880131ca19a0 > <4>[77877.528218] ffff88020f695aa0 0000000000000000 ffff880214c48b40 ffff88020be55000 > <4>[77877.535756] Call Trace: > <4>[77877.538279] [<ffffffff81642d85>] dump_stack+0x46/0x58 > <4>[77877.543439] [<ffffffff8104985c>] warn_slowpath_common+0x8c/0xc0 > <4>[77877.549548] [<ffffffff810498aa>] warn_slowpath_null+0x1a/0x20 > <4>[77877.555413] [<ffffffff8127adb1>] jbd2_journal_dirty_metadata+0x1f1/0x2e0 > <4>[77877.562288] [<ffffffff812578c3>] __ext4_handle_dirty_metadata+0xa3/0x140 > <4>[77877.569155] [<ffffffff81268e23>] ext4_xattr_release_block+0x103/0x1f0 > <4>[77877.575723] [<ffffffff812692b0>] ext4_xattr_block_set+0x1e0/0x910 > <4>[77877.581990] [<ffffffff8126a58b>] ext4_xattr_set_handle+0x38b/0x4a0 > <4>[77877.588335] [<ffffffff810af7cd>] ? trace_hardirqs_on+0xd/0x10 > <4>[77877.594188] [<ffffffff8126a765>] ext4_xattr_set+0xc5/0x140 > <4>[77877.599837] [<ffffffff8126b177>] ext4_xattr_user_set+0x47/0x50 > <4>[77877.605779] [<ffffffff811a3fee>] generic_setxattr+0x6e/0x90 > <4>[77877.611514] [<ffffffff811a48eb>] __vfs_setxattr_noperm+0x7b/0x1c0 > <4>[77877.617773] [<ffffffff811a4af4>] vfs_setxattr+0xc4/0xd0 > <4>[77877.623103] [<ffffffff811a4c3e>] setxattr+0x13e/0x1e0 > <4>[77877.628317] [<ffffffff81181ec7>] ? __sb_start_write+0xe7/0x1b0 > <4>[77877.634260] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > <4>[77877.640428] [<ffffffff8119cf0c>] ? fget_light+0x3c/0x130 > <4>[77877.645847] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > <4>[77877.652015] [<ffffffff8119e902>] ? mnt_clone_write+0x12/0x30 > <4>[77877.657897] [<ffffffff811a50de>] SyS_fsetxattr+0xbe/0x100 > <4>[77877.663405] [<ffffffff81653782>] system_call_fastpath+0x16/0x1b > <4>[77877.669488] ---[ end trace bb7933908cd5a32a ]--- > <2>[77877.674126] EXT4-fs error (device sda1) in ext4_handle_dirty_xattr_block:167: error 117 > <3>[77877.692983] Aborting journal on device sda1-8. > <2>[77877.721561] EXT4-fs (sda1): Remounting filesystem read-only > <0>[77877.721657] journal commit I/O error > <0>[77877.721706] journal commit I/O error > <0>[77877.721707] journal commit I/O error > <2>[77877.727300] EXT4-fs error (device sda1): ext4_journal_check_start:56: Detected aborted journal > <2>[77877.727338] EXT4-fs (sda1): Remounting filesystem read-only > <2>[77877.727613] EXT4-fs error (device sda1): ext4_journal_check_start:56: Detected aborted journal > <2>[77877.727618] EXT4-fs error (device sda1): ext4_journal_check_start:56: Detected aborted journal > <2>[77877.727625] EXT4-fs error (device sda1): ext4_journal_check_start:56: Detected aborted journal > <2>[77877.778239] EXT4-fs error (device sda1) in ext4_xattr_release_block:558: error 117 > <3>[77877.786051] Dirtying buffer without jh at 4302720332: state 10c029,jh added from 0xffffffff8127eb88 at 4302720326, removed from 0xffffffff8127b5b0 at 4302720274 > <4>[77877.800516] ------------[ cut here ]------------ > <4>[77877.805156] WARNING: CPU: 7 PID: 26045 at /srv/autobuild-ceph/gitbuilder.git/build/fs/jbd2/transaction.c:1380 jbd2_journal_dirty_metadata+0x1f1/0x2e0() > > <4>[77877.856583] CPU: 7 PID: 26045 Comm: ceph-osd Tainted: G W 3.11.0-rc5-ceph-00061-g546140d #1 > <4>[77877.865896] Hardware name: Dell Inc. PowerEdge R410/01V648, BIOS 1.6.3 02/07/2011 > <4>[77877.873475] 0000000000000564 ffff880131ca19b8 ffffffff81642d85 ffff8802272ef290 > <4>[77877.880954] 0000000000000000 ffff880131ca19f8 ffffffff8104985c ffff880131ca1a20 > <4>[77877.888488] ffff8801c499be58 0000000000000000 ffff880029010000 ffff880029010c30 > <4>[77877.895962] Call Trace: > <4>[77877.898484] [<ffffffff81642d85>] dump_stack+0x46/0x58 > <4>[77877.903643] [<ffffffff8104985c>] warn_slowpath_common+0x8c/0xc0 > <4>[77877.909724] [<ffffffff810498aa>] warn_slowpath_null+0x1a/0x20 > <4>[77877.915577] [<ffffffff8127adb1>] jbd2_journal_dirty_metadata+0x1f1/0x2e0 > <4>[77877.922443] [<ffffffff810af7cd>] ? trace_hardirqs_on+0xd/0x10 > <4>[77877.928353] [<ffffffff812578c3>] __ext4_handle_dirty_metadata+0xa3/0x140 > <4>[77877.935165] [<ffffffff8122ca3e>] ext4_mark_iloc_dirty+0x40e/0x660 > <4>[77877.941421] [<ffffffff8126a465>] ext4_xattr_set_handle+0x265/0x4a0 > <4>[77877.947766] [<ffffffff8126a765>] ext4_xattr_set+0xc5/0x140 > <4>[77877.953358] [<ffffffff8126b177>] ext4_xattr_user_set+0x47/0x50 > <4>[77877.959354] [<ffffffff811a3fee>] generic_setxattr+0x6e/0x90 > <4>[77877.965034] [<ffffffff811a48eb>] __vfs_setxattr_noperm+0x7b/0x1c0 > <4>[77877.971289] [<ffffffff811a4af4>] vfs_setxattr+0xc4/0xd0 > <4>[77877.976621] [<ffffffff811a4c3e>] setxattr+0x13e/0x1e0 > <4>[77877.981837] [<ffffffff81181ec7>] ? __sb_start_write+0xe7/0x1b0 > <4>[77877.987830] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > <4>[77877.993944] [<ffffffff8119cf0c>] ? fget_light+0x3c/0x130 > <4>[77877.999417] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > <4>[77878.005530] [<ffffffff8119e902>] ? mnt_clone_write+0x12/0x30 > <4>[77878.011349] [<ffffffff811a50de>] SyS_fsetxattr+0xbe/0x100 > <4>[77878.016856] [<ffffffff81653782>] system_call_fastpath+0x16/0x1b > <4>[77878.022941] ---[ end trace bb7933908cd5a32b ]--- > [7]kdb> rd > ax: ffff88020aadbf20 bx: ffff8800290100a0 cx: 0000000000000000 > dx: ffff8800290100a0 si: ffff8800290100a0 di: ffff8800290100a0 > bp: ffff880131ca1a28 sp: ffff880131ca1978 r8: 0000000000000002 > r9: 0000000000000000 r10: 0000000000000001 r11: 0000000000000000 > r12: ffff880029010000 r13: 0000000000000000 r14: ffff880029010c30 > r15: 00000000ffffff8b ip: ffffffff81279f84 flags: 00010286 cs: 00000010 > ss: 00000018 ds: 00000018 es: 00000018 fs: 00000018 gs: 00000018 > [7]kdb> bt > Stack traceback for pid 26045 > 0xffff88020aadbf20 26045 25958 1 7 R 0xffff88020aadc3a8 *ceph-osd > ffff880131ca1978 0000000000000018 ffff880131ca1978 ffff880131ca1998 > bb7933908cd5a32b 0000000000000000 0000000000000001 0000000000000002 > 0000000000000000 ffff880131ca19b8 0000000000000000 ffff880131ca19f8 > Call Trace: > [<ffffffff8104986f>] ? warn_slowpath_common+0x9f/0xc0 > [<ffffffff81257308>] ? __ext4_journal_stop+0x78/0xa0 > [<ffffffff812578dc>] ? __ext4_handle_dirty_metadata+0xbc/0x140 > [<ffffffff8122ca3e>] ? ext4_mark_iloc_dirty+0x40e/0x660 > [<ffffffff8126a465>] ? ext4_xattr_set_handle+0x265/0x4a0 > [<ffffffff8126a765>] ? ext4_xattr_set+0xc5/0x140 > [<ffffffff8126b177>] ? ext4_xattr_user_set+0x47/0x50 > [<ffffffff811a3fee>] ? generic_setxattr+0x6e/0x90 > [<ffffffff811a48eb>] ? __vfs_setxattr_noperm+0x7b/0x1c0 > [<ffffffff811a4af4>] ? vfs_setxattr+0xc4/0xd0 > [<ffffffff811a4c3e>] ? setxattr+0x13e/0x1e0 > [<ffffffff81181ec7>] ? __sb_start_write+0xe7/0x1b0 > [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > [<ffffffff8119cf0c>] ? fget_light+0x3c/0x130 > [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > [<ffffffff8119e902>] ? mnt_clone_write+0x12/0x30 > [<ffffffff811a50de>] ? SyS_fsetxattr+0xbe/0x100 > [<ffffffff81653782>] ? system_call_fastpath+0x16/0x1b > > Let me know if there is anything else I can gather from this machine that > will help! > > sage -- Jan Kara <jack@suse.cz> SUSE Labs, CR ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: crash in __jbd2_journal_file_buffer 2013-08-23 9:54 ` Jan Kara @ 2013-08-23 15:02 ` Sage Weil 2013-08-23 19:52 ` Jan Kara 0 siblings, 1 reply; 16+ messages in thread From: Sage Weil @ 2013-08-23 15:02 UTC (permalink / raw) To: Jan Kara; +Cc: linux-ext4 [-- Attachment #1: Type: TEXT/PLAIN, Size: 9026 bytes --] On Fri, 23 Aug 2013, Jan Kara wrote: > On Thu 22-08-13 16:35:15, Sage Weil wrote: > > On Tue, 13 Aug 2013, Jan Kara wrote: > > > On Mon 12-08-13 11:13:06, Sage Weil wrote: > > > > Full dmesg is attached. > > > Hum, nothing interesting in there... > > > > > > > Our QA seems to hit this with some regularity. Let me know if there's > > > > some combination of patches that would help shed more light! > > > If they can run with attached debug patch it could maybe sched some more > > > light. Please send also your System.map file together with the dmesg of the > > > kernel when the crash happens so that I can map addresses to function > > > names... Thanks! > > > > Okay, finally hit it again: > > > > <6>[75193.192249] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro,user_xattr,user_xattr > > <3>[77877.426658] Dirtying buffer without jh at 4302720297: state 218c029,jh added from 0xffffffff8127ab1d at 4302720297, removed from 0xffffffff8127b5b0 at 4302720296 > Great! Can you please send me /proc/kallsyms from the machine? Attached! sage > > Honza > > > <4>[77877.441200] ------------[ cut here ]------------ > > <4>[77877.445845] WARNING: CPU: 7 PID: 26045 at /srv/autobuild-ceph/gitbuilder.git/build/fs/jbd2/transaction.c:1380 jbd2_journal_dirty_metadata+0x1f1/0x2e0() > > > > <4>[77877.497349] CPU: 7 PID: 26045 Comm: ceph-osd Not tainted 3.11.0-rc5-ceph-00061-g546140d #1 > > <4>[77877.505649] Hardware name: Dell Inc. PowerEdge R410/01V648, BIOS 1.6.3 02/07/2011 > > <4>[77877.513213] 0000000000000564 ffff880131ca1938 ffffffff81642d85 ffff8802272ef290 > > <4>[77877.520694] 0000000000000000 ffff880131ca1978 ffffffff8104985c ffff880131ca19a0 > > <4>[77877.528218] ffff88020f695aa0 0000000000000000 ffff880214c48b40 ffff88020be55000 > > <4>[77877.535756] Call Trace: > > <4>[77877.538279] [<ffffffff81642d85>] dump_stack+0x46/0x58 > > <4>[77877.543439] [<ffffffff8104985c>] warn_slowpath_common+0x8c/0xc0 > > <4>[77877.549548] [<ffffffff810498aa>] warn_slowpath_null+0x1a/0x20 > > <4>[77877.555413] [<ffffffff8127adb1>] jbd2_journal_dirty_metadata+0x1f1/0x2e0 > > <4>[77877.562288] [<ffffffff812578c3>] __ext4_handle_dirty_metadata+0xa3/0x140 > > <4>[77877.569155] [<ffffffff81268e23>] ext4_xattr_release_block+0x103/0x1f0 > > <4>[77877.575723] [<ffffffff812692b0>] ext4_xattr_block_set+0x1e0/0x910 > > <4>[77877.581990] [<ffffffff8126a58b>] ext4_xattr_set_handle+0x38b/0x4a0 > > <4>[77877.588335] [<ffffffff810af7cd>] ? trace_hardirqs_on+0xd/0x10 > > <4>[77877.594188] [<ffffffff8126a765>] ext4_xattr_set+0xc5/0x140 > > <4>[77877.599837] [<ffffffff8126b177>] ext4_xattr_user_set+0x47/0x50 > > <4>[77877.605779] [<ffffffff811a3fee>] generic_setxattr+0x6e/0x90 > > <4>[77877.611514] [<ffffffff811a48eb>] __vfs_setxattr_noperm+0x7b/0x1c0 > > <4>[77877.617773] [<ffffffff811a4af4>] vfs_setxattr+0xc4/0xd0 > > <4>[77877.623103] [<ffffffff811a4c3e>] setxattr+0x13e/0x1e0 > > <4>[77877.628317] [<ffffffff81181ec7>] ? __sb_start_write+0xe7/0x1b0 > > <4>[77877.634260] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > > <4>[77877.640428] [<ffffffff8119cf0c>] ? fget_light+0x3c/0x130 > > <4>[77877.645847] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > > <4>[77877.652015] [<ffffffff8119e902>] ? mnt_clone_write+0x12/0x30 > > <4>[77877.657897] [<ffffffff811a50de>] SyS_fsetxattr+0xbe/0x100 > > <4>[77877.663405] [<ffffffff81653782>] system_call_fastpath+0x16/0x1b > > <4>[77877.669488] ---[ end trace bb7933908cd5a32a ]--- > > <2>[77877.674126] EXT4-fs error (device sda1) in ext4_handle_dirty_xattr_block:167: error 117 > > <3>[77877.692983] Aborting journal on device sda1-8. > > <2>[77877.721561] EXT4-fs (sda1): Remounting filesystem read-only > > <0>[77877.721657] journal commit I/O error > > <0>[77877.721706] journal commit I/O error > > <0>[77877.721707] journal commit I/O error > > <2>[77877.727300] EXT4-fs error (device sda1): ext4_journal_check_start:56: Detected aborted journal > > <2>[77877.727338] EXT4-fs (sda1): Remounting filesystem read-only > > <2>[77877.727613] EXT4-fs error (device sda1): ext4_journal_check_start:56: Detected aborted journal > > <2>[77877.727618] EXT4-fs error (device sda1): ext4_journal_check_start:56: Detected aborted journal > > <2>[77877.727625] EXT4-fs error (device sda1): ext4_journal_check_start:56: Detected aborted journal > > <2>[77877.778239] EXT4-fs error (device sda1) in ext4_xattr_release_block:558: error 117 > > <3>[77877.786051] Dirtying buffer without jh at 4302720332: state 10c029,jh added from 0xffffffff8127eb88 at 4302720326, removed from 0xffffffff8127b5b0 at 4302720274 > > <4>[77877.800516] ------------[ cut here ]------------ > > <4>[77877.805156] WARNING: CPU: 7 PID: 26045 at /srv/autobuild-ceph/gitbuilder.git/build/fs/jbd2/transaction.c:1380 jbd2_journal_dirty_metadata+0x1f1/0x2e0() > > > > <4>[77877.856583] CPU: 7 PID: 26045 Comm: ceph-osd Tainted: G W 3.11.0-rc5-ceph-00061-g546140d #1 > > <4>[77877.865896] Hardware name: Dell Inc. PowerEdge R410/01V648, BIOS 1.6.3 02/07/2011 > > <4>[77877.873475] 0000000000000564 ffff880131ca19b8 ffffffff81642d85 ffff8802272ef290 > > <4>[77877.880954] 0000000000000000 ffff880131ca19f8 ffffffff8104985c ffff880131ca1a20 > > <4>[77877.888488] ffff8801c499be58 0000000000000000 ffff880029010000 ffff880029010c30 > > <4>[77877.895962] Call Trace: > > <4>[77877.898484] [<ffffffff81642d85>] dump_stack+0x46/0x58 > > <4>[77877.903643] [<ffffffff8104985c>] warn_slowpath_common+0x8c/0xc0 > > <4>[77877.909724] [<ffffffff810498aa>] warn_slowpath_null+0x1a/0x20 > > <4>[77877.915577] [<ffffffff8127adb1>] jbd2_journal_dirty_metadata+0x1f1/0x2e0 > > <4>[77877.922443] [<ffffffff810af7cd>] ? trace_hardirqs_on+0xd/0x10 > > <4>[77877.928353] [<ffffffff812578c3>] __ext4_handle_dirty_metadata+0xa3/0x140 > > <4>[77877.935165] [<ffffffff8122ca3e>] ext4_mark_iloc_dirty+0x40e/0x660 > > <4>[77877.941421] [<ffffffff8126a465>] ext4_xattr_set_handle+0x265/0x4a0 > > <4>[77877.947766] [<ffffffff8126a765>] ext4_xattr_set+0xc5/0x140 > > <4>[77877.953358] [<ffffffff8126b177>] ext4_xattr_user_set+0x47/0x50 > > <4>[77877.959354] [<ffffffff811a3fee>] generic_setxattr+0x6e/0x90 > > <4>[77877.965034] [<ffffffff811a48eb>] __vfs_setxattr_noperm+0x7b/0x1c0 > > <4>[77877.971289] [<ffffffff811a4af4>] vfs_setxattr+0xc4/0xd0 > > <4>[77877.976621] [<ffffffff811a4c3e>] setxattr+0x13e/0x1e0 > > <4>[77877.981837] [<ffffffff81181ec7>] ? __sb_start_write+0xe7/0x1b0 > > <4>[77877.987830] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > > <4>[77877.993944] [<ffffffff8119cf0c>] ? fget_light+0x3c/0x130 > > <4>[77877.999417] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > > <4>[77878.005530] [<ffffffff8119e902>] ? mnt_clone_write+0x12/0x30 > > <4>[77878.011349] [<ffffffff811a50de>] SyS_fsetxattr+0xbe/0x100 > > <4>[77878.016856] [<ffffffff81653782>] system_call_fastpath+0x16/0x1b > > <4>[77878.022941] ---[ end trace bb7933908cd5a32b ]--- > > [7]kdb> rd > > ax: ffff88020aadbf20 bx: ffff8800290100a0 cx: 0000000000000000 > > dx: ffff8800290100a0 si: ffff8800290100a0 di: ffff8800290100a0 > > bp: ffff880131ca1a28 sp: ffff880131ca1978 r8: 0000000000000002 > > r9: 0000000000000000 r10: 0000000000000001 r11: 0000000000000000 > > r12: ffff880029010000 r13: 0000000000000000 r14: ffff880029010c30 > > r15: 00000000ffffff8b ip: ffffffff81279f84 flags: 00010286 cs: 00000010 > > ss: 00000018 ds: 00000018 es: 00000018 fs: 00000018 gs: 00000018 > > [7]kdb> bt > > Stack traceback for pid 26045 > > 0xffff88020aadbf20 26045 25958 1 7 R 0xffff88020aadc3a8 *ceph-osd > > ffff880131ca1978 0000000000000018 ffff880131ca1978 ffff880131ca1998 > > bb7933908cd5a32b 0000000000000000 0000000000000001 0000000000000002 > > 0000000000000000 ffff880131ca19b8 0000000000000000 ffff880131ca19f8 > > Call Trace: > > [<ffffffff8104986f>] ? warn_slowpath_common+0x9f/0xc0 > > [<ffffffff81257308>] ? __ext4_journal_stop+0x78/0xa0 > > [<ffffffff812578dc>] ? __ext4_handle_dirty_metadata+0xbc/0x140 > > [<ffffffff8122ca3e>] ? ext4_mark_iloc_dirty+0x40e/0x660 > > [<ffffffff8126a465>] ? ext4_xattr_set_handle+0x265/0x4a0 > > [<ffffffff8126a765>] ? ext4_xattr_set+0xc5/0x140 > > [<ffffffff8126b177>] ? ext4_xattr_user_set+0x47/0x50 > > [<ffffffff811a3fee>] ? generic_setxattr+0x6e/0x90 > > [<ffffffff811a48eb>] ? __vfs_setxattr_noperm+0x7b/0x1c0 > > [<ffffffff811a4af4>] ? vfs_setxattr+0xc4/0xd0 > > [<ffffffff811a4c3e>] ? setxattr+0x13e/0x1e0 > > [<ffffffff81181ec7>] ? __sb_start_write+0xe7/0x1b0 > > [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > > [<ffffffff8119cf0c>] ? fget_light+0x3c/0x130 > > [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > > [<ffffffff8119e902>] ? mnt_clone_write+0x12/0x30 > > [<ffffffff811a50de>] ? SyS_fsetxattr+0xbe/0x100 > > [<ffffffff81653782>] ? system_call_fastpath+0x16/0x1b > > > > Let me know if there is anything else I can gather from this machine that > > will help! > > > > sage > -- > Jan Kara <jack@suse.cz> > SUSE Labs, CR > > [-- Attachment #2: Type: APPLICATION/octet-stream, Size: 0 bytes --] ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: crash in __jbd2_journal_file_buffer 2013-08-23 15:02 ` Sage Weil @ 2013-08-23 19:52 ` Jan Kara 0 siblings, 0 replies; 16+ messages in thread From: Jan Kara @ 2013-08-23 19:52 UTC (permalink / raw) To: Sage Weil; +Cc: Jan Kara, linux-ext4 On Fri 23-08-13 08:02:45, Sage Weil wrote: > On Fri, 23 Aug 2013, Jan Kara wrote: > > On Thu 22-08-13 16:35:15, Sage Weil wrote: > > > On Tue, 13 Aug 2013, Jan Kara wrote: > > > > On Mon 12-08-13 11:13:06, Sage Weil wrote: > > > > > Full dmesg is attached. > > > > Hum, nothing interesting in there... > > > > > > > > > Our QA seems to hit this with some regularity. Let me know if there's > > > > > some combination of patches that would help shed more light! > > > > If they can run with attached debug patch it could maybe sched some more > > > > light. Please send also your System.map file together with the dmesg of the > > > > kernel when the crash happens so that I can map addresses to function > > > > names... Thanks! > > > > > > Okay, finally hit it again: > > > > > > <6>[75193.192249] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro,user_xattr,user_xattr > > > <3>[77877.426658] Dirtying buffer without jh at 4302720297: state 218c029,jh added from 0xffffffff8127ab1d at 4302720297, removed from 0xffffffff8127b5b0 at 4302720296 > > Great! Can you please send me /proc/kallsyms from the machine? > > Attached! Sadly not. I think your MUA got confused by the fact that files in /proc have 0 length and attached empty file. Honza -- Jan Kara <jack@suse.cz> SUSE Labs, CR ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: crash in __jbd2_journal_file_buffer 2013-08-22 23:35 ` Sage Weil 2013-08-23 9:54 ` Jan Kara @ 2013-08-23 20:48 ` Jan Kara 2013-09-10 22:19 ` Jan Kara 1 sibling, 1 reply; 16+ messages in thread From: Jan Kara @ 2013-08-23 20:48 UTC (permalink / raw) To: Sage Weil; +Cc: Jan Kara, linux-ext4 On Thu 22-08-13 16:35:15, Sage Weil wrote: > On Tue, 13 Aug 2013, Jan Kara wrote: > > On Mon 12-08-13 11:13:06, Sage Weil wrote: > > > Full dmesg is attached. > > Hum, nothing interesting in there... > > > > > Our QA seems to hit this with some regularity. Let me know if there's > > > some combination of patches that would help shed more light! > > If they can run with attached debug patch it could maybe sched some more > > light. Please send also your System.map file together with the dmesg of the > > kernel when the crash happens so that I can map addresses to function > > names... Thanks! > > Okay, finally hit it again: > > <6>[75193.192249] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro,user_xattr,user_xattr > <3>[77877.426658] Dirtying buffer without jh at 4302720297: state 218c029,jh added from 0xffffffff8127ab1d at 4302720297, removed from 0xffffffff8127b5b0 at 4302720296 > <4>[77877.441200] ------------[ cut here ]------------ > <4>[77877.445845] WARNING: CPU: 7 PID: 26045 at /srv/autobuild-ceph/gitbuilder.git/build/fs/jbd2/transaction.c:1380 jbd2_journal_dirty_metadata+0x1f1/0x2e0() > > <4>[77877.497349] CPU: 7 PID: 26045 Comm: ceph-osd Not tainted 3.11.0-rc5-ceph-00061-g546140d #1 > <4>[77877.505649] Hardware name: Dell Inc. PowerEdge R410/01V648, BIOS 1.6.3 02/07/2011 > <4>[77877.513213] 0000000000000564 ffff880131ca1938 ffffffff81642d85 ffff8802272ef290 > <4>[77877.520694] 0000000000000000 ffff880131ca1978 ffffffff8104985c ffff880131ca19a0 > <4>[77877.528218] ffff88020f695aa0 0000000000000000 ffff880214c48b40 ffff88020be55000 > <4>[77877.535756] Call Trace: > <4>[77877.538279] [<ffffffff81642d85>] dump_stack+0x46/0x58 > <4>[77877.543439] [<ffffffff8104985c>] warn_slowpath_common+0x8c/0xc0 > <4>[77877.549548] [<ffffffff810498aa>] warn_slowpath_null+0x1a/0x20 > <4>[77877.555413] [<ffffffff8127adb1>] jbd2_journal_dirty_metadata+0x1f1/0x2e0 > <4>[77877.562288] [<ffffffff812578c3>] __ext4_handle_dirty_metadata+0xa3/0x140 > <4>[77877.569155] [<ffffffff81268e23>] ext4_xattr_release_block+0x103/0x1f0 > <4>[77877.575723] [<ffffffff812692b0>] ext4_xattr_block_set+0x1e0/0x910 > <4>[77877.581990] [<ffffffff8126a58b>] ext4_xattr_set_handle+0x38b/0x4a0 > <4>[77877.588335] [<ffffffff810af7cd>] ? trace_hardirqs_on+0xd/0x10 > <4>[77877.594188] [<ffffffff8126a765>] ext4_xattr_set+0xc5/0x140 > <4>[77877.599837] [<ffffffff8126b177>] ext4_xattr_user_set+0x47/0x50 > <4>[77877.605779] [<ffffffff811a3fee>] generic_setxattr+0x6e/0x90 > <4>[77877.611514] [<ffffffff811a48eb>] __vfs_setxattr_noperm+0x7b/0x1c0 > <4>[77877.617773] [<ffffffff811a4af4>] vfs_setxattr+0xc4/0xd0 > <4>[77877.623103] [<ffffffff811a4c3e>] setxattr+0x13e/0x1e0 > <4>[77877.628317] [<ffffffff81181ec7>] ? __sb_start_write+0xe7/0x1b0 > <4>[77877.634260] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > <4>[77877.640428] [<ffffffff8119cf0c>] ? fget_light+0x3c/0x130 > <4>[77877.645847] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > <4>[77877.652015] [<ffffffff8119e902>] ? mnt_clone_write+0x12/0x30 > <4>[77877.657897] [<ffffffff811a50de>] SyS_fsetxattr+0xbe/0x100 > <4>[77877.663405] [<ffffffff81653782>] system_call_fastpath+0x16/0x1b > <4>[77877.669488] ---[ end trace bb7933908cd5a32a ]--- I was scratching my head for a while how this could happen but I think I see the race now. Think we have two inodes A and B which share the same xattr block (so &BHDR(bh)->h_refcount == 2). Now we are changing xattrs for both inodes in parallel - that can easily happen because xattr locking is generally per inode (EXT4_I(inode)->xattr_sem). The following race then happens: CPU1 CPU2 ext4_xattr_release_block() ext4_xattr_release_block() lock_buffer(bh); /* False */ if (BHDR(bh)->h_refcount == cpu_to_le32(1)) } else { le32_add_cpu(&BHDR(bh)->h_refcount, -1); unlock_buffer(bh); lock_buffer(bh); /* True */ if (BHDR(bh)->h_refcount == cpu_to_le32(1)) get_bh(bh); ext4_free_blocks() ... jbd2_journal_forget() jbd2_journal_unfile_buffer() -> JH is gone error = ext4_handle_dirty_xattr_block(handle, inode, bh); -> triggers warning Now easy fix would be to move ext4_handle_dirty_xattr_block() before unlock_buffer() but I don't really like that because of locking constraints. I'll think about it... Honza -- Jan Kara <jack@suse.cz> SUSE Labs, CR ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: crash in __jbd2_journal_file_buffer 2013-08-23 20:48 ` Jan Kara @ 2013-09-10 22:19 ` Jan Kara 2013-09-10 22:32 ` Sage Weil 2014-04-05 19:20 ` Sage Weil 0 siblings, 2 replies; 16+ messages in thread From: Jan Kara @ 2013-09-10 22:19 UTC (permalink / raw) To: Sage Weil; +Cc: Jan Kara, linux-ext4 [-- Attachment #1: Type: text/plain, Size: 4706 bytes --] On Fri 23-08-13 22:48:10, Jan Kara wrote: > On Thu 22-08-13 16:35:15, Sage Weil wrote: > > On Tue, 13 Aug 2013, Jan Kara wrote: > > > On Mon 12-08-13 11:13:06, Sage Weil wrote: > > > > Full dmesg is attached. > > > Hum, nothing interesting in there... > > > > > > > Our QA seems to hit this with some regularity. Let me know if there's > > > > some combination of patches that would help shed more light! > > > If they can run with attached debug patch it could maybe sched some more > > > light. Please send also your System.map file together with the dmesg of the > > > kernel when the crash happens so that I can map addresses to function > > > names... Thanks! > > > > Okay, finally hit it again: > > > > <6>[75193.192249] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro,user_xattr,user_xattr > > <3>[77877.426658] Dirtying buffer without jh at 4302720297: state 218c029,jh added from 0xffffffff8127ab1d at 4302720297, removed from 0xffffffff8127b5b0 at 4302720296 > > <4>[77877.441200] ------------[ cut here ]------------ > > <4>[77877.445845] WARNING: CPU: 7 PID: 26045 at /srv/autobuild-ceph/gitbuilder.git/build/fs/jbd2/transaction.c:1380 jbd2_journal_dirty_metadata+0x1f1/0x2e0() > > > > <4>[77877.497349] CPU: 7 PID: 26045 Comm: ceph-osd Not tainted 3.11.0-rc5-ceph-00061-g546140d #1 > > <4>[77877.505649] Hardware name: Dell Inc. PowerEdge R410/01V648, BIOS 1.6.3 02/07/2011 > > <4>[77877.513213] 0000000000000564 ffff880131ca1938 ffffffff81642d85 ffff8802272ef290 > > <4>[77877.520694] 0000000000000000 ffff880131ca1978 ffffffff8104985c ffff880131ca19a0 > > <4>[77877.528218] ffff88020f695aa0 0000000000000000 ffff880214c48b40 ffff88020be55000 > > <4>[77877.535756] Call Trace: > > <4>[77877.538279] [<ffffffff81642d85>] dump_stack+0x46/0x58 > > <4>[77877.543439] [<ffffffff8104985c>] warn_slowpath_common+0x8c/0xc0 > > <4>[77877.549548] [<ffffffff810498aa>] warn_slowpath_null+0x1a/0x20 > > <4>[77877.555413] [<ffffffff8127adb1>] jbd2_journal_dirty_metadata+0x1f1/0x2e0 > > <4>[77877.562288] [<ffffffff812578c3>] __ext4_handle_dirty_metadata+0xa3/0x140 > > <4>[77877.569155] [<ffffffff81268e23>] ext4_xattr_release_block+0x103/0x1f0 > > <4>[77877.575723] [<ffffffff812692b0>] ext4_xattr_block_set+0x1e0/0x910 > > <4>[77877.581990] [<ffffffff8126a58b>] ext4_xattr_set_handle+0x38b/0x4a0 > > <4>[77877.588335] [<ffffffff810af7cd>] ? trace_hardirqs_on+0xd/0x10 > > <4>[77877.594188] [<ffffffff8126a765>] ext4_xattr_set+0xc5/0x140 > > <4>[77877.599837] [<ffffffff8126b177>] ext4_xattr_user_set+0x47/0x50 > > <4>[77877.605779] [<ffffffff811a3fee>] generic_setxattr+0x6e/0x90 > > <4>[77877.611514] [<ffffffff811a48eb>] __vfs_setxattr_noperm+0x7b/0x1c0 > > <4>[77877.617773] [<ffffffff811a4af4>] vfs_setxattr+0xc4/0xd0 > > <4>[77877.623103] [<ffffffff811a4c3e>] setxattr+0x13e/0x1e0 > > <4>[77877.628317] [<ffffffff81181ec7>] ? __sb_start_write+0xe7/0x1b0 > > <4>[77877.634260] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > > <4>[77877.640428] [<ffffffff8119cf0c>] ? fget_light+0x3c/0x130 > > <4>[77877.645847] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > > <4>[77877.652015] [<ffffffff8119e902>] ? mnt_clone_write+0x12/0x30 > > <4>[77877.657897] [<ffffffff811a50de>] SyS_fsetxattr+0xbe/0x100 > > <4>[77877.663405] [<ffffffff81653782>] system_call_fastpath+0x16/0x1b > > <4>[77877.669488] ---[ end trace bb7933908cd5a32a ]--- > I was scratching my head for a while how this could happen but I think I > see the race now. Think we have two inodes A and B which share the same > xattr block (so &BHDR(bh)->h_refcount == 2). Now we are changing xattrs for > both inodes in parallel - that can easily happen because xattr locking is > generally per inode (EXT4_I(inode)->xattr_sem). The following race then > happens: > CPU1 CPU2 > ext4_xattr_release_block() ext4_xattr_release_block() > lock_buffer(bh); > /* False */ > if (BHDR(bh)->h_refcount == cpu_to_le32(1)) > } else { > le32_add_cpu(&BHDR(bh)->h_refcount, -1); > unlock_buffer(bh); > lock_buffer(bh); > /* True */ > if (BHDR(bh)->h_refcount == cpu_to_le32(1)) > get_bh(bh); > ext4_free_blocks() > ... > jbd2_journal_forget() > jbd2_journal_unfile_buffer() > -> JH is gone > error = ext4_handle_dirty_xattr_block(handle, inode, bh); > -> triggers warning > > Now easy fix would be to move ext4_handle_dirty_xattr_block() before > unlock_buffer() but I don't really like that because of locking > constraints. I'll think about it... So finally I've got back to this. Attached is a somewhat ugly patch that should fix this issue. Can you please test it? Thanks! Honza -- Jan Kara <jack@suse.cz> SUSE Labs, CR [-- Attachment #2: 0001-ext4-Fix-jbd2-warning-under-heavy-xattr-load.patch --] [-- Type: text/x-patch, Size: 5425 bytes --] >From f70fdf2341118eddc2ad1d5ef29498097b3630ef Mon Sep 17 00:00:00 2001 From: Jan Kara <jack@suse.cz> Date: Wed, 11 Sep 2013 00:04:25 +0200 Subject: [PATCH] ext4: Fix jbd2 warning under heavy xattr load When heavily exercising xattr code the assertion that jbd2_journal_dirty_metadata() shouldn't return error was triggered: WARNING: at /srv/autobuild-ceph/gitbuilder.git/build/fs/jbd2/transaction.c:1237 jbd2_journal_dirty_metadata+0x1ba/0x260() CPU: 0 PID: 8877 Comm: ceph-osd Tainted: G W 3.10.0-ceph-00049-g68d04c9 #1 Hardware name: Dell Inc. PowerEdge R410/01V648, BIOS 1.6.3 02/07/2011 ffffffff81a1d3c8 ffff880214469928 ffffffff816311b0 ffff880214469968 ffffffff8103fae0 ffff880214469958 ffff880170a9dc30 ffff8802240fbe80 0000000000000000 ffff88020b366000 ffff8802256e7510 ffff880214469978 Call Trace: [<ffffffff816311b0>] dump_stack+0x19/0x1b [<ffffffff8103fae0>] warn_slowpath_common+0x70/0xa0 [<ffffffff8103fb2a>] warn_slowpath_null+0x1a/0x20 [<ffffffff81267c2a>] jbd2_journal_dirty_metadata+0x1ba/0x260 [<ffffffff81245093>] __ext4_handle_dirty_metadata+0xa3/0x140 [<ffffffff812561f3>] ext4_xattr_release_block+0x103/0x1f0 [<ffffffff81256680>] ext4_xattr_block_set+0x1e0/0x910 [<ffffffff8125795b>] ext4_xattr_set_handle+0x38b/0x4a0 [<ffffffff810a319d>] ? trace_hardirqs_on+0xd/0x10 [<ffffffff81257b32>] ext4_xattr_set+0xc2/0x140 [<ffffffff81258547>] ext4_xattr_user_set+0x47/0x50 [<ffffffff811935ce>] generic_setxattr+0x6e/0x90 [<ffffffff81193ecb>] __vfs_setxattr_noperm+0x7b/0x1c0 [<ffffffff811940d4>] vfs_setxattr+0xc4/0xd0 [<ffffffff8119421e>] setxattr+0x13e/0x1e0 [<ffffffff811719c7>] ? __sb_start_write+0xe7/0x1b0 [<ffffffff8118f2e8>] ? mnt_want_write_file+0x28/0x60 [<ffffffff8118c65c>] ? fget_light+0x3c/0x130 [<ffffffff8118f2e8>] ? mnt_want_write_file+0x28/0x60 [<ffffffff8118f1f8>] ? __mnt_want_write+0x58/0x70 [<ffffffff811946be>] SyS_fsetxattr+0xbe/0x100 [<ffffffff816407c2>] system_call_fastpath+0x16/0x1b The reason for the warning is that buffer_head passed into jbd2_journal_dirty_metadata() didn't have journal_head attached. This is caused by the following race of two ext4_xattr_release_block() calls: CPU1 CPU2 ext4_xattr_release_block() ext4_xattr_release_block() lock_buffer(bh); /* False */ if (BHDR(bh)->h_refcount == cpu_to_le32(1)) } else { le32_add_cpu(&BHDR(bh)->h_refcount, -1); unlock_buffer(bh); lock_buffer(bh); /* True */ if (BHDR(bh)->h_refcount == cpu_to_le32(1)) get_bh(bh); ext4_free_blocks() ... jbd2_journal_forget() jbd2_journal_unfile_buffer() -> JH is gone error = ext4_handle_dirty_xattr_block(handle, inode, bh); -> triggers the warning We fix the problem by moving ext4_handle_dirty_xattr_block() under the buffer lock. Sadly this cannot be done in nojournal mode as that function can call sync_dirty_buffer() which would deadlock. Luckily in nojournal mode the race is harmless (we only dirty already freed buffer) and thus for nojournal mode we leave the dirtying outside of the buffer lock. Reported-by: Sage Weil <sage@inktank.com> Signed-off-by: Jan Kara <jack@suse.cz> --- fs/ext4/xattr.c | 23 +++++++++++++++++++---- 1 file changed, 19 insertions(+), 4 deletions(-) diff --git a/fs/ext4/xattr.c b/fs/ext4/xattr.c index c081e34..dc99e17 100644 --- a/fs/ext4/xattr.c +++ b/fs/ext4/xattr.c @@ -517,8 +517,8 @@ static void ext4_xattr_update_super_block(handle_t *handle, } /* - * Release the xattr block BH: If the reference count is > 1, decrement - * it; otherwise free the block. + * Release the xattr block BH: If the reference count is > 1, decrement it; + * otherwise free the block. */ static void ext4_xattr_release_block(handle_t *handle, struct inode *inode, @@ -538,16 +538,31 @@ ext4_xattr_release_block(handle_t *handle, struct inode *inode, if (ce) mb_cache_entry_free(ce); get_bh(bh); + unlock_buffer(bh); ext4_free_blocks(handle, inode, bh, 0, 1, EXT4_FREE_BLOCKS_METADATA | EXT4_FREE_BLOCKS_FORGET); - unlock_buffer(bh); } else { le32_add_cpu(&BHDR(bh)->h_refcount, -1); if (ce) mb_cache_entry_release(ce); + /* + * Beware of this ugliness: Releasing of xattr block references + * from different inodes can race and so we have to protect + * from a race where someone else frees the block (and releases + * its journal_head) before we are done dirtying the buffer. In + * nojournal mode this race is harmless and we actually cannot + * call ext4_handle_dirty_xattr_block() with locked buffer as + * that function can call sync_dirty_buffer() so for that case + * we handle the dirtying after unlocking the buffer. + */ + if (ext4_handle_valid(handle)) + error = ext4_handle_dirty_xattr_block(handle, inode, + bh); unlock_buffer(bh); - error = ext4_handle_dirty_xattr_block(handle, inode, bh); + if (!ext4_handle_valid(handle)) + error = ext4_handle_dirty_xattr_block(handle, inode, + bh); if (IS_SYNC(inode)) ext4_handle_sync(handle); dquot_free_block(inode, EXT4_C2B(EXT4_SB(inode->i_sb), 1)); -- 1.8.1.4 ^ permalink raw reply related [flat|nested] 16+ messages in thread
* Re: crash in __jbd2_journal_file_buffer 2013-09-10 22:19 ` Jan Kara @ 2013-09-10 22:32 ` Sage Weil 2013-11-11 22:20 ` Jan Kara 2014-04-05 19:20 ` Sage Weil 1 sibling, 1 reply; 16+ messages in thread From: Sage Weil @ 2013-09-10 22:32 UTC (permalink / raw) To: Jan Kara; +Cc: linux-ext4 On Wed, 11 Sep 2013, Jan Kara wrote: > On Fri 23-08-13 22:48:10, Jan Kara wrote: > > On Thu 22-08-13 16:35:15, Sage Weil wrote: > > > On Tue, 13 Aug 2013, Jan Kara wrote: > > > > On Mon 12-08-13 11:13:06, Sage Weil wrote: > > > > > Full dmesg is attached. > > > > Hum, nothing interesting in there... > > > > > > > > > Our QA seems to hit this with some regularity. Let me know if there's > > > > > some combination of patches that would help shed more light! > > > > If they can run with attached debug patch it could maybe sched some more > > > > light. Please send also your System.map file together with the dmesg of the > > > > kernel when the crash happens so that I can map addresses to function > > > > names... Thanks! > > > > > > Okay, finally hit it again: > > > > > > <6>[75193.192249] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro,user_xattr,user_xattr > > > <3>[77877.426658] Dirtying buffer without jh at 4302720297: state 218c029,jh added from 0xffffffff8127ab1d at 4302720297, removed from 0xffffffff8127b5b0 at 4302720296 > > > <4>[77877.441200] ------------[ cut here ]------------ > > > <4>[77877.445845] WARNING: CPU: 7 PID: 26045 at /srv/autobuild-ceph/gitbuilder.git/build/fs/jbd2/transaction.c:1380 jbd2_journal_dirty_metadata+0x1f1/0x2e0() > > > > > > <4>[77877.497349] CPU: 7 PID: 26045 Comm: ceph-osd Not tainted 3.11.0-rc5-ceph-00061-g546140d #1 > > > <4>[77877.505649] Hardware name: Dell Inc. PowerEdge R410/01V648, BIOS 1.6.3 02/07/2011 > > > <4>[77877.513213] 0000000000000564 ffff880131ca1938 ffffffff81642d85 ffff8802272ef290 > > > <4>[77877.520694] 0000000000000000 ffff880131ca1978 ffffffff8104985c ffff880131ca19a0 > > > <4>[77877.528218] ffff88020f695aa0 0000000000000000 ffff880214c48b40 ffff88020be55000 > > > <4>[77877.535756] Call Trace: > > > <4>[77877.538279] [<ffffffff81642d85>] dump_stack+0x46/0x58 > > > <4>[77877.543439] [<ffffffff8104985c>] warn_slowpath_common+0x8c/0xc0 > > > <4>[77877.549548] [<ffffffff810498aa>] warn_slowpath_null+0x1a/0x20 > > > <4>[77877.555413] [<ffffffff8127adb1>] jbd2_journal_dirty_metadata+0x1f1/0x2e0 > > > <4>[77877.562288] [<ffffffff812578c3>] __ext4_handle_dirty_metadata+0xa3/0x140 > > > <4>[77877.569155] [<ffffffff81268e23>] ext4_xattr_release_block+0x103/0x1f0 > > > <4>[77877.575723] [<ffffffff812692b0>] ext4_xattr_block_set+0x1e0/0x910 > > > <4>[77877.581990] [<ffffffff8126a58b>] ext4_xattr_set_handle+0x38b/0x4a0 > > > <4>[77877.588335] [<ffffffff810af7cd>] ? trace_hardirqs_on+0xd/0x10 > > > <4>[77877.594188] [<ffffffff8126a765>] ext4_xattr_set+0xc5/0x140 > > > <4>[77877.599837] [<ffffffff8126b177>] ext4_xattr_user_set+0x47/0x50 > > > <4>[77877.605779] [<ffffffff811a3fee>] generic_setxattr+0x6e/0x90 > > > <4>[77877.611514] [<ffffffff811a48eb>] __vfs_setxattr_noperm+0x7b/0x1c0 > > > <4>[77877.617773] [<ffffffff811a4af4>] vfs_setxattr+0xc4/0xd0 > > > <4>[77877.623103] [<ffffffff811a4c3e>] setxattr+0x13e/0x1e0 > > > <4>[77877.628317] [<ffffffff81181ec7>] ? __sb_start_write+0xe7/0x1b0 > > > <4>[77877.634260] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > > > <4>[77877.640428] [<ffffffff8119cf0c>] ? fget_light+0x3c/0x130 > > > <4>[77877.645847] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > > > <4>[77877.652015] [<ffffffff8119e902>] ? mnt_clone_write+0x12/0x30 > > > <4>[77877.657897] [<ffffffff811a50de>] SyS_fsetxattr+0xbe/0x100 > > > <4>[77877.663405] [<ffffffff81653782>] system_call_fastpath+0x16/0x1b > > > <4>[77877.669488] ---[ end trace bb7933908cd5a32a ]--- > > I was scratching my head for a while how this could happen but I think I > > see the race now. Think we have two inodes A and B which share the same > > xattr block (so &BHDR(bh)->h_refcount == 2). Now we are changing xattrs for > > both inodes in parallel - that can easily happen because xattr locking is > > generally per inode (EXT4_I(inode)->xattr_sem). The following race then > > happens: > > CPU1 CPU2 > > ext4_xattr_release_block() ext4_xattr_release_block() > > lock_buffer(bh); > > /* False */ > > if (BHDR(bh)->h_refcount == cpu_to_le32(1)) > > } else { > > le32_add_cpu(&BHDR(bh)->h_refcount, -1); > > unlock_buffer(bh); > > lock_buffer(bh); > > /* True */ > > if (BHDR(bh)->h_refcount == cpu_to_le32(1)) > > get_bh(bh); > > ext4_free_blocks() > > ... > > jbd2_journal_forget() > > jbd2_journal_unfile_buffer() > > -> JH is gone > > error = ext4_handle_dirty_xattr_block(handle, inode, bh); > > -> triggers warning > > > > Now easy fix would be to move ext4_handle_dirty_xattr_block() before > > unlock_buffer() but I don't really like that because of locking > > constraints. I'll think about it... > So finally I've got back to this. Attached is a somewhat ugly patch that > should fix this issue. Can you please test it? Thanks! Sure; added it to our test tree. I haven't seen this in a week probably, so it'll be hard to definitively say it's fixed, but it'll get plenty of testing. :) Thanks! sage ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: crash in __jbd2_journal_file_buffer 2013-09-10 22:32 ` Sage Weil @ 2013-11-11 22:20 ` Jan Kara 0 siblings, 0 replies; 16+ messages in thread From: Jan Kara @ 2013-11-11 22:20 UTC (permalink / raw) To: Sage Weil; +Cc: Jan Kara, linux-ext4 On Tue 10-09-13 15:32:47, Sage Weil wrote: > On Wed, 11 Sep 2013, Jan Kara wrote: > > On Fri 23-08-13 22:48:10, Jan Kara wrote: > > > On Thu 22-08-13 16:35:15, Sage Weil wrote: > > > > On Tue, 13 Aug 2013, Jan Kara wrote: > > > > > On Mon 12-08-13 11:13:06, Sage Weil wrote: > > > > > > Full dmesg is attached. > > > > > Hum, nothing interesting in there... > > > > > > > > > > > Our QA seems to hit this with some regularity. Let me know if there's > > > > > > some combination of patches that would help shed more light! > > > > > If they can run with attached debug patch it could maybe sched some more > > > > > light. Please send also your System.map file together with the dmesg of the > > > > > kernel when the crash happens so that I can map addresses to function > > > > > names... Thanks! > > > > > > > > Okay, finally hit it again: > > > > > > > > <6>[75193.192249] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro,user_xattr,user_xattr > > > > <3>[77877.426658] Dirtying buffer without jh at 4302720297: state 218c029,jh added from 0xffffffff8127ab1d at 4302720297, removed from 0xffffffff8127b5b0 at 4302720296 > > > > <4>[77877.441200] ------------[ cut here ]------------ > > > > <4>[77877.445845] WARNING: CPU: 7 PID: 26045 at /srv/autobuild-ceph/gitbuilder.git/build/fs/jbd2/transaction.c:1380 jbd2_journal_dirty_metadata+0x1f1/0x2e0() > > > > > > > > <4>[77877.497349] CPU: 7 PID: 26045 Comm: ceph-osd Not tainted 3.11.0-rc5-ceph-00061-g546140d #1 > > > > <4>[77877.505649] Hardware name: Dell Inc. PowerEdge R410/01V648, BIOS 1.6.3 02/07/2011 > > > > <4>[77877.513213] 0000000000000564 ffff880131ca1938 ffffffff81642d85 ffff8802272ef290 > > > > <4>[77877.520694] 0000000000000000 ffff880131ca1978 ffffffff8104985c ffff880131ca19a0 > > > > <4>[77877.528218] ffff88020f695aa0 0000000000000000 ffff880214c48b40 ffff88020be55000 > > > > <4>[77877.535756] Call Trace: > > > > <4>[77877.538279] [<ffffffff81642d85>] dump_stack+0x46/0x58 > > > > <4>[77877.543439] [<ffffffff8104985c>] warn_slowpath_common+0x8c/0xc0 > > > > <4>[77877.549548] [<ffffffff810498aa>] warn_slowpath_null+0x1a/0x20 > > > > <4>[77877.555413] [<ffffffff8127adb1>] jbd2_journal_dirty_metadata+0x1f1/0x2e0 > > > > <4>[77877.562288] [<ffffffff812578c3>] __ext4_handle_dirty_metadata+0xa3/0x140 > > > > <4>[77877.569155] [<ffffffff81268e23>] ext4_xattr_release_block+0x103/0x1f0 > > > > <4>[77877.575723] [<ffffffff812692b0>] ext4_xattr_block_set+0x1e0/0x910 > > > > <4>[77877.581990] [<ffffffff8126a58b>] ext4_xattr_set_handle+0x38b/0x4a0 > > > > <4>[77877.588335] [<ffffffff810af7cd>] ? trace_hardirqs_on+0xd/0x10 > > > > <4>[77877.594188] [<ffffffff8126a765>] ext4_xattr_set+0xc5/0x140 > > > > <4>[77877.599837] [<ffffffff8126b177>] ext4_xattr_user_set+0x47/0x50 > > > > <4>[77877.605779] [<ffffffff811a3fee>] generic_setxattr+0x6e/0x90 > > > > <4>[77877.611514] [<ffffffff811a48eb>] __vfs_setxattr_noperm+0x7b/0x1c0 > > > > <4>[77877.617773] [<ffffffff811a4af4>] vfs_setxattr+0xc4/0xd0 > > > > <4>[77877.623103] [<ffffffff811a4c3e>] setxattr+0x13e/0x1e0 > > > > <4>[77877.628317] [<ffffffff81181ec7>] ? __sb_start_write+0xe7/0x1b0 > > > > <4>[77877.634260] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > > > > <4>[77877.640428] [<ffffffff8119cf0c>] ? fget_light+0x3c/0x130 > > > > <4>[77877.645847] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > > > > <4>[77877.652015] [<ffffffff8119e902>] ? mnt_clone_write+0x12/0x30 > > > > <4>[77877.657897] [<ffffffff811a50de>] SyS_fsetxattr+0xbe/0x100 > > > > <4>[77877.663405] [<ffffffff81653782>] system_call_fastpath+0x16/0x1b > > > > <4>[77877.669488] ---[ end trace bb7933908cd5a32a ]--- > > > I was scratching my head for a while how this could happen but I think I > > > see the race now. Think we have two inodes A and B which share the same > > > xattr block (so &BHDR(bh)->h_refcount == 2). Now we are changing xattrs for > > > both inodes in parallel - that can easily happen because xattr locking is > > > generally per inode (EXT4_I(inode)->xattr_sem). The following race then > > > happens: > > > CPU1 CPU2 > > > ext4_xattr_release_block() ext4_xattr_release_block() > > > lock_buffer(bh); > > > /* False */ > > > if (BHDR(bh)->h_refcount == cpu_to_le32(1)) > > > } else { > > > le32_add_cpu(&BHDR(bh)->h_refcount, -1); > > > unlock_buffer(bh); > > > lock_buffer(bh); > > > /* True */ > > > if (BHDR(bh)->h_refcount == cpu_to_le32(1)) > > > get_bh(bh); > > > ext4_free_blocks() > > > ... > > > jbd2_journal_forget() > > > jbd2_journal_unfile_buffer() > > > -> JH is gone > > > error = ext4_handle_dirty_xattr_block(handle, inode, bh); > > > -> triggers warning > > > > > > Now easy fix would be to move ext4_handle_dirty_xattr_block() before > > > unlock_buffer() but I don't really like that because of locking > > > constraints. I'll think about it... > > So finally I've got back to this. Attached is a somewhat ugly patch that > > should fix this issue. Can you please test it? Thanks! > > Sure; added it to our test tree. I haven't seen this in a week probably, > so it'll be hard to definitively say it's fixed, but it'll get plenty of > testing. :) Any luck with testing? It has been two months so if the bug didn't reappear I'd hope it really got fixed... Honza -- Jan Kara <jack@suse.cz> SUSE Labs, CR ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: crash in __jbd2_journal_file_buffer 2013-09-10 22:19 ` Jan Kara 2013-09-10 22:32 ` Sage Weil @ 2014-04-05 19:20 ` Sage Weil 1 sibling, 0 replies; 16+ messages in thread From: Sage Weil @ 2014-04-05 19:20 UTC (permalink / raw) To: Jan Kara; +Cc: linux-ext4, ceph-devel Hi Jan, Thanks for reminding me about this at LSF. Both your debug patch and this fix were dropped from our testing branch a while ago, but we just hit the crash again yesterday on 3.14-rc5. The fix was in our tree for quite some time, though, and did not cause any problems; I think it got dropped when we rebased for the 3.14 cycle. I'll add it back now. Unfortunately this triggers pretty infrequently so I'm not sure I can give a definitive "this fixes it," but it feels that way, and we haven't seen any fallout as a result. Let me know if there's anything else we can put into the test kernel that might help out. Thanks! sage On Wed, 11 Sep 2013, Jan Kara wrote: > On Fri 23-08-13 22:48:10, Jan Kara wrote: > > On Thu 22-08-13 16:35:15, Sage Weil wrote: > > > On Tue, 13 Aug 2013, Jan Kara wrote: > > > > On Mon 12-08-13 11:13:06, Sage Weil wrote: > > > > > Full dmesg is attached. > > > > Hum, nothing interesting in there... > > > > > > > > > Our QA seems to hit this with some regularity. Let me know if there's > > > > > some combination of patches that would help shed more light! > > > > If they can run with attached debug patch it could maybe sched some more > > > > light. Please send also your System.map file together with the dmesg of the > > > > kernel when the crash happens so that I can map addresses to function > > > > names... Thanks! > > > > > > Okay, finally hit it again: > > > > > > <6>[75193.192249] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro,user_xattr,user_xattr > > > <3>[77877.426658] Dirtying buffer without jh at 4302720297: state 218c029,jh added from 0xffffffff8127ab1d at 4302720297, removed from 0xffffffff8127b5b0 at 4302720296 > > > <4>[77877.441200] ------------[ cut here ]------------ > > > <4>[77877.445845] WARNING: CPU: 7 PID: 26045 at /srv/autobuild-ceph/gitbuilder.git/build/fs/jbd2/transaction.c:1380 jbd2_journal_dirty_metadata+0x1f1/0x2e0() > > > > > > <4>[77877.497349] CPU: 7 PID: 26045 Comm: ceph-osd Not tainted 3.11.0-rc5-ceph-00061-g546140d #1 > > > <4>[77877.505649] Hardware name: Dell Inc. PowerEdge R410/01V648, BIOS 1.6.3 02/07/2011 > > > <4>[77877.513213] 0000000000000564 ffff880131ca1938 ffffffff81642d85 ffff8802272ef290 > > > <4>[77877.520694] 0000000000000000 ffff880131ca1978 ffffffff8104985c ffff880131ca19a0 > > > <4>[77877.528218] ffff88020f695aa0 0000000000000000 ffff880214c48b40 ffff88020be55000 > > > <4>[77877.535756] Call Trace: > > > <4>[77877.538279] [<ffffffff81642d85>] dump_stack+0x46/0x58 > > > <4>[77877.543439] [<ffffffff8104985c>] warn_slowpath_common+0x8c/0xc0 > > > <4>[77877.549548] [<ffffffff810498aa>] warn_slowpath_null+0x1a/0x20 > > > <4>[77877.555413] [<ffffffff8127adb1>] jbd2_journal_dirty_metadata+0x1f1/0x2e0 > > > <4>[77877.562288] [<ffffffff812578c3>] __ext4_handle_dirty_metadata+0xa3/0x140 > > > <4>[77877.569155] [<ffffffff81268e23>] ext4_xattr_release_block+0x103/0x1f0 > > > <4>[77877.575723] [<ffffffff812692b0>] ext4_xattr_block_set+0x1e0/0x910 > > > <4>[77877.581990] [<ffffffff8126a58b>] ext4_xattr_set_handle+0x38b/0x4a0 > > > <4>[77877.588335] [<ffffffff810af7cd>] ? trace_hardirqs_on+0xd/0x10 > > > <4>[77877.594188] [<ffffffff8126a765>] ext4_xattr_set+0xc5/0x140 > > > <4>[77877.599837] [<ffffffff8126b177>] ext4_xattr_user_set+0x47/0x50 > > > <4>[77877.605779] [<ffffffff811a3fee>] generic_setxattr+0x6e/0x90 > > > <4>[77877.611514] [<ffffffff811a48eb>] __vfs_setxattr_noperm+0x7b/0x1c0 > > > <4>[77877.617773] [<ffffffff811a4af4>] vfs_setxattr+0xc4/0xd0 > > > <4>[77877.623103] [<ffffffff811a4c3e>] setxattr+0x13e/0x1e0 > > > <4>[77877.628317] [<ffffffff81181ec7>] ? __sb_start_write+0xe7/0x1b0 > > > <4>[77877.634260] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > > > <4>[77877.640428] [<ffffffff8119cf0c>] ? fget_light+0x3c/0x130 > > > <4>[77877.645847] [<ffffffff8119fb98>] ? mnt_want_write_file+0x28/0x60 > > > <4>[77877.652015] [<ffffffff8119e902>] ? mnt_clone_write+0x12/0x30 > > > <4>[77877.657897] [<ffffffff811a50de>] SyS_fsetxattr+0xbe/0x100 > > > <4>[77877.663405] [<ffffffff81653782>] system_call_fastpath+0x16/0x1b > > > <4>[77877.669488] ---[ end trace bb7933908cd5a32a ]--- > > I was scratching my head for a while how this could happen but I think I > > see the race now. Think we have two inodes A and B which share the same > > xattr block (so &BHDR(bh)->h_refcount == 2). Now we are changing xattrs for > > both inodes in parallel - that can easily happen because xattr locking is > > generally per inode (EXT4_I(inode)->xattr_sem). The following race then > > happens: > > CPU1 CPU2 > > ext4_xattr_release_block() ext4_xattr_release_block() > > lock_buffer(bh); > > /* False */ > > if (BHDR(bh)->h_refcount == cpu_to_le32(1)) > > } else { > > le32_add_cpu(&BHDR(bh)->h_refcount, -1); > > unlock_buffer(bh); > > lock_buffer(bh); > > /* True */ > > if (BHDR(bh)->h_refcount == cpu_to_le32(1)) > > get_bh(bh); > > ext4_free_blocks() > > ... > > jbd2_journal_forget() > > jbd2_journal_unfile_buffer() > > -> JH is gone > > error = ext4_handle_dirty_xattr_block(handle, inode, bh); > > -> triggers warning > > > > Now easy fix would be to move ext4_handle_dirty_xattr_block() before > > unlock_buffer() but I don't really like that because of locking > > constraints. I'll think about it... > So finally I've got back to this. Attached is a somewhat ugly patch that > should fix this issue. Can you please test it? Thanks! > > Honza > -- > Jan Kara <jack@suse.cz> > SUSE Labs, CR > ^ permalink raw reply [flat|nested] 16+ messages in thread
end of thread, other threads:[~2014-04-05 19:20 UTC | newest]
Thread overview: 16+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2013-07-30 22:41 crash in __jbd2_journal_file_buffer Sage Weil
2013-07-31 19:02 ` Jan Kara
2013-08-09 17:36 ` Sage Weil
2013-08-09 21:24 ` Jan Kara
2013-08-09 22:11 ` Sage Weil
2013-08-12 12:52 ` Jan Kara
[not found] ` <alpine.DEB.2.00.1308121106320.29150@cobra.newdream.net>
2013-08-13 10:34 ` Jan Kara
2013-08-22 23:35 ` Sage Weil
2013-08-23 9:54 ` Jan Kara
2013-08-23 15:02 ` Sage Weil
2013-08-23 19:52 ` Jan Kara
2013-08-23 20:48 ` Jan Kara
2013-09-10 22:19 ` Jan Kara
2013-09-10 22:32 ` Sage Weil
2013-11-11 22:20 ` Jan Kara
2014-04-05 19:20 ` Sage Weil
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.