[LU-13414] Page allocation failure: order 1 Created: 03/Apr/20  Updated: 15/Aug/20  Resolved: 15/Aug/20

Status: Resolved
Project: Lustre
Component/s: None
Affects Version/s: Lustre 2.12.3
Fix Version/s: None

Type: Bug Priority: Critical
Reporter: Mahmoud Hanafi Assignee: Serguei Smirnov
Resolution: Duplicate Votes: 0
Labels: None

Attachments: Text File host1.2020_03_13.dmesg.txt     Text File host1.2020_03_20.dmesg.txt     Text File host2.2020_04_16.dmesg.txt    
Severity: 2
Rank (Obsolete): 9223372036854775807

 Description   

Client crashed with page allocation

[1585943028.070342] Lustre: 4989:0:(client.c:2133:ptlrpc_expire_one_request()) Skipped 6 previous similar messages^M

[1585943028.082342] Lustre: nbp1-MDT0000-mdc-ffff95b11d94a000: Connection to nbp1-MDT0000 (at 10.151.26.117@o2ib) was lost; in progress operations using this service will wait for recovery to complete^M

[1585943985.970771] ldlm_bl_58: page allocation failure: order:1, mode:0x1604040(GFP_NOFS|__GFP_COMP|__GFP_NOTRACK), nodemask=(null)^M

[1585943985.982770] ldlm_bl_110: ^M

[1585943985.986770] ldlm_bl_09: page allocation failure: order:1, mode:0x1604040(GFP_NOFS|__GFP_COMP|__GFP_NOTRACK), nodemask=(null)^M

[1585943985.998770] CPU: 13 PID: 42680 Comm: ldlm_bl_09 Tainted: G           OE      4.12.14-95.48.1.20200304-nasa #1 SLE12-SP4 (unreleased)^M

[1585943986.010769] Hardware name: SGI.COM C1104-RP7/X9DRW-3LN4F+/X9DRW-3TF+, BIOS 3.00 09/12/2013^M

[1585943986.018769] Call Trace:^M

[1585943986.022769]  dump_stack+0x5a/0x75^M

[1585943986.022769]  warn_alloc+0xf0/0x190^M

[1585943986.026769]  __alloc_pages_slowpath+0x865/0xa0d^M

[1585943986.034768]  __alloc_pages_nodemask+0x1e9/0x210^M

[1585943986.038768]  cache_grow_begin+0x85/0x560^M

[1585943986.042768]  fallback_alloc+0x167/0x1f0^M

[1585943986.046768]  kmem_cache_alloc+0x187/0x1d0^M

[1585943986.050768]  ptlrpc_request_cache_alloc+0x26/0x100 [ptlrpc]^M

[1585943986.058767] ldlm_bl_10: page allocation failure: order:1^M

[1585943986.062767]  ptlrpc_request_alloc_internal+0x1e/0x540 [ptlrpc]^M

[1585943986.070767] , mode:0x1604040(GFP_NOFS|__GFP_COMP|__GFP_NOTRACK), nodemask=^M

[1585943986.078767]  ldlm_cli_cancel_req+0x161/0x6c0 [ptlrpc]^M

[1585943986.082767] (null)^M

[1585943986.082767]  ldlm_cli_cancel_list+0x268/0x3b0 [ptlrpc]^M

[1585943986.090766] / mems_allowed=0-1^M

[1585943986.094766]  ldlm_bl_thread_main+0x3d1/0x8b0 [ptlrpc]^M

[1585943986.098766] ldlm_bl_02: page allocation failure: order:1^M

[1585943986.106766]  ? wake_up_q+0x70/0x70^M

[1585943986.110766] , mode:0x1604040(GFP_NOFS|__GFP_COMP|__GFP_NOTRACK), nodemask=^M

[1585943986.114765]  kthread+0xff/0x140^M

[1585943986.118765] (null)^M

[1585943986.122765]  ? ldlm_handle_bl_callback+0x4d0/0x4d0 [ptlrpc]^M

