|
Hi Chris,
could you please enable at least "rpctrace" and "ha" logging and debug_daemon on the MDS and OSS and collect enough logs that you have at least once instance of this failure (about 15 minutes) and attach them here. Unfortunately, I don't think it is practical to collect -1 debug logs on the MDS for 15 minutes if the system is busy, though that might be possible after you have otherwise unmounted all the clients for some system maintenance. It appears that the reason this RPC is being regenerated even after an MDS restart is because it is a destroy from the OST orphan unlink llog. We aren't sure if there is enough information to be collected from the currently running system with just RPCTRACE and HA logs, or if we will need to collect the logs from right after a restart, but we thought to start with what logs can be collected without restarting the OSS.
When you say the "same transaction number", do you mean the same XID (i.e. x1506778035514940)? In that case it appears the RPC is being resent repeatedly by the PTLRPC layer, thougha it seems unlikely that this would persist across the restart of the MDS.
|
|
Yes, I meant the XID. I had "rpctrace" and "lnet" enabled, and I did not see anywhere that the XID was ever actually transmitted. Actually, I have not retested since the MDS was rebooted, so I don't know if the XID changed after that. It was the same for many hours before the MDS was rebooted.
Using the debug_daemon on a production MDS for 15 minutes is not terribly practical. The logs are prohibitive in size. We'll need to be a bit more targeted, at least while it is in production use. If we can avoid a down time for the filesystem to get to the root of the problem, that is certainly preferable.
But while gather a 11+ minute log is difficult, I did manually dump two logs of back-to-back timeouts. That allowed me to use the "sent" time from the second timeout to go back in the log from the previous timeout. That log did seem to fully cover the "sent" time, but I saw no messages concerning the transmission of that XID.
Granted, I'm not 100% sure that I have captured everything, but thats about as much as we can reasonably do while the system is in production use.
|
|
I wonder if you can do simultaneous OST logs gathering to see if the xid really arrives there?
|
|
Is the logs available now?
as per the flags of the request "Rpc:Xru" , this request is Not marked as "resend".
|
|
We will have a system maintenance window mid September if we need to increase the debugging level.
|
|
Hongchao
Is there any specific debugging we want to ask from LLNL?
Thanks
Peter
|
|
Hi,
Please enable the "ha", "rpctrace" and "net", and collecting the debug logs from both MDS and OSS.
the debug size could be needed to be increased to contain more logs to cover the time period of the timeout.
Thanks!
|
|
Thank you. The system maintenance we had planned for Sept has been postponed to sometime in October. I will provide an update after the maintenance.
|
|
I have attached the debug logs as requested.
|
|
Thanks for the logs! and still need some more time to analysis the logs and will update the status of this ticket soon!
|
|
in the OSS, there is already one OST_DESTROY request being found to be processed, then this request was failed with -EBUSY and
OSS dropped the request, which caused the timeout at client and the recovery process is triggered, the OST_DESTROY request is
resent and encounter the same error, which caused the OST_DESTROY to be sent periodically.
Could you please collect the processes stack dump at the OSS by "echo 't' > syrq-trigger"? Thanks!
|
|
I've attached a process dump starting at 08:26:26 that should include the OST problem at 08:26:27.
|
|
as per the logs, the destroy process hung at "txg_wait_open", and it could be the same on as LU-6923
|
|
Indeed, in both tickets, the processes are waiting for a txg to open. And in LU-6923, where I didn't run Lustre on top of ZFS, the txg_sync process was stuck on memory allocation. Did you find a similar process doing the same thing in this case?
|
|
the following process is similar to that stuck "txt_sync" in LU-6923
|
|
probably the same root cause as in LU-5242 ? I'm not sure whether the patch was landed on that branch.
|
|
Hi Cameron,
Which version of ZFS you are using on you site? and does the problem still exist now? if so, could you please collect one more
the stack traces of the processes on the OST, then we can compare it with the previous one to help understand the problem?
and please attach the output of the "top" meanwhile.
As per the comment from Alex, could you please check whether the patch http://review.whamcloud.com/#/c/13630/ is contained
in the branch 2.5.4-4chaos? (the patch is contained since b2_7).
Thanks
|
|
I believe that LU-5242 is included in 2.5.4, which is the release LLNL are currently based on. Hongchao was also wondering if it would be possible to check the consistence of the pool by "zpool scrub"? and mount the ZFS filesystem without Lustre to see whether the ZFS can be used normally?
|
|
Hongchao,
As you pointed out, we're running 2.5.4-4 and our ZFS version is 0.6.4.2.
The original problem does still exist and I've captured another stack trace. Unfortunately, the capture of the trace crashed the node after a while, causing me to lose the top output. The OST is failed over at this point and I can attempt to fail back, though past attempts on failing back the OST (without rebooting both OSSs) have been unsuccessful. Let me know if you would like me to try the trace again to get the top output?
Cameron
|
|
New stack trace attached. This capture resulted in crashing the OSS so it's possible some information is missing. The OST reconnect messages show at 08:20:32.
|
|
Peter,
I started a scrub on that OST's pool. I believe I've done one before (since getting the error) that didn't report any problems, but it won't hurt to try again. As for mounting the file system as ZFS, we will be updating TOSS next week and will have some downtime so I might be able to squeeze that in. Are you mostly just looking to see if it's mountable or should I look for anything specifically?
|
|
there are more Lustre processes in the "D" state in the new stack traces, and also found two almost same "D" multipathd processes.
The other "multipathd" processes are normal (PIDs are 2649, 2651, 2655, 2656, 2658, 3607, 3643, 3661, 3668, 3755, 3791).
Is it possible that the "multipathd" process 2657 caused the problem by blocking the IO?
|
|
Cameron
I was mostly hoping to stimulate thought being given to different options to break the impasse on this ticket. I will defer to Hongchao as to whether this option is worth pursuing but it certainly sounds like an interesting possibility to me
Peter
|
|
Hi Cameron,
Could you please attach the console logs and the dmesg logs in the affected MDT? I want to check whether there are some logs
similar with "INFO: task multipathd:xxxx blocked for more than 120 seconds." in the console logs, or try to find some info related to
the reason that the "multipathd" is blocked, e.g. the IO paths failed in multipathd (if the multi IO paths are failed, it could be possible
to cause this problem due to IO blocked).
Thanks
Hongchao
|
|
I have checked the console logs. There are no errors reported.
pilsneri:/g/g0/marc# grep -i multi /var/log/conman/console.pilsner-mds1
pilsneri:/g/g0/marc#
All the devices are in an active ready running state, just like the other 9 file systems here at LLNL.
|
|
It is important to remember that a backtrace is just a snapshot in time, it does not imply on its own that a thread is stuck.
I did a bit more investigation and asked Brian for help interpreting what I was seeing. Here is what we found:
When I logged into the problem OST this time, I immediately noted that the txg_sync and txg_quiesce processes are almost constantly busy, and have accumulated orders of magnitude more CPU time than the the processes on other OSS nodes.
Also, the ll_ost_01_005 thread has a pretty constant, but low, CPU usage of about 7.6%.
So Brian showed me how to turn on txg history (echo 100 > /sys/module/zfs/parameters/zfs_txg_history). Here is an excerpt from /proc/spl/kstat/zfs/pilsner59/txgs:
This means that transaction groups are being synced many, many times per seconds, and very few of those of the txgs contain any actual data (zero bytes written, zero bytes read).
Next Brian pointed my to the /proc/spl/kstat/zfs/dmu_tx file, which apparently lists dmu tx error counts:
Brian was kind enough to look up dmu_tx_memory_reserve for me in the code, and it basically means that something is requesting a dmu transaction size that exceeds the entire size of the ARC. The ARC right now is around 33GiB, for reference.
So lets go back to that ll_ost_01_005 thread. Here is the backtrace:
It keeps showing up in ofd_destroy. Could that have anything to do with our problem OST_DESTROY? It does seem quite likely.
So it would certainly appear that Lustre is asking for a transaction size that is absurd, ZFS replies with EAGAIN, and then I guess that Lustre forces a sync on the txg? Then Lustre immediately starts the whole thing over again, and repeats it forever.
I think that is probably enough information to get you looking in the right place.
|
|
Brian gave me a direct pointer to where ZFS is catching the bad TX size request:
|
|
I think this is what we were fixing in LU-5242. dmu_free_long_range() was used to truncate an object in few transactions.
|
|
Hi Alex,
Currently, if the object size is less than 16M, the "dmu_object_free" will be used to destroy the object in one transaction.
how about decreasing the size limit to reduce the transaction size? in LU-5242, Brian suggested the size of one transaction
is better about ~10M.
|
|
object size is not equal transaction size. transaction size includes blocks the transaction modifies, but blocks used for user's data aren't modified, so they are not part of transaction. IOW, it's only metadata blocks (dnode, tree).
|
|
This is late notice, but we have planned OS upgrades on this system this morning (08:30-10:00 PST) and I will have the system offline for a small amount of time. It looks like we have some pointers to chase down, but let me know if you'd like me to do anything with that downtime.
|
|
Yes, it certainly sounds like LU-5242 is a likely candidate for fixing this issue. It looks like something that fell through the cracks at Intel when it came time to land the backport.
|
|
the patch back-ported from http://review.whamcloud.com/#/c/13630/ in LU-5242 is tracked at http://review.whamcloud.com/#/c/17154/
|
|
I updated to Lustre 2.5.5-3chaos today on the system and there appears to be no change in the behavior. Following is output taken after the system has been updated:
Jan 14 09:34:34 pilsner-mds1 kernel: Lustre: lsd-OST003a-osc-MDT0000: Connection to lsd-OST003a (at 172.19.2.162@o2ib100) was lost; in progress operations using this service will wait for recovery to complete
Jan 14 09:34:34 pilsner59 kernel: Lustre: lsd-OST003a: Client lsd-MDT0000-mdtlov_UUID (at 172.19.2.102@o2ib100) reconnecting
Jan 14 09:34:34 pilsner59 kernel: Lustre: lsd-OST003a: deleting orphan objects from 0x0:26258401 to 0x0:26258561
Jan 14 09:34:34 pilsner-mds1 kernel: Lustre: lsd-OST003a-osc-MDT0000: Connection restored to lsd-OST003a (at 172.19.2.162@o2ib100)
Jan 14 09:34:34 pilsner-mds1 kernel: Lustre: Skipped 1 previous similar message
Jan 14 09:45:20 pilsner-mds1 kernel: Lustre: lsd-OST003a-osc-MDT0000: Connection to lsd-OST003a (at 172.19.2.162@o2ib100) was lost; in progress operations using this service will wait for recovery to complete
Jan 14 09:45:20 pilsner59 kernel: Lustre: lsd-OST003a: Client lsd-MDT0000-mdtlov_UUID (at 172.19.2.102@o2ib100) reconnecting
Jan 14 09:45:20 pilsner-mds1 kernel: Lustre: lsd-OST003a-osc-MDT0000: Connection restored to lsd-OST003a (at 172.19.2.162@o2ib100)
Jan 14 09:45:39 pilsner59 kernel: Lustre: lsd-OST003a: deleting orphan objects from 0x0:26260525 to 0x0:26260961
Jan 14 09:56:05 pilsner-mds1 kernel: Lustre: lsd-OST003a-osc-MDT0000: Connection to lsd-OST003a (at 172.19.2.162@o2ib100) was lost; in progress operations using this service will wait for recovery to complete
Jan 14 09:56:05 pilsner59 kernel: Lustre: lsd-OST003a: Client lsd-MDT0000-mdtlov_UUID (at 172.19.2.102@o2ib100) reconnecting
Jan 14 09:56:05 pilsner59 kernel: Lustre: lsd-OST003a: deleting orphan objects from 0x0:26262647 to 0x0:26262977
Jan 14 09:56:05 pilsner-mds1 kernel: Lustre: lsd-OST003a-osc-MDT0000: Connection restored to lsd-OST003a (at 172.19.2.162@o2ib100)
|
|
Hi Cameron,
The logs in the above seems to be normal. the precreated objects at OST will be deleted by MDT when the MDT recover the connection
to OST, the logs "deleting orphan objects from xxx to xxx ..." is just these cases, and the corresponding request code OST_CREATE(5)
is different from the request code in the issue (OST_DESTORY 6).
Is there other logs to indicate the OST_DESTROY request is resent periodically?
Thanks
|
|
Hongchao,
These messages were symptomatic of the reported issue, following the same format and period. However, looking again, it looks like the messages stopped about 10 minutes after I copied these messages. It appears that the problem did resolve itself with the patched code and I should have waited about 22 more minutes before responding  .
|
|
That's good news Cameron. So, can we close this ticket as a duplicate of LU-5242?
|
|
Yes. It can be closed.
|
|
Thanks Cameron
|
Generated at Sat Feb 10 02:05:18 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
debug_log.pilsner-mds1.LU-7020.2015.10.15.txt.gz
debug_log.pilsner59.LU-7020.2015.10.15.txt.gz