kernel issue tracked in THP huge page

Posted on December 25, 2014

/ written @2014, by chen xi/

Kernel version:2.6.32
Checked: KSM , THP

LOG:

<4>————[ cut here ]————

<2>kernel BUG at mm/huge_memory.c:1194!

<4>invalid opcode: 0000 [#1] SMP

<4>last sysfs file: /sys/devices/pci0000:00/0000:00:11.0/0000:06:00.0/host7/scsi_host/host7/proc_name

<4>CPU 1

<4>Modules linked in: nf_conntrack bonding 8021q garp stp llc ipv6 openvswitch(U) libcrc32c iptable_filter ip_tables sg igb dca microcode serio_raw i2c_i801 i2c_core iTCO_wdt iTCO_vendor_support shpchp ext4 mbcache jbd2 sd_mod crc_t10dif isci libsas scsi_transport_sas ahci megaraid_sas wmi dm_mirror dm_region_hash dm_log dm_mod [last unloaded: scsi_wait_scan]

<4>

<4>Pid: 3084, comm: redis-server Tainted: G ————— H 2.6.32-279.19.5.el6.ucloud.x86_64 #1 Huawei Technologies Co., Ltd. Tecal RH2288H V2-12L/BC11SRSG1

<4>RIP: 0010:[] [] split_huge_page+0x802/0x850

<4>RSP: 0018:ffff880c5edddbd8 EFLAGS: 00010086

<4>RAX: 00000000ffffffff RBX: ffffea0029333970 RCX: ffffc9000c06b000

<4>RDX: 0000000000000002 RSI: ffff880c61fe9c00 RDI: 0000000000000004

<4>RBP: ffff880c5edddca8 R08: 0000000000000064 R09: 0000000000000001

<4>R10: 0000000000000106 R11: ffff880c5941f300 R12: ffffea0029334000

<4>R13: 0000000000000000 R14: ffffea002932d000 R15: 00000007fcd17be1

<4>FS: 00007fcd25858720(0000) GS:ffff880053820000(0000) knlGS:0000000000000000

<4>CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b

<4>CR2: 00007f7086a8a740 CR3: 0000000c57daf000 CR4: 00000000001406e0

<4>DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000

<4>DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400

<4>Process redis-server (pid: 3084, threadinfo ffff880c5eddc000, task ffff880c5941e940)

<4>Stack:

<4> 0000000000000002 0000000000000000 0000000000000000 ffff880c00000001

<4> ffff880c5edddc78 ffff88184155d5f0 0000000000000000 ffffffff81180f9b

<4> ffff88184155d630 ffffffff810a9f0d ffffea0052938e78 0000000180010f40

<4>Call Trace:

<4> [] ? __split_huge_page_pmd+0x2b/0xc0

<4> [] ? trace_hardirqs_on_caller+0x14d/0x190

<4> [] __split_huge_page_pmd+0x80/0xc0

<4> [] unmap_vmas+0xa34/0xc00

<4> [] zap_page_range+0x7d/0xe0

<4> [] sys_madvise+0x54d/0x770

<4> [] ? thread_return+0x4e/0x7d3

<4> [] ? trace_hardirqs_on_caller+0x14d/0x190

<4> [] ? trace_hardirqs_on_thunk+0x3a/0x3f

<4> [] system_call_fastpath+0x16/0x1b

<4>Code: 83 c1 01 e8 69 5e 38 00 0f 0b eb fe 0f 0b eb fe 0f 0b 0f 1f 80 00 00 00 00 eb f7 0f 0b eb fe 0f 0b 0f 1f 84 00 00 00 00 00 eb f6 <0f> 0b eb fe 0f 0b 0f 1f 84 00 00 00 00 00 eb f6 0f 0b eb fe 0f

<1>RIP [] split_huge_page+0x802/0x850

<4> RSP

结合代码： 找到的call path:

<上面的back trace中， >

unmap_vmas
    --unmap_page_range
        --zap_pud_range
            --zap_pmd_range
                --split_huge_page_pmd
                    --__split_huge_page_pmd
                        --split_huge_page
                            --__split_huge_page
                                --__split_huge_page_refcount

line: 1194行如上：

【汇编code】： objdump vmlinux之后， 因为很多函数是static inline的， 所以system map里面找到jump地址，要到调用函数里面去找。

RAX: 00000000ffffffff

RBX: ffffea0029333970

R12: ffffea0029334000

触发原因： eax的值是-1;

eax放的是： add $0x1, %eax <——-> atomic_read(&(page)->_mapcount) + 1;

即： _mapcount的值是-2， 相加之后出现了-1值。

现象是 mapcount出现了理论上不应该也不能出现的值；

mapcount:

    • Count of ptes mapped in
    • mms, to show when page is
    • mapped & limit reverse map
    • searches.

start from “-1”；

经过分析， 理论上此处的mapcount值是 -1

BUG_ON(page_mapcount(page_tail) < 0); 判断值是0 ，就不会出现BUG。

而改写的值不是脏值，看起来像是被减一后出现的。

都是在 put_compound_page中。。。

经过搜索

得到下面的一个记录：

+====== start quote =======

  • mapcount 0 page_mapcount 1
  • kernel BUG at mm/huge_memory.c:1384!
    • +At some point prior to the panic, a “bad pmd …” message similar to the
      +following is logged on the console:
      +
  • mm/memory.c:145: bad pmd ffff8800376e1f98(80000000314000e7).
    • +The “bad pmd …” message is logged by pmd_clear_bad() before it clears
      +the page’s PMD table entry.
      +
  • 143 void pmd_clear_bad(pmd_t *pmd)
  • 144 {
    +-> 145 pmd_ERROR(*pmd);
  • 146 pmd_clear(pmd);
  • 147 }
    • +After the PMD table entry has been cleared, there is an inconsistency
      +between the actual number of PMD table entries that are mapping the page
      +and the page’s map count (_mapcount field in struct page). When the page
      +is subsequently reclaimed, __split_huge_page() detects this inconsistency.
      +
  • 1381 if (mapcount != page_mapcount(page))
  • 1382 printk(KERN_ERR “mapcount %d page_mapcount %d\n”,
  • 1383 mapcount, page_mapcount(page));
    +-> 1384 BUG_ON(mapcount != page_mapcount(page));
    • +The root cause of the problem is a race of two threads in a multithreaded
      +process. Thread B incurs a page fault on a virtual address that has never
      +been accessed (PMD entry is zero) while Thread A is executing an madvise()
      +system call on a virtual address within the same 2 MB (huge page) range.
      +
  • virtual address space
  • .———————.
  •  
  •  
  • .- ———————
  •    
  •     <– B(fault)
  •    
  • 2 MB   ///////////////////// -.
  • huge < ///////////////////// > A(range)
  • page   ///////////////////// -‘
  •    
  •    
  • ‘- ———————
  •  
  •  
  • ‘———————‘
    • +- Thread A is executing an madvise(…, MADV_DONTNEED) system call
  • on the virtual address range “A(range)” shown in the picture.
    • +sys_madvise
  • // Acquire the semaphore in shared mode.
  • down_read(&current->mm->mmap_sem)
  • …
  • madvise_vma
  • switch (behavior)
  • case MADV_DONTNEED:
  • madvise_dontneed
  • zap_page_range
  • unmap_vmas
  • unmap_page_range
  • zap_pud_range
  • zap_pmd_range
  • //
  • // Assume that this huge page has never been accessed.
  • // I.e. content of the PMD entry is zero (not mapped).
  • //
  • if (pmd_trans_huge(*pmd)) {
  • // We don’t get here due to the above assumption.
  • }
  • //
  • // Assume that Thread B incurred a page fault and
  • .———> // sneaks in here as shown below.
  • //
  • if (pmd_none_or_clear_bad(pmd))
  • {
  • if (unlikely(pmd_bad(*pmd)))
  • pmd_clear_bad
  • {
  • pmd_ERROR
  • // Log “bad pmd …” message here.
  • pmd_clear
  • // Clear the page’s PMD entry.
  • // Thread B incremented the map count
  • // in page_add_new_anon_rmap(), but
  • // now the page is no longer mapped
  • // by a PMD entry (-> inconsistency).
  • }
  • }
  • v
    +- Thread B is handling a page fault on virtual address “B(fault)” shown
  • in the picture.
    • +…
      +do_page_fault
  • __do_page_fault
  • // Acquire the semaphore in shared mode.
  • down_read_trylock(&mm->mmap_sem)
  • …
  • handle_mm_fault
  • if (pmd_none(*pmd) && transparent_hugepage_enabled(vma))
  • // We get here due to the above assumption (PMD entry is zero).
  • do_huge_pmd_anonymous_page
  • alloc_hugepage_vma
  • // Allocate a new transparent huge page here.
  • …
  • __do_huge_pmd_anonymous_page
  • …
  • spin_lock(&mm->page_table_lock)
  • …
  • page_add_new_anon_rmap
  • // Here we increment the page’s map count (starts at -1).
  • atomic_set(&page->_mapcount, 0)
  • set_pmd_at
  • // Here we set the page’s PMD entry which will be cleared
  • // when Thread A calls pmd_clear_bad().
  • …
  • spin_unlock(&mm->page_table_lock)
    • +The mmap_sem does not prevent the race because both threads are acquiring
      +it in shared mode (down_read). Thread B holds the page_table_lock while
      +the page’s map count and PMD table entry are updated. However, Thread A
      +does not synchronize on that lock.
    • +====== end quote =======

通过上面的分析， 和目前的情况。。。。。。

有理由判断：multi thread的情况出现（函数调用过程中，嵌套了多个循环，multi thread的执行是有各种条件的。

The mmap_sem does not prevent the race because both threads are acquiring
+it in shared mode (down_read). Thread B holds the page_table_lock while
+the page’s map count and PMD table entry are updated. However, Thread A
+does not synchronize on that lock.

需要进一步判断，具体哪里触发的。。。。。

已经怎么构造测试的环境。。。。