[1585943986.126765]  ? __kthread_parkme+0x70/0x70^M

[1585943986.130765] /^M

[1585943986.134765]  ret_from_fork+0x35/0x40^M

[1585943986.138764]  mems_allowed=0-1^M

[1585943986.142764] CPU: 2 PID: 46182 Comm: ldlm_bl_10 Tainted: G           OE      4.12.14-95.48.1.20200304-nasa #1 SLE12-SP4 (unreleased)^M

[1585943986.154764] Mem-Info:^M

[1585943986.158764] Hardware name: SGI.COM C1104-RP7/X9DRW-3LN4F+/X9DRW-3TF+, BIOS 3.00 09/12/2013^M

[1585943986.166763] Call Trace:^M

[1585943986.166763] active_anon:5278063 inactive_anon:527834 isolated_anon:0^M

[1585943986.166763]  active_file:829456 inactive_file:220089 isolated_file:0^M

[1585943986.166763]  unevictable:20 dirty:37 writeback:7936 unstable:0^M

[1585943986.166763]  slab_reclaimable:480664 slab_unreclaimable:7863786^M

[1585943986.166763]  mapped:125735 shmem:15500 pagetables:35760 bounce:0^M

[1585943986.166763]  free:63139 free_pcp:4009 free_cma:0^M

[1585943986.206762]  dump_stack+0x5a/0x75^M

[1585943986.210762] Node 0 active_anon:11355416kB inactive_anon:1135584kB active_file:2393776kB inactive_file:573716kB unevictable:80kB isolated(anon):0kB isolated(file):0kB mapped:297864kB dirty:96kB writeback:18944kB shmem:41224kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 991232kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no^M

[1585943986.238761]  warn_alloc+0xf0/0x190^M

[1585943986.242761] Node 1 active_anon:9756836kB inactive_anon:975752kB active_file:924048kB inactive_file:306640kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:205076kB dirty:52kB writeback:12800kB shmem:20776kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 6144kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no^M

[1585943986.270760]  __alloc_pages_slowpath+0x865/0xa0d^M

[1585943986.278759] Node 0 DMA free:4kB min:60kB low:72kB high:84kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15920kB managed:15748kB mlocked:0kB slab_reclaimable:0kB slab_unreclaimable:15744kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB^M


 Comments   
Comment by Andreas Dilger [ 03/Apr/20 ]

Hi Mahmoud, this doesn't look like a "crash" per-se, but a warning that a memory allocation failed (only 8KB), along with a stack dump of that process (which happens to be a Lustre thread, but that isn't necessarily indicative of the source of the problem).

How much RAM does this client have? It looks like about 30GB of RAM is accounted for in the messages shown here. You can check the Lustre internal memory allocations via "lctl get_param '*memused'" (bytes allocated by Lustre and LNet, excluding page cache used for file data). You could also check "top" for big applications running, or "slabtop" to see if there are a large number of allocations that would indicate what the source of the memory usage is.

Comment by Mahmoud Hanafi [ 04/Apr/20 ]

You are correct the memory allocation didn't cause the crash. Here is what the crash dump shows

crash> sys
      KERNEL: vmlinux-4.12.14-95.48.1.20200304-nasa.gz
   DEBUGINFO: /usr/lib/debug/boot/vmlinux-4.12.14-95.48.1.20200304-nasa.debug
    DUMPFILE: vmcore  [PARTIAL DUMP]
        CPUS: 32 [OFFLINE: 16]
        DATE: Fri Apr  3 12:59:48 2020
      UPTIME: 22:03:05
LOAD AVERAGE: 37.92, 14.87, 8.24
       TASKS: 1626
    NODENAME: pfe20
     RELEASE: 4.12.14-95.48.1.20200304-nasa
     VERSION: #1 SMP Thu Feb 27 07:40:02 UTC 2020 (ddfe57a)
     MACHINE: x86_64  (2600 Mhz)
      MEMORY: 64 GB
       PANIC: "BUG: unable to handle kernel NULL pointer dereference at 0000000000000024"
