Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1498974 > unrolled thread
| Started by | Dave Jones <davej@codemonkey.org.uk> |
|---|---|
| First post | 2016-10-11 17:30 +0200 |
| Last post | 2016-10-20 09:30 +0200 |
| Articles | 20 on this page of 50 — 7 participants |
Back to article view | Back to linux.kernel
btrfs bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-11 17:30 +0200
Re: btrfs bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-11 18:30 +0200
Re: btrfs bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-12 15:50 +0200
Re: btrfs bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-12 16:50 +0200
Re: btrfs bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-13 20:20 +0200
Re: btrfs bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-14 00:30 +0200
Re: btrfs bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-16 02:50 +0200
Re: bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-19 00:50 +0200
Re: bio linked list corruption. Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-19 01:40 +0200
Re: bio linked list corruption. Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-19 02:20 +0200
Re: bio linked list corruption. Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-19 02:30 +0200
Re: bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-21 00:50 +0200
Re: bio linked list corruption. Andy Lutomirski <luto@kernel.org> - 2016-10-19 03:10 +0200
Re: bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-21 01:00 +0200
Re: bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-21 01:10 +0200
Re: bio linked list corruption. Andy Lutomirski <luto@amacapital.net> - 2016-10-21 01:30 +0200
Re: bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-21 22:10 +0200
Re: bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-21 22:30 +0200
Re: bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-21 23:20 +0200
Re: bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-22 17:30 +0200
Re: bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-24 06:50 +0200
Re: bio linked list corruption. Andy Lutomirski <luto@amacapital.net> - 2016-10-24 22:10 +0200
Re: bio linked list corruption. Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-24 22:50 +0200
Re: bio linked list corruption. Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-24 23:20 +0200
Re: bio linked list corruption. Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-25 00:00 +0200
Re: bio linked list corruption. Andy Lutomirski <luto@amacapital.net> - 2016-10-25 00:50 +0200
Re: bio linked list corruption. Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-25 02:10 +0200
Re: bio linked list corruption. Andy Lutomirski <luto@amacapital.net> - 2016-10-25 03:20 +0200
Re: bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-26 02:30 +0200
Re: bio linked list corruption. Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-26 03:40 +0200
Re: bio linked list corruption. Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-26 03:40 +0200
Re: bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-26 18:40 +0200
Re: bio linked list corruption. Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-26 18:50 +0200
Re: bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-26 20:20 +0200
Re: bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-26 20:50 +0200
Re: bio linked list corruption. Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-26 21:10 +0200
Re: bio linked list corruption. Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-27 00:10 +0200
Re: bio linked list corruption. Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-27 00:30 +0200
Re: bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-27 00:50 +0200
Re: bio linked list corruption. Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-27 01:00 +0200
Re: bio linked list corruption. Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-27 01:00 +0200
Re: bio linked list corruption. Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-27 01:10 +0200
Re: bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-27 01:50 +0200
Re: bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-27 01:10 +0200
Re: bio linked list corruption. Dave Jones <davej@codemonkey.org.uk> - 2016-10-27 01:10 +0200
Re: bio linked list corruption. Andy Lutomirski <luto@amacapital.net> - 2016-10-21 01:10 +0200
Re: bio linked list corruption. Philipp Hahn <pmhahn@pmhahn.de> - 2016-10-19 19:10 +0200
Re: bio linked list corruption. Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-19 19:50 +0200
Re: bio linked list corruption. Ingo Molnar <mingo@kernel.org> - 2016-10-20 09:00 +0200
Re: bio linked list corruption. Thomas Gleixner <tglx@linutronix.de> - 2016-10-20 09:30 +0200
Page 1 of 3 [1] 2 3 Next page →
| From | Dave Jones <davej@codemonkey.org.uk> |
|---|---|
| Date | 2016-10-11 17:30 +0200 |
| Subject | btrfs bio linked list corruption. |
| Message-ID | <sr70t-8n0-5@gated-at.bofh.it> |
This is from Linus' current tree, with Al's iovec fixups on top. ------------[ cut here ]------------ WARNING: CPU: 1 PID: 3673 at lib/list_debug.c:33 __list_add+0x89/0xb0 list_add corruption. prev->next should be next (ffffe8ffff806648), but was ffffc9000067fcd8. (prev=ffff880503878b80). CPU: 1 PID: 3673 Comm: trinity-c0 Not tainted 4.8.0-think+ #13 ffffc90000d87458 ffffffff8d32007c ffffc90000d874a8 0000000000000000 ffffc90000d87498 ffffffff8d07a6c1 0000002100000246 ffff88050388e880 ffff880503878b80 ffffe8ffff806648 ffffe8ffffc06600 ffff880502808008 Call Trace: [<ffffffff8d32007c>] dump_stack+0x4f/0x73 [<ffffffff8d07a6c1>] __warn+0xc1/0xe0 [<ffffffff8d07a73a>] warn_slowpath_fmt+0x5a/0x80 [<ffffffff8d33e689>] __list_add+0x89/0xb0 [<ffffffff8d30a1c8>] blk_sq_make_request+0x2f8/0x350 [<ffffffff8d2fd9cc>] ? generic_make_request+0xec/0x240 [<ffffffff8d2fd9d9>] generic_make_request+0xf9/0x240 [<ffffffff8d2fdb98>] submit_bio+0x78/0x150 [<ffffffff8d349c05>] ? __percpu_counter_add+0x85/0xb0 [<ffffffffc03627de>] btrfs_map_bio+0x19e/0x330 [btrfs] [<ffffffffc03289ca>] btree_submit_bio_hook+0xfa/0x110 [btrfs] [<ffffffffc034ff15>] submit_one_bio+0x65/0xa0 [btrfs] [<ffffffffc0358cb0>] read_extent_buffer_pages+0x2f0/0x3d0 [btrfs] [<ffffffffc0327020>] ? free_root_pointers+0x60/0x60 [btrfs] [<ffffffffc03283c8>] btree_read_extent_buffer_pages.constprop.55+0xa8/0x110 [btrfs] [<ffffffffc0328bcd>] read_tree_block+0x2d/0x50 [btrfs] [<ffffffffc03080a4>] read_block_for_search.isra.33+0x134/0x330 [btrfs] [<ffffffff8d7c2d6c>] ? _raw_write_unlock+0x2c/0x50 [<ffffffffc0302fec>] ? unlock_up+0x16c/0x1a0 [btrfs] [<ffffffffc030a3d0>] btrfs_search_slot+0x450/0xa40 [btrfs] [<ffffffffc0324983>] btrfs_del_csums+0xe3/0x2e0 [btrfs] [<ffffffffc03134fd>] __btrfs_free_extent.isra.82+0x32d/0xc90 [btrfs] [<ffffffffc03178b3>] __btrfs_run_delayed_refs+0x4d3/0x1010 [btrfs] [<ffffffff8d33e5d7>] ? debug_smp_processor_id+0x17/0x20 [<ffffffff8d0c6109>] ? get_lock_stats+0x19/0x50 [<ffffffffc031b32c>] btrfs_run_delayed_refs+0x9c/0x2d0 [btrfs] [<ffffffffc033d628>] btrfs_truncate_inode_items+0x888/0xda0 [btrfs] [<ffffffffc033dc25>] btrfs_truncate+0xe5/0x2b0 [btrfs] [<ffffffffc033e569>] btrfs_setattr+0x249/0x360 [btrfs] [<ffffffff8d1f4092>] notify_change+0x252/0x440 [<ffffffff8d1d164e>] do_truncate+0x6e/0xc0 [<ffffffff8d1d1a4c>] do_sys_ftruncate.constprop.19+0x10c/0x170 [<ffffffff8d33e5f3>] ? __this_cpu_preempt_check+0x13/0x20 [<ffffffff8d1d1ad9>] SyS_ftruncate+0x9/0x10 [<ffffffff8d00259c>] do_syscall_64+0x5c/0x170 [<ffffffff8d7c2f8b>] entry_SYSCALL64_slow_path+0x25/0x25 --[ end trace 906673a2f703b373 ]---
[toc] | [next] | [standalone]
| From | Dave Jones <davej@codemonkey.org.uk> |
|---|---|
| Date | 2016-10-11 18:30 +0200 |
| Message-ID | <sr86d-wM-11@gated-at.bofh.it> |
| In reply to | #1498974 |
On Tue, Oct 11, 2016 at 11:54:09AM -0400, Chris Mason wrote:
>
>
> On 10/11/2016 10:45 AM, Dave Jones wrote:
> > This is from Linus' current tree, with Al's iovec fixups on top.
> >
> > ------------[ cut here ]------------
> > WARNING: CPU: 1 PID: 3673 at lib/list_debug.c:33 __list_add+0x89/0xb0
> > list_add corruption. prev->next should be next (ffffe8ffff806648), but was ffffc9000067fcd8. (prev=ffff880503878b80).
> > CPU: 1 PID: 3673 Comm: trinity-c0 Not tainted 4.8.0-think+ #13
> > ffffc90000d87458 ffffffff8d32007c ffffc90000d874a8 0000000000000000
> > ffffc90000d87498 ffffffff8d07a6c1 0000002100000246 ffff88050388e880
> > ffff880503878b80 ffffe8ffff806648 ffffe8ffffc06600 ffff880502808008
> > Call Trace:
> > [<ffffffff8d32007c>] dump_stack+0x4f/0x73
> > [<ffffffff8d07a6c1>] __warn+0xc1/0xe0
> > [<ffffffff8d07a73a>] warn_slowpath_fmt+0x5a/0x80
> > [<ffffffff8d33e689>] __list_add+0x89/0xb0
> > [<ffffffff8d30a1c8>] blk_sq_make_request+0x2f8/0x350
>
> /*
> * A task plug currently exists. Since this is completely lockless,
> * utilize that to temporarily store requests until the task is
> * either done or scheduled away.
> */
> plug = current->plug;
> if (plug) {
> blk_mq_bio_to_request(rq, bio);
> if (!request_count)
> trace_block_plug(q);
>
> blk_mq_put_ctx(data.ctx);
>
> if (request_count >= BLK_MAX_REQUEST_COUNT) {
> blk_flush_plug_list(plug, false);
> trace_block_plug(q);
> }
>
> list_add_tail(&rq->queuelist, &plug->mq_list);
> ^^^^^^^^^^^^^^^^^^^^^^
>
> Dave, is this where we're crashing? This seems strange.
According to objdump -S ..
ffffffff8130a1b7: 48 8b 70 50 mov 0x50(%rax),%rsi
list_add_tail(&rq->queuelist, &ctx->rq_list);
ffffffff8130a1bb: 48 8d 50 48 lea 0x48(%rax),%rdx
ffffffff8130a1bf: 48 89 45 a8 mov %rax,-0x58(%rbp)
ffffffff8130a1c3: e8 38 44 03 00 callq ffffffff8133e600 <__list_add>
blk_mq_hctx_mark_pending(hctx, ctx);
ffffffff8130a1c8: 48 8b 45 a8 mov -0x58(%rbp),%rax
ffffffff8130a1cc: 4c 89 ff mov %r15,%rdi
That looks like the list_add_tail from __blk_mq_insert_req_list
Dave
[toc] | [prev] | [next] | [standalone]
| From | Dave Jones <davej@codemonkey.org.uk> |
|---|---|
| Date | 2016-10-12 15:50 +0200 |
| Message-ID | <srs4V-56s-3@gated-at.bofh.it> |
| In reply to | #1498974 |
On Tue, Oct 11, 2016 at 11:54:09AM -0400, Chris Mason wrote: > > > On 10/11/2016 10:45 AM, Dave Jones wrote: > > This is from Linus' current tree, with Al's iovec fixups on top. > > > > ------------[ cut here ]------------ > > WARNING: CPU: 1 PID: 3673 at lib/list_debug.c:33 __list_add+0x89/0xb0 > > list_add corruption. prev->next should be next (ffffe8ffff806648), but was ffffc9000067fcd8. (prev=ffff880503878b80). > > CPU: 1 PID: 3673 Comm: trinity-c0 Not tainted 4.8.0-think+ #13 > > ffffc90000d87458 ffffffff8d32007c ffffc90000d874a8 0000000000000000 > > ffffc90000d87498 ffffffff8d07a6c1 0000002100000246 ffff88050388e880 I hit this again overnight, it's the same trace, the only difference being slightly different addresses in the list pointers: [42572.777196] list_add corruption. prev->next should be next (ffffe8ffff806648), but was ffffc90000647cd8. (prev=ffff880503a0ba00). I'm actually a little surprised that ->next was the same across two reboots on two different kernel builds. That might be a sign this is more repeatable than I'd thought, even if it does take hours of runtime right now to trigger it. I'll try and narrow the scope of what trinity is doing to see if I can make it happen faster. Dave
[toc] | [prev] | [next] | [standalone]
| From | Dave Jones <davej@codemonkey.org.uk> |
|---|---|
| Date | 2016-10-12 16:50 +0200 |
| Message-ID | <srt10-5LT-21@gated-at.bofh.it> |
| In reply to | #1499705 |
On Wed, Oct 12, 2016 at 09:47:17AM -0400, Dave Jones wrote: > On Tue, Oct 11, 2016 at 11:54:09AM -0400, Chris Mason wrote: > > > > > > On 10/11/2016 10:45 AM, Dave Jones wrote: > > > This is from Linus' current tree, with Al's iovec fixups on top. > > > > > > ------------[ cut here ]------------ > > > WARNING: CPU: 1 PID: 3673 at lib/list_debug.c:33 __list_add+0x89/0xb0 > > > list_add corruption. prev->next should be next (ffffe8ffff806648), but was ffffc9000067fcd8. (prev=ffff880503878b80). > > > CPU: 1 PID: 3673 Comm: trinity-c0 Not tainted 4.8.0-think+ #13 > > > ffffc90000d87458 ffffffff8d32007c ffffc90000d874a8 0000000000000000 > > > ffffc90000d87498 ffffffff8d07a6c1 0000002100000246 ffff88050388e880 > > I hit this again overnight, it's the same trace, the only difference > being slightly different addresses in the list pointers: > > [42572.777196] list_add corruption. prev->next should be next (ffffe8ffff806648), but was ffffc90000647cd8. (prev=ffff880503a0ba00). > > I'm actually a little surprised that ->next was the same across two > reboots on two different kernel builds. That might be a sign this is > more repeatable than I'd thought, even if it does take hours of runtime > right now to trigger it. I'll try and narrow the scope of what trinity > is doing to see if I can make it happen faster. .. and of course the first thing that happens is a completely different btrfs trace.. WARNING: CPU: 1 PID: 21706 at fs/btrfs/transaction.c:489 start_transaction+0x40a/0x440 [btrfs] CPU: 1 PID: 21706 Comm: trinity-c16 Not tainted 4.8.0-think+ #14 ffffc900019076a8 ffffffffb731ff3c 0000000000000000 0000000000000000 ffffc900019076e8 ffffffffb707a6c1 000001e9f5806ce0 ffff8804f74c4d98 0000000000000801 ffff880501cfa2a8 000000000000008a 000000000000008a Call Trace: [<ffffffffb731ff3c>] dump_stack+0x4f/0x73 [<ffffffffb707a6c1>] __warn+0xc1/0xe0 [<ffffffffb707a7e8>] warn_slowpath_null+0x18/0x20 [<ffffffffc01d312a>] start_transaction+0x40a/0x440 [btrfs] [<ffffffffc01a6215>] ? btrfs_alloc_path+0x15/0x20 [btrfs] [<ffffffffc01d31b2>] btrfs_join_transaction+0x12/0x20 [btrfs] [<ffffffffc01d92cf>] cow_file_range_inline+0xef/0x830 [btrfs] [<ffffffffc01d9d75>] cow_file_range.isra.64+0x365/0x480 [btrfs] [<ffffffffb77c24cc>] ? _raw_spin_unlock+0x2c/0x50 [<ffffffffc01f229f>] ? release_extent_buffer+0x9f/0x110 [btrfs] [<ffffffffc01da299>] run_delalloc_nocow+0x409/0xbd0 [btrfs] [<ffffffffb70c6109>] ? get_lock_stats+0x19/0x50 [<ffffffffc01dadea>] run_delalloc_range+0x38a/0x3e0 [btrfs] [<ffffffffc01f4aba>] writepage_delalloc.isra.47+0x10a/0x190 [btrfs] [<ffffffffc01f7678>] __extent_writepage+0xd8/0x2c0 [btrfs] [<ffffffffc01f7b2e>] extent_write_cache_pages.isra.44.constprop.63+0x2ce/0x430 [btrfs] [<ffffffffb733e497>] ? debug_smp_processor_id+0x17/0x20 [<ffffffffb70c6109>] ? get_lock_stats+0x19/0x50 [<ffffffffc01f8278>] extent_writepages+0x58/0x80 [btrfs] [<ffffffffc01d7a80>] ? btrfs_releasepage+0x40/0x40 [btrfs] [<ffffffffc01d4a63>] btrfs_writepages+0x23/0x30 [btrfs] [<ffffffffb7162e9c>] do_writepages+0x1c/0x30 [<ffffffffb71550f1>] __filemap_fdatawrite_range+0xc1/0x100 [<ffffffffb71551ee>] filemap_fdatawrite_range+0xe/0x10 [<ffffffffc01eb2fb>] btrfs_fdatawrite_range+0x1b/0x50 [btrfs] [<ffffffffc01f0820>] btrfs_wait_ordered_range+0x40/0x100 [btrfs] [<ffffffffc01eb5d5>] btrfs_sync_file+0x285/0x390 [btrfs] [<ffffffffb7207626>] vfs_fsync_range+0x46/0xa0 [<ffffffffb72076d8>] do_fsync+0x38/0x60 [<ffffffffb720795b>] SyS_fsync+0xb/0x10 [<ffffffffb700259c>] do_syscall_64+0x5c/0x170 [<ffffffffb77c2e4b>] entry_SYSCALL64_slow_path+0x25/0x25
[toc] | [prev] | [next] | [standalone]
| From | Dave Jones <davej@codemonkey.org.uk> |
|---|---|
| Date | 2016-10-13 20:20 +0200 |
| Message-ID | <srSLM-78p-25@gated-at.bofh.it> |
| In reply to | #1499736 |
On Wed, Oct 12, 2016 at 10:42:46AM -0400, Chris Mason wrote: > On 10/12/2016 10:40 AM, Dave Jones wrote: > > On Wed, Oct 12, 2016 at 09:47:17AM -0400, Dave Jones wrote: > > > On Tue, Oct 11, 2016 at 11:54:09AM -0400, Chris Mason wrote: > > > > > > > > > > > > On 10/11/2016 10:45 AM, Dave Jones wrote: > > > > > This is from Linus' current tree, with Al's iovec fixups on top. > > > > > > > > > > ------------[ cut here ]------------ > > > > > WARNING: CPU: 1 PID: 3673 at lib/list_debug.c:33 __list_add+0x89/0xb0 > > > > > list_add corruption. prev->next should be next (ffffe8ffff806648), but was ffffc9000067fcd8. (prev=ffff880503878b80). > > > > > CPU: 1 PID: 3673 Comm: trinity-c0 Not tainted 4.8.0-think+ #13 > > > > > ffffc90000d87458 ffffffff8d32007c ffffc90000d874a8 0000000000000000 > > > > > ffffc90000d87498 ffffffff8d07a6c1 0000002100000246 ffff88050388e880 > > > > > > I hit this again overnight, it's the same trace, the only difference > > > being slightly different addresses in the list pointers: > > > > > > [42572.777196] list_add corruption. prev->next should be next (ffffe8ffff806648), but was ffffc90000647cd8. (prev=ffff880503a0ba00). > > > > > > I'm actually a little surprised that ->next was the same across two > > > reboots on two different kernel builds. That might be a sign this is > > > more repeatable than I'd thought, even if it does take hours of runtime > > > right now to trigger it. I'll try and narrow the scope of what trinity > > > is doing to see if I can make it happen faster. > > > > .. and of course the first thing that happens is a completely different > > btrfs trace.. > > > > > > WARNING: CPU: 1 PID: 21706 at fs/btrfs/transaction.c:489 start_transaction+0x40a/0x440 [btrfs] > > CPU: 1 PID: 21706 Comm: trinity-c16 Not tainted 4.8.0-think+ #14 > > ffffc900019076a8 ffffffffb731ff3c 0000000000000000 0000000000000000 > > ffffc900019076e8 ffffffffb707a6c1 000001e9f5806ce0 ffff8804f74c4d98 > > 0000000000000801 ffff880501cfa2a8 000000000000008a 000000000000008a > > This isn't even IO. Uuughhhh. We're going to need a fast enough test > that we can bisect. Progress... I've found that this combination of syscalls.. ./trinity -C64 -q -l off -a64 --enable-fds=testfile -c fsync -c fsetxattr -c lremovexattr -c pwritev2 hits one of these two bugs in a few minutes runtime. Just the xattr syscalls + fsync isn't enough, neither is just pwrite + fsync. Mix them together though, and something goes awry. Dave
[toc] | [prev] | [next] | [standalone]
| From | Dave Jones <davej@codemonkey.org.uk> |
|---|---|
| Date | 2016-10-14 00:30 +0200 |
| Message-ID | <srWFH-180-7@gated-at.bofh.it> |
| In reply to | #1500491 |
On Thu, Oct 13, 2016 at 05:18:46PM -0400, Chris Mason wrote: > > > > WARNING: CPU: 1 PID: 21706 at fs/btrfs/transaction.c:489 start_transaction+0x40a/0x440 [btrfs] > > > > CPU: 1 PID: 21706 Comm: trinity-c16 Not tainted 4.8.0-think+ #14 > > > > ffffc900019076a8 ffffffffb731ff3c 0000000000000000 0000000000000000 > > > > ffffc900019076e8 ffffffffb707a6c1 000001e9f5806ce0 ffff8804f74c4d98 > > > > 0000000000000801 ffff880501cfa2a8 000000000000008a 000000000000008a > > > > > > This isn't even IO. Uuughhhh. We're going to need a fast enough test > > > that we can bisect. > > > > Progress... > > I've found that this combination of syscalls.. > > > > ./trinity -C64 -q -l off -a64 --enable-fds=testfile -c fsync -c fsetxattr -c lremovexattr -c pwritev2 > > > > hits one of these two bugs in a few minutes runtime. > > > > Just the xattr syscalls + fsync isn't enough, neither is just pwrite + fsync. > > Mix them together though, and something goes awry. > > > > Hasn't triggered here yet. I'll leave it running though. With that combo of params I triggered it 3-4 times in a row within minutes.. Then as soon as I posted, it stopped being so easy to repro. There's some other variable I haven't figured out yet (maybe how the random way that files get opened in fds/testfiles.c), but it does seem to point at the xattr changes. I'll poke at it some more tomorrow. Dave
[toc] | [prev] | [next] | [standalone]
| From | Dave Jones <davej@codemonkey.org.uk> |
|---|---|
| Date | 2016-10-16 02:50 +0200 |
| Message-ID | <ssHOh-6Qj-5@gated-at.bofh.it> |
| In reply to | #1500491 |
On Thu, Oct 13, 2016 at 05:18:46PM -0400, Chris Mason wrote: > > > > .. and of course the first thing that happens is a completely different > > > > btrfs trace.. > > > > > > > > > > > > WARNING: CPU: 1 PID: 21706 at fs/btrfs/transaction.c:489 start_transaction+0x40a/0x440 [btrfs] > > > > CPU: 1 PID: 21706 Comm: trinity-c16 Not tainted 4.8.0-think+ #14 > > > > ffffc900019076a8 ffffffffb731ff3c 0000000000000000 0000000000000000 > > > > ffffc900019076e8 ffffffffb707a6c1 000001e9f5806ce0 ffff8804f74c4d98 > > > > 0000000000000801 ffff880501cfa2a8 000000000000008a 000000000000008a > > > > > > This isn't even IO. Uuughhhh. We're going to need a fast enough test > > > that we can bisect. > > > > Progress... > > I've found that this combination of syscalls.. > > > > ./trinity -C64 -q -l off -a64 --enable-fds=testfile -c fsync -c fsetxattr -c lremovexattr -c pwritev2 > > > > hits one of these two bugs in a few minutes runtime. > > > > Just the xattr syscalls + fsync isn't enough, neither is just pwrite + fsync. > > Mix them together though, and something goes awry. > > > Hasn't triggered here yet. I'll leave it running though. The hits keep coming.. BUG: Bad page state in process kworker/u8:12 pfn:4988fa page:ffffea0012623e80 count:0 mapcount:0 mapping:ffff8804450456e0 index:0x9 flags: 0x400000000000000c(referenced|uptodate) page dumped because: non-NULL mapping CPU: 2 PID: 1388 Comm: kworker/u8:12 Not tainted 4.8.0-think+ #18 Workqueue: writeback wb_workfn (flush-btrfs-1) ffffc90000aef7e8 ffffffff81320e7c ffffea0012623e80 ffffffff819fe6ec ffffc90000aef810 ffffffff81159b3f 0000000000000000 ffffea0012623e80 400000000000000c ffffc90000aef820 ffffffff81159bfa ffffc90000aef868 Call Trace: [<ffffffff81320e7c>] dump_stack+0x4f/0x73 [<ffffffff81159b3f>] bad_page+0xbf/0x120 [<ffffffff81159bfa>] free_pages_check_bad+0x5a/0x70 [<ffffffff8115c0fb>] free_hot_cold_page+0x20b/0x270 [<ffffffff8115c41b>] free_hot_cold_page_list+0x2b/0x50 [<ffffffff81165062>] release_pages+0x2d2/0x380 [<ffffffff811665d2>] __pagevec_release+0x22/0x30 [<ffffffffa009f810>] extent_write_cache_pages.isra.48.constprop.63+0x350/0x430 [btrfs] [<ffffffff8133f487>] ? debug_smp_processor_id+0x17/0x20 [<ffffffff810c6999>] ? get_lock_stats+0x19/0x50 [<ffffffffa009fce8>] extent_writepages+0x58/0x80 [btrfs] [<ffffffffa007f150>] ? btrfs_releasepage+0x40/0x40 [btrfs] [<ffffffffa007c0d3>] btrfs_writepages+0x23/0x30 [btrfs] [<ffffffff8116370c>] do_writepages+0x1c/0x30 [<ffffffff81202d63>] __writeback_single_inode+0x33/0x180 [<ffffffff8120357b>] writeback_sb_inodes+0x2cb/0x5d0 [<ffffffff8120390d>] __writeback_inodes_wb+0x8d/0xc0 [<ffffffff81203c03>] wb_writeback+0x203/0x210 [<ffffffff81204197>] wb_workfn+0xe7/0x2a0 [<ffffffff810c8b7f>] ? __lock_acquire.isra.32+0x1cf/0x8c0 [<ffffffff8109458a>] process_one_work+0x1da/0x4b0 [<ffffffff8109452a>] ? process_one_work+0x17a/0x4b0 [<ffffffff810948a9>] worker_thread+0x49/0x490 [<ffffffff81094860>] ? process_one_work+0x4b0/0x4b0 [<ffffffff81094860>] ? process_one_work+0x4b0/0x4b0
[toc] | [prev] | [next] | [standalone]
| From | Dave Jones <davej@codemonkey.org.uk> |
|---|---|
| Date | 2016-10-19 00:50 +0200 |
| Subject | Re: bio linked list corruption. |
| Message-ID | <stLmN-9l-13@gated-at.bofh.it> |
| In reply to | #1498974 |
On Tue, Oct 11, 2016 at 10:45:07AM -0400, Dave Jones wrote: > WARNING: CPU: 1 PID: 3673 at lib/list_debug.c:33 __list_add+0x89/0xb0 > list_add corruption. prev->next should be next (ffffe8ffff806648), but was ffffc9000067fcd8. (prev=ffff880503878b80). > CPU: 1 PID: 3673 Comm: trinity-c0 Not tainted 4.8.0-think+ #13 > ffffc90000d87458 ffffffff8d32007c ffffc90000d874a8 0000000000000000 > ffffc90000d87498 ffffffff8d07a6c1 0000002100000246 ffff88050388e880 > ffff880503878b80 ffffe8ffff806648 ffffe8ffffc06600 ffff880502808008 > Call Trace: > [<ffffffff8d32007c>] dump_stack+0x4f/0x73 > [<ffffffff8d07a6c1>] __warn+0xc1/0xe0 > [<ffffffff8d07a73a>] warn_slowpath_fmt+0x5a/0x80 > [<ffffffff8d33e689>] __list_add+0x89/0xb0 > [<ffffffff8d30a1c8>] blk_sq_make_request+0x2f8/0x350 > [<ffffffff8d2fd9cc>] ? generic_make_request+0xec/0x240 > [<ffffffff8d2fd9d9>] generic_make_request+0xf9/0x240 > [<ffffffff8d2fdb98>] submit_bio+0x78/0x150 > [<ffffffff8d349c05>] ? __percpu_counter_add+0x85/0xb0 > [<ffffffffc03627de>] btrfs_map_bio+0x19e/0x330 [btrfs] > [<ffffffffc03289ca>] btree_submit_bio_hook+0xfa/0x110 [btrfs] > [<ffffffffc034ff15>] submit_one_bio+0x65/0xa0 [btrfs] > [<ffffffffc0358cb0>] read_extent_buffer_pages+0x2f0/0x3d0 [btrfs] > [<ffffffffc0327020>] ? free_root_pointers+0x60/0x60 [btrfs] > [<ffffffffc03283c8>] btree_read_extent_buffer_pages.constprop.55+0xa8/0x110 [btrfs] > [<ffffffffc0328bcd>] read_tree_block+0x2d/0x50 [btrfs] > [<ffffffffc03080a4>] read_block_for_search.isra.33+0x134/0x330 [btrfs] > [<ffffffff8d7c2d6c>] ? _raw_write_unlock+0x2c/0x50 > [<ffffffffc0302fec>] ? unlock_up+0x16c/0x1a0 [btrfs] > [<ffffffffc030a3d0>] btrfs_search_slot+0x450/0xa40 [btrfs] > [<ffffffffc0324983>] btrfs_del_csums+0xe3/0x2e0 [btrfs] > [<ffffffffc03134fd>] __btrfs_free_extent.isra.82+0x32d/0xc90 [btrfs] > [<ffffffffc03178b3>] __btrfs_run_delayed_refs+0x4d3/0x1010 [btrfs] > [<ffffffff8d33e5d7>] ? debug_smp_processor_id+0x17/0x20 > [<ffffffff8d0c6109>] ? get_lock_stats+0x19/0x50 > [<ffffffffc031b32c>] btrfs_run_delayed_refs+0x9c/0x2d0 [btrfs] > [<ffffffffc033d628>] btrfs_truncate_inode_items+0x888/0xda0 [btrfs] > [<ffffffffc033dc25>] btrfs_truncate+0xe5/0x2b0 [btrfs] > [<ffffffffc033e569>] btrfs_setattr+0x249/0x360 [btrfs] > [<ffffffff8d1f4092>] notify_change+0x252/0x440 > [<ffffffff8d1d164e>] do_truncate+0x6e/0xc0 > [<ffffffff8d1d1a4c>] do_sys_ftruncate.constprop.19+0x10c/0x170 > [<ffffffff8d33e5f3>] ? __this_cpu_preempt_check+0x13/0x20 > [<ffffffff8d1d1ad9>] SyS_ftruncate+0x9/0x10 > [<ffffffff8d00259c>] do_syscall_64+0x5c/0x170 > [<ffffffff8d7c2f8b>] entry_SYSCALL64_slow_path+0x25/0x25 So Chris had me do a run on ext4 just for giggles. It took a while, but eventually this fell out... WARNING: CPU: 3 PID: 21324 at lib/list_debug.c:33 __list_add+0x89/0xb0 list_add corruption. prev->next should be next (ffffe8ffffc05648), but was ffffc9000028bcd8. (prev=ffff880503a145c0). CPU: 3 PID: 21324 Comm: modprobe Not tainted 4.9.0-rc1-think+ #1 ffffc90000a6b7b8 ffffffff81320e3c ffffc90000a6b808 0000000000000000 ffffc90000a6b7f8 ffffffff8107a711 0000002100000246 ffff8805039f1740 ffff880503a145c0 ffffe8ffffc05648 ffffe8ffffa05600 ffff880502c39548 Call Trace: [<ffffffff81320e3c>] dump_stack+0x4f/0x73 [<ffffffff8107a711>] __warn+0xc1/0xe0 [<ffffffff8107a78a>] warn_slowpath_fmt+0x5a/0x80 [<ffffffff8133f499>] __list_add+0x89/0xb0 [<ffffffff8130af88>] blk_sq_make_request+0x2f8/0x350 [<ffffffff812fe6dc>] ? generic_make_request+0xec/0x240 [<ffffffff812fe6e9>] generic_make_request+0xf9/0x240 [<ffffffff812fe8a8>] submit_bio+0x78/0x150 [<ffffffff8120bde6>] ? __find_get_block+0x126/0x130 [<ffffffff8120cbff>] submit_bh_wbc+0x16f/0x1e0 [<ffffffff8120a400>] ? __end_buffer_read_notouch+0x20/0x20 [<ffffffff8120d958>] ll_rw_block+0xa8/0xb0 [<ffffffff8120da0f>] __breadahead+0x3f/0x70 [<ffffffff81264ffc>] __ext4_get_inode_loc+0x37c/0x3d0 [<ffffffff8126806d>] ext4_iget+0x8d/0xb90 [<ffffffff811f0759>] ? d_alloc_parallel+0x329/0x700 [<ffffffff81268b9a>] ext4_iget_normal+0x2a/0x30 [<ffffffff81273cd6>] ext4_lookup+0x136/0x250 [<ffffffff811e118d>] lookup_slow+0x12d/0x220 [<ffffffff811e3897>] walk_component+0x1e7/0x310 [<ffffffff811e33f8>] ? path_init+0x4d8/0x520 [<ffffffff811e4022>] path_lookupat+0x62/0x120 [<ffffffff811e4f22>] ? getname_flags+0x32/0x180 [<ffffffff811e5278>] filename_lookup+0xa8/0x130 [<ffffffff81352526>] ? strncpy_from_user+0x46/0x170 [<ffffffff811e4f3e>] ? getname_flags+0x4e/0x180 [<ffffffff811e53d1>] user_path_at_empty+0x31/0x40 [<ffffffff811d9df1>] vfs_fstatat+0x61/0xc0 [<ffffffff810c8b9f>] ? __lock_acquire.isra.32+0x1cf/0x8c0 [<ffffffff811da30e>] SYSC_newstat+0x2e/0x60 [<ffffffff8133f403>] ? __this_cpu_preempt_check+0x13/0x20 [<ffffffff811da499>] SyS_newstat+0x9/0x10 [<ffffffff8100259c>] do_syscall_64+0x5c/0x170 [<ffffffff817c27cb>] entry_SYSCALL64_slow_path+0x25/0x25 So this one isn't a btrfs specific problem as I first thought. This sometimes reproduces within minutes, sometimes hours, which makes it a pain to bisect. It only started showing up this merge window though. Dave
[toc] | [prev] | [next] | [standalone]
| From | Linus Torvalds <torvalds@linux-foundation.org> |
|---|---|
| Date | 2016-10-19 01:40 +0200 |
| Subject | Re: bio linked list corruption. |
| Message-ID | <stM9c-HJ-3@gated-at.bofh.it> |
| In reply to | #1503409 |
On Tue, Oct 18, 2016 at 4:31 PM, Chris Mason <clm@fb.com> wrote:
>
> Jens, not sure if you saw the whole thread. This has triggered bad page
> state errors, and also corrupted a btrfs list. It hurts me to say, but it
> might not actually be your fault.
Where is that thread, and what is the "this" that triggers problems?
Looking at the "->mq_list" users, I'm not seeing any changes there in
the last year or so. So I don't think it's the list itself.
Linus
[toc] | [prev] | [next] | [standalone]
| From | Linus Torvalds <torvalds@linux-foundation.org> |
|---|---|
| Date | 2016-10-19 02:20 +0200 |
| Subject | Re: bio linked list corruption. |
| Message-ID | <stMLT-1jl-3@gated-at.bofh.it> |
| In reply to | #1503450 |
On Tue, Oct 18, 2016 at 4:42 PM, Chris Mason <clm@fb.com> wrote:
>
> Seems to be the whole thing:
Ahh. On lkml, so I do have it in my mailbox, but Dave changed the
subject line when he tested on ext4 rather than btrfs..
Anyway, the corrupted address is somewhat interesting. As Dave Jones
said, he saw
list_add corruption. prev->next should be next (ffffe8ffff806648),
but was ffffc9000067fcd8. (prev=ffff880503878b80).
list_add corruption. prev->next should be next (ffffe8ffffc05648),
but was ffffc9000028bcd8. (prev=ffff880503a145c0).
and Dave Chinner reports
list_add corruption. prev->next should be next (ffffe8ffffc02808),
but was ffffc90005f6bda8. (prev=ffff88013363bb80).
and it's worth noting that the "but was" is a remarkably consistent
vmalloc address (the ffffc9000.. pattern gives it away). In fact, it's
identical across two boots for DaveJ in the low 14 bits, and fairly
high up in those low 14 bots (0x3cd8).
DaveC has a different address, but it's also in the vmalloc space, and
also looks like it is fairly high up in 14 bits (0x3da8). So in both
cases it's almost certainly a stack address with a fairly empty stack.
The differences are presumably due to different kernel configurations
and/or just different filesystems calling the same function that does
the same bad thing but now at different depths in the stack.
Adding Andy to the cc, because this *might* be triggered by the
vmalloc stack code itself. Maybe the re-use of stacks showing some
problem? Maybe Chris (who can't see the problem) doesn't have
CONFIG_VMAP_STACK enabled?
Andy - this is on lkml, under
Dave Chinner:
[regression, 4.9-rc1] blk-mq: list corruption in request queue
Dave Jones:
btrfs bio linked list corruption.
Re: bio linked list corruption.
and they are definitely the same thing across three different
filesystems (xfs, btrfs and ext4), and they are consistent enough that
there is almost certainly a single very specific memory corrupting
issue that overwrites something with a stack pointer.
Linus
[toc] | [prev] | [next] | [standalone]
| From | Linus Torvalds <torvalds@linux-foundation.org> |
|---|---|
| Date | 2016-10-19 02:30 +0200 |
| Subject | Re: bio linked list corruption. |
| Message-ID | <stMVz-1oo-1@gated-at.bofh.it> |
| In reply to | #1503460 |
On Tue, Oct 18, 2016 at 5:10 PM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
>
> Adding Andy to the cc, because this *might* be triggered by the
> vmalloc stack code itself. Maybe the re-use of stacks showing some
> problem? Maybe Chris (who can't see the problem) doesn't have
> CONFIG_VMAP_STACK enabled?
I bet it's the plug itself that is the stack address. In fact, it's
probably that mq_list head pointer
I think every single users of block plugging uses the pattern
struct blk_plug plug;
blk_start_plug(&plug);
and then we'll have
INIT_LIST_HEAD(&plug->mq_list);
which initializes that mq_list head with the stack addresses pointing to itself.
So when we see something like this:
list_add corruption. prev->next should be next (ffffe8ffff806648),
but was ffffc9000067fcd8. (prev=ffff880503878b80)
and it comes from
list_add_tail(&rq->queuelist, &plug->mq_list);
which will expand to
__list_add(new, head->prev, head)
which in this case *should* be:
__list_add(&rq->queuelist, plug->mq_list.prev, &plug->mq_list);
so in fact we *should* have "next" be a stack address.
So that debug message is really really odd. I would expect that "next"
is the stack address (because we're adding to the tail of the list, so
"next" is the list head itself), but the debug message corruption
printout says that "was" is the stack address, but next isn't.
Weird.The "but was" value actually looks like the right address should
look, but the actual address (which *should* be just "&plug->mq_list"
and really should be on the stack) looks bogus.
I'm now very confused.
Linus
[toc] | [prev] | [next] | [standalone]
| From | Dave Jones <davej@codemonkey.org.uk> |
|---|---|
| Date | 2016-10-21 00:50 +0200 |
| Subject | Re: bio linked list corruption. |
| Message-ID | <suujT-5ja-7@gated-at.bofh.it> |
| In reply to | #1503465 |
On Tue, Oct 18, 2016 at 05:28:44PM -0700, Linus Torvalds wrote: > On Tue, Oct 18, 2016 at 5:10 PM, Linus Torvalds > <torvalds@linux-foundation.org> wrote: > > > > Adding Andy to the cc, because this *might* be triggered by the > > vmalloc stack code itself. Maybe the re-use of stacks showing some > > problem? Maybe Chris (who can't see the problem) doesn't have > > CONFIG_VMAP_STACK enabled? > > I bet it's the plug itself that is the stack address. In fact, it's > probably that mq_list head pointer So I've done a few experiments the last couple days. 1, I see some kind of disaster happen with every filesystem ext4, btrfs, xfs. For some reason I can repro it faster on btrfs (though xfs blew up pretty quickly too, but I don't know if it's the same as this list corruption bug). 2, I ran for 24 hours with VMAP_STACK turned off. I saw some _different_ btrfs problems, but I never hit that list debug corruption once. 3, I turned vmap stacks back on, and got this pretty quickly. Another new flavor of crash, but Chris recommended I post this one because it looks interesting. [ 3943.514961] BUG: Bad page state in process kworker/u8:14 pfn:482244 [ 3943.532400] page:ffffea0012089100 count:0 mapcount:0 mapping:ffff8804c40d6ae0 index:0x2f [ 3943.551865] flags: 0x4000000000000008(uptodate) [ 3943.561652] page dumped because: non-NULL mapping [ 3943.587698] CPU: 2 PID: 26823 Comm: kworker/u8:14 Not tainted 4.9.0-rc1-think+ #9 [ 3943.607409] Workqueue: writeback wb_workfn [ 3943.617194] (flush-btrfs-2) [ 3943.617260] ffffc90001bf7870 [ 3943.627007] ffffffff8130c93c [ 3943.627075] ffffea0012089100 [ 3943.627112] ffffffff819ff37c [ 3943.627149] ffffc90001bf7898 [ 3943.636918] ffffffff81150fef [ 3943.636985] 0000000000000000 [ 3943.637021] ffffea0012089100 [ 3943.637059] 4000000000000008 [ 3943.646965] ffffc90001bf78a8 [ 3943.647041] ffffffff811510aa [ 3943.647081] ffffc90001bf78f0 [ 3943.647126] Call Trace: [ 3943.657068] [<ffffffff8130c93c>] dump_stack+0x4f/0x73 [ 3943.666996] [<ffffffff81150fef>] bad_page+0xbf/0x120 [ 3943.676839] [<ffffffff811510aa>] free_pages_check_bad+0x5a/0x70 [ 3943.686646] [<ffffffff8115355b>] free_hot_cold_page+0x20b/0x270 [ 3943.696402] [<ffffffff8115387b>] free_hot_cold_page_list+0x2b/0x50 [ 3943.706092] [<ffffffff8115c1fd>] release_pages+0x2bd/0x350 [ 3943.715726] [<ffffffff8115d732>] __pagevec_release+0x22/0x30 [ 3943.725358] [<ffffffffa00a0d4e>] extent_write_cache_pages.isra.48.constprop.63+0x32e/0x400 [btrfs] [ 3943.735126] [<ffffffffa00a1199>] extent_writepages+0x49/0x60 [btrfs] [ 3943.744808] [<ffffffffa0081840>] ? btrfs_releasepage+0x40/0x40 [btrfs] [ 3943.754457] [<ffffffffa007e993>] btrfs_writepages+0x23/0x30 [btrfs] [ 3943.764085] [<ffffffff8115a91c>] do_writepages+0x1c/0x30 [ 3943.773667] [<ffffffff811f65f3>] __writeback_single_inode+0x33/0x180 [ 3943.783233] [<ffffffff811f6de8>] writeback_sb_inodes+0x2a8/0x5b0 [ 3943.792870] [<ffffffff811f733b>] wb_writeback+0xeb/0x1f0 [ 3943.802326] [<ffffffff811f7972>] wb_workfn+0xd2/0x280 [ 3943.811673] [<ffffffff810906e5>] process_one_work+0x1d5/0x490 [ 3943.821044] [<ffffffff81090685>] ? process_one_work+0x175/0x490 [ 3943.830447] [<ffffffff810909e9>] worker_thread+0x49/0x490 [ 3943.839756] [<ffffffff810909a0>] ? process_one_work+0x490/0x490 [ 3943.849074] [<ffffffff810909a0>] ? process_one_work+0x490/0x490 [ 3943.858264] [<ffffffff81095b5e>] kthread+0xee/0x110 [ 3943.867451] [<ffffffff81095a70>] ? kthread_park+0x60/0x60 [ 3943.876616] [<ffffffff81095a70>] ? kthread_park+0x60/0x60 [ 3943.885624] [<ffffffff81095a70>] ? kthread_park+0x60/0x60 [ 3943.894580] [<ffffffff81790492>] ret_from_fork+0x22/0x30 This feels like chasing a moving target, because the crash keeps changing.. I'm going to spend some time trying to at least pin down a selection of syscalls that trinity can reproduce this with quickly. Early-on, it seemed like this was xattr related, but now I'm not so sure. Once or twice, I was able to repro it within a few minutes using just writev, fsync, lsetxattr and lremovexattr. Then a day later, I found I could run for a day before seeing it. Position of the moon or something. Or it could have been entirely unrelated to the actual syscalls being run, and based just on how contended the cpu/memory was. Dave
[toc] | [prev] | [next] | [standalone]
| From | Andy Lutomirski <luto@kernel.org> |
|---|---|
| Date | 2016-10-19 03:10 +0200 |
| Subject | Re: bio linked list corruption. |
| Message-ID | <stNyi-1V9-3@gated-at.bofh.it> |
| In reply to | #1503460 |
On 10/18/2016 05:10 PM, Linus Torvalds wrote: > On Tue, Oct 18, 2016 at 4:42 PM, Chris Mason <clm@fb.com> wrote: >> >> Seems to be the whole thing: > > Ahh. On lkml, so I do have it in my mailbox, but Dave changed the > subject line when he tested on ext4 rather than btrfs.. > > Anyway, the corrupted address is somewhat interesting. As Dave Jones > said, he saw > > list_add corruption. prev->next should be next (ffffe8ffff806648), > but was ffffc9000067fcd8. (prev=ffff880503878b80). > list_add corruption. prev->next should be next (ffffe8ffffc05648), > but was ffffc9000028bcd8. (prev=ffff880503a145c0). > > and Dave Chinner reports > > list_add corruption. prev->next should be next (ffffe8ffffc02808), > but was ffffc90005f6bda8. (prev=ffff88013363bb80). > > and it's worth noting that the "but was" is a remarkably consistent > vmalloc address (the ffffc9000.. pattern gives it away). In fact, it's > identical across two boots for DaveJ in the low 14 bits, and fairly > high up in those low 14 bots (0x3cd8). > > DaveC has a different address, but it's also in the vmalloc space, and > also looks like it is fairly high up in 14 bits (0x3da8). So in both > cases it's almost certainly a stack address with a fairly empty stack. > The differences are presumably due to different kernel configurations > and/or just different filesystems calling the same function that does > the same bad thing but now at different depths in the stack. > > Adding Andy to the cc, because this *might* be triggered by the > vmalloc stack code itself. Maybe the re-use of stacks showing some > problem? Maybe Chris (who can't see the problem) doesn't have > CONFIG_VMAP_STACK enabled? Wouldn't this cause the exact opposite problem? If the warning is to be believed, then prev is *not* on the stack but somehow prev->next ended up pointing to the stack. If stack reuse caused something to corrupt a value on the stack, then how would this cause a stack address to be written to a non-stack location? All I can think of is that "prev" itself is corrupted somehow. One possible debugging approach would be to change: #define NR_CACHED_STACKS 2 to #define NR_CACHED_STACKS 0 in kernel/fork.c and to set CONFIG_DEBUG_PAGEALLOC=y. The latter will force an immediate TLB flush after vfree. Also, CONFIG_DEBUG_VIRTUAL=y can be quite helpful for debugging stack issues. I'm tempted to do something equivalent to hardwiring that option on for a while if CONFIG_VMAP_STACK=y.
[toc] | [prev] | [next] | [standalone]
| From | Dave Jones <davej@codemonkey.org.uk> |
|---|---|
| Date | 2016-10-21 01:00 +0200 |
| Subject | Re: bio linked list corruption. |
| Message-ID | <suutA-5mC-33@gated-at.bofh.it> |
| In reply to | #1503473 |
On Tue, Oct 18, 2016 at 06:05:57PM -0700, Andy Lutomirski wrote: > One possible debugging approach would be to change: > > #define NR_CACHED_STACKS 2 > > to > > #define NR_CACHED_STACKS 0 > > in kernel/fork.c and to set CONFIG_DEBUG_PAGEALLOC=y. The latter will > force an immediate TLB flush after vfree. I can give that idea some runtime, but it sounds like this a case where we're trying to prove a negative, and that'll just run and run ? In which case I might do this when I'm travelling on Sunday. > Also, CONFIG_DEBUG_VIRTUAL=y can be quite helpful for debugging stack > issues. I'm tempted to do something equivalent to hardwiring that > option on for a while if CONFIG_VMAP_STACK=y. This one I had on. Nothing interesting jumped out. Dave
[toc] | [prev] | [next] | [standalone]
| From | Dave Jones <davej@codemonkey.org.uk> |
|---|---|
| Date | 2016-10-21 01:10 +0200 |
| Subject | Re: bio linked list corruption. |
| Message-ID | <suuDg-5F6-7@gated-at.bofh.it> |
| In reply to | #1505314 |
On Thu, Oct 20, 2016 at 04:01:12PM -0700, Andy Lutomirski wrote: > On Thu, Oct 20, 2016 at 3:50 PM, Dave Jones <davej@codemonkey.org.uk> wrote: > > On Tue, Oct 18, 2016 at 06:05:57PM -0700, Andy Lutomirski wrote: > > > > > One possible debugging approach would be to change: > > > > > > #define NR_CACHED_STACKS 2 > > > > > > to > > > > > > #define NR_CACHED_STACKS 0 > > > > > > in kernel/fork.c and to set CONFIG_DEBUG_PAGEALLOC=y. The latter will > > > force an immediate TLB flush after vfree. > > > > I can give that idea some runtime, but it sounds like this a case where > > we're trying to prove a negative, and that'll just run and run ? In which case I > > might do this when I'm travelling on Sunday. > > The idea is that the stack will be free and unmapped immediately upon > process exit if configured like this so that bogus stack accesses (by > the CPU, not DMA) would OOPS immediately. oh, misparsed. ok, I can definitely get behind that idea then. I'll do that next. Dave
[toc] | [prev] | [next] | [standalone]
| From | Andy Lutomirski <luto@amacapital.net> |
|---|---|
| Date | 2016-10-21 01:30 +0200 |
| Subject | Re: bio linked list corruption. |
| Message-ID | <suuWB-5LC-1@gated-at.bofh.it> |
| In reply to | #1505317 |
On Thu, Oct 20, 2016 at 4:03 PM, Dave Jones <davej@codemonkey.org.uk> wrote: > On Thu, Oct 20, 2016 at 04:01:12PM -0700, Andy Lutomirski wrote: > > On Thu, Oct 20, 2016 at 3:50 PM, Dave Jones <davej@codemonkey.org.uk> wrote: > > > On Tue, Oct 18, 2016 at 06:05:57PM -0700, Andy Lutomirski wrote: > > > > > > > One possible debugging approach would be to change: > > > > > > > > #define NR_CACHED_STACKS 2 > > > > > > > > to > > > > > > > > #define NR_CACHED_STACKS 0 > > > > > > > > in kernel/fork.c and to set CONFIG_DEBUG_PAGEALLOC=y. The latter will > > > > force an immediate TLB flush after vfree. > > > > > > I can give that idea some runtime, but it sounds like this a case where > > > we're trying to prove a negative, and that'll just run and run ? In which case I > > > might do this when I'm travelling on Sunday. > > > > The idea is that the stack will be free and unmapped immediately upon > > process exit if configured like this so that bogus stack accesses (by > > the CPU, not DMA) would OOPS immediately. > > oh, misparsed. ok, I can definitely get behind that idea then. > I'll do that next. > It could be worth trying this, too: https://git.kernel.org/cgit/linux/kernel/git/luto/linux.git/commit/?h=x86/vmap_stack&id=174531fef4e8 It occurred to me that the current code is a little bit fragile. --Andy
[toc] | [prev] | [next] | [standalone]
| From | Dave Jones <davej@codemonkey.org.uk> |
|---|---|
| Date | 2016-10-21 22:10 +0200 |
| Subject | Re: bio linked list corruption. |
| Message-ID | <suOiB-20g-13@gated-at.bofh.it> |
| In reply to | #1505329 |
On Thu, Oct 20, 2016 at 04:23:32PM -0700, Andy Lutomirski wrote: > On Thu, Oct 20, 2016 at 4:03 PM, Dave Jones <davej@codemonkey.org.uk> wrote: > > On Thu, Oct 20, 2016 at 04:01:12PM -0700, Andy Lutomirski wrote: > > > On Thu, Oct 20, 2016 at 3:50 PM, Dave Jones <davej@codemonkey.org.uk> wrote: > > > > On Tue, Oct 18, 2016 at 06:05:57PM -0700, Andy Lutomirski wrote: > > > > > > > > > One possible debugging approach would be to change: > > > > > > > > > > #define NR_CACHED_STACKS 2 > > > > > > > > > > to > > > > > > > > > > #define NR_CACHED_STACKS 0 > > > > > > > > > > in kernel/fork.c and to set CONFIG_DEBUG_PAGEALLOC=y. The latter will > > > > > force an immediate TLB flush after vfree. > > > > > > > > I can give that idea some runtime, but it sounds like this a case where > > > > we're trying to prove a negative, and that'll just run and run ? In which case I > > > > might do this when I'm travelling on Sunday. > > > > > > The idea is that the stack will be free and unmapped immediately upon > > > process exit if configured like this so that bogus stack accesses (by > > > the CPU, not DMA) would OOPS immediately. > > > > oh, misparsed. ok, I can definitely get behind that idea then. > > I'll do that next. > > > > It could be worth trying this, too: > > https://git.kernel.org/cgit/linux/kernel/git/luto/linux.git/commit/?h=x86/vmap_stack&id=174531fef4e8 > > It occurred to me that the current code is a little bit fragile. It's been nearly 24hrs with the above changes, and it's been pretty much silent the whole time. The only thing of note over that time period has been a btrfs lockdep warning that's been around for a while, and occasional btrfs checksum failures, which I've been seeing for a while, but seem to have gotten worse since 4.8. I'm pretty confident in the disk being ok in this machine, so I think the checksum warnings are bogus. Chris suggested they may be the result of memory corruption, but there's little else going on. BTRFS warning (device sda3): csum failed ino 130654 off 0 csum 2566472073 expected csum 3008371513 BTRFS warning (device sda3): csum failed ino 131057 off 4096 csum 3563910319 expected csum 738595262 BTRFS warning (device sda3): csum failed ino 131176 off 4096 csum 1344477721 expected csum 441864825 BTRFS warning (device sda3): csum failed ino 131241 off 245760 csum 3576232181 expected csum 2566472073 BTRFS warning (device sda3): csum failed ino 131429 off 0 csum 1494450239 expected csum 2646577722 BTRFS warning (device sda3): csum failed ino 131471 off 0 csum 3949539320 expected csum 3828807800 BTRFS warning (device sda3): csum failed ino 131471 off 4096 csum 3475108475 expected csum 2566472073 BTRFS warning (device sda3): csum failed ino 131471 off 958464 csum 142982740 expected csum 2566472073 BTRFS warning (device sda3): csum failed ino 131471 off 0 csum 3949539320 expected csum 3828807800 BTRFS warning (device sda3): csum failed ino 131532 off 270336 csum 3138898528 expected csum 2566472073 BTRFS warning (device sda3): csum failed ino 131532 off 1249280 csum 2169165042 expected csum 2566472073 BTRFS warning (device sda3): csum failed ino 131649 off 16384 csum 2914965650 expected csum 1425742005 A curious thing: the expected csum 2566472073 turns up a number of times for different inodes, and gets differing actual csums each time. I suppose this could be something like a block of all zeros in multiple files, but it struck me as surprising. btrfs people: is there an easy way to map those inodes to a filename ? I'm betting those are the test files that trinity generates. If so, it might point to a race somewhere. Dave
[toc] | [prev] | [next] | [standalone]
| From | Dave Jones <davej@codemonkey.org.uk> |
|---|---|
| Date | 2016-10-21 22:30 +0200 |
| Subject | Re: bio linked list corruption. |
| Message-ID | <suOBY-2ad-3@gated-at.bofh.it> |
| In reply to | #1506262 |
On Fri, Oct 21, 2016 at 04:17:48PM -0400, Chris Mason wrote: > > BTRFS warning (device sda3): csum failed ino 130654 off 0 csum 2566472073 expected csum 3008371513 > > BTRFS warning (device sda3): csum failed ino 131057 off 4096 csum 3563910319 expected csum 738595262 > > BTRFS warning (device sda3): csum failed ino 131176 off 4096 csum 1344477721 expected csum 441864825 > > BTRFS warning (device sda3): csum failed ino 131241 off 245760 csum 3576232181 expected csum 2566472073 > > BTRFS warning (device sda3): csum failed ino 131429 off 0 csum 1494450239 expected csum 2646577722 > > BTRFS warning (device sda3): csum failed ino 131471 off 0 csum 3949539320 expected csum 3828807800 > > BTRFS warning (device sda3): csum failed ino 131471 off 4096 csum 3475108475 expected csum 2566472073 > > BTRFS warning (device sda3): csum failed ino 131471 off 958464 csum 142982740 expected csum 2566472073 > > BTRFS warning (device sda3): csum failed ino 131471 off 0 csum 3949539320 expected csum 3828807800 > > BTRFS warning (device sda3): csum failed ino 131532 off 270336 csum 3138898528 expected csum 2566472073 > > BTRFS warning (device sda3): csum failed ino 131532 off 1249280 csum 2169165042 expected csum 2566472073 > > BTRFS warning (device sda3): csum failed ino 131649 off 16384 csum 2914965650 expected csum 1425742005 > > > > > > A curious thing: the expected csum 2566472073 turns up a number of times for different inodes, and gets > > differing actual csums each time. I suppose this could be something like a block of all zeros in multiple files, > > but it struck me as surprising. > > > > btrfs people: is there an easy way to map those inodes to a filename ? I'm betting those are the > > test files that trinity generates. If so, it might point to a race somewhere. > > btrfs inspect inode 130654 mntpoint Interesting, they all return ERROR: ino paths ioctl: No such file or directory So these files got deleted perhaps ? Dave
[toc] | [prev] | [next] | [standalone]
| From | Dave Jones <davej@codemonkey.org.uk> |
|---|---|
| Date | 2016-10-21 23:20 +0200 |
| Subject | Re: bio linked list corruption. |
| Message-ID | <suPom-2G3-19@gated-at.bofh.it> |
| In reply to | #1506266 |
On Fri, Oct 21, 2016 at 04:41:09PM -0400, Josef Bacik wrote: > >> > > >> > btrfs inspect inode 130654 mntpoint > >> > >> Interesting, they all return > >> > >> ERROR: ino paths ioctl: No such file or directory > >> > >> So these files got deleted perhaps ? > >> > > Yeah, they must have. > > > > So one thing that will cause spurious csum errors is if you do things like > change the memory while it is in flight during O_DIRECT. Does trinity do that? > If so then that would explain it. If not we should probably dig into it. Thanks, Yeah, that's definitely possible. And it wasn't that long ago I added some code to always open testfiles multiple times with different modes, so the likely of O_DIRECT went up. That would explain why I've started seeing this more. Dave
[toc] | [prev] | [next] | [standalone]
| From | Dave Jones <davej@codemonkey.org.uk> |
|---|---|
| Date | 2016-10-22 17:30 +0200 |
| Subject | Re: bio linked list corruption. |
| Message-ID | <sv6pb-5b6-1@gated-at.bofh.it> |
| In reply to | #1506262 |
On Fri, Oct 21, 2016 at 04:02:45PM -0400, Dave Jones wrote: > > It could be worth trying this, too: > > > > https://git.kernel.org/cgit/linux/kernel/git/luto/linux.git/commit/?h=x86/vmap_stack&id=174531fef4e8 > > > > It occurred to me that the current code is a little bit fragile. > > It's been nearly 24hrs with the above changes, and it's been pretty much > silent the whole time. > > The only thing of note over that time period has been a btrfs lockdep > warning that's been around for a while, and occasional btrfs checksum > failures, which I've been seeing for a while, but seem to have gotten > worse since 4.8. > > I'm pretty confident in the disk being ok in this machine, so I think > the checksum warnings are bogus. Chris suggested they may be the result > of memory corruption, but there's little else going on. The only interesting thing last nights run was this.. BUG: Bad page state in process kworker/u8:1 pfn:4e2b70 page:ffffea00138adc00 count:0 mapcount:0 mapping:ffff88046e9fc2e0 index:0xdf0 flags: 0x400000000000000c(referenced|uptodate) page dumped because: non-NULL mapping CPU: 3 PID: 24234 Comm: kworker/u8:1 Not tainted 4.9.0-rc1-think+ #11 Workqueue: writeback wb_workfn (flush-btrfs-2) ffffc90001f97828 ffffffff8130d07c ffffea00138adc00 ffffffff819ff524 ffffc90001f97850 ffffffff8115117f 0000000000000000 ffffea00138adc00 400000000000000c ffffc90001f97860 ffffffff8115123a ffffc90001f978a8 Call Trace: [<ffffffff8130d07c>] dump_stack+0x4f/0x73 [<ffffffff8115117f>] bad_page+0xbf/0x120 [<ffffffff8115123a>] free_pages_check_bad+0x5a/0x70 [<ffffffff81153b38>] free_hot_cold_page+0x248/0x290 [<ffffffff81153e3b>] free_hot_cold_page_list+0x2b/0x50 [<ffffffff8115c84d>] release_pages+0x2bd/0x350 [<ffffffff8115dd82>] __pagevec_release+0x22/0x30 [<ffffffffa009cd4e>] extent_write_cache_pages.isra.48.constprop.63+0x32e/0x400 [btrfs] [<ffffffffa009d199>] extent_writepages+0x49/0x60 [btrfs] [<ffffffffa007d840>] ? btrfs_releasepage+0x40/0x40 [btrfs] [<ffffffffa007a993>] btrfs_writepages+0x23/0x30 [btrfs] [<ffffffff8115af6c>] do_writepages+0x1c/0x30 [<ffffffff811f6d33>] __writeback_single_inode+0x33/0x180 [<ffffffff811f7528>] writeback_sb_inodes+0x2a8/0x5b0 [<ffffffff811f78bd>] __writeback_inodes_wb+0x8d/0xc0 [<ffffffff811f7b73>] wb_writeback+0x1e3/0x1f0 [<ffffffff811f80b2>] wb_workfn+0xd2/0x280 [<ffffffff81090875>] process_one_work+0x1d5/0x490 [<ffffffff81090815>] ? process_one_work+0x175/0x490 [<ffffffff81090b79>] worker_thread+0x49/0x490 [<ffffffff81090b30>] ? process_one_work+0x490/0x490 [<ffffffff81095cee>] kthread+0xee/0x110 [<ffffffff81095c00>] ? kthread_park+0x60/0x60 [<ffffffff81790bd2>] ret_from_fork+0x22/0x30
[toc] | [prev] | [next] | [standalone]
Page 1 of 3 [1] 2 3 Next page →
Back to top | Article view | linux.kernel
csiph-web