Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1503409 > unrolled thread

Re: bio linked list corruption.

Started byDave Jones <davej@codemonkey.org.uk>
First post2016-10-19 00:50 +0200
Last post2016-10-20 09:30 +0200
Articles 20 on this page of 43 — 7 participants

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  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 →

#1503409 — Re: bio linked list corruption.

FromDave Jones <davej@codemonkey.org.uk>
Date2016-10-19 00:50 +0200
SubjectRe: bio linked list corruption.
Message-ID<stLmN-9l-13@gated-at.bofh.it>
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] | [next] | [standalone]

#1503450

FromLinus Torvalds <torvalds@linux-foundation.org>
Date2016-10-19 01:40 +0200
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]

#1503460

FromLinus Torvalds <torvalds@linux-foundation.org>
Date2016-10-19 02:20 +0200
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]

#1503465

FromLinus Torvalds <torvalds@linux-foundation.org>
Date2016-10-19 02:30 +0200
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]

#1505310

FromDave Jones <davej@codemonkey.org.uk>
Date2016-10-21 00:50 +0200
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]

#1503473

FromAndy Lutomirski <luto@kernel.org>
Date2016-10-19 03:10 +0200
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]

#1505314

FromDave Jones <davej@codemonkey.org.uk>
Date2016-10-21 01:00 +0200
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]

#1505317

FromDave Jones <davej@codemonkey.org.uk>
Date2016-10-21 01:10 +0200
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]

#1505329

FromAndy Lutomirski <luto@amacapital.net>
Date2016-10-21 01:30 +0200
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]

#1506262

FromDave Jones <davej@codemonkey.org.uk>
Date2016-10-21 22:10 +0200
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]

#1506266

FromDave Jones <davej@codemonkey.org.uk>
Date2016-10-21 22:30 +0200
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]

#1506301

FromDave Jones <davej@codemonkey.org.uk>
Date2016-10-21 23:20 +0200
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]

#1506556

FromDave Jones <davej@codemonkey.org.uk>
Date2016-10-22 17:30 +0200
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]

#1506894

FromDave Jones <davej@codemonkey.org.uk>
Date2016-10-24 06:50 +0200
Message-ID<svFmW-2IU-25@gated-at.bofh.it>
In reply to#1506556
On Sun, Oct 23, 2016 at 05:32:21PM -0400, Chris Mason wrote:
 > 
 > 
 > On 10/22/2016 11:20 AM, Dave Jones wrote:
 > > 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)
 > 
 > Well crud, we're back to wondering if this is Btrfs or the stack 
 > corruption.  Since the pagevecs are on the stack and this is a new 
 > crash, my guess is you'll be able to trigger it on xfs/ext4 too.  But we 
 > should make sure.

Here's an interesting one from today, pointing the finger at xattrs again.


