Details
-
Bug
-
Resolution: Fixed
-
Blocker
-
Lustre 2.5.4
-
Lustre Build: https://build.hpdd.intel.com/job/lustre-b2_5/112/
FSTYPE=zfs
-
3
-
17337
Description
sanity-hsm test 251 failed as follows:
CMD: shadow-26vm10 pkill -INT -x lhsmtool_posix CMD: shadow-26vm10 pgrep -x lhsmtool_posix shadow-26vm10: 7902 Copytool still running on shadow-26vm10 CMD: shadow-26vm10 pgrep -x lhsmtool_posix shadow-26vm10: 7902 Copytool still running on shadow-26vm10 CMD: shadow-26vm10 pgrep -x lhsmtool_posix shadow-26vm10: 7902 Copytool still running on shadow-26vm10 CMD: shadow-26vm10 pgrep -x lhsmtool_posix shadow-26vm10: 7902 Copytool still running on shadow-26vm10 CMD: shadow-26vm10 pgrep -x lhsmtool_posix shadow-26vm10: 7902 Copytool still running on shadow-26vm10 CMD: shadow-26vm10 pgrep -x lhsmtool_posix shadow-26vm10: 7902 Copytool still running on shadow-26vm10 CMD: shadow-26vm10 pgrep -x lhsmtool_posix shadow-26vm10: 7902 Copytool still running on shadow-26vm10 CMD: shadow-26vm10 pgrep -x lhsmtool_posix shadow-26vm10: 7902 Copytool still running on shadow-26vm10 CMD: shadow-26vm10 pgrep -x lhsmtool_posix shadow-26vm10: 7902 Copytool still running on shadow-26vm10 CMD: shadow-26vm10 pgrep -x lhsmtool_posix shadow-26vm10: 7902 sanity-hsm test_251: @@@@@@ FAIL: Copytool failed to stop in 20s ...
Maloo reports:
https://testing.hpdd.intel.com/test_sets/49281842-a9ef-11e4-8c6f-5254006e85c2
https://testing.hpdd.intel.com/test_sets/4cac5380-aa11-11e4-a5c6-5254006e85c2
Attachments
Issue Links
Activity
Last 2 failures occurrences again show the same delay of copytool death/cleanup due to being stuck, during tens of seconds, because waiting for lock flush/cancel (between Client, who have created file and asked for its archive, and OST[s]) upon archiving file.
This seem to only occur on ZFS until now, and I have verified that my patch, adding a cancel_lru_locks() before hsm_archive allows the copytool copy to start immediatelly, which is normally delayed to allow for previous Client's lock flush/cancel.
Another failure instance on b2_5:
https://testing.hpdd.intel.com/test_sets/465bb228-bbfa-11e4-a79b-5254006e85c2
Concerning the "https://testing.hpdd.intel.com/test_sets/97fd06d8-ac1c-11e4-992b-5254006e85c2" case, the 'Copytool failed to stop in 20s ...' errors/symptoms there looks more as an additional consequence (due to cleanup()/copytool_cleanup() execute as a trap, set in copytool_cleanup(), upon exit) of previous problem within same sub-test or even preceeding sub-tests :
_ 1st sub-test reported to have failed for 'Copytool failed to stop in 20s ...' is test_33, but it has failed previously with "sanity-hsm test_33: @@@@@@ FAIL: request on 0x200007931:0x2b:0x0 is not SUCCEED on mds1" waiting for archive to complete/succeed ...
_ 2nd sub-test reported to have failed for 'Copytool failed to stop in 20s ...' is test_60, but it has failed previously with "sanity-hsm test_60: @@@@@@ FAIL: Timed out waiting for progress update!" waiting for a progress update during archive.
_ 3rd sub-test reported to have failed for 'Copytool failed to stop in 20s ...' is test_70, but it is the next just after test_60 and since its 1st cmd is a copytool_cleanup that is likely to have encountered the same problem than the preceeding.
_ 4th sub-test reported to have failed for 'Copytool failed to stop in 20s ...' is test_71, but it is the next just after test_70 and since its 1st cmd is a copytool_cleanup that is likely to have encountered the same problem than the 2 preceeding.
_ 5th sub-test reported to have failed for 'Copytool failed to stop in 20s ...' is test_103, and according to its specific logs it is the only one that seems to have triggered the same scenario (huge delay during lock flush/cancel processing) I have already described in my previous update. So it may be an other potential subject to the same change than for test_251.
After more Lustre debug log reading, it seems that the "huge delay during lock flush/cancel processing" that seems to be the root cause of the problem is mainly on the OSS side, after the Client has handled the Blocking callback and sent back its Cancel of lock to the OSS. The thread handling it on the OSS can then spend multiple tens of seconds in ldlm_request_cancel()>ldlm_lock_cancel()>ldlm_cancel_callback()-> .... and
highly probably tgt_blocking_ast()>tgt_sync()>dt_object_sync()->osd_object_sync(). So is this finally some kind of ZFS performance issue?
The failure started affecting patch review testing on Lustre b2_5 patches:
https://testing.hpdd.intel.com/test_sets/66e27944-acde-11e4-872a-5254006e85c2
The zfs full group test session was not run on master branch. Maybe this is the reason that we did not search out failure instances on master branch on Maloo.
In the following report on b2_5 branch, many sub-tests failed with this issue:
https://testing.hpdd.intel.com/test_sets/97fd06d8-ac1c-11e4-992b-5254006e85c2
http://review.whamcloud.com/13646 implements early lock cancel solution to speed-up copytool death.
Faccini Bruno (bruno.faccini@intel.com) uploaded a new patch: http://review.whamcloud.com/13646
Subject: LU-6203 tests: early lock cancel to allow early copytool death
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: cc1f9bc9c062e07515fe6c08e358a703cee116ae
Andreas: no not on master. Based on Maloo reports search, latest test_251 sub-test failures in master have occurred about a year ago and at this time, my patch for LU-5622 was far to be integrated!, and they were linked to LU-3852
There has only been a bunch of 8 failures, between 2014-12-30 07:31:46 UTC and 2015-01-30 14:05:49 UTC and after my patch for LU-5622 has been integrated, all with b2_5 (2 occurrences) or b_ieel2_0 (6 occurrences) branches, and only when using zfs targets. But there are also frequent success for b2_5/b_ieel2_0 branches using zfs!
I have still not been able to reproduce the problem running with b2_5 build #112, that has been reported to trigger the problem.
I have also analyzed the logs of the different failures and it appears that :
_ the copytool's PID still being reported as alive is either the one running the archive action or the main one.
_ each time the copytool log shows that at the time of the kill, the archive action seems to have a slow start and the last log line is "processing file ...", when the "archiving ..."/"saving stripe info of ..."/"start copy of ..." log lines are present in the successful run logs.
_ the Agent debug log shows that the PID running the archive action has been stuck awaiting for an OST_GETATTR request to be replied, during a variable period of time but each time exceeding the 20s allowed to wait for copytool death.
_ during that time the concerned OSS has been trying/waiting to cancel a contending lock from the Client that has created the file being archived.
So could this be the consequence of some ZFS/Network config/performance related causing the file's dirty page flush, occuring at lock cancel time, to take more than 20s under some circumstances ?
I think that a fix for these failures could be either to raise the timer waiting for copytool death (40s?) or ensure dirty data/blocks, during file creation, have been flushed before to start the archive operation (with "cancel_lru_locks osc"?).
Also, I wonder if the priority of this ticket should be kept as Blocker ??
Yu Jian, thanks for all this research work already!!
Will try to reproduce with a ZFS-only configuration and also have a look to the logs of the different cases you pointed to.
Oleg Drokin (oleg.drokin@intel.com) merged in patch http://review.whamcloud.com/13646/
Subject:
LU-6203tests: early lock cancel to allow early copytool deathProject: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 446ad1ef8be5b282224336817936043b42a10fee