crash> bt
PID: 4981   TASK: ffff95b11e8d9440  CPU: 0   COMMAND: "ptlrpcd_00_05"
 #0 [fffffe0000009c20] machine_kexec at ffffffffa705e9f2
 #1 [fffffe0000009c70] __crash_kexec at ffffffffa7120fea
 #2 [fffffe0000009d30] crash_kexec at ffffffffa7122009
 #3 [fffffe0000009d48] kdb_kdump_check at ffffffffa714c056
 #4 [fffffe0000009d50] kdb_main_loop at ffffffffa714c282
 #5 [fffffe0000009d88] kdb_stub at ffffffffa714f058
 #6 [fffffe0000009db0] kgdb_cpu_enter at ffffffffa71451fd
 #7 [fffffe0000009e08] kgdb_nmicallback at ffffffffa7145747
 #8 [fffffe0000009e58] kgdb_nmi_handler at ffffffffa7062d18
 #9 [fffffe0000009e68] nmi_handle at ffffffffa702ebe9
#10 [fffffe0000009eb8] default_do_nmi at ffffffffa702f05e
#11 [fffffe0000009ed0] do_nmi at ffffffffa702f21a
#12 [fffffe0000009ef0] end_repeat_nmi at ffffffffa7801b60
    [exception RIP: _raw_spin_lock+20]
    RIP: ffffffffa76d2da4  RSP: ffffb2fd0b66bb30  RFLAGS: 00000246
    RAX: 0000000000000000  RBX: ffff95a65ec63880  RCX: 0000000000000000
    RDX: 0000000000000001  RSI: 0000000000000000  RDI: ffff95a91e38ee40
    RBP: 0000000000000000   R8: ffff95b11dbadd00   R9: 0000000000000000
    R10: 0000000000000000  R11: ffff95a3bba8d400  R12: 0000000000000000
    R13: ffff95a30646dc18  R14: 0000000000000000  R15: 0000000000000001
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
--- <NMI exception stack> ---
#13 [ffffb2fd0b66bb30] _raw_spin_lock at ffffffffa76d2da4
#14 [ffffb2fd0b66bb30] LNetMDBind at ffffffffc0c1977a [lnet]
#15 [ffffb2fd0b66bb68] ptl_send_buf at ffffffffc0f4d6cf [ptlrpc]
#16 [ffffb2fd0b66bc20] ptl_send_rpc at ffffffffc0f4f26f [ptlrpc]
#17 [ffffb2fd0b66bcd8] ptlrpc_send_new_req at ffffffffc0f45313 [ptlrpc]
#18 [ffffb2fd0b66bd30] ptlrpc_check_set at ffffffffc0f4814e [ptlrpc]
#19 [ffffb2fd0b66bdc0] ptlrpcd_check at ffffffffc0f72c41 [ptlrpc]
#20 [ffffb2fd0b66be10] ptlrpcd at ffffffffc0f72fb3 [ptlrpc]
#21 [ffffb2fd0b66bf10] kthread at ffffffffa70a8d5f
#22 [ffffb2fd0b66bf50] ret_from_fork at ffffffffa7800235
Comment by Peter Jones [ 06/Apr/20 ]

Serguei

Could you please investigate?

Thanks

Peter

Comment by Mahmoud Hanafi [ 06/Apr/20 ]

We have started to see this after upgrading to sles 4.12.14-95.48.1 kernel

Comment by Mahmoud Hanafi [ 06/Apr/20 ]

We had 2 more crashes. One on the same host and one on a different host:
All are preceded by Allocation failures.

crash> sys
      KERNEL: vmlinux-4.12.14-95.48.1.20200304-nasa
   DEBUGINFO: /usr/lib/debug/boot/vmlinux-4.12.14-95.48.1.20200304-nasa.debug
    DUMPFILE: vmcore  [PARTIAL DUMP]
        CPUS: 32 [OFFLINE: 16]
        DATE: Fri Apr  3 19:39:42 2020
      UPTIME: 05:59:14