[69943.450108] Oops: 0003 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[69943.454452] CPU: 1 PID: 21558 Comm: trinity-c60 Not tainted 4.9.0-rc1-think+ #11 
[69943.463510] task: ffff8804f8dd3740 task.stack: ffffc9000b108000
[69943.468077] RIP: 0010:[<ffffffff810c3f6b>] 
[69943.472704]  [<ffffffff810c3f6b>] __lock_acquire.isra.32+0x6b/0x8c0
[69943.477489] RSP: 0018:ffffc9000b10b9e8  EFLAGS: 00010086
[69943.482368] RAX: ffffffff81789b90 RBX: ffff8804f8dd3740 RCX: 0000000000000000
[69943.487410] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[69943.492515] RBP: ffffc9000b10ba18 R08: 0000000000000001 R09: 0000000000000000
[69943.497666] R10: 0000000000000001 R11: 00003f9cfa7f4e73 R12: 0000000000000000
[69943.502880] R13: 0000000000000000 R14: ffffc9000af7bd48 R15: ffff8804f8dd3740
[69943.508163] FS:  00007f64904a2b40(0000) GS:ffff880507a00000(0000) knlGS:0000000000000000
[69943.513591] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[69943.518917] CR2: ffffffff81789d28 CR3: 00000004a8f16000 CR4: 00000000001406e0
[69943.524253] DR0: 00007f5b97fd4000 DR1: 0000000000000000 DR2: 0000000000000000
[69943.529488] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
[69943.534771] Stack:
[69943.540023]  ffff880507bd74c0
[69943.545317]  ffff8804f8dd3740 0000000000000046 0000000000000286[69943.545456]  ffffc9000af7bd08
[69943.550930]  0000000000000100 ffffc9000b10ba50 ffffffff810c4b68[69943.551069]  ffffffff810ba40c
[69943.556657]  ffff880400000000 0000000000000000 ffffc9000af7bd48[69943.556796] Call Trace:
[69943.562465]  [<ffffffff810c4b68>] lock_acquire+0x58/0x70
[69943.568354]  [<ffffffff810ba40c>] ? finish_wait+0x3c/0x70
[69943.574306]  [<ffffffff8178fef2>] _raw_spin_lock_irqsave+0x42/0x80
[69943.580335]  [<ffffffff810ba40c>] ? finish_wait+0x3c/0x70
[69943.586237]  [<ffffffff810ba40c>] finish_wait+0x3c/0x70
[69943.591992]  [<ffffffff81169727>] shmem_fault+0x167/0x1b0
[69943.597807]  [<ffffffff810ba6c0>] ? prepare_to_wait_event+0x100/0x100
[69943.603741]  [<ffffffff8117b46d>] __do_fault+0x6d/0x1b0
[69943.609743]  [<ffffffff8117f168>] handle_mm_fault+0xc58/0x1170
[69943.615822]  [<ffffffff8117e553>] ? handle_mm_fault+0x43/0x1170
[69943.621971]  [<ffffffff81044982>] __do_page_fault+0x172/0x4e0
[69943.628184]  [<ffffffff81044d10>] do_page_fault+0x20/0x70
[69943.634449]  [<ffffffff8132a897>] ? debug_smp_processor_id+0x17/0x20
[69943.640784]  [<ffffffff81791f3f>] page_fault+0x1f/0x30
[69943.647170]  [<ffffffff8133d69c>] ? strncpy_from_user+0x5c/0x170
[69943.653480]  [<ffffffff8133d686>] ? strncpy_from_user+0x46/0x170
[69943.659632]  [<ffffffff811f22a7>] setxattr+0x57/0x170
[69943.665846]  [<ffffffff8132a897>] ? debug_smp_processor_id+0x17/0x20
[69943.672172]  [<ffffffff810c1f09>] ? get_lock_stats+0x19/0x50
[69943.678558]  [<ffffffff810a58f6>] ? sched_clock_cpu+0xb6/0xd0
[69943.685007]  [<ffffffff810c40cf>] ? __lock_acquire.isra.32+0x1cf/0x8c0
[69943.691542]  [<ffffffff8132a8b3>] ? __this_cpu_preempt_check+0x13/0x20
[69943.698130]  [<ffffffff8109b9bc>] ? preempt_count_add+0x7c/0xc0
[69943.704791]  [<ffffffff811ecda1>] ? __mnt_want_write+0x61/0x90
[69943.711519]  [<ffffffff811f2638>] SyS_fsetxattr+0x78/0xa0
[69943.718300]  [<ffffffff8100255c>] do_syscall_64+0x5c/0x170
[69943.724949]  [<ffffffff81790a4b>] entry_SYSCALL64_slow_path+0x25/0x25
[69943.731521] Code: 
[69943.738124] 00 83 fe 01 0f 86 0e 03 00 00 31 d2 4c 89 f7 44 89 45 d0 89 4d d4 e8 75 e7 ff ff 8b 4d d4 48 85 c0 44 8b 45 d0 0f 84 d8 02 00 00 <f0> ff 80 98 01 00 00 8b 15 e0 21 8f 01 45 8b 8f 50 08 00 00 85 [69943.745506] RIP 
[69943.752432]  [<ffffffff810c3f6b>] __lock_acquire.isra.32+0x6b/0x8c0
 RSP <ffffc9000b10b9e8>
[69943.766856] CR2: ffffffff81789d28

[toc] | [prev] | [next] | [standalone]

#1507684

