|
Bobijam
What do you advise here?
Thanks
Peter
|
|
Is it reliably reproducible? what are the reproduce steps if possible? I tried to reproduce it with 2.1.6 server/1.8 client and didn't make it.
|
|
Hi Zhenyu,
Yes this is reproducible by just doing 'ls' to long listing of directory. The nature of the problem starts or gets reproducible after like 15-20 days of filesystem operation from the downtime. Which means we took down the MDS and OSS to clear that same problem and after reboot of the MDS and OSS file system got online and at that time we were not able to reproduce that problem. But after like 12-15 days the same problem re-appeared and we were able to reproduce it again by just doing a 'ls' on the directory to get the directory stats.
Here is in brief explanation from IU, what they are seeing and experiencing.
we're actually experiencing two issues, or at least different manifestations of a single problem. First, we have clients that hang when stat'ing certain directories and eventually get evicted from the MDS, and only the MDS. These clients log "The mds_connect operation failed with -16" until they detect that they've been evicted by the MDS.
Second, we're seeing clients evicted from OSS's with "
lock blocking callback time out: rc -107", which usually are not accompanied by an eviction from the MDS. Often 2-3 clients will get evicted at the same second, see the samples below:
Thank You,
Manish
|
|
Would you mind trying this: when this issue happens, try to mount a new client and to check whether this new client also has this issue and collect the -1 logs (client, MDS and OSS) during the procedure?
|
|
the currently provided log does not reveal why client returns -22 to OSS server.
|
|
Hi Zhenyu,
In reference to the comment "try to mount a new client", do you mean freshly built/created new Lustre Client with v 1.8.9 which is never connected before.
I have complete two sets of MDS and Lustre-client stack traces of those time, which you can download it from here.
http://ddntsr.com/ftp/2014-02-26-LU-4616.rar
I hope that helps to shed some light and if not then let me know what logs are required from the next test.
Thank You,
Manish
|
|
yes, I mean a freshly connected new Lustre client, so that you can collect as small as relevant client logs from it.
|
|
the 2014-02-26-LU-4616.rar does not contain info to reveal the root cause, if possible, I still need your help to get -1 debug logs (newly connected client, MDS and OSS) during the rehit. If the newly created client can rehit the issue, the -1 log covering that time span would contain relevant information. Thank you in advance.
|
|
Hi Zhenyu,
Thank you for your prompt response. Ok I will check with IU and see if we can get this setup done, to get new set of logs. In reference to "get -1 debug logs", so you mean to enable on client using below commands
sysctl -w lnet.printk=-1
And does that needs to be done on just that newly connected client or it has to be enabled on MDS and OSS also.
Other then that, do you also need stack trace, dlmtrace or rpctrace. If yes then from which nodes and what buffer size and what is the right way to enable those debug options and collect the logs out of it.
Thank You,
Manish
|
|
Suppose you've builded a new client, set debug level to -1 on all involving re-hit nodes (the new client, MDS nodes, OSS nodes) with "lctl set_param debug=-1", then mount the client and try the re-hit procedure. If the rehit occurs, "lctl dk <log file>" to dump the -1 logs on all involving nodes, the -1 level log contains all level of logs.
|
|
Hi Zhenyu,
We have setup new client and collected the logs as you requested. Here is the 'ls' behavior on the directory as below:
The `ls -al` job timestamps and output are included below:
Here are the URL of those logs and I have attached one file which contains kern logs from MDS and OSS nodes log file named as "Server_System_logs_from_MDS_OSS_03-032014.txt".
http://ddntsr.com/ftp/2014-03-03-29545_run9.tar.gz
http://ddntsr.com/ftp/2014-03-03-dc2ossXX_run9_debug_logs.tar.gz
Let me know if you need anything else from our end.
Thank You,
Manish
|
|
from the 29545_run9/mds_run9_debug.log, I can see the client 149.165.235.42@tcp was evicted at "Tue Mar 4 03:31:13 CST 2014"
00010000:00020000:8.1:1393875073.142106:0:0:0:(ldlm_lockd.c:358:waiting_locks_callback()) ### lock callback timer expired after 9437s: evicting client at 149.165.235.42@tcp ns: mdt-ffff881843d1a000 lock: ffff882afe438000/0xcf86cae155f4b253 lrc: 3/0,0 mode: PR/PR res: 35127297/2218887223 bits 0x3 rrc: 382 type: IBT flags: 0x4000020 remote: 0x8a1cc956fcd9690 expref: 53 pid: 12292 timeout: 8892268113
at "Tue Mar 4 03:31:14 CST 2014", the client thought that it is still connected with MDS, and tried to reconnect.
00000100:00100000:1:1393875074.464664:0:1977:0:(import.c:720:ptlrpc_connect_import()) @@@ reconnect request 1219 req@ffff8800307ed000 x1461574032228883/t0 o38->dc2-MDT0000_UUID@10.10.0.171@o2ib:12/10 lens 368/584 e 0 to 1 dl 0 ref 1 fl New:N/0/0 rc 0/0
but MDS has evicted it and told the client the situation, client realized the eviction.
00010000:00000400:3.0:1393875078.627576:0:12472:0:(ldlm_lib.c:952:target_handle_connect()) dc2-MDT0000: connection from a69ef170-baaf-a6ea-059d-2e445759c567@149.165.235.42@tcp t230235724090 exp (null) cur 1393875078 last 0
note: exp is NULL, which means MDS does not recognize this client, and treat it as a new client connection request.
the logs do not cover why the client failed to answer the MDS lock request though.
|
|
Hi Zhenyu,
We took a maintenance window and captured the vmcore crash dump by doing a manual Sysreq-trigger. Here is the back trace which was captured to see if that sheds some light here. There are also few Intel ticket which has some similar type of traces as in LU-2807, LU-4733, LU-4335 and LU-4195, which I thought might be helpful in investigating this issues.
Another thing, as the maintenance window was over and customer started mounting the Lustre-Client nodes and one of the node failed right after connecting to MDS. The only difference was that they used the different mount option. Originally that client node was mounted using "loclflock" option and this time it was mounted as "flock".
I have attached the backtrace logs and the logs from server and client nodes for this client eviction incidence.
https://jira.hpdd.intel.com/secure/attachment/14246/server_logs_03_05.log
https://jira.hpdd.intel.com/secure/attachment/14245/rt_119855.c6.lustre_logs
https://jira.hpdd.intel.com/secure/attachment/14244/backtrace.tar.gz
Thank You,
Manish
|
|
the last client LBUG so far is addressed by patch http://review.whamcloud.com/#/c/5971 (LU-3067)
|
|
Hi Zhenyu,
Thank you for the updates. What about the backtrace of the MDS server which I provided? Can you check and see if that helps to find out about why the "stats of directory listing was not showing" and the "lock completion callback time out" and "blocking timeouts"?
Thank You,
Manish
|
|
Some info in server_logs_03_05.log reminds me of LU-4359, they are some sort look alike.
It turned out that there is some problem about their network setup, does this system use hybrid network and would you mind taking consider of the network issue possibility?
|
|
Hi Zhenyu,
Yes this is the hybrid network with IB and TCP network with multiple subnet. At the last maintenance window we did some network changes suggested by the Intel in LU-4531, but still we seeing the MDS lockup or directory stats listing issues, so I would like you to reconsider looking at those old backtraces which I sent last time.
Yesterday we had one more downtime due to MDS lockup and we had to reboot the MDS to fix the directory stats listings issues. We have collected the stacktrace and the logs from the server and the clients of that time period. The logs are as below:
http://ddntsr.com/ftp/2014-03-12-29545_stacktraces.tgz
https://jira.hpdd.intel.com/secure/attachment/14289/march_12_svr.log.gz
https://jira.hpdd.intel.com/secure/attachment/14290/aprun-DebugLogs.tar.gz
http://ddntsr.com/ftp/2014-03-13-29545_es_lustre_showall_2014-03-13_082243.tar.bz2
Let me know if you need anything else from our end.
Thank You,
Manish
|
|
From the logs it looks like some OST became super slow for some reason (overloaded?) there are signs of MDT requests taking long time (in ost logs).
The "all logs" file sadly does not have any logs for dc2mds01 from what I see, so it's a bit harder to fully verify this theory, but it's pretty plausible.
We can see this picture in your earlier log excerpt too.
The code that's waiting for the objects to be allocated does so while holding an ldlm lock on the file and parent, so conflicting accesses also block in a cascading manner.
Also we can see there's a bunch of clients dropping (no pings happening) that I am not sure why, some network problems?
|
|
Hi, I have a few questions here, it could be helpful if you can provide information about them:
- when client(s) got evicted, I assume other clients in the same network are still functional, right?
- if they are still functional, could you run LNet stress tests (LNet selftest) between another client and servers
- when this issue appeared, could you check all routers (I assume there are four?) are still working.
- check router status on the evicted clients
- check router status on other clients in the same network.
- check router status on server
- login routers to see if they are able to connect to other nodes.
Thanks!
|
|
When running LNet selftest between client and servers, it makes sense to do it in 3 steps:
1. test between clients and routers
2. test between routers and servers
3. test between clients and servers
If either 1 or 2 fails, there's no need to go step 3. If step 3 fails, we know there's something wrong with LNet routing as the complete path has been verified by steps 1 and 2.
|
|
IB OSS - 10.10.0.1@o2ib
GNI/IB Router - 30@gni
GNI/IB Router - 10.10.0.51@o2ib
GNI Client - 396@gni
1. test between client and router
/opt/ddn/bin/lnet_selftest.sh -c "396@gni" -s "30@gni" -d 1:1 > /tmp/4616.client-router.lnet
2. test between routers and servers
/opt/ddn/bin/lnet_selftest.sh -c "30@gni" -s "10.10.0.1@o2ib" -d 1:1 > /tmp/4616.router-server.lnet
3. test between clients and servers
/opt/ddn/bin/lnet_selftest.sh -c "396@gni" -s "10.10.0.1@o2ib" -d 1:1 >
/tmp/4616.client-server.lnet
|
|
> when client(s) got evicted, I assume other clients in the same network are still functional, right?
Yes, other clients remain functional
> if they are still functional, could you run LNet stress tests (LNet selftest) between another client and servers
Yes, lnet selftest has been run from another client on that network and attached to this ticket
> when this issue appeared, could you check all routers (I assume there are four?) are still working.
There are four TCP<->IB routers for the clusters that mount over TCP.
There are twenty two GNI<->IB routers for the Cray clients on GNI.
The lnet selftests attached are for the GNI<->IB router, IB server, GNI client.
> check router status on the evicted clients
All routers are in UP state
> check router status on other clients in the same network.
All routers are in UP state
> check router status on server
All routers are in UP state
> login routers to see if they are able to connect to other nodes.
GNI<->IB routers are able to ping all GNI clients, all IB Lustre servers, including nodes in the bad state
|
|
In 4616.client-server.lnet and 4616.router-server.lnet, there's lots of output like:
[R] Avg: inf MB/s Min: inf MB/s Max: inf MB/s
These don't look right, but I don't know why yet.
|
|
Just an update to explain the debug session I ran earlier today with the IU team :
_ they 1st showed me "live" how easy they can reproduce the issue. Its interesting to note that only certain directory seem to be always able to trigger and all others do not !!! When we do a simple "ls" in a known directory to trigger, it just hangs and the Client will be later evicted and can no longer reconnect.
_ after that, I asked to redo it from a fresh Client. Before to reproduce, I enabled the full debug-logs and grew the buffer size to 2M, and cleared the debug-log on both the MDS and the Client. And a few second after we reproduced the "ls" hang, I dumped the debug-log in /tmp/lustre-debug.bfi on both the MDS and the Client, then I forced-crash the Client and took a full stacks trace on the MDS (to be found in /var/log/messages).
Here is the Console output of the cmds I ran on the Client, that shows the "ls" PID :
After that, I requested via email to the IU team to provide us the following infos :
|
|
I checked the uploaded stuff and seems that the /tmp/lustre-log.bfi (full debug-log) of both Client/c4 and MDS are missing, along with the kernel-debuginfo* rpms. They are not available on the IU dropbox too.
Seems that others debug-logs have been provided but their date is more than 2 hours later than the debug session I ran.
Also does the Client/c4 run with a stock 2.6.32-358.11.1.el6.x86_64 kernel ?
|
|
Just to keep all the info in the ticket for those monitoring
"We uploaded the missing /tmp/lustre-log.bfi to the ftp server as well as
the box site.
I am not sure why the timestamps are different. Are the different inside
the file (log entry timestamps) or is the file's timestamp off?
I believe the kernel-debuginfo* files you are looking for are inside the
tar files we uploaded. If they are not, we can re-upload.
I will check with our Cray admin to get the answer on the c4 client
version.
Please let me know if you need anything else."
then
"Concerning he time stamps being off, we had to perform the debug/crash
procedure multiple times before we properly captured all the debug info.
So it makes sense that the time stamps are later, as we performed the
actions later.
I will let you know about the client version when we get an update."
then
"c4 is running 1.8.9 with the ll_getname patch."
|
|
the lustre-log.bfi from the MDS has been upload to the ftp and box.iu.edu as dc2mds01.lustre-log.bfi.gz
the kernel-debuginfo* rpms are in box.iu.edu as well, or also in the client and mds tgz on the ftp site.
Concerning the time stamps being off, we had to perform the debug/crash procedure multiple times before we properly captured all the debug info. So it makes sense that the time stamps are later, as we performed the
actions later.
The full debug information provided is from a host named oss30, which is TCP client that connects through the dc2xfer[01-04] routers.
[root@oss30 ~]# rpm -qa | grep lustre
lustre-client-2.1.6-2.6.32_358.11.1.el6.x86_64.x86_64
lustre-client-modules-2.1.6-2.6.32_358.11.1.el6.x86_64.x86_64
[root@oss30 ~]# uname -a
Linux oss30 2.6.32-358.11.1.el6.x86_64 #1 SMP Wed May 15 10:48:38 EDT 2013 x86_64 x86_64 x86_64 GNU/Linux
there is some confusion about the c4 client that needs cleared up. c4 was the client we were using for interactive debugging with Bruno, but its debug dumps got lost. We followed the same procedure for crashing and collecting on another client oss30
|
|
A few information got from discussion with Justin
1. when "ls" failure happens, it only hit the certain directories, i.e. client only got evicted when ls these certain directories. But these "certain" directories might change after each restart.
2. The FS is created with lustre 2.1.3, right now it is 2.1.6 plus some patches. But client is 1.8.6, which is be mounted at least 2 filesystem, one is 2.1.6, another one is 1.8. (Justin, please confirm?)
3. The "ls" failure will happen on all clients, no matter 1.8 and 2.1.3 clients.
4. Before the failure happens on these directory, no correlated applications are being identified to touch these directories. But needs confirm.
|
|
Thanks Di. For #2 the patches are LU-2943 and LU-3645
|
|
Justin: Thanks for the clarification. But the "date/time" confusion I seemed to introduce, comes from the fact I was expecting files/logs/crash-dump from the session on c4/Client and did not find any clear indication/warning that you re-ran the session on an other node!!
|
|
Andreas, Di, feel free to correct/add !!
The MDS full stacks output in the syslog/messages shows a lot of threads being stuck doing renames. Actually we wonder if this could not be related to the problem.
In order to confirm this it would be nice if you can also provide us with the syslog/messages file from the MDS (dc2mds01 ?) that was used during the time when I was connected at IU and we reproduced with Client/c4, can you also provide this ??
Also, thanks to provide the dc2mds01.lustre-log.bfi from my debug session, but I still don't find the Client/c4 one in what is on ftp or dropbox. In fact, I may be wrong, but I think you did not actually provide anything from my debug session when connected at IU but only what you got from the remake on your own, can you help there ?
|
|
Bruno: You are right, we should have been clear about the logs that were upload. We unfortunately were unable to save full stack output from c4. We recreated the full stack output from another very similar client following the same procedures, and that is what we shared with everyone. They're from oss30 which I described previously.
We do have the dc2mds01 syslog/messages from the time of our interactive debug session while using c4. I have uploaded that log to box as 4616.mds01syslog.20130314.txt In fact that file is the entire March 14 messages file for dc2mds01, so it will have the c4 client debug, as well as our later oss30 client debug.
|
|
Looking through the mds_messages.log file, and filtering out the many other messages which are being printed there (e.g. spurious llog -ENOSPC error that would be fixed by LU-2336 patch http://review.whamcloud.com/5146, patch needed for b1_8 clients to fix LU-532 http://review.whamcloud.com/1161 warning, etc), it seems the first real problem in that log is Wednesday morning (2014-03-12 09:31):
After this quite a number of other MDS threads also reported waiting and dumping stacks in lov_create(). Later on Wednesday the MDS was rebooted (17:04 and again at 18:02). The same problem with create threads waiting in lov_create() looks to have happened again a few hours later that evening (2014-03-12 23:01). An increasing number of threads appeared to become permanently blocked on the 13th and 14th, until the MDS was taken offline on the 14th, but I suspect those are just a byproduct of the other threads holding locks on the affected directories.
It isn't totally clear, but this may be caused by the LU-3645 patch http://review.whamcloud.com/7559 that is (AFAIK) installed at IU, but not landed on b2_1 yet. Fan Yong's comments on that patch are:
osc_create_with_fakereq() is blocked operation, call it within the interpret environment may cause the ptlrpcd to be blocked. Such behaviour should be avoided, otherwise the whole system may be hung.
If you really need to make some blocked operation, you can make it to be processed by some non-ptlrpcd environment. For example, a dedicated thread just handle the async_create callback.
I can't say for sure that this is the problem since the stacks of the other threads on the MDS are not available, but it does seem possible that this patch is causing problems. It might also just be that the OSTs are overloaded, but I never saw any messages in the rest of the console logs for any of the MDS threads that reported being blocked, and if the OSTs were just busy the threads would eventually have become unstuck. Given the number of other messages being printed, I would have expected some messages to be printed by those threads (there were other unrelated messages occasionally being printed before the threads dumped stack).
I would recommend that this patch be reverted from the MDS for now, to see if it is the cause of the problem. Should the problem happen again, in particular either of the messages:
indicating that there are hung threads on the MDS, please dump all of the process stacks on the MDS via "echo t > /proc/sysrq-trigger" and attach the stack traces from the console here. It may be that only a partial dump of the stack traces is shown in /var/log/messages because of the large volume of messages, so preferably they can be captured directly from a serial console.
At this point, I don't think that the clients have anything to do with the current problem, they are just suffering from the hung MDS threads not being able to service requests, or blocking on locks held by the hung MDS service threads. I don't think the current problem relates to the one reported earlier in this ticket.
The original problem may potentially be caused by the MDS being busy and not processing RPC requests in a timely manner and evicting clients too soon. I saw a number of cases in the logs where a client was evicted due to a timed-out lock callback, and then a few seconds later the MDS rejected a cancel request from the same client. That kind of problem might be fixed by increasing the AT max timeout, or more recent changes to high-priority request handling.
It would probably be good to split these issues into two separate bugs.
|
|
mdt_reint (include create case) and mdt_getattr are handled via the same request portal on the MDS, as long as the create operations as blocked because of interpret hung, even though other rdpg/seq service threads are idle, the "ls -l" on client still will be affected. Just as you have seen that the files namelist is available (via rpgd service), but you cannot get the owner/mode information (via mdt_getattr/mdt_getattr_name).
So I agree with Andreas to drop the patch http://review.whamcloud.com/7559 as a temporary solution.
|
|
As per DDN ok to close this ticket
|
Generated at Sat Feb 10 01:44:20 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
4616.client-router.lnet
Flock_lock_logs.txt