|
At the very minimum we need to fix the error handling for this allocation.
|
|
Part of the issue is we never check the return state of the call and seem to just pass it along.
This svc->srv_ops.so_req_handler(request) should be failing with ENOMEM, but we don't check and just call ptlrpc_rqphase_move like everything is fine.
from ptlrpc_server_handle_request
The only mention of rc to the end of the function is an log message. I will make a patch to spurn conversation it seems we only return 0 or 1 out of this function.
|
|
Hmm I am not sure these are 2 backtraces are 100% related as they are from different threads but there is an odd things I see on the lbug error call chain that confuses me a bit.
In:
sptlrpc_svc_alloc_rs does a little safety check and calls this:
Is some separate thread acting on this request at the same time?
You don't happen to have the a Lustre Debug log hanging around do you Oleg?
|
|
I'm more concerned about why running sanity.sh in a loop is running out of memory?
|
|
We hit the same LBUG on MDS too. Maybe service->srv_max_reply_size is not big enough to hold the reply message? When memory is under pressure and the buffer is returned by lustre_get_emerg_rs, this LBUG happens.
|
|
here's a debug log from recent instance.
The crash info is:
I also have a crashdump.
|
|
Hit this twice in the last few days on an MDS running master from Nov. 1st during testing for another bug. I've got dumps of both events if they'd be of any use. (Logging was set to default levels)
The stack traces look the same for both of them, here's one:
<0>LustreError: 2252:0:(sec_null.c:318:null_alloc_rs()) ASSERTION( rs->rs_size >= rs_size ) failed:
<0>LustreError: 2252:0:(sec_null.c:318:null_alloc_rs()) LBUG
<4>Pid: 2252, comm: mdt00_001
<4>
<4>Call Trace:
<4> [<ffffffffa032d895>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
<4> [<ffffffffa032de97>] lbug_with_loc+0x47/0xb0 [libcfs]
<4> [<ffffffffa0627722>] null_alloc_rs+0x272/0x390 [ptlrpc]
<4> [<ffffffffa06161e9>] sptlrpc_svc_alloc_rs+0x1d9/0x2a0 [ptlrpc]
<4> [<ffffffffa05ecd03>] lustre_pack_reply_v2+0x93/0x280 [ptlrpc]
<4> [<ffffffffa05ecf9e>] lustre_pack_reply_flags+0xae/0x1f0 [ptlrpc]
<4> [<ffffffffa05ed0f1>] lustre_pack_reply+0x11/0x20 [ptlrpc]
<4> [<ffffffffa06138b3>] req_capsule_server_pack+0x53/0x100 [ptlrpc]
<4> [<ffffffffa0c3eea5>] mdt_getxattr+0x545/0x1490 [mdt]
<4> [<ffffffffa0c1c5ee>] mdt_intent_getxattr+0x9e/0x160 [mdt]
<4> [<ffffffffa0c198ce>] mdt_intent_policy+0x3ae/0x770 [mdt]
<4> [<ffffffffa05a4461>] ldlm_lock_enqueue+0x361/0x8c0 [ptlrpc]
<4> [<ffffffffa05cd17f>] ldlm_handle_enqueue0+0x4ef/0x10a0 [ptlrpc]
<4> [<ffffffffa0c19d96>] mdt_enqueue+0x46/0xe0 [mdt]
<4> [<ffffffffa0c20a8a>] mdt_handle_common+0x52a/0x1470 [mdt]
<4> [<ffffffffa0c5ac55>] mds_regular_handle+0x15/0x20 [mdt]
<4> [<ffffffffa05fce25>] ptlrpc_server_handle_request+0x385/0xc00 [ptlrpc]
<4> [<ffffffffa032e4ce>] ? cfs_timer_arm+0xe/0x10 [libcfs]
<4> [<ffffffffa033f27f>] ? lc_watchdog_touch+0x6f/0x170 [libcfs]
<4> [<ffffffffa05f44c9>] ? ptlrpc_wait_event+0xa9/0x2d0 [ptlrpc]
<4> [<ffffffff81051439>] ? __wake_up_common+0x59/0x90
<4> [<ffffffffa05fe18d>] ptlrpc_main+0xaed/0x1740 [ptlrpc]
<4> [<ffffffffa05fd6a0>] ? 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
|
|
Just occurred to me I should mention: I can reproduce this fairly consistently. If requested, I can try to do this with debugging turned up.
|
|
Patrick.
What is the memory usage like when you hit this error?
|
|
Keith,
Very high - Memory pressure, definitely. Not actually OOM, but as low as it can go (At the point where the kernel starts freeing memory and I see memory usage bounce around in the tens of MB free.).
I've been working around it (still testing my other, unrelated bug) by adding more RAM to the virtual machine running the MDS and also dumping caches periodically to keep from going OOM. That's worked for me.
|
|
Low memory is a tricky space in Lustre. Are you seeing other errors or just this one?
|
|
This is the only one I've seen on the MDS. However, I've seen this one at least three times, and can reproduce it readily, so it may be obscuring others.
On the client, we're chasing a recurrence of LU-3027/LU-3889, in which low memory can also play a role, but that's the client, not the MDS. (Oddly, the client testing for THAT was what led to our low memory issues on the MDS, but that's mostly due to an underspecced MDS in the testing system.)
|
|
Hi Patrick,
Would you please apply following patch and try to reproduce the problem again? I am not able to reproduce this consistently.
http://review.whamcloud.com/#/c/8200/
Thank you very much!
|
|
Li,
Sure. I'm doing that now - I've just tested to confirm I can still hit the problem, now I'm going to test the patch in the same situation.
|
|
Li,
Still hit the same crash with that patch in place. Stack trace is the same as before. I can make the dump available if you'd like. (Does Intel have an FTP site I could use? Otherwise I can find another way to make it available)
[Edit]
It occurred to me it's past midnight in China, so I've uploaded the dump rather than potentially making you wait another day if you do need it.
It's at:
ftp.us.cray.com
Username:
anonymous
Password:
anonymous
The file is at:
outbound/LU-3680/LU-3680-mds-dump.tar.gz
You cannot ls in outbound or LU-3680, but you should be able to grab the dump.
|
|
Hi Patrick,
Thank you very much for your test. It seems that the problem is complexer than I thought. I will investigate more.
We can share the debug files by uploading it to ftp://ftp.whamcloud.com/uploads/LU-*.
|
|
Hi Patrick,
It seems that there is a problem in lustre_get_emerg_rs(). The size of the buffer is set to zero, which will cause this LBUG when the memeory is under high pressure. I've updated the patch. Would you please test whether it works? Thank you very much!
|
|
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:
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.
|
|
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?
|
|
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.
|
|
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,
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,
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!
|
|
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,
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,
Thank you very much for confirming this! I am glad that we've made some progress finally.
Li Xi
|
|
Re-pushed patch to get Maloo to test again. If tests pass, I'm planning to invite Oleg to review.
|
|
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.
|
|
Shows mode:0x40 == __GFP_IO, but missing __GFP_WAIT from LU-4357.
|
|
http://review.whamcloud.com/#/c/9726/ - osd_thread_info fits 4K
|
|
Oleg Drokin (oleg.drokin@intel.com) merged in patch http://review.whamcloud.com/9726/
Subject: LU-3680 osd: reduce osd_thread_info in ldiskfs osd
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 56875fde8c66a4a937b173ccb065a9a6a3c67419
|
Generated at Sat Feb 10 01:35:59 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
lu3680.txt.gz