LOAD AVERAGE: 18.53, 9.07, 7.55
       TASKS: 1024
    NODENAME: pfe20
     RELEASE: 4.12.14-95.48.1.20200304-nasa
     VERSION: #1 SMP Thu Feb 27 07:40:02 UTC 2020 (ddfe57a)
     MACHINE: x86_64  (2599 Mhz)
      MEMORY: 64 GB
       PANIC: "BUG: unable to handle kernel "
crash> bt
PID: 2579   TASK: ffff901c75258c80  CPU: 0   COMMAND: "ptlrpcd_00_06"
 #0 [fffffe0000009c20] machine_kexec at ffffffff8705e9f2
 #1 [fffffe0000009c70] __crash_kexec at ffffffff87120fea
 #2 [fffffe0000009d30] crash_kexec at ffffffff87122009
 #3 [fffffe0000009d48] kdb_kdump_check at ffffffff8714c056
 #4 [fffffe0000009d50] kdb_main_loop at ffffffff8714c282
 #5 [fffffe0000009d88] kdb_stub at ffffffff8714f058
 #6 [fffffe0000009db0] kgdb_cpu_enter at ffffffff871451fd
 #7 [fffffe0000009e08] kgdb_nmicallback at ffffffff87145747
 #8 [fffffe0000009e58] kgdb_nmi_handler at ffffffff87062d18
 #9 [fffffe0000009e68] nmi_handle at ffffffff8702ebe9
#10 [fffffe0000009eb8] default_do_nmi at ffffffff8702f05e
#11 [fffffe0000009ed0] do_nmi at ffffffff8702f21a
#12 [fffffe0000009ef0] end_repeat_nmi at ffffffff87801b60
    [exception RIP: native_queued_spin_lock_slowpath+215]
    RIP: ffffffff870d6c17  RSP: ffffa4f84b613bc8  RFLAGS: 00000246
    RAX: 0000000000000000  RBX: ffff90249ef6eec0  RCX: 0000000000040000
    RDX: ffff901c9fa23a00  RSI: ffff901c9fbe3a00  RDI: ffff901d44ee9380
    RBP: ffffa4f84b613c18   R8: 0000000000000001   R9: ffff9017d9c98d20
    R10: 00000000000003f2  R11: ffffffffffffff83  R12: 0000000000000012
    R13: 0000000000000000  R14: 0005e87a31117950  R15: ffff9017d9c98d20
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
--- <NMI exception stack> ---
#13 [ffffa4f84b613bc8] native_queued_spin_lock_slowpath at ffffffff870d6c17
#14 [ffffa4f84b613bc8] queued_spin_lock_slowpath at ffffffff871afb8b
#15 [ffffa4f84b613bd0] LNetMEAttach at ffffffffc0e13f74 [lnet]
#16 [ffffa4f84b613c20] ptl_send_rpc at ffffffffc12c3ff2 [ptlrpc]
#17 [ffffa4f84b613c48] __switch_to_asm at ffffffff878001c4
#18 [ffffa4f84b613c80] __switch_to_asm at ffffffff878001d0
#19 [ffffa4f84b613cd8] ptlrpc_send_new_req at ffffffffc12ba313 [ptlrpc]
#20 [ffffa4f84b613d30] ptlrpc_check_set at ffffffffc12bd14e [ptlrpc]
#21 [ffffa4f84b613dc0] ptlrpcd_check at ffffffffc12e7c41 [ptlrpc]
#22 [ffffa4f84b613e10] ptlrpcd at ffffffffc12e7fb3 [ptlrpc]
#23 [ffffa4f84b613f10] kthread at ffffffff870a8d5f
#24 [ffffa4f84b613f50] ret_from_fork at ffffffff87800235

