lists.openwall.net   lists  /  announce  owl-users  owl-dev  john-users  john-dev  passwdqc-users  yescrypt  popa3d-users  /  oss-security  kernel-hardening  musl  sabotage  tlsify  passwords  /  crypt-dev  xvendor  /  Bugtraq  Full-Disclosure  linux-kernel  linux-netdev  linux-ext4  linux-hardening  linux-cve-announce  PHC 
Open Source and information security mailing list archives
 
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<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

Powered by Openwall GNU/*/Linux Powered by OpenVZ