FromAndy Lutomirski <luto@amacapital.net>
Date2016-10-24 22:10 +0200
Message-ID<svTJf-3Yl-3@gated-at.bofh.it>
In reply to#1506894
On Sun, Oct 23, 2016 at 9:40 PM, Dave Jones <davej@codemonkey.org.uk> wrote:
> On Sun, Oct 23, 2016 at 05:32:21PM -0400, Chris Mason wrote:
>  >
>  >
>  > On 10/22/2016 11:20 AM, Dave Jones wrote:
>  > > 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)
>  >
>  > Well crud, we're back to wondering if this is Btrfs or the stack
>  > corruption.  Since the pagevecs are on the stack and this is a new
>  > crash, my guess is you'll be able to trigger it on xfs/ext4 too.  But we
>  > should make sure.
>
> Here's an interesting one from today, pointing the finger at xattrs again.
>
>
> [69943.450108] Oops: 0003 [#1] PREEMPT SMP DEBUG_PAGEALLOC

This is an unhandled kernel page fault.  The string "Oops" is so helpful :-/

> [69943.454452] CPU: 1 PID: 21558 Comm: trinity-c60 Not tainted 4.9.0-rc1-think+ #11
> [69943.463510] task: ffff8804f8dd3740 task.stack: ffffc9000b108000
> [69943.468077] RIP: 0010:[<ffffffff810c3f6b>]
> [69943.472704]  [<ffffffff810c3f6b>] __lock_acquire.isra.32+0x6b/0x8c0
> [69943.477489] RSP: 0018:ffffc9000b10b9e8  EFLAGS: 00010086
> [69943.482368] RAX: ffffffff81789b90 RBX: ffff8804f8dd3740 RCX: 0000000000000000
> [69943.487410] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
> [69943.492515] RBP: ffffc9000b10ba18 R08: 0000000000000001 R09: 0000000000000000
> [69943.497666] R10: 0000000000000001 R11: 00003f9cfa7f4e73 R12: 0000000000000000
> [69943.502880] R13: 0000000000000000 R14: ffffc9000af7bd48 R15: ffff8804f8dd3740
> [69943.508163] FS:  00007f64904a2b40(0000) GS:ffff880507a00000(0000) knlGS:0000000000000000
> [69943.513591] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [69943.518917] CR2: ffffffff81789d28 CR3: 00000004a8f16000 CR4: 00000000001406e0
> [69943.524253] DR0: 00007f5b97fd4000 DR1: 0000000000000000 DR2: 0000000000000000
> [69943.529488] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
> [69943.534771] Stack:
> [69943.540023]  ffff880507bd74c0
> [69943.545317]  ffff8804f8dd3740 0000000000000046 0000000000000286[69943.545456]  ffffc9000af7bd08
> [69943.550930]  0000000000000100 ffffc9000b10ba50 ffffffff810c4b68[69943.551069]  ffffffff810ba40c
> [69943.556657]  ffff880400000000 0000000000000000 ffffc9000af7bd48[69943.556796] Call Trace:
> [69943.562465]  [<ffffffff810c4b68>] lock_acquire+0x58/0x70
> [69943.568354]  [<ffffffff810ba40c>] ? finish_wait+0x3c/0x70
> [69943.574306]  [<ffffffff8178fef2>] _raw_spin_lock_irqsave+0x42/0x80
> [69943.580335]  [<ffffffff810ba40c>] ? finish_wait+0x3c/0x70
> [69943.586237]  [<ffffffff810ba40c>] finish_wait+0x3c/0x70
> [69943.591992]  [<ffffffff81169727>] shmem_fault+0x167/0x1b0
> [69943.597807]  [<ffffffff810ba6c0>] ? prepare_to_wait_event+0x100/0x100
> [69943.603741]  [<ffffffff8117b46d>] __do_fault+0x6d/0x1b0
> [69943.609743]  [<ffffffff8117f168>] handle_mm_fault+0xc58/0x1170
> [69943.615822]  [<ffffffff8117e553>] ? handle_mm_fault+0x43/0x1170
> [69943.621971]  [<ffffffff81044982>] __do_page_fault+0x172/0x4e0
> [69943.628184]  [<ffffffff81044d10>] do_page_fault+0x20/0x70
> [69943.634449]  [<ffffffff8132a897>] ? debug_smp_processor_id+0x17/0x20
> [69943.640784]  [<ffffffff81791f3f>] page_fault+0x1f/0x30
> [69943.647170]  [<ffffffff8133d69c>] ? strncpy_from_user+0x5c/0x170
> [69943.653480]  [<ffffffff8133d686>] ? strncpy_from_user+0x46/0x170
> [69943.659632]  [<ffffffff811f22a7>] setxattr+0x57/0x170
> [69943.665846]  [<ffffffff8132a897>] ? debug_smp_processor_id+0x17/0x20
> [69943.672172]  [<ffffffff810c1f09>] ? get_lock_stats+0x19/0x50
> [69943.678558]  [<ffffffff810a58f6>] ? sched_clock_cpu+0xb6/0xd0
> [69943.685007]  [<ffffffff810c40cf>] ? __lock_acquire.isra.32+0x1cf/0x8c0
> [69943.691542]  [<ffffffff8132a8b3>] ? __this_cpu_preempt_check+0x13/0x20
> [69943.698130]  [<ffffffff8109b9bc>] ? preempt_count_add+0x7c/0xc0
> [69943.704791]  [<ffffffff811ecda1>] ? __mnt_want_write+0x61/0x90
> [69943.711519]  [<ffffffff811f2638>] SyS_fsetxattr+0x78/0xa0
> [69943.718300]  [<ffffffff8100255c>] do_syscall_64+0x5c/0x170
> [69943.724949]  [<ffffffff81790a4b>] entry_SYSCALL64_slow_path+0x25/0x25
> [69943.731521] Code:
> [69943.738124] 00 83 fe 01 0f 86 0e 03 00 00 31 d2 4c 89 f7 44 89 45 d0 89 4d d4 e8 75 e7 ff ff 8b 4d d4 48 85 c0 44 8b 45 d0 0f 84 d8 02 00 00 <f0> ff 80 98 01 00 00 8b 15 e0 21 8f 01 45 8b 8f 50 08 00 00 85

That's lock incl 0x198(%rax).  I think this is:

    atomic_inc((atomic_t *)&class->ops);

I suppose this could be stack corruption at work, but after a fair
amount of staring, I still haven't found anything in the vmap_stack
code that would cause stack corruption.

[toc] | [prev] | [next] | [standalone]

#1507718

FromLinus Torvalds <torvalds@linux-foundation.org>
Date2016-10-24 22:50 +0200
Message-ID<svUlY-4eX-33@gated-at.bofh.it>
In reply to#1507684
On Mon, Oct 24, 2016 at 1:06 PM, Andy Lutomirski <luto@amacapital.net> wrote:
>>
>> [69943.450108] Oops: 0003 [#1] PREEMPT SMP DEBUG_PAGEALLOC
>
> This is an unhandled kernel page fault.  The string "Oops" is so helpful :-/

I think there was a line above it that DaveJ just didn't include.

>
>> [69943.454452] CPU: 1 PID: 21558 Comm: trinity-c60 Not tainted 4.9.0-rc1-think+ #11
>> [69943.463510] task: ffff8804f8dd3740 task.stack: ffffc9000b108000
>> [69943.468077] RIP: 0010:[<ffffffff810c3f6b>]
>> [69943.472704]  [<ffffffff810c3f6b>] __lock_acquire.isra.32+0x6b/0x8c0
>> [69943.477489] RSP: 0018:ffffc9000b10b9e8  EFLAGS: 00010086
>> [69943.482368] RAX: ffffffff81789b90 RBX: ffff8804f8dd3740 RCX: 0000000000000000
>> [69943.487410] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
>> [69943.492515] RBP: ffffc9000b10ba18 R08: 0000000000000001 R09: 0000000000000000
>> [69943.497666] R10: 0000000000000001 R11: 00003f9cfa7f4e73 R12: 0000000000000000
>> [69943.502880] R13: 0000000000000000 R14: ffffc9000af7bd48 R15: ffff8804f8dd3740
>> [69943.508163] FS:  00007f64904a2b40(0000) GS:ffff880507a00000(0000) knlGS:0000000000000000
>> [69943.513591] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [69943.518917] CR2: ffffffff81789d28 CR3: 00000004a8f16000 CR4: 00000000001406e0
>> [69943.524253] DR0: 00007f5b97fd4000 DR1: 0000000000000000 DR2: 0000000000000000
>> [69943.529488] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
>> [69943.534771] Stack:
>> [69943.540023]  ffff880507bd74c0
>> [69943.545317]  ffff8804f8dd3740 0000000000000046 0000000000000286[69943.545456]  ffffc9000af7bd08
>> [69943.550930]  0000000000000100 ffffc9000b10ba50 ffffffff810c4b68[69943.551069]  ffffffff810ba40c
>> [69943.556657]  ffff880400000000 0000000000000000 ffffc9000af7bd48[69943.556796] Call Trace:
>> [69943.562465]  [<ffffffff810c4b68>] lock_acquire+0x58/0x70
>> [69943.568354]  [<ffffffff810ba40c>] ? finish_wait+0x3c/0x70
>> [69943.574306]  [<ffffffff8178fef2>] _raw_spin_lock_irqsave+0x42/0x80
>> [69943.580335]  [<ffffffff810ba40c>] ? finish_wait+0x3c/0x70
>> [69943.586237]  [<ffffffff810ba40c>] finish_wait+0x3c/0x70
>> [69943.591992]  [<ffffffff81169727>] shmem_fault+0x167/0x1b0
>> [69943.597807]  [<ffffffff810ba6c0>] ? prepare_to_wait_event+0x100/0x100
>> [69943.603741]  [<ffffffff8117b46d>] __do_fault+0x6d/0x1b0
>> [69943.609743]  [<ffffffff8117f168>] handle_mm_fault+0xc58/0x1170
>> [69943.615822]  [<ffffffff8117e553>] ? handle_mm_fault+0x43/0x1170
>> [69943.621971]  [<ffffffff81044982>] __do_page_fault+0x172/0x4e0
>> [69943.628184]  [<ffffffff81044d10>] do_page_fault+0x20/0x70
>> [69943.634449]  [<ffffffff8132a897>] ? debug_smp_processor_id+0x17/0x20
>> [69943.640784]  [<ffffffff81791f3f>] page_fault+0x1f/0x30
>> [69943.647170]  [<ffffffff8133d69c>] ? strncpy_from_user+0x5c/0x170
>> [69943.653480]  [<ffffffff8133d686>] ? strncpy_from_user+0x46/0x170
>> [69943.659632]  [<ffffffff811f22a7>] setxattr+0x57/0x170
>> [69943.665846]  [<ffffffff8132a897>] ? debug_smp_processor_id+0x17/0x20
>> [69943.672172]  [<ffffffff810c1f09>] ? get_lock_stats+0x19/0x50
>> [69943.678558]  [<ffffffff810a58f6>] ? sched_clock_cpu+0xb6/0xd0
>> [69943.685007]  [<ffffffff810c40cf>] ? __lock_acquire.isra.32+0x1cf/0x8c0
>> [69943.691542]  [<ffffffff8132a8b3>] ? __this_cpu_preempt_check+0x13/0x20
>> [69943.698130]  [<ffffffff8109b9bc>] ? preempt_count_add+0x7c/0xc0
>> [69943.704791]  [<ffffffff811ecda1>] ? __mnt_want_write+0x61/0x90
>> [69943.711519]  [<ffffffff811f2638>] SyS_fsetxattr+0x78/0xa0
>> [69943.718300]  [<ffffffff8100255c>] do_syscall_64+0x5c/0x170
>> [69943.724949]  [<ffffffff81790a4b>] entry_SYSCALL64_slow_path+0x25/0x25
>> [69943.731521] Code:
>> [69943.738124] 00 83 fe 01 0f 86 0e 03 00 00 31 d2 4c 89 f7 44 89 45 d0 89 4d d4 e8 75 e7 ff ff 8b 4d d4 48 85 c0 44 8b 45 d0 0f 84 d8 02 00 00 <f0> ff 80 98 01 00 00 8b 15 e0 21 8f 01 45 8b 8f 50 08 00 00 85
>
> That's lock incl 0x198(%rax).  I think this is:
>
>     atomic_inc((atomic_t *)&class->ops);
>
> I suppose this could be stack corruption at work, but after a fair
> amount of staring, I still haven't found anything in the vmap_stack
> code that would cause stack corruption.

Well, it is intriguing that what faults is this:

                        finish_wait(shmem_falloc_waitq, &shmem_fault_wait);

where 'shmem_fault_wait' is a on-stack wait queue. So it really looks
very much like stack corruption.

What strikes me is that "finish_wait()" does this optimistic "has my
entry been removed" without holding the waitqueue lock (and uses
list_empty_careful() to make sure it does that "safely").

It has that big comment too:

                        /*
                         * shmem_falloc_waitq points into the shmem_fallocate()
                         * stack of the hole-punching task: shmem_falloc_waitq
                         * is usually invalid by the time we reach here, but
                         * finish_wait() does not dereference it in that case;
                         * though i_lock needed lest racing with wake_up_all().
                         */

the stack it comes from is the wait queue head from shmem_fallocate(),
which will do "wake_up_all()" under the inode lock.

On the face of it, the inode lock should make that safe and serialize
everything. And yes, finish_wait() does not touch the unsafe stuff if
the wait-queue (in the local stack) is empty, which wake_up_all()
*should* have guaranteed. It's just a regular wait-queue entry (that
DEFINE_WAIT() does that), so it uses the normal
autoremove_wake_function() that removes things on successful wakeup:

