|
Bobijam
Could you please help with this one?
Thanks
Peter
|
|
Sprig2 hung again on 6th Feb. Log files from the client as well as the OSS and MDS nodes are attached. The only user on the machine at that time said he was updating the working copy of a subversion repository and had a couple of editor sessions open.
Thanks.
|
|
Another crash event on 2/17. Attaching a fresh set of logs. Any feedback is appreciated.
|
|
hm, what do you mean by another "crash" event? Before you only had hangs of clients with the diagnostics, right? What was the crash?
|
|
Saw several communication errors
Feb 6 16:18:56 sprig2 kernel: [621533.228954] LustreError: 11-0: scratch-OST0003-osc-ffff881f4fe08400: Communicating with 11.3.0.14@o2ib, operation obd_ping failed with -107.
Feb 6 16:27:41 sprig2 kernel: [622057.364356] LustreError: 11-0: scratch-MDT0000-mdc-ffff881f4fe08400: Communicating with 11.3.0.13@o2ib, operation obd_ping failed with -107.
Feb 6 16:29:46 sprig2 kernel: [622182.158450] LustreError: 11-0: scratch-OST0002-osc-ffff881f4fe08400: Communicating with 11.3.0.14@o2ib, operation obd_ping failed with -107.
Feb 6 16:31:26 sprig2 kernel: [622281.993824] LustreError: 11-0: scratch-OST0004-osc-ffff881f4fe08400: Communicating with 11.3.0.14@o2ib, operation obd_ping failed with -107.
Feb 6 16:39:21 sprig2 kernel: [622756.211587] LustreError: 11-0: scratch-OST0009-osc-ffff881f4fe08400: Communicating with 11.3.0.15@o2ib, operation obd_ping failed with -107.
oss1-messages:Feb 17 13:04:45 sprig-oss1 kernel: : LustreError: 138-a: scratch-OST0003: A client on nid 11.3.0.47@o2ib was evicted due to a lock blocking callback time out: rc -107
oss1-messages:Feb 17 13:05:00 sprig-oss1 kernel: : LustreError: 138-a: scratch-OST0004: A client on nid 11.3.0.47@o2ib was evicted due to a lock blocking callback time out: rc -107
oss1-messages:Feb 17 13:05:15 sprig-oss1 kernel: : LustreError: 138-a: scratch-OST0001: A client on nid 11.3.0.47@o2ib was evicted due to a lock blocking callback time out: rc -107
oss2-messages:Feb 17 13:04:53 sprig-oss2 kernel: : LustreError: 138-a: scratch-OST0006: A client on nid 11.3.0.47@o2ib was evicted due to a lock blocking callback time out: rc -107
oss2-messages:Feb 17 13:05:08 sprig-oss2 kernel: : LustreError: 138-a: scratch-OST0007: A client on nid 11.3.0.47@o2ib was evicted due to a lock blocking callback time out: rc -107
oss2-messages:Feb 17 13:05:22 sprig-oss2 kernel: : LustreError: 138-a: scratch-OST000a: A client on nid 11.3.0.47@o2ib was evicted due to a lock blocking callback time out: rc -107
oss2-messages:Feb 17 13:05:30 sprig-oss2 kernel: : LustreError: 138-a: scratch-OST000b: A client on nid 11.3.0.47@o2ib was evicted due to a lock blocking callback time out: rc -107
Is the lustre network working during the client hung?
|
|
You can use "lctl ping <NID>" to test lustre network, NID can be MDS nid or OSS nid, like 11.3.0.47@o2ib
|
|
Hi, this came in from the customer on 2/26. The SR owner asked me to update the notes with the new logs but I missed that original request. Here's it is:
Please find attached “lctl ping” test results as well as the dmesg, Lustre log and messages file produced by a Lustre OST eviction event that occurred this morning on sprig5.
This time we were the ones who triggered the bug rather than our users. We were recursively deleting a number of directories which contained a large number of small files on sprig5 which we use as a “scheduler node”. We therefore the only users logged in and the deletion was performed as the root user.
I have since been able to recreate the issue on a compute node using a simple bash script that creates a large number of small files and then recursively deletes them using the rm command. Unfortunately, the bug isn’t 100% reproducible, but I hope this information may help you debug the issue further.
|
|
Still see sprig5 lost connection to OSS (11.3.0.14@o2ib) for unknown reason
Feb 26 10:50:44 sprig5 kernel: [7247556.277424] LustreError: 11-0: scratch-OST0001-osc-ffff880800c76400: Communicating with 11.3.0.14@o2ib, operation obd_ping failed with -107.
Feb 26 10:50:44 sprig5 kernel: [7247556.277432] Lustre: scratch-OST0003-osc-ffff880800c76400: Connection to scratch-OST0003 (at 11.3.0.14@o2ib) was lost; in progress operations using this service will wait for recovery to complete
and this makes lots of ongoing IO error out, as
Feb 26 10:51:40 sprig5 kernel: [7247612.124147] LustreError: 129994:0:(cl_lock.c:1420:cl_unuse_try()) result = -108, this is unlikely!
|
|
Received the latest Logs.
The eviction has happened again on a login node. We’ve been able to get the output from both dump files, dmesg and the messages file. We tried the lctl ping and were able to ping each of the mds and oss nodes.
|
|
The eviction has happened again on a login node. We’ve been able to get the output from both dump files, dmesg and the messages file. We tried the lctl ping and were able to ping each of the mds and oss nodes.
|
|
from lustre-lost.1393924031.9592 and LU-4593-lustre-log.1393924031.9587
00000100:00020000:29.0F:1393927331.111498:0:137200:0:(import.c:324:ptlrpc_invalidate_import()) scratch-OST0007_UUID: rc = -110 waiting for callback (1 != 0)
00000100:00020000:28.0F:1393927331.111498:0:141486:0:(import.c:324:ptlrpc_invalidate_import()) scratch-OST0004_UUID: rc = -110 waiting for callback (1 != 0)
00000100:00020000:4.0F:1393927331.111501:0:141487:0:(import.c:324:ptlrpc_invalidate_import()) scratch-OST0001_UUID: rc = -110 waiting for callback (1 != 0)
00000100:00020000:37.0F:1393926731.111467:0:137200:0:(import.c:324:ptlrpc_invalidate_import()) scratch-OST0007_UUID: rc = -110 waiting for callback (1 != 0)
00000100:00020000:20.0F:1393926731.111476:0:141487:0:(import.c:324:ptlrpc_invalidate_import()) scratch-OST0001_UUID: rc = -110 waiting for callback (1 != 0)
00000100:00020000:0.0F:1393926731.111480:0:141486:0:(import.c:324:ptlrpc_invalidate_import()) scratch-OST0004_UUID: rc = -110 waiting for callback (1 != 0)
Is the OSS which holds OST0001/4/7 very busy during the eviction?
|
|
We have checked the system load, but they look normal, here is the update received..
OST 1 & 4 are hosted on oss1, OST 7 is hosted on oss2.
We have sysstat installed on the OSSs.
The OSS machines don’t seem heavily loaded. Most samples report 99.90% idle using the sar command. The eviction happened at 23:08 last night but the OSSs reported no real change to the load at that time.
Looking at the load on the machine yesterday we see peaks of SYSTEM use and IOWAIT times at 10:30 and 14:30 on both OSSs. These peaks increase from the normal 0.07% system use to 0.30% and 0.01% iowait to 0.27 at 14:30. I wouldn’t imagine this is considered heavily loaded?
|
|
Would you mind trying to rehit the issue for another time with client/OSS/MDS debug setting as
#lctl set_param debug="+rpctrace +dlmtrace"
and try to setup bigger debug buffer
#lctl set_param debug_mb=<# of megabytes>
after the eviction happens, "lctl dk > log_file" on client, OSS and MDS nodes.
I try to understand where the eviction come from. The existing log is brief and does not cover the troublesome lock's lifespan. Thanks in advance.
|
|
I have added new set of logs into FTP site, ftp.whamcloud.com/uploads/LU-4593
The filenames are
2014-03-10-SR29797_AWE_luster_client.tar
2014-03-10-SR29797_AWE_luster_mds1.tar
2014-03-10-SR29797_AWE_luster_mds2.tar.gz
2014-03-10-SR29797_AWE_luster_oss1.tar.gz
2014-03-10-SR29797_AWE_luster_oss2.tar.gz
|
|
Sprig3 has just been evicted (by user activity) – that was 07 March 2014 16:41
|
|
the client logs uploaded (2014-03-10-SR29797_AWE_luster_client.tar
) only covers between Fri Mar 7 10:08:16 to Fri Mar 7 10:08:46, while the eviction happened after Mar 7 15:41:18. And I could not find error message in the lustre-log.xxxx.xxx files, I think you've set /proc/sys/lustre/dump_on_eviction to 1 that when eviction happens it will dump a log automatically, but the problem is when the eviction happens again and again, the same log file for the same thread will be overwritten. Please put 0 to /proc/sys/lustre/dump_on_eviction. I'm still checking server logs.
PS. Can I know what "cat /proc/sys/lustre/dump_on_eviction" and "lctl get_param debug" command output? Thanks.
|
|
Also can you help find whether network works when high load happens? What's the network topology and setup here? I strongly suspect it could be network problem since logs keep on showing lost connection among each other and reconnection afterwards and repeat the cycle.
|
|
Let me clarify the situation of this issue.
1. Client got evicted from OST and never got reconnect back, does the client hung? If it hangs, can you collect/upload the stacktrace of it?
2. When the eviction happens, MDS and OSS are not highly loaded, and they can serve other clients well, are they?
|
|
1-sprig3 was evicted and none of the OSTs reconnected. The node was not hung as we could log into it to grab the Lustre logs etc. In the end we rebooted to get Lustre back into service on the node.
2-Looking at the system accounting logs for the time period the OSS and MDS nodes show no high loads.
|
|
update for what I've observed so far.
From the evicted client log (lustre-log.1394206866.9593.gz), from the begining (Mar 7 08:47:46) to the end of the log (Mar 7 17:07:46), there are several enqueue (o101) RPCs always in-flight to OSS1, while didn't get response from OSS1.
the sprig3 is using 11.3.0.47@o2ib
And oss1 shows corresponding communication with sprig3
|
|
from the client forever waiting request status
Mar 7 15:42:46 sprig3 kernel: [1562020.535961] LustreError: 27830:0:(import.c:350:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff883ac3c15800 x1460291788607144/t0(0) o101->scratch-OST0005-osc-ffff883f77c95800@11.3.0.14@o2ib:28/4 lens 328/368 e 0 to 0 dl 1394205665 ref 1 fl Interpret:RE/0/0 rc -5/0
it's rq_phase is "Interpret" and it's been replied and contains error "RE", so that drag my eyes to ptlrpc_check_set()
...
interpret:
LASSERT(req->rq_phase == RQ_PHASE_INTERPRET);
/* This moves to "unregistering" phase we need to wait for
* reply unlink. */
if (!unregistered && !ptlrpc_unregister_reply(req, 1)) {
ptlrpc_unregister_bulk(req, 1);
continue;
}
if (!ptlrpc_unregister_bulk(req, 1))
continue;
/* When calling interpret receiving already should be
* finished. */
LASSERT(!req->rq_receiving_reply);
ptlrpc_req_interpret(env, req, req->rq_status);
ptlrpc_rqphase_move(req, RQ_PHASE_COMPLETE);
I suspect there is a bug here.
|
|
Hi Rajeshwaran,
This is a debug patch http://review.whamcloud.com/#/c/9732/, only client need it, please remember to set debug level including rpctrace and dlmtrace, current uploaded logs do not have these debug messages. Please use this debug patch and turn on these debug level and try to rehit the issue, thank you.
|
|
Hello,
Is it possible to get the patched lustre source rpm. We had some issues while compling source rpm with the patches. it would be great, if you can give us the patched lustre client.
Thanks,
|
|
http://build.whamcloud.com/job/lustre-reviews/22597/ could possible contains what you need, you can check your system from the build matrix, and in their "Build Artifacts" you can corresponding source rpm.
|
|
We have applied the patch on the client and monitoring it for any eviction.
|
|
Here are some news/updates for this ticket after the conf-call :
_ an IB network audit/test (ibdiagnet from the subnet manager/node) has been run and did not show any problem.
_ debug-patch #9732 has been applied on Clients.
_ a known reproducer/script is currently being run, and we are waiting for a new occurrence.
_ this reproducer/script will be provided, along with any details to reproduce and also the Lustre configuration (OSSs/OSTs number, ...) being used on-site.
_ as already requested, customer is running with D_RPCTRACE and D_DLMTRACE traces enabled on their Clients.
_ debug buffer size has also been increased (exact value to be provided).
_ dump_on_timeout and dump_on_eviction have been unset.
_ when the eviction will re-occur, the Lustre debug-log will be manually taken on Client, OSS and MDS nodes.
_ would be also of interest to have the exact Lustre version being run on Clients/Servers along with the list/detail of any additional patches applied.
|
|
The ibdiagnet logs in the ftp server under LU-4593 folder.
The clients are running SLES 11 SP3:
Lustre On Clients -2.4.3
Kernel:3.0.93-0.8-default
Server Info:
MDS/OSSes are in CentOS and Lustre 2.4.1
Kernel:kernel-2.6.32-358.18.1.
|
|
Hello Rajeshwaran,
Thanks for the ibdiagnet traces already, but is there anything else you can provide in the items I listed in my previous update ??
|
|
After a joint conf-call with DDN/SGI/AWE, it appears that they do not trigger evictions anymore, running Lustre 2.4.3 (including debug patch #9732) on Clients. So we need to determine if this new behavior is caused by the debug patch or due to changes between 2.4.1 and 2.4.3.
|
|
As requested during last conf-call, I am adding here the Commit-msg content from patch #9732 which qualifies its non-debug/fix change :
|
|
Rajeshwaran: I forgot to ask you if, when running with debug version of #9732, you have found any of the "Handled 1000 reqs in the set 0xxxxx during yyyy seconds." added debug msg and also a long list of ptlrpc_request(s) being dumped for the set, in the debug-log (with dlmtrace+rpctrace set) of the Client where you reproduced the problem ?
Bobi: now that you pushed a "fix only" version/patch-set of #9732, do you think that the same fix is required for b2_5/master too ?
|
|
yes, I'd push patches for master and b2_5.
|
|
patch for master tracking at http://review.whamcloud.com/#/c/9975/, for b2_5 at http://review.whamcloud.com/#/c/9992
|
|
Hello,
Please close the LU-4593, we issue didnt occur after the patch.
Thanks,
Rajesh
|
|
Thank you for the update and confirmation Rajesh – very helpful!
~ jfc.
|
Generated at Sat Feb 10 01:44:08 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
LU-4593-lustre-log.1393924031.9587.gz
lctl_ping.txt