crash> sys
      KERNEL: vmlinux-4.12.14-95.48.1.20200304-nasa
   DEBUGINFO: /usr/lib/debug/boot/vmlinux-4.12.14-95.48.1.20200304-nasa.debug
    DUMPFILE: vmcore  [PARTIAL DUMP]
        CPUS: 40
        DATE: Sat Apr  4 14:00:34 2020
      UPTIME: 05:08:49
LOAD AVERAGE: 73.86, 42.59, 19.62
       TASKS: 692
    NODENAME: hw-console02
     RELEASE: 4.12.14-95.48.1.20200304-nasa
     VERSION: #1 SMP Thu Feb 27 07:40:02 UTC 2020 (ddfe57a)
     MACHINE: x86_64  (2793 Mhz)
      MEMORY: 63.9 GB
       PANIC: "BUG: unable to handle kernel "
crash> bt
PID: 2627   TASK: ffff9ed7d6d91580  CPU: 0   COMMAND: "ptlrpcd_00_03"
 #0 [fffffe0000009c20] machine_kexec at ffffffff8d05e9f2
 #1 [fffffe0000009c70] __crash_kexec at ffffffff8d120fea
 #2 [fffffe0000009d30] crash_kexec at ffffffff8d122009
 #3 [fffffe0000009d48] kdb_kdump_check at ffffffff8d14c056
 #4 [fffffe0000009d50] kdb_main_loop at ffffffff8d14c282
 #5 [fffffe0000009d88] kdb_stub at ffffffff8d14f058
 #6 [fffffe0000009db0] kgdb_cpu_enter at ffffffff8d1451fd
 #7 [fffffe0000009e08] kgdb_nmicallback at ffffffff8d145747
 #8 [fffffe0000009e58] kgdb_nmi_handler at ffffffff8d062d18
 #9 [fffffe0000009e68] nmi_handle at ffffffff8d02ebe9
#10 [fffffe0000009eb8] default_do_nmi at ffffffff8d02f05e
#11 [fffffe0000009ed0] do_nmi at ffffffff8d02f21a
#12 [fffffe0000009ef0] end_repeat_nmi at ffffffff8d801b60
    [exception RIP: lnet_res_lh_lookup+62]
    RIP: ffffffffc0e62f0e  RSP: ffffb3e64e36fbb8  RFLAGS: 00000206
    RAX: 0000000000000000  RBX: 0000000000000001  RCX: ffffb3e64bad5480
    RDX: ffff9ed94dc04918  RSI: 0000000011827a45  RDI: ffff9edfff4ee080
    RBP: ffffb3e64e36fc90   R8: 00000000001c0000   R9: 0000000000000001
    R10: 00000000000000ec  R11: 0000000200024108  R12: 0000000011827a45
    R13: 0000000004609e91  R14: 0000000000000000  R15: ffff9ed945eeca28
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
--- <NMI exception stack> ---
#13 [ffffb3e64e36fbb8] lnet_res_lh_lookup at ffffffffc0e62f0e [lnet]
#14 [ffffb3e64e36fbb8] LNetMDUnlink at ffffffffc0e74759 [lnet]
#15 [ffffb3e64e36fc98] ptlrpc_unregister_reply at ffffffffc12d5132 [ptlrpc]
#16 [ffffb3e64e36fd30] ptlrpc_check_set at ffffffffc12dcdc6 [ptlrpc]
#17 [ffffb3e64e36fdc0] ptlrpcd_check at ffffffffc1306c41 [ptlrpc]
#18 [ffffb3e64e36fe10] ptlrpcd at ffffffffc1306fb3 [ptlrpc]
#19 [ffffb3e64e36ff10] kthread at ffffffff8d0a8d5f
#20 [ffffb3e64e36ff50] ret_from_fork at ffffffff8d800235
Comment by Serguei Smirnov [ 06/Apr/20 ]

Hi mhanafi,

 

As far as I can tell from the logs this issue looks very similar to LU-12436. Please consider porting the patches listed under that ticket.

 

Thanks,

Serguei

Comment by Mahmoud Hanafi [ 14/Aug/20 ]

Please close.

Generated at Sat Feb 10 03:01:04 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.