int autoremove_wake_function(wait_queue_t *wait, unsigned mode, int
sync, void *key)
{
        int ret = default_wake_function(wait, mode, sync, key);

        if (ret)
                list_del_init(&wait->task_list);
        return ret;
}

So the only issue is "did default_wake_function() return true"? That's
try_to_wake_up(TASK_NORMAL, 0), and I note that it can return zero
(and thus *not* remove the entry - leavign the invalid entry tghere)
if

        if (!(p->state & state))
                goto out;

but "prepare_to_wait()" (which also ran with the inode->i_lock held,
and also takes the wait-queue lock) did set p->state to
TASK_UNINTERRUPTIBLE.

So this is all some really subtle code, but I'm not seeing that it
would be wrong.

            Linus

[toc] | [prev] | [next] | [standalone]

#1507742

FromLinus Torvalds <torvalds@linux-foundation.org>
Date2016-10-24 23:20 +0200
Message-ID<svUP0-4Ew-33@gated-at.bofh.it>
In reply to#1507718
On Mon, Oct 24, 2016 at 1:46 PM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
>
> So this is all some really subtle code, but I'm not seeing that it
> would be wrong.

Ahh... Except maybe..

The vmalloc/vfree code itself is a bit scary. In particular, we have a
rather insane model of TLB flushing. We leave the virtual area on a
lazy purge-list, and we delay flushing the TLB and actually freeing
the virtual memory for it so that we can batch things up.

