[<prev] [next>] [day] [month] [year] [list]
Message-ID: <20181115055443.GF18977@shao2-debian>
Date: Thu, 15 Nov 2018 13:54:43 +0800
From: kernel test robot <rong.a.chen@...el.com>
To: Yang Shi <yang.shi@...ux.alibaba.com>
Cc: Matthew Wilcox <willy@...radead.org>,
Andrew Morton <akpm@...ux-foundation.org>,
Linux Memory Management List <linux-mm@...ck.org>,
linux-kernel@...r.kernel.org, LKP <lkp@...org>
Subject: [LKP] dd2283f260 [ 97.263072]
WARNING:at_kernel/locking/lockdep.c:#lock_downgrade
Greetings,
0day kernel testing robot got the below dmesg and the first bad commit is
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master
commit dd2283f2605e3b3e9c61bcae844b34f2afa4813f
Author: Yang Shi <yang.shi@...ux.alibaba.com>
AuthorDate: Fri Oct 26 15:07:11 2018 -0700
Commit: Linus Torvalds <torvalds@...ux-foundation.org>
CommitDate: Fri Oct 26 16:26:33 2018 -0700
mm: mmap: zap pages with read mmap_sem in munmap
Patch series "mm: zap pages with read mmap_sem in munmap for large
mapping", v11.
Background:
Recently, when we ran some vm scalability tests on machines with large memory,
we ran into a couple of mmap_sem scalability issues when unmapping large memory
space, please refer to https://lkml.org/lkml/2017/12/14/733 and
https://lkml.org/lkml/2018/2/20/576.
History:
Then akpm suggested to unmap large mapping section by section and drop mmap_sem
at a time to mitigate it (see https://lkml.org/lkml/2018/3/6/784).
V1 patch series was submitted to the mailing list per Andrew's suggestion
(see https://lkml.org/lkml/2018/3/20/786). Then I received a lot great
feedback and suggestions.
Then this topic was discussed on LSFMM summit 2018. In the summit, Michal
Hocko suggested (also in the v1 patches review) to try "two phases"
approach. Zapping pages with read mmap_sem, then doing via cleanup with
write mmap_sem (for discussion detail, see
https://lwn.net/Articles/753269/)
Approach:
Zapping pages is the most time consuming part, according to the suggestion from
Michal Hocko [1], zapping pages can be done with holding read mmap_sem, like
what MADV_DONTNEED does. Then re-acquire write mmap_sem to cleanup vmas.
But, we can't call MADV_DONTNEED directly, since there are two major drawbacks:
* The unexpected state from PF if it wins the race in the middle of munmap.
It may return zero page, instead of the content or SIGSEGV.
* Can't handle VM_LOCKED | VM_HUGETLB | VM_PFNMAP and uprobe mappings, which
is a showstopper from akpm
But, some part may need write mmap_sem, for example, vma splitting. So,
the design is as follows:
acquire write mmap_sem
lookup vmas (find and split vmas)
deal with special mappings
detach vmas
downgrade_write
zap pages
free page tables
release mmap_sem
The vm events with read mmap_sem may come in during page zapping, but
since vmas have been detached before, they, i.e. page fault, gup, etc,
will not be able to find valid vma, then just return SIGSEGV or -EFAULT as
expected.
If the vma has VM_HUGETLB | VM_PFNMAP, they are considered as special
mappings. They will be handled by falling back to regular do_munmap()
with exclusive mmap_sem held in this patch since they may update vm flags.
But, with the "detach vmas first" approach, the vmas have been detached
when vm flags are updated, so it sounds safe to update vm flags with read
mmap_sem for this specific case. So, VM_HUGETLB and VM_PFNMAP will be
handled by using the optimized path in the following separate patches for
bisectable sake.
Unmapping uprobe areas may need update mm flags (MMF_RECALC_UPROBES).
However it is fine to have false-positive MMF_RECALC_UPROBES according to
uprobes developer. So, uprobe unmap will not be handled by the regular
path.
With the "detach vmas first" approach we don't have to re-acquire mmap_sem
again to clean up vmas to avoid race window which might get the address
space changed since downgrade_write() doesn't release the lock to lead
regression, which simply downgrades to read lock.
And, since the lock acquire/release cost is managed to the minimum and
almost as same as before, the optimization could be extended to any size
of mapping without incurring significant penalty to small mappings.
For the time being, just do this in munmap syscall path. Other
vm_munmap() or do_munmap() call sites (i.e mmap, mremap, etc) remain
intact due to some implementation difficulties since they acquire write
mmap_sem from very beginning and hold it until the end, do_munmap() might
be called in the middle. But, the optimized do_munmap would like to be
called without mmap_sem held so that we can do the optimization. So, if
we want to do the similar optimization for mmap/mremap path, I'm afraid we
would have to redesign them. mremap might be called on very large area
depending on the usecases, the optimization to it will be considered in
the future.
This patch (of 3):
When running some mmap/munmap scalability tests with large memory (i.e.
> 300GB), the below hung task issue may happen occasionally.
INFO: task ps:14018 blocked for more than 120 seconds.
Tainted: G E 4.9.79-009.ali3000.alios7.x86_64 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
ps D 0 14018 1 0x00000004
ffff885582f84000 ffff885e8682f000 ffff880972943000 ffff885ebf499bc0
ffff8828ee120000 ffffc900349bfca8 ffffffff817154d0 0000000000000040
00ffffff812f872a ffff885ebf499bc0 024000d000948300 ffff880972943000
Call Trace:
[<ffffffff817154d0>] ? __schedule+0x250/0x730
[<ffffffff817159e6>] schedule+0x36/0x80
[<ffffffff81718560>] rwsem_down_read_failed+0xf0/0x150
[<ffffffff81390a28>] call_rwsem_down_read_failed+0x18/0x30
[<ffffffff81717db0>] down_read+0x20/0x40
[<ffffffff812b9439>] proc_pid_cmdline_read+0xd9/0x4e0
[<ffffffff81253c95>] ? do_filp_open+0xa5/0x100
[<ffffffff81241d87>] __vfs_read+0x37/0x150
[<ffffffff812f824b>] ? security_file_permission+0x9b/0xc0
[<ffffffff81242266>] vfs_read+0x96/0x130
[<ffffffff812437b5>] SyS_read+0x55/0xc0
[<ffffffff8171a6da>] entry_SYSCALL_64_fastpath+0x1a/0xc5
It is because munmap holds mmap_sem exclusively from very beginning to all
the way down to the end, and doesn't release it in the middle. When
unmapping large mapping, it may take long time (take ~18 seconds to unmap
320GB mapping with every single page mapped on an idle machine).
Zapping pages is the most time consuming part, according to the suggestion
from Michal Hocko [1], zapping pages can be done with holding read
mmap_sem, like what MADV_DONTNEED does. Then re-acquire write mmap_sem to
cleanup vmas.
But, some part may need write mmap_sem, for example, vma splitting. So,
the design is as follows:
acquire write mmap_sem
lookup vmas (find and split vmas)
deal with special mappings
detach vmas
downgrade_write
zap pages
free page tables
release mmap_sem
The vm events with read mmap_sem may come in during page zapping, but
since vmas have been detached before, they, i.e. page fault, gup, etc,
will not be able to find valid vma, then just return SIGSEGV or -EFAULT as
expected.
If the vma has VM_HUGETLB | VM_PFNMAP, they are considered as special
mappings. They will be handled by without downgrading mmap_sem in this
patch since they may update vm flags.
But, with the "detach vmas first" approach, the vmas have been detached
when vm flags are updated, so it sounds safe to update vm flags with read
mmap_sem for this specific case. So, VM_HUGETLB and VM_PFNMAP will be
handled by using the optimized path in the following separate patches for
bisectable sake.
Unmapping uprobe areas may need update mm flags (MMF_RECALC_UPROBES).
However it is fine to have false-positive MMF_RECALC_UPROBES according to
uprobes developer.
With the "detach vmas first" approach we don't have to re-acquire mmap_sem
again to clean up vmas to avoid race window which might get the address
space changed since downgrade_write() doesn't release the lock to lead
regression, which simply downgrades to read lock.
And, since the lock acquire/release cost is managed to the minimum and
almost as same as before, the optimization could be extended to any size
of mapping without incurring significant penalty to small mappings.
For the time being, just do this in munmap syscall path. Other
vm_munmap() or do_munmap() call sites (i.e mmap, mremap, etc) remain
intact due to some implementation difficulties since they acquire write
mmap_sem from very beginning and hold it until the end, do_munmap() might
be called in the middle. But, the optimized do_munmap would like to be
called without mmap_sem held so that we can do the optimization. So, if
we want to do the similar optimization for mmap/mremap path, I'm afraid we
would have to redesign them. mremap might be called on very large area
depending on the usecases, the optimization to it will be considered in
the future.
With the patches, exclusive mmap_sem hold time when munmap a 80GB address
space on a machine with 32 cores of E5-2680 @ 2.70GHz dropped to us level
from second.
munmap_test-15002 [008] 594.380138: funcgraph_entry: |
__vm_munmap() {
munmap_test-15002 [008] 594.380146: funcgraph_entry: !2485684 us
| unmap_region();
munmap_test-15002 [008] 596.865836: funcgraph_exit: !2485692 us
| }
Here the execution time of unmap_region() is used to evaluate the time of
holding read mmap_sem, then the remaining time is used with holding
exclusive lock.
[1] https://lwn.net/Articles/753269/
Link: http://lkml.kernel.org/r/1537376621-51150-2-git-send-email-yang.shi@linux.alibaba.com
Signed-off-by: Yang Shi <yang.shi@...ux.alibaba.com>Suggested-by: Michal Hocko <mhocko@...nel.org>
Suggested-by: Kirill A. Shutemov <kirill@...temov.name>
Suggested-by: Matthew Wilcox <willy@...radead.org>
Reviewed-by: Matthew Wilcox <willy@...radead.org>
Acked-by: Kirill A. Shutemov <kirill.shutemov@...ux.intel.com>
Acked-by: Vlastimil Babka <vbabka@...e.cz>
Cc: Laurent Dufour <ldufour@...ux.vnet.ibm.com>
Cc: Vlastimil Babka <vbabka@...e.cz>
Signed-off-by: Andrew Morton <akpm@...ux-foundation.org>
Signed-off-by: Linus Torvalds <torvalds@...ux-foundation.org>
a8dda165ec vfree: add debug might_sleep()
dd2283f260 mm: mmap: zap pages with read mmap_sem in munmap
5929a1f0ff Merge tag 'riscv-for-linus-4.20-rc2' of git://git.kernel.org/pub/scm/linux/kernel/git/palmer/riscv-linux
0bc80e3cb0 Add linux-next specific files for 20181114
+-----------------------------------------------------+------------+------------+------------+---------------+
| | a8dda165ec | dd2283f260 | 5929a1f0ff | next-20181114 |
+-----------------------------------------------------+------------+------------+------------+---------------+
| boot_successes | 314 | 178 | 190 | 168 |
| boot_failures | 393 | 27 | 21 | 40 |
| WARNING:held_lock_freed | 383 | 23 | 17 | 39 |
| is_freeing_memory#-#,with_a_lock_still_held_there | 383 | 23 | 17 | 39 |
| BUG:unable_to_handle_kernel | 5 | 2 | 4 | 1 |
| Oops:#[##] | 9 | 3 | 4 | 1 |
| EIP:debug_check_no_locks_freed | 9 | 3 | 4 | 1 |
| Kernel_panic-not_syncing:Fatal_exception | 9 | 3 | 4 | 1 |
| Mem-Info | 4 | 1 | | |
| invoked_oom-killer:gfp_mask=0x | 1 | 1 | | |
| WARNING:at_kernel/locking/lockdep.c:#lock_downgrade | 0 | 6 | 4 | 7 |
| EIP:lock_downgrade | 0 | 6 | 4 | 7 |
+-----------------------------------------------------+------------+------------+------------+---------------+
[ 96.288009] random: get_random_u32 called from arch_rnd+0x3c/0x70 with crng_init=0
[ 96.359626] input_id (331) used greatest stack depth: 6360 bytes left
[ 96.749228] grep (358) used greatest stack depth: 6336 bytes left
[ 96.921470] network.sh (341) used greatest stack depth: 6212 bytes left
[ 97.262340]
[ 97.262587] =========================
[ 97.263072] WARNING: held lock freed!
[ 97.263536] 4.19.0-06969-gdd2283f #1 Not tainted
[ 97.264110] -------------------------
[ 97.264575] udevd/198 is freeing memory 9c16c930-9c16c99b, with a lock still held there!
[ 97.265542] (ptrval) (&anon_vma->rwsem){....}, at: unlink_anon_vmas+0x14e/0x420
[ 97.266450] 1 lock held by udevd/198:
[ 97.266924] #0: (ptrval) (&mm->mmap_sem){....}, at: __do_munmap+0x531/0x730
[ 97.267773]
[ 97.267773] stack backtrace:
[ 97.268140] _warn_unseeded_randomness: 113 callbacks suppressed
[ 97.268148] random: get_random_u32 called from copy_process+0x673/0x2d80 with crng_init=0
[ 97.268310] CPU: 1 PID: 198 Comm: udevd Not tainted 4.19.0-06969-gdd2283f #1
[ 97.270901] Call Trace:
[ 97.271232] dump_stack+0xd6/0x11a
[ 97.271674] debug_check_no_locks_freed+0x249/0x2c0
[ 97.272311] kmem_cache_free+0x193/0x6e0
[ 97.272805] __put_anon_vma+0xd6/0x240
[ 97.273280] unlink_anon_vmas+0x362/0x420
[ 97.273793] free_pgtables+0x46/0x190
[ 97.274253] unmap_region+0x168/0x1b0
[ 97.274711] __do_munmap+0x558/0x730
[ 97.275164] __vm_munmap+0x92/0x120
[ 97.275604] sys_munmap+0x26/0x40
[ 97.276026] do_int80_syscall_32+0xfe/0x360
[ 97.276545] entry_INT80_32+0xda/0xda
[ 97.277036] EIP: 0x47f42d61
[ 97.277391] Code: c1 be a2 09 00 8b 89 08 ff ff ff 31 d2 29 c2 65 89 11 83 c8 ff eb d7 90 90 89 da 8b 4c 24 08 8b 5c 24 04 b8 5b 00 00 00 cd 80 <89> d3 3d 01 f0 ff ff 73 01 c3 e8 76 c3 03 00 81 c1 84 a2 09 00 8b
[ 97.279628] EAX: ffffffda EBX: 77f68000 ECX: 00001000 EDX: 47fdcff4
[ 97.280412] ESI: 08080da0 EDI: 00000000 EBP: 00000000 ESP: 7fbf1d08
[ 97.281182] DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 007b EFLAGS: 00000206
[ 97.376958] ------------[ cut here ]------------
[ 97.377600] downgrading a read lock
[ 97.377622] WARNING: CPU: 0 PID: 198 at kernel/locking/lockdep.c:3556 lock_downgrade+0x20c/0x3a0
[ 97.379416] CPU: 0 PID: 198 Comm: udevd Not tainted 4.19.0-06969-gdd2283f #1
[ 97.380330] EIP: lock_downgrade+0x20c/0x3a0
[ 97.380896] Code: 05 78 7a 95 84 01 c7 04 24 4f 5e b9 83 89 45 e0 83 15 7c 7a 95 84 00 e8 e2 5c f5 ff 83 05 80 7a 95 84 01 83 15 84 7a 95 84 00 <0f> 0b 8b 45 ec 83 05 88 7a 95 84 01 89 45 e8 8b 45 e0 83 15 8c 7a
[ 97.383256] EAX: 00000017 EBX: 9d6adc80 ECX: 00000000 EDX: 000002dc
[ 97.384100] ESI: 00000001 EDI: 8141bb11 EBP: 9c1b5ee8 ESP: 9c1b5ec0
[ 97.384938] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00010046
[ 97.385831] CR0: 80050033 CR2: 77f68000 CR3: 1c11d000 CR4: 00140690
[ 97.386641] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 97.387443] DR6: fffe0ff0 DR7: 00000400
[ 97.387980] Call Trace:
[ 97.388333] downgrade_write+0x3d/0x1b0
[ 97.388865] __do_munmap+0x531/0x730
[ 97.389406] __vm_munmap+0x92/0x120
[ 97.389891] sys_munmap+0x26/0x40
[ 97.390351] do_int80_syscall_32+0xfe/0x360
[ 97.390923] entry_INT80_32+0xda/0xda
[ 97.391437] EIP: 0x47f42d61
[ 97.391813] Code: c1 be a2 09 00 8b 89 08 ff ff ff 31 d2 29 c2 65 89 11 83 c8 ff eb d7 90 90 89 da 8b 4c 24 08 8b 5c 24 04 b8 5b 00 00 00 cd 80 <89> d3 3d 01 f0 ff ff 73 01 c3 e8 76 c3 03 00 81 c1 84 a2 09 00 8b
[ 97.394148] EAX: ffffffda EBX: 77f68000 ECX: 00001000 EDX: 47fdcff4
[ 97.394945] ESI: 08080da0 EDI: 00000000 EBP: 00000000 ESP: 7fbf1d08
[ 97.395759] DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 007b EFLAGS: 00000206
[ 97.396628] ---[ end trace 2d49d562090f3ba6 ]---
[ 97.502082] random: get_random_u32 called from arch_rnd+0x3c/0x70 with crng_init=0
# HH:MM RESULT GOOD BAD GOOD_BUT_DIRTY DIRTY_NOT_BAD
git bisect start ccda4af0f4b92f7b4c308d3acc262f4a7e3affad v4.19 --
git bisect bad ac435075892e3e651c667b4a9f2267cf3ef1d5a2 # 01:46 B 4 1 3 3 Merge tag 'csky-for-linus-4.20' of https://github.com/c-sky/csky-linux
git bisect good 01aa9d518eae8a4d75cd3049defc6ed0b6d0a658 # 03:05 G 42 0 6 6 Merge tag 'docs-4.20' of git://git.lwn.net/linux
git bisect good 26873acacbdbb4e4b444f5dd28dcc4853f0e8ba2 # 03:30 G 44 0 4 4 Merge tag 'driver-core-4.20-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/gregkh/driver-core
git bisect good a45dcff7489f7cb21a3a8e967a90ea41b31c1559 # 03:49 G 44 0 8 8 Merge git://git.kernel.org/pub/scm/linux/kernel/git/davem/sparc
git bisect bad 5ecf3e110c32c5756351eed067cdf6a91c308e62 # 04:07 B 17 1 1 1 Merge tag 'linux-watchdog-4.20-rc1' of git://www.linux-watchdog.org/linux-watchdog
git bisect bad b59dfdaef173677b0b7e10f375226c0a1114fd20 # 04:35 B 20 1 5 5 i2c-hid: properly terminate i2c_hid_dmi_desc_override_table[] array
git bisect good 4904008165c8a1c48602b8316139691b8c735e6e # 05:48 G 200 0 24 24 Merge git://git.kernel.org/pub/scm/linux/kernel/git/davem/net
git bisect bad 345671ea0f9258f410eb057b9ced9cefbbe5dc78 # 06:13 B 31 1 5 5 Merge branch 'akpm' (patches from Andrew)
git bisect good 4b85afbdacd290c7a22c96df40a6433fdcacb509 # 06:53 G 205 0 101 101 mm: zero-seek shrinkers
git bisect bad 85a06835f6f1ba79f0f00838ccd5ad840dd1eafb # 07:24 B 61 3 34 34 mm: mremap: downgrade mmap_sem to read when shrinking
git bisect bad 85cfb245060e45640fa3447f8b0bad5e8bd3bdaf # 07:43 B 20 1 2 2 memcg: remove memcg_kmem_skip_account
git bisect bad dd2283f2605e3b3e9c61bcae844b34f2afa4813f # 08:02 B 15 1 0 0 mm: mmap: zap pages with read mmap_sem in munmap
git bisect good dedf2c73b80b4566dfcae8ebe9ed46a38b63a1f9 # 08:36 G 196 0 33 33 mm/mempolicy.c: use match_string() helper to simplify the code
git bisect good 3ca4ea3a7a78a243ee9edf71a2736bc8fb26d70f # 10:40 G 197 0 31 31 mm/vmalloc.c: improve vfree() kerneldoc
git bisect good a8dda165ec34fac2b4119654330150e2c896e531 # 11:28 G 202 0 114 115 vfree: add debug might_sleep()
# first bad commit: [dd2283f2605e3b3e9c61bcae844b34f2afa4813f] mm: mmap: zap pages with read mmap_sem in munmap
git bisect good a8dda165ec34fac2b4119654330150e2c896e531 # 12:17 G 585 0 283 399 vfree: add debug might_sleep()
# extra tests with debug options
git bisect bad dd2283f2605e3b3e9c61bcae844b34f2afa4813f # 12:38 B 14 1 4 4 mm: mmap: zap pages with read mmap_sem in munmap
# extra tests on HEAD of linux-devel/devel-hourly-2018111421
git bisect bad ead84f4ee6640e1bda88302f402bf5f2e0cf78ec # 12:38 B 5 3 0 5 0day head guard for 'devel-hourly-2018111421'
# extra tests on tree/branch linus/master
git bisect bad 5929a1f0ff30d04ccf4b0f9c648e7aa8bc816bbd # 12:59 B 36 1 8 8 Merge tag 'riscv-for-linus-4.20-rc2' of git://git.kernel.org/pub/scm/linux/kernel/git/palmer/riscv-linux
# extra tests on tree/branch linux-next/master
git bisect bad 0bc80e3cb0c14878ae0a7779d46f1192221f080e # 13:19 B 57 3 14 14 Add linux-next specific files for 20181114
---
0-DAY kernel test infrastructure Open Source Technology Center
https://lists.01.org/pipermail/lkp Intel Corporation
Download attachment "dmesg-yocto-lkp-kboot01-3:20181115080451:i386-randconfig-c0-11142356:4.19.0-06969-gdd2283f:1.gz" of type "application/gzip" (18270 bytes)
Download attachment "dmesg-vm-lkp-hsw-4ep1-quantal-i386-24:20181115110127:i386-randconfig-c0-11142356:4.19.0-06968-ga8dda16:1.gz" of type "application/gzip" (27226 bytes)
View attachment "reproduce-yocto-lkp-kboot01-3:20181115080451:i386-randconfig-c0-11142356:4.19.0-06969-gdd2283f:1" of type "text/plain" (920 bytes)
View attachment "config-4.19.0-06969-gdd2283f" of type "text/plain" (116267 bytes)
Powered by blists - more mailing lists