| Message ID | 488f9edc-6a1c-2c68-0d33-d3aa32ece9a4@fb.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
On 10/26/2016 04:00 PM, Chris Mason wrote: > > > On 10/26/2016 03:06 PM, Linus Torvalds wrote: >> On Wed, Oct 26, 2016 at 11:42 AM, Dave Jones <davej@codemonkey.org.uk> wrote: >>> >>> The stacks show nearly all of them are stuck in sync_inodes_sb >> >> That's just wb_wait_for_completion(), and it means that some IO isn't >> completing. >> >> There's also a lot of processes waiting for inode_lock(), and a few >> waiting for mnt_want_write() >> >> Ignoring those, we have >> >>> [<ffffffffa009554f>] btrfs_wait_ordered_roots+0x3f/0x200 [btrfs] >>> [<ffffffffa00470d1>] btrfs_sync_fs+0x31/0xc0 [btrfs] >>> [<ffffffff811fbd4e>] sync_filesystem+0x6e/0xa0 >>> [<ffffffff811fbebc>] SyS_syncfs+0x3c/0x70 >>> [<ffffffff8100255c>] do_syscall_64+0x5c/0x170 >>> [<ffffffff817908cb>] entry_SYSCALL64_slow_path+0x25/0x25 >>> [<ffffffffffffffff>] 0xffffffffffffffff >> >> Don't know this one. There's a couple of them. Could there be some >> ABBA deadlock on the ordered roots waiting? > > It's always possible, but we haven't changed anything here. > > I've tried a long list of things to reproduce this on my test boxes, > including days of trinity runs and a kernel module to exercise vmalloc, > and thread creation. > > Today I turned off every CONFIG_DEBUG_* except for list debugging, and > ran dbench 2048: > This one is special because CONFIG_VMAP_STACK is not set. Btrfs triggers in < 10 minutes. I've done 30 minutes each with XFS and Ext4 without luck. This is all in a virtual machine that I can copy on to a bunch of hosts. So I'll get some parallel tests going tonight to narrow it down. ------------[ cut here ]------------ WARNING: CPU: 6 PID: 4481 at lib/list_debug.c:33 __list_add+0xbe/0xd0 list_add corruption. prev->next should be next (ffffe8ffffd80b08), but was ffff88012b65fb88. (prev=ffff880128c8d500). Modules linked in: crc32c_intel aesni_intel aes_x86_64 glue_helper lrw gf128mul ablk_helper i2c_piix4 cryptd i2c_core virtio_net serio_raw floppy button pcspkr sch_fq_codel autofs4 virtio_blk CPU: 6 PID: 4481 Comm: dbench Not tainted 4.9.0-rc2-15419-g811d54d #319 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.0-1.fc24 04/01/2014 ffff880104eff868 ffffffff814fde0f ffffffff8151c46e ffff880104eff8c8 ffff880104eff8c8 0000000000000000 ffff880104eff8b8 ffffffff810648cf ffff880128cab2c0 000000213fc57c68 ffff8801384e8928 ffff880128cab180 Call Trace: [<ffffffff814fde0f>] dump_stack+0x53/0x74 [<ffffffff8151c46e>] ? __list_add+0xbe/0xd0 [<ffffffff810648cf>] __warn+0xff/0x120 [<ffffffff810649a9>] warn_slowpath_fmt+0x49/0x50 [<ffffffff8151c46e>] __list_add+0xbe/0xd0 [<ffffffff814dec38>] blk_sq_make_request+0x388/0x580 [<ffffffff814d5444>] generic_make_request+0x104/0x200 [<ffffffff814d55a5>] submit_bio+0x65/0x130 [<ffffffff8152a256>] ? __percpu_counter_add+0x96/0xd0 [<ffffffff81425c7c>] btrfs_map_bio+0x23c/0x310 [<ffffffff813f3e73>] btrfs_submit_bio_hook+0xd3/0x190 [<ffffffff8141136d>] submit_one_bio+0x6d/0xa0 [<ffffffff814113ee>] flush_epd_write_bio+0x4e/0x70 [<ffffffff8141894d>] extent_writepages+0x5d/0x70 [<ffffffff813f80a0>] ? btrfs_releasepage+0x50/0x50 [<ffffffff81220d0e>] ? wbc_attach_and_unlock_inode+0x6e/0x170 [<ffffffff813f4c07>] btrfs_writepages+0x27/0x30 [<ffffffff811783a0>] do_writepages+0x20/0x30 [<ffffffff81167a95>] __filemap_fdatawrite_range+0xb5/0x100 [<ffffffff81167f73>] filemap_fdatawrite_range+0x13/0x20 [<ffffffff8140563b>] btrfs_fdatawrite_range+0x2b/0x70 [<ffffffff81405768>] btrfs_sync_file+0x88/0x490 [<ffffffff81074ef2>] ? group_send_sig_info+0x42/0x80 [<ffffffff81074f8d>] ? kill_pid_info+0x5d/0x90 [<ffffffff8107535a>] ? SYSC_kill+0xba/0x1d0 [<ffffffff811f2348>] ? __sb_end_write+0x58/0x80 [<ffffffff812258ac>] vfs_fsync_range+0x4c/0xb0 [<ffffffff81002501>] ? syscall_trace_enter+0x201/0x2e0 [<ffffffff8122592c>] vfs_fsync+0x1c/0x20 [<ffffffff8122596d>] do_fsync+0x3d/0x70 [<ffffffff810029cb>] ? syscall_slow_exit_work+0xfb/0x100 [<ffffffff812259d0>] SyS_fsync+0x10/0x20 [<ffffffff81002b65>] do_syscall_64+0x55/0xd0 [<ffffffff810026d7>] ? prepare_exit_to_usermode+0x37/0x40 [<ffffffff819ad246>] entry_SYSCALL64_slow_path+0x25/0x25 ---[ end trace efe6b17c6dba2a6e ]--- -- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Wed, Oct 26, 2016 at 1:00 PM, Chris Mason <clm@fb.com> wrote: > > Today I turned off every CONFIG_DEBUG_* except for list debugging, and > ran dbench 2048: > > [ 2759.118711] WARNING: CPU: 2 PID: 31039 at lib/list_debug.c:33 __list_add+0xbe/0xd0 > [ 2759.119652] list_add corruption. prev->next should be next (ffffe8ffffc80308), but was ffffc90000ccfb88. (prev=ffff880128522380). > [ 2759.121039] Modules linked in: crc32c_intel i2c_piix4 aesni_intel aes_x86_64 virtio_net glue_helper i2c_core lrw floppy gf128mul serio_raw pcspkr button ablk_helper cryptd sch_fq_codel autofs4 virtio_blk > [ 2759.124369] CPU: 2 PID: 31039 Comm: dbench Not tainted 4.9.0-rc1-15246-g4ce9206-dirty #317 > [ 2759.125077] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.0-1.fc24 04/01/2014 > [ 2759.125077] ffffc9000f6fb868 ffffffff814fe4ff ffffffff8151cb5e ffffc9000f6fb8c8 > [ 2759.125077] ffffc9000f6fb8c8 0000000000000000 ffffc9000f6fb8b8 ffffffff81064bbf > [ 2759.127444] ffff880128523680 0000002139968000 ffff880138b7a4a0 ffff880128523540 > [ 2759.127444] Call Trace: > [ 2759.127444] [<ffffffff814fe4ff>] dump_stack+0x53/0x74 > [ 2759.127444] [<ffffffff8151cb5e>] ? __list_add+0xbe/0xd0 > [ 2759.127444] [<ffffffff81064bbf>] __warn+0xff/0x120 > [ 2759.127444] [<ffffffff81064c99>] warn_slowpath_fmt+0x49/0x50 > [ 2759.127444] [<ffffffff8151cb5e>] __list_add+0xbe/0xd0 > [ 2759.127444] [<ffffffff814df338>] blk_sq_make_request+0x388/0x580 Ok, that's definitely the same one that Dave started out seeing. The fact that it is that reliable - two different machines, two very different loads (dbench looks nothing like trinity) really makes me think that maybe the problem really is in the block plugging after all. It very much does not smell like random stack corruption. It's simply not random enough. And I just noticed something: I originally thought that this is the "list_add_tail()" to the plug - which is the only "list_add()" variant in that function. But that never made sense, because the whole "but was" isn't a stack address, and "next" in "list_add_tail()" is basically fixed, and would have to be the stack. But I now notice that there's actually another "list_add()" variant there, and it's the one from __blk_mq_insert_request() that gets inlined into blk_mq_insert_request(), which then gets inlined into blk_mq_make_request(). And that actually makes some sense just looking at the offsets too: blk_sq_make_request+0x388/0x580 so it's somewhat at the end of blk_sq_make_request(). So it's not unlikely. And there it makes perfect sense that the "next should be" value is *not* on the stack. Chris, if you built with debug info, you can try ./scripts/faddr2line /boot/vmlinux blk_sq_make_request+0x388 to get what line that blk_sq_make_request+0x388 address actually is. I think it's the list_add_tail(&rq->queuelist, &ctx->rq_list); in __blk_mq_insert_req_list() (when it's inlined from blk_sq_make_request(), "at_head" will be false. So it smells like "&ctx->rq_list" might be corrupt. And that actually seems much more likely than the "plug" list, because while the plug is entirely thread-local (and thus shouldn't have any races), the ctx->rq_list very much is not. Jens? For example, should we have a BUG_ON(ctx != rq->mq_ctx); in blk_mq_merge_queue_io()? Because it locks ctx->lock, but then __blk_mq_insert_request() will insert things onto the queues of rq->mq_ctx. blk_mq_insert_requests() has similar issues, but there has that BUG_ON(). The locking there really is *very* messy. All the lockers do spin_lock(&ctx->lock); ... spin_unlock(&ctx->lock); but then __blk_mq_insert_request() and __blk_mq_insert_req_list don't act on "ctx", but on "ctx = rq->mq_ctx", so if you ever get those wrong, you're completely dead. Now, I'm not seeing why they'd be wrong, and why they'd be associated with the VMAP_STACK thing, but it could just be an unlucky timing thing. Linus -- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Wed, Oct 26, 2016 at 03:07:10PM -0700, Linus Torvalds wrote: >On Wed, Oct 26, 2016 at 1:00 PM, Chris Mason <clm@fb.com> wrote: >> >> Today I turned off every CONFIG_DEBUG_* except for list debugging, and >> ran dbench 2048: >> >> [ 2759.118711] WARNING: CPU: 2 PID: 31039 at lib/list_debug.c:33 __list_add+0xbe/0xd0 >> [ 2759.119652] list_add corruption. prev->next should be next (ffffe8ffffc80308), but was ffffc90000ccfb88. (prev=ffff880128522380). >> [ 2759.121039] Modules linked in: crc32c_intel i2c_piix4 aesni_intel aes_x86_64 virtio_net glue_helper i2c_core lrw floppy gf128mul serio_raw pcspkr button ablk_helper cryptd sch_fq_codel autofs4 virtio_blk >> [ 2759.124369] CPU: 2 PID: 31039 Comm: dbench Not tainted 4.9.0-rc1-15246-g4ce9206-dirty #317 >> [ 2759.125077] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.0-1.fc24 04/01/2014 >> [ 2759.125077] ffffc9000f6fb868 ffffffff814fe4ff ffffffff8151cb5e ffffc9000f6fb8c8 >> [ 2759.125077] ffffc9000f6fb8c8 0000000000000000 ffffc9000f6fb8b8 ffffffff81064bbf >> [ 2759.127444] ffff880128523680 0000002139968000 ffff880138b7a4a0 ffff880128523540 >> [ 2759.127444] Call Trace: >> [ 2759.127444] [<ffffffff814fe4ff>] dump_stack+0x53/0x74 >> [ 2759.127444] [<ffffffff8151cb5e>] ? __list_add+0xbe/0xd0 >> [ 2759.127444] [<ffffffff81064bbf>] __warn+0xff/0x120 >> [ 2759.127444] [<ffffffff81064c99>] warn_slowpath_fmt+0x49/0x50 >> [ 2759.127444] [<ffffffff8151cb5e>] __list_add+0xbe/0xd0 >> [ 2759.127444] [<ffffffff814df338>] blk_sq_make_request+0x388/0x580 > >Ok, that's definitely the same one that Dave started out seeing. > >The fact that it is that reliable - two different machines, two very >different loads (dbench looks nothing like trinity) really makes me >think that maybe the problem really is in the block plugging after >all. > >It very much does not smell like random stack corruption. It's simply >not random enough. Agreed. I'd feel better if I could trigger this outside of btrfs, even though Dave Chinner hit something very similar on xfs. I'll peel off another test machine for a long XFS run. > >And I just noticed something: I originally thought that this is the >"list_add_tail()" to the plug - which is the only "list_add()" variant >in that function. > >But that never made sense, because the whole "but was" isn't a stack >address, and "next" in "list_add_tail()" is basically fixed, and would >have to be the stack. > >But I now notice that there's actually another "list_add()" variant >there, and it's the one from __blk_mq_insert_request() that gets >inlined into blk_mq_insert_request(), which then gets inlined into >blk_mq_make_request(). > >And that actually makes some sense just looking at the offsets too: > > blk_sq_make_request+0x388/0x580 > >so it's somewhat at the end of blk_sq_make_request(). So it's not unlikely. > >And there it makes perfect sense that the "next should be" value is >*not* on the stack. > >Chris, if you built with debug info, you can try > > ./scripts/faddr2line /boot/vmlinux blk_sq_make_request+0x388 > >to get what line that blk_sq_make_request+0x388 address actually is. I >think it's the > > list_add_tail(&rq->queuelist, &ctx->rq_list); > >in __blk_mq_insert_req_list() (when it's inlined from >blk_sq_make_request(), "at_head" will be false. > >So it smells like "&ctx->rq_list" might be corrupt. I'm running your current git here, so these line numbers should line up for you: blk_sq_make_request+0x388/0x578: __blk_mq_insert_request at block/blk-mq.c:1049 (inlined by) blk_mq_merge_queue_io at block/blk-mq.c:1175 (inlined by) blk_sq_make_request at block/blk-mq.c:1419 The fsync path in the WARN doesn't have any plugs that I can see, so its not surprising that we're not in the plugging path. I'm here: if (!blk_mq_merge_queue_io(data.hctx, data.ctx, rq, bio)) { /* * For a SYNC request, send it to the hardware immediately. For * an ASYNC request, just ensure that we run it later on. The * latter allows for merging opportunities and more efficient * dispatching. */ I'll try the debugging patch you sent in the other email. -chris -- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
diff --git a/kernel/fork.c b/kernel/fork.c index 623259f..de95e19 100644 --- a/kernel/fork.c +++ b/kernel/fork.c @@ -165,7 +165,7 @@ void __weak arch_release_thread_stack(unsigned long *stack) * vmalloc() is a bit slow, and calling vfree() enough times will force a TLB * flush. Try to minimize the number of calls by caching stacks. */ -#define NR_CACHED_STACKS 2 +#define NR_CACHED_STACKS 256 static DEFINE_PER_CPU(struct vm_struct *, cached_stacks[NR_CACHED_STACKS]); #endif @@ -173,7 +173,9 @@ static unsigned long *alloc_thread_stack_node(struct task_struct *tsk, int node) { #ifdef CONFIG_VMAP_STACK void *stack; + char *p; int i; + int j; local_irq_disable(); for (i = 0; i < NR_CACHED_STACKS; i++) { @@ -183,7 +185,15 @@ static unsigned long *alloc_thread_stack_node(struct task_struct *tsk, int node) continue; this_cpu_write(cached_stacks[i], NULL); + p = s->addr; + for (j = 0; j < THREAD_SIZE; j++) { + if (p[j] != 'c') { + printk_ratelimited(KERN_CRIT "bad poison %c byte %d\n", p[j], j); + break; + } + } tsk->stack_vm_area = s; + local_irq_enable(); return s->addr; } @@ -219,6 +229,7 @@ static inline void free_thread_stack(struct task_struct *tsk) int i; local_irq_save(flags); + memset(tsk->stack_vm_area->addr, 'c', THREAD_SIZE); for (i = 0; i < NR_CACHED_STACKS; i++) { if (this_cpu_read(cached_stacks[i])) continue;