But we've free'd the physical pages that are *mapped* by that area
when we do the vfree(). So there can be stale TLB entries that point
to pages that have gotten re-used. They shouldn't matter, because
nothing should be writing to those pages, but it strikes me that this
may also be hurting the DEBUG_PAGEALLOC thing. Maybe we're not getting
the page fautls that we *should* be getting, and there are hidden
reads and writes to those paghes that already got free'd.\

There was some nasty reason why we did that insane thing. I think it
was just that there are a few high-frequency vmalloc/vfree users and
the TLB flushing was killing some performance.

But it does strike me that we are playing very fast and loose with the
TLB on the vmalloc area.

So maybe all the new VMAP code is fine, and it's really vmalloc/vfree
that has been subtly broken but nobody has ever cared before?

              Linus

[toc] | [prev] | [next] | [standalone]

#1507764

FromLinus Torvalds <torvalds@linux-foundation.org>
Date2016-10-25 00:00 +0200
Message-ID<svVrH-4RK-7@gated-at.bofh.it>
In reply to#1507742
On Mon, Oct 24, 2016 at 2:17 PM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
>
> The vmalloc/vfree code itself is a bit scary. In particular, we have a
> rather insane model of TLB flushing. We leave the virtual area on a
> lazy purge-list, and we delay flushing the TLB and actually freeing
> the virtual memory for it so that we can batch things up.

