[LU-3680] OOM crash: null_alloc_rs()) ASSERTION( rs->rs_size >= rs_size ) failed

• Type: Bug
• Resolution: Fixed
• Priority: Major
• Fix Version/s: Lustre 2.6.0, Lustre 2.5.1, Lustre 2.4.3, Lustre 2.8.0
• Affects Version/s: Lustre 2.5.0
• Severity: 3
• Assignee: Oleg Drokin
• Reporter: Oleg Drokin

Description

Hit this running sanity in a loop:

<4>[80900.195000] ldlm_cn01_000: page allocation failure. order:1, mode:0x40
<4>[80900.195002] Pid: 17587, comm: ldlm_cn01_000 Not tainted 2.6.32-rhe6.4-debug #2
<4>[80900.195003] Call Trace:
<4>[80900.195008]  [<ffffffff8112a666>] ? __alloc_pages_nodemask+0x7c6/0x980
<4>[80900.195011]  [<ffffffff811658f2>] ? kmem_getpages+0x62/0x170
<4>[80900.195013]  [<ffffffff8116834a>] ? fallback_alloc+0x1ba/0x270
<4>[80900.195015]  [<ffffffff81167bf7>] ? cache_grow+0x4d7/0x520
<4>[80900.195017]  [<ffffffff81168038>] ? ____cache_alloc_node+0xa8/0x200
<4>[80900.195018]  [<ffffffff81168943>] ? kmem_cache_alloc_trace+0x1c3/0x250
<4>[80900.195029]  [<ffffffffa099cbc5>] ? osd_key_init+0x25/0x4e0 [osd_ldiskfs]
<4>[80900.195035]  [<ffffffffa099cbc5>] ? osd_key_init+0x25/0x4e0 [osd_ldiskfs]
<4>[80900.195060]  [<ffffffffa0bdd27f>] ? keys_fill+0x6f/0x190 [obdclass]
<4>[80900.195090]  [<ffffffffa0be132e>] ? lu_context_init+0x4e/0x240 [obdclass]
<4>[80900.195109]  [<ffffffffa0be1383>] ? lu_context_init+0xa3/0x240 [obdclass]
<4>[80900.195111]  [<ffffffff811665be>] ? cache_free_debugcheck+0x2ae/0x360
<4>[80900.195130]  [<ffffffffa0be153e>] ? lu_env_init+0x1e/0x30 [obdclass]
<4>[80900.195140]  [<ffffffffa0e3d69a>] ? ofd_lvbo_update+0x7a/0xea8 [ofd]
<4>[80900.195164]  [<ffffffffa04ac434>] ? ldlm_resource_putref+0x1d4/0x280 [ptlrpc]
<4>[80900.195186]  [<ffffffffa04c97b7>] ? ldlm_request_cancel+0x247/0x410 [ptlrpc]
<4>[80900.195206]  [<ffffffffa04c9abd>] ? ldlm_handle_cancel+0x13d/0x240 [ptlrpc]
<4>[80900.195226]  [<ffffffffa04cefb9>] ? ldlm_cancel_handler+0x1e9/0x500 [ptlrpc]
<4>[80900.195250]  [<ffffffffa04ffad1>] ? ptlrpc_server_handle_request+0x3b1/0xc70 [ptlrpc]
<4>[80900.195260]  [<ffffffffa0a2355e>] ? cfs_timer_arm+0xe/0x10 [libcfs]
<4>[80900.195270]  [<ffffffffa0a34b6f>] ? lc_watchdog_touch+0x6f/0x170 [libcfs]
<4>[80900.195340]  [<ffffffffa04f6bb1>] ? ptlrpc_wait_event+0xb1/0x2a0 [ptlrpc]
<4>[80900.195345]  [<ffffffff81054613>] ? __wake_up+0x53/0x70
<4>[80900.195367]  [<ffffffffa0500db2>] ? ptlrpc_main+0xa22/0x1650 [ptlrpc]
<4>[80900.195437]  [<ffffffffa0500390>] ? ptlrpc_main+0x0/0x1650 [ptlrpc]
<4>[80900.195441]  [<ffffffff81094606>] ? kthread+0x96/0xa0
<4>[80900.195444]  [<ffffffff8100c10a>] ? child_rip+0xa/0x20
<4>[80900.195447]  [<ffffffff81094570>] ? kthread+0x0/0xa0
<4>[80900.195448]  [<ffffffff8100c100>] ? child_rip+0x0/0x20
<6>[80900.195449] Mem-Info:
<4>[80900.195450] Node 0 DMA per-cpu:
<4>[80900.195451] CPU    0: hi:    0, btch:   1 usd:   0
<4>[80900.195452] CPU    1: hi:    0, btch:   1 usd:   0
<4>[80900.195453] CPU    2: hi:    0, btch:   1 usd:   0
<4>[80900.195454] CPU    3: hi:    0, btch:   1 usd:   0
<4>[80900.195455] CPU    4: hi:    0, btch:   1 usd:   0
<4>[80900.195456] CPU    5: hi:    0, btch:   1 usd:   0
<4>[80900.195458] CPU    6: hi:    0, btch:   1 usd:   0
<4>[80900.195459] CPU    7: hi:    0, btch:   1 usd:   0
<4>[80900.195459] Node 0 DMA32 per-cpu:
<4>[80900.195460] CPU    0: hi:  186, btch:  31 usd:  51
<4>[80900.195461] CPU    1: hi:  186, btch:  31 usd:  26
<4>[80900.195462] CPU    2: hi:  186, btch:  31 usd:   0
<4>[80900.195463] CPU    3: hi:  186, btch:  31 usd:   0
<4>[80900.195464] CPU    4: hi:  186, btch:  31 usd:  57
<4>[80900.195465] CPU    5: hi:  186, btch:  31 usd: 174
<4>[80900.195466] CPU    6: hi:  186, btch:  31 usd: 162
<4>[80900.195467] CPU    7: hi:  186, btch:  31 usd:  32
<4>[80900.195470] active_anon:61548 inactive_anon:61459 isolated_anon:0
<4>[80900.195470]  active_file:94797 inactive_file:74222 isolated_file:0
<4>[80900.195471]  unevictable:0 dirty:20 writeback:0 unstable:0
<4>[80900.195471]  free:43025 slab_reclaimable:75111 slab_unreclaimable:271092
<4>[80900.195472]  mapped:577 shmem:119300 pagetables:383 bounce:0
<4>[80900.195473] Node 0 DMA free:9692kB min:136kB low:168kB high:204kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:9296kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
<4>[80900.195478] lowmem_reserve[]: 0 2967 2967 2967
<4>[80900.195479] Node 0 DMA32 free:162408kB min:44916kB low:56144kB high:67372kB active_anon:246192kB inactive_anon:245836kB active_file:379188kB inactive_file:296888kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3039076kB mlocked:0kB dirty:80kB writeback:0kB mapped:2308kB shmem:477200kB slab_reclaimable:300444kB slab_unreclaimable:1084368kB kernel_stack:3296kB pagetables:1532kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
<4>[80900.195485] lowmem_reserve[]: 0 0 0 0
<4>[80900.195486] Node 0 DMA: 3*4kB 0*8kB 3*16kB 1*32kB 2*64kB 0*128kB 1*256kB 0*512kB 1*1024kB 0*2048kB 2*4096kB = 9692kB
<4>[80900.195490] Node 0 DMA32: 37378*4kB 1032*8kB 32*16kB 1*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 1*4096kB = 162408kB
<4>[80900.195495] 129723 total pagecache pages
<4>[80900.195496] 925 pages in swap cache
<4>[80900.195497] Swap cache stats: add 376365, delete 375440, find 1323456/1328202
<4>[80900.195498] Free swap  = 1869104kB
<4>[80900.195499] Total swap = 2097144kB
<6>[80900.198861] 774396 pages RAM
<6>[80900.198861] 38583 pages reserved
<6>[80900.198861] 11942 pages shared
<6>[80900.198861] 675636 pages non-shared
<4>[80900.226747] 129650 total pagecache pages
<4>[80900.226747] 1136 pages in swap cache
<4>[80900.226747] Swap cache stats: add 376650, delete 375514, find 1323456/1328202
<4>[80900.226747] Free swap  = 1867964kB
<4>[80900.226747] Total swap = 2097144kB
<6>[80900.226747] 774396 pages RAM
<6>[80900.226747] 38583 pages reserved
<6>[80900.226747] 11963 pages shared
<6>[80900.226747] 668761 pages non-shared
<0>[80900.502883] LustreError: 17604:0:(sec_null.c:318:null_alloc_rs()) ASSERTION( rs->rs_size >= rs_size ) failed: 
<0>[80900.504111] LustreError: 17604:0:(sec_null.c:318:null_alloc_rs()) LBUG
<4>[80900.504782] Pid: 17604, comm: mdt01_002
<4>[80900.505352] 
<4>[80900.505353] Call Trace:
<4>[80900.506312]  [<ffffffffa0a228a5>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
<4>[80900.507011]  [<ffffffffa0a22ea7>] lbug_with_loc+0x47/0xb0 [libcfs]
<4>[80900.507716]  [<ffffffffa052a382>] null_alloc_rs+0x272/0x390 [ptlrpc]
<4>[80900.508419]  [<ffffffffa0518f19>] sptlrpc_svc_alloc_rs+0x1d9/0x2a0 [ptlrpc]
<4>[80900.509166]  [<ffffffffa04ef218>] lustre_pack_reply_v2+0x98/0x2a0 [ptlrpc]
<4>[80900.509906]  [<ffffffffa04ef4ce>] lustre_pack_reply_flags+0xae/0x1f0 [ptlrpc]
<4>[80900.510935]  [<ffffffffa04ef621>] lustre_pack_reply+0x11/0x20 [ptlrpc]
<4>[80900.511642]  [<ffffffffa0516603>] req_capsule_server_pack+0x53/0x100 [ptlrpc]
<4>[80900.513248]  [<ffffffffa0d472e5>] mdt_getxattr+0x585/0x13c0 [mdt]
<4>[80900.514017]  [<ffffffffa0d2570e>] mdt_intent_getxattr+0x9e/0x160 [mdt]
<4>[80900.514572]  [<ffffffffa0d2265e>] mdt_intent_policy+0x3ae/0x770 [mdt]
<4>[80900.515391]  [<ffffffffa04a735a>] ldlm_lock_enqueue+0x2ea/0x860 [ptlrpc]
<4>[80900.516099]  [<ffffffffa04cfc7f>] ldlm_handle_enqueue0+0x4ef/0x10c0 [ptlrpc]
<4>[80900.518542]  [<ffffffffa0d22b26>] mdt_enqueue+0x46/0xe0 [mdt]
<4>[80900.519098]  [<ffffffffa0d28ca7>] mdt_handle_common+0x647/0x16d0 [mdt]
<4>[80900.519529]  [<ffffffffa0d63335>] mds_regular_handle+0x15/0x20 [mdt]
<4>[80900.519959]  [<ffffffffa04ffad1>] ptlrpc_server_handle_request+0x3b1/0xc70 [ptlrpc]
<4>[80900.520740]  [<ffffffffa0a2355e>] ? cfs_timer_arm+0xe/0x10 [libcfs]
<4>[80900.521190]  [<ffffffffa0a34b6f>] ? lc_watchdog_touch+0x6f/0x170 [libcfs]
<4>[80900.521644]  [<ffffffffa04f6bb1>] ? ptlrpc_wait_event+0xb1/0x2a0 [ptlrpc]
<4>[80900.522146]  [<ffffffff81054613>] ? __wake_up+0x53/0x70
<4>[80900.522670]  [<ffffffffa0500db2>] ptlrpc_main+0xa22/0x1650 [ptlrpc]
<4>[80900.523097]  [<ffffffffa0500390>] ? ptlrpc_main+0x0/0x1650 [ptlrpc]
<4>[80900.523532]  [<ffffffff81094606>] kthread+0x96/0xa0
<4>[80900.526690]  [<ffffffff8100c10a>] child_rip+0xa/0x20
<4>[80900.527224]  [<ffffffff81094570>] ? kthread+0x0/0xa0
<4>[80900.527603]  [<ffffffff8100c100>] ? child_rip+0x0/0x20
<4>[80900.528010] 
<0>[80900.528950] Kernel panic - not syncing: LBUG

Issue Links

• duplicates: LU-4357 page allocation failure. mode:0x40 caused by missing __GFP_WAIT flag
• is duplicated by: LU-6472 OI scrub causes MDS reboot
• is related to: LU-6324 CLASSERT(sizeof(struct osd_thread_info) <= PAGE_SIZE) fails for some configs

Comments

[Oleg Drokin]

Patch landed to master for 2.6.0, and to b2_4 for 2.4.3 (should it ever happen) and b2_5 for 2.5.1.

[Patrick Farrell (Inactive)]

Re-pushed patch to get Maloo to test again. If tests pass, I'm planning to invite Oleg to review.

[Li Xi (Inactive)]

Patrick,

Thank you very much for confirming this! I am glad that we've made some progress finally.

Li Xi

[Patrick Farrell (Inactive)]

Li,

It looks like you're right - I must have made a mistake in my build/install process before. With your patch, I am no longer able to hit this bug.

• Patrick

[Patrick Farrell (Inactive)]

Li,

I'm sorry, you're right - I misread my own dump. I'm fairly sure I had the patch in place, but I'm happy to try again. It's always possible I made a mistake in setting things up.

I should be able to test that tomorrow.

By the way, if you're interested in trying to reproduce this, I'm just running this script from a client to generate activity:

for idx in $(seq 0 10000); do
    time ls -laR > /dev/null
    touch somefile
    rm -f somefiles
    echo $idx: $(date +%T) $(grep MemFree /proc/meminfo)
done

Then running this code on the MDS to create memory pressure (you have to hold down enter, it consumes real memory much more slowly than the rate at which it's allocating memory). Once memory gets low, just keep running this code and you should see the bug within a minute or so:

#include <stdio.h>
#include <unistd.h>

int main()
{
    int i;
    char* junk;

start: i = 0;

    while(i < 50) { 
        printf("Malloc!\n"); 
        junk = malloc(1024*1024*1024); 
        junk[0] = i; 
        i++; 
    }

    printf("Mallocced 50 GB. Press enter to malloc another 50.\n");
    printf("Note: This seems to use roughly 10 MB of real memory each time.\n");
    getchar();
    goto start;
}

[Li Xi (Inactive)]

Patrick,

Thanks for you test. I am sorry that this LBUG happended again. You said that this is a different LBUG, but the trace looks the same to me. Is there anything I missed?
It surprises me that the patch does not help at all. I though it fixes a problem and might eliminate the LBUG. Would you please doule check that the patch is applied properly?
Since the problem happens when the memory is under heavy pressure, I think the buffer is likely to be allocaed by lustre_get_emerg_rs(). And that's why I am surpised that the patch didn't help...

Thanks!

[Patrick Farrell (Inactive)]

Li,

Different LBUG, same function:
<0>LustreError: 12155:0:(sec_null.c:318:null_alloc_rs()) ASSERTION( rs->rs_size >= rs_size ) failed:
<0>LustreError: 12155:0:(sec_null.c:318:null_alloc_rs()) LBUG
<4>Pid: 12155, comm: mdt00_000
<4>
<4>Call Trace:
<4> [<ffffffffa032d895>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
<4> [<ffffffffa032de97>] lbug_with_loc+0x47/0xb0 [libcfs]
<4> [<ffffffffa06296a2>] null_alloc_rs+0x272/0x390 [ptlrpc]
<4> [<ffffffffa0617527>] sptlrpc_svc_alloc_rs+0x1e7/0x350 [ptlrpc]
<4> [<ffffffffa05edfb3>] lustre_pack_reply_v2+0x93/0x280 [ptlrpc]
<4> [<ffffffffa05ee24e>] lustre_pack_reply_flags+0xae/0x1f0 [ptlrpc]
<4> [<ffffffffa05ee3a1>] lustre_pack_reply+0x11/0x20 [ptlrpc]
<4> [<ffffffffa0614be3>] req_capsule_server_pack+0x53/0x100 [ptlrpc]
<4> [<ffffffffa0c3ef65>] mdt_getxattr+0x545/0x1490 [mdt]
<4> [<ffffffffa0c212ae>] mdt_intent_getxattr+0x9e/0x160 [mdt]
<4> [<ffffffffa046a356>] ? lu_object_find+0x16/0x20 [obdclass]
<4> [<ffffffffa0c1b659>] mdt_intent_policy+0x499/0xca0 [mdt]
<4> [<ffffffffa05a5441>] ldlm_lock_enqueue+0x361/0x8c0 [ptlrpc]
<4> [<ffffffffa05ce17f>] ldlm_handle_enqueue0+0x4ef/0x10a0 [ptlrpc]
<4> [<ffffffffa0643b12>] tgt_enqueue+0x62/0x1d0 [ptlrpc]
<4> [<ffffffffa064203f>] tgt_request_handle+0x5ff/0x1200 [ptlrpc]
<4> [<ffffffffa05ef2bc>] ? lustre_msg_get_transno+0x8c/0x100 [ptlrpc]
<4> [<ffffffffa05fe0d5>] ptlrpc_server_handle_request+0x385/0xc00 [ptlrpc]
<4> [<ffffffffa032e4ce>] ? cfs_timer_arm+0xe/0x10 [libcfs]
<4> [<ffffffffa033f3df>] ? lc_watchdog_touch+0x6f/0x170 [libcfs]
<4> [<ffffffffa05f5779>] ? ptlrpc_wait_event+0xa9/0x2d0 [ptlrpc]
<4> [<ffffffff81051439>] ? __wake_up_common+0x59/0x90
<4> [<ffffffffa05ff43d>] ptlrpc_main+0xaed/0x1740 [ptlrpc]
<4> [<ffffffffa05fe950>] ? ptlrpc_main+0x0/0x1740 [ptlrpc]
<4> [<ffffffff81096a36>] kthread+0x96/0xa0
<4> [<ffffffff8100c0ca>] child_rip+0xa/0x20
<4> [<ffffffff810969a0>] ? kthread+0x0/0xa0
<4> [<ffffffff8100c0c0>] ? child_rip+0x0/0x20

Dump is going up on the WC FTP site momentarily.

Dump is in /LU-3680, file is named:
lu-3680-mds-dump 2.tar.gz

[Patrick Farrell (Inactive)]

Li,

You're right - I was using a Windows FTP command line client, and now that I've switched to a Unix one, everything is fine.

Thanks!

[Li Xi (Inactive)]

Hi Patrick,

I've just test the FTP. It works well. Following are the commands.

lixitekiMacBook-Pro:~ lixi$ ftp ftp.whamcloud.com
Connected to eric.whamcloud.com.
220 (vsFTPd 2.2.2)
Name (ftp.whamcloud.com:lixi): anonymous
331 Please specify the password.
Password:
230 Login successful.
Remote system type is UNIX.
Using binary mode to transfer files.
ftp> ls
229 Entering Extended Passive Mode (|||38409|).
150 Here comes the directory listing.
d-wxrwx--- 68 123 840000001 4096 Nov 05 08:12 uploads
226 Directory send OK.
ftp> cd uploads
250 Directory successfully changed.
ftp> mkdir LU-3680
257 "/uploads/LU-3680" created
ftp> cd LU-3680
250 Directory successfully changed.
ftp> lpwd
Local directory: /Users/lixi
ftp> put test.rtf
local: test.rtf remote: test.rtf
229 Entering Extended Passive Mode (|||53942|).
150 Ok to send data.
100% |***********************************| 315 397.43 KiB/s 00:00 ETA
226 Transfer complete.
315 bytes sent in 00:00 (0.49 KiB/s)
ftp> ls
229 Entering Extended Passive Mode (|||40673|).
150 Here comes the directory listing.
rw-rr- 1 123 114 315 Nov 07 18:57 test.rtf
226 Directory send OK.

[Patrick Farrell (Inactive)]

Li,

Just testing the FTP site...
I'm connected to ftp.whamcloud.com as anonymous, but I can't create files in /upload, and I can't seem to cd to any LU directories. I tried LU-3680, LU-3027, LU-4152 and a few others. Also can't make a new directory.

Is there something I've missed here?

• Patrick

[Patrick Farrell (Inactive)]

Li,

Sure. I'll probably be testing this tomorrow. I expect you've noticed this, but you've got a small mistake in the current patch that's causing it not to build on RHEL6:

/* Just return failure if the size is too big */
CERROR("size of message is too big (%lu), %d allowed",
msglen + sizeof(struct ptlrpc_reply_state),

You're printing %lu, but msglen + sizeof([...]) is an int. I'd just do a cast to a long unsigned int, I suppose.

(unsigned long) (msglen + sizeof(struct ptlrpc_reply_state)),

Should do it.

• Patrick