Never mind. If DaveJ is running with DEBUG_PAGEALLOC, then the code in
vmap_debug_free_range() should have forced a synchronous TLB flush fro
vmalloc ranges too, so that doesn't explain it either.

             Linus

[toc] | [prev] | [next] | [standalone]

#1507810

FromAndy Lutomirski <luto@amacapital.net>
Date2016-10-25 00:50 +0200
Message-ID<svWe6-5rW-17@gated-at.bofh.it>
In reply to#1507718
On Mon, Oct 24, 2016 at 1:46 PM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
> On Mon, Oct 24, 2016 at 1:06 PM, Andy Lutomirski <luto@amacapital.net> wrote:
>>>
>>> [69943.450108] Oops: 0003 [#1] PREEMPT SMP DEBUG_PAGEALLOC
>>
>> This is an unhandled kernel page fault.  The string "Oops" is so helpful :-/
>
> I think there was a line above it that DaveJ just didn't include.
>
>>
>>> [69943.454452] CPU: 1 PID: 21558 Comm: trinity-c60 Not tainted 4.9.0-rc1-think+ #11
>>> [69943.463510] task: ffff8804f8dd3740 task.stack: ffffc9000b108000
>>> [69943.468077] RIP: 0010:[<ffffffff810c3f6b>]
>>> [69943.472704]  [<ffffffff810c3f6b>] __lock_acquire.isra.32+0x6b/0x8c0
>>> [69943.477489] RSP: 0018:ffffc9000b10b9e8  EFLAGS: 00010086
>>> [69943.482368] RAX: ffffffff81789b90 RBX: ffff8804f8dd3740 RCX: 0000000000000000
>>> [69943.487410] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
>>> [69943.492515] RBP: ffffc9000b10ba18 R08: 0000000000000001 R09: 0000000000000000
>>> [69943.497666] R10: 0000000000000001 R11: 00003f9cfa7f4e73 R12: 0000000000000000
>>> [69943.502880] R13: 0000000000000000 R14: ffffc9000af7bd48 R15: ffff8804f8dd3740
>>> [69943.508163] FS:  00007f64904a2b40(0000) GS:ffff880507a00000(0000) knlGS:0000000000000000
>>> [69943.513591] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>>> [69943.518917] CR2: ffffffff81789d28 CR3: 00000004a8f16000 CR4: 00000000001406e0
>>> [69943.524253] DR0: 00007f5b97fd4000 DR1: 0000000000000000 DR2: 0000000000000000
>>> [69943.529488] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
>>> [69943.534771] Stack:
>>> [69943.540023]  ffff880507bd74c0
>>> [69943.545317]  ffff8804f8dd3740 0000000000000046 0000000000000286[69943.545456]  ffffc9000af7bd08
>>> [69943.550930]  0000000000000100 ffffc9000b10ba50 ffffffff810c4b68[69943.551069]  ffffffff810ba40c
>>> [69943.556657]  ffff880400000000 0000000000000000 ffffc9000af7bd48[69943.556796] Call Trace:
>>> [69943.562465]  [<ffffffff810c4b68>] lock_acquire+0x58/0x70
>>> [69943.568354]  [<ffffffff810ba40c>] ? finish_wait+0x3c/0x70
>>> [69943.574306]  [<ffffffff8178fef2>] _raw_spin_lock_irqsave+0x42/0x80
>>> [69943.580335]  [<ffffffff810ba40c>] ? finish_wait+0x3c/0x70
>>> [69943.586237]  [<ffffffff810ba40c>] finish_wait+0x3c/0x70
>>> [69943.591992]  [<ffffffff81169727>] shmem_fault+0x167/0x1b0
>>> [69943.597807]  [<ffffffff810ba6c0>] ? prepare_to_wait_event+0x100/0x100
>>> [69943.603741]  [<ffffffff8117b46d>] __do_fault+0x6d/0x1b0
>>> [69943.609743]  [<ffffffff8117f168>] handle_mm_fault+0xc58/0x1170
>>> [69943.615822]  [<ffffffff8117e553>] ? handle_mm_fault+0x43/0x1170
>>> [69943.621971]  [<ffffffff81044982>] __do_page_fault+0x172/0x4e0
>>> [69943.628184]  [<ffffffff81044d10>] do_page_fault+0x20/0x70
>>> [69943.634449]  [<ffffffff8132a897>] ? debug_smp_processor_id+0x17/0x20
>>> [69943.640784]  [<ffffffff81791f3f>] page_fault+0x1f/0x30
>>> [69943.647170]  [<ffffffff8133d69c>] ? strncpy_from_user+0x5c/0x170
>>> [69943.653480]  [<ffffffff8133d686>] ? strncpy_from_user+0x46/0x170
>>> [69943.659632]  [<ffffffff811f22a7>] setxattr+0x57/0x170
>>> [69943.665846]  [<ffffffff8132a897>] ? debug_smp_processor_id+0x17/0x20
>>> [69943.672172]  [<ffffffff810c1f09>] ? get_lock_stats+0x19/0x50
>>> [69943.678558]  [<ffffffff810a58f6>] ? sched_clock_cpu+0xb6/0xd0
>>> [69943.685007]  [<ffffffff810c40cf>] ? __lock_acquire.isra.32+0x1cf/0x8c0
>>> [69943.691542]  [<ffffffff8132a8b3>] ? __this_cpu_preempt_check+0x13/0x20
>>> [69943.698130]  [<ffffffff8109b9bc>] ? preempt_count_add+0x7c/0xc0
>>> [69943.704791]  [<ffffffff811ecda1>] ? __mnt_want_write+0x61/0x90
>>> [69943.711519]  [<ffffffff811f2638>] SyS_fsetxattr+0x78/0xa0
>>> [69943.718300]  [<ffffffff8100255c>] do_syscall_64+0x5c/0x170
>>> [69943.724949]  [<ffffffff81790a4b>] entry_SYSCALL64_slow_path+0x25/0x25
>>> [69943.731521] Code:
>>> [69943.738124] 00 83 fe 01 0f 86 0e 03 00 00 31 d2 4c 89 f7 44 89 45 d0 89 4d d4 e8 75 e7 ff ff 8b 4d d4 48 85 c0 44 8b 45 d0 0f 84 d8 02 00 00 <f0> ff 80 98 01 00 00 8b 15 e0 21 8f 01 45 8b 8f 50 08 00 00 85
>>
>> That's lock incl 0x198(%rax).  I think this is:
>>
>>     atomic_inc((atomic_t *)&class->ops);
>>
>> I suppose this could be stack corruption at work, but after a fair
>> amount of staring, I still haven't found anything in the vmap_stack
>> code that would cause stack corruption.
>
> Well, it is intriguing that what faults is this:
>
>                         finish_wait(shmem_falloc_waitq, &shmem_fault_wait);
>
> where 'shmem_fault_wait' is a on-stack wait queue. So it really looks
> very much like stack corruption.
>
> What strikes me is that "finish_wait()" does this optimistic "has my
> entry been removed" without holding the waitqueue lock (and uses
> list_empty_careful() to make sure it does that "safely").
>
> It has that big comment too:
>
>                         /*
>                          * shmem_falloc_waitq points into the shmem_fallocate()
>                          * stack of the hole-punching task: shmem_falloc_waitq
>                          * is usually invalid by the time we reach here, but
>                          * finish_wait() does not dereference it in that case;
>                          * though i_lock needed lest racing with wake_up_all().
>                          */
>
> the stack it comes from is the wait queue head from shmem_fallocate(),
> which will do "wake_up_all()" under the inode lock.

Here's my theory: I think you're looking at the right code but the
wrong stack.  shmem_fault_wait is fine, but shmem_fault_waitq looks
really dicey.  Consider:

fallocate calls wake_up_all(), which calls autoremove_wait_function().
That wakes up the shmem_fault thread.  Suppose that the shmem_fault
thread gets moving really quickly (presumably because it never went to
sleep in the first place -- suppose it hadn't made it to schedule(),
so schedule() turns into a no-op).  It calls finish_wait() *before*
autoremove_wake_function() does the list_del_init().  finish_wait()
gets to the list_empty_careful() call and it returns true.

Now the fallocate thread catches up and *exits*.  Dave's test makes a
new thread that reuses the stack (the vmap area or the backing store).

Now the shmem_fault thread continues on its merry way and takes
q->lock.  But oh crap, q->lock is pointing at some random spot on some
other thread's stack.  Kaboom!

If I'm right, actually blowing up due to this bug would have been
very, very unlikely on 4.8 and below, and it has nothing to do with
vmap stacks per se -- it was the RCU removal.  We used to wait for an
RCU grace period before reusing a stack, and there couldn't have been
an RCU grace period in the middle of finish_wait(), so we were safer.
(Not totally safe, because the thread that called fallocate() could
have made it somewhere else that used the same stack depth, but I can
see that being less likely.)

IOW, I think that autoremove_wake_function() is buggy.  It should
remove the wait entry, then try to wake the thread, then re-add the
wait entry if the wakeup fails.  Or maybe it should use some atomic
flag in the wait entry or have some other locking to make sure that
finish_wait does not touch q->lock if autoremove_wake_function
succeeds.

--Andy

[toc] | [prev] | [next] | [standalone]

#1507839

FromLinus Torvalds <torvalds@linux-foundation.org>
Date2016-10-25 02:10 +0200
Message-ID<svXtv-6p0-9@gated-at.bofh.it>
In reply to#1507810
On Mon, Oct 24, 2016 at 3:42 PM, Andy Lutomirski <luto@amacapital.net> wrote:
>
> Here's my theory: I think you're looking at the right code but the
> wrong stack.  shmem_fault_wait is fine, but shmem_fault_waitq looks
> really dicey.

Hmm.

> Consider:
>
> fallocate calls wake_up_all(), which calls autoremove_wait_function().
> That wakes up the shmem_fault thread.  Suppose that the shmem_fault
> thread gets moving really quickly (presumably because it never went to
> sleep in the first place -- suppose it hadn't made it to schedule(),
> so schedule() turns into a no-op).  It calls finish_wait() *before*
> autoremove_wake_function() does the list_del_init().  finish_wait()
> gets to the list_empty_careful() call and it returns true.

All of this happens under inode->i_lock, so the different parts are
serialized. So if this happens before the wakeup, then finish_wait()
will se that the wait-queue entry is not empty (it points to the wait
queue head in shmem_falloc_waitq.

But then it will just remove itself carefully with list_del_init()
under the waitqueue lock, and things are fine.

Yes, it uses the waitiqueue lock on the other stack, but that stack is
still ok since
 (a) we're serialized by inode->i_lock
 (b) this code ran before the fallocate thread catches up and exits.

In other words, your scenario seems to be dependent on those two
threads being able to race. But they both hold inode->i_lock in the
critical region you are talking about.

> Now the fallocate thread catches up and *exits*.  Dave's test makes a
> new thread that reuses the stack (the vmap area or the backing store).
>
> Now the shmem_fault thread continues on its merry way and takes
> q->lock.  But oh crap, q->lock is pointing at some random spot on some
> other thread's stack.  Kaboom!

Note that q->lock should be entirely immaterial, since inode->i_lock
nests outside of it in all uses.

Now, if there is some code that runs *without* the inode->i_lock, then
that would be a big bug.

But I'm not seeing it.

I do agree that some race on some stack data structure could easily be
the cause of these issues. And yes, the vmap code obviously starts
reusing the stack much earlier, and would trigger problems that would
essentially be hidden by the fact that the kernel stack used to stay
around not just until exit(), but until the process was reaped.

I just think that in this case i_lock really looks like it should
serialize things correctly.

Or are you seeing something I'm not?

                   Linus

[toc] | [prev] | [next] | [standalone]

Page 1 of 3  [1] 2 3  Next page →

Back to top | Article view | linux.kernel

csiph-web