|
Thanks Stephane
|
|
Stephane,
I wonder if according to the stack trace, in the infos you have provided, a thead is in the process to be started in order to do garbage collection (introduced by my patch for LU-7340) of space consumed by changelogs due to a user/consumer (cl1?) being idle since quite a long time ?
But for some unknown reason kthreadd is not starting it, or has still not reported it did... When on the other hand, the mdd_changelog_clear() error msgs seem to indicate changelogs garbage collection may have already started!
Thus, I would like to analyze the crash-dump available, but to do so I also need the lustre-debuginfo RPM from your Lustre version, can you also make it available ?
|
|
Hey Bruno,
Thanks for checking. I noticed that function `mdd_chlg_garbage_collect()` in the "inactivate thread" stack trace too. But this is weird because it is very unlikely cl1 was actually idle, it's a robinhood consumer and if I check the robinhood log just a bit before the issue / crash dump, it seems to be running:
2018/02/16 10:29:18 [7022/2] STATS | ==================== Dumping stats at 2018/02/16 10:29:18 =====================
2018/02/16 10:29:18 [7022/2] STATS | ======== General statistics =========
2018/02/16 10:29:18 [7022/2] STATS | Daemon start time: 2018/01/29 11:23:38
2018/02/16 10:29:18 [7022/2] STATS | Started modules: scan,log_reader,policy_run(modeguard)
2018/02/16 10:29:18 [7022/2] STATS | ======== FS scan statistics =========
2018/02/16 10:29:18 [7022/2] STATS | last scan = 2018/01/30 00:24:56
2018/02/16 10:29:18 [7022/2] STATS | duration = 13h 01min 18s (46878 s)
2018/02/16 10:29:18 [7022/2] STATS | status = complete
2018/02/16 10:29:18 [7022/2] STATS | current scan interval = 22.0d
2018/02/16 10:29:18 [7022/2] STATS | ChangeLog reader #0:
2018/02/16 10:29:18 [7022/2] STATS | fs_name = oak
2018/02/16 10:29:18 [7022/2] STATS | mdt_name = MDT0000
2018/02/16 10:29:18 [7022/2] STATS | reader_id = cl1
2018/02/16 10:29:18 [7022/2] STATS | records read = 176082077
2018/02/16 10:29:18 [7022/2] STATS | interesting records = 119680156
2018/02/16 10:29:18 [7022/2] STATS | suppressed records = 56401921
2018/02/16 10:29:18 [7022/2] STATS | records pending = 999
2018/02/16 10:29:18 [7022/2] STATS | last received = 2018/02/16 10:29:17
2018/02/16 10:29:18 [7022/2] STATS | last read record time = 2018/02/16 10:29:17.671089
2018/02/16 10:29:18 [7022/2] STATS | last read record id = 3459537671
2018/02/16 10:29:18 [7022/2] STATS | last pushed record id = 3459535680
2018/02/16 10:29:18 [7022/2] STATS | last committed record id = 3459535680
2018/02/16 10:29:18 [7022/2] STATS | last cleared record id = 3459535680
2018/02/16 10:29:18 [7022/2] STATS | read speed = 76977.50 record/sec (513.18 incl. idle time)
2018/02/16 10:29:18 [7022/2] STATS | processing speed ratio = 1.00
2018/02/16 10:29:18 [7022/2] STATS | ChangeLog stats:
2018/02/16 10:29:18 [7022/2] STATS | MARK: 18414, CREAT: 16458408, MKDIR: 3318418, HLINK: 35763559, SLINK: 120840, MKNOD: 726
2018/02/16 10:29:18 [7022/2] STATS | UNLNK: 43112348, RMDIR: 3143745, RENME: 6424858, RNMTO: 0, OPEN: 0, CLOSE: 32387229
2018/02/16 10:29:18 [7022/2] STATS | LYOUT: 118087, TRUNC: 3063071, SATTR: 29921326, XATTR: 0, HSM: 0, MTIME: 695102, CTIME: 1535946
2018/02/16 10:29:18 [7022/2] STATS | ATIME: 0, MIGRT: 0
I also just checked that we only have one changelog consumer, cl1:
[root@oak-md1-s2 ~]# cat /proc/fs/lustre/mdd/oak-MDT0000/changelog_users
current index: 3475865674
ID index (idle seconds)
cl1 3475865473 (1)
[root@oak-md1-s2 ~]#
You should be able to download the debuginfo RPMs at the following links:
Thanks!
|
|
Well after doing some analysis on the crash-dump I feel puzzled by what I seem to have discovered.
It looks like the assembly generated code of mdd_changelog_store() routine, including my patch for LU-7340, is wrong :
where it appears that the compiler has completely avoided run_gc_task variable setting/testing.
This may have been caused y the fact run_gc_task has been mistakenly forgotten to be initialized, but then it is unclear why there has been no warning/error to be generated at build/compile time (even if we use -Wall option of gcc, but seems that -Wuninitialized specific check may be, silently?, omitted because no optimization is requested as per some forums threads are reporting?) and also why the generated assembly code do not strictly correspond to the source code.
The side effect of all of this is that an attempt to create a kthread occurs during each ChangeLog record creation (instead of only when garbage-collection conditions have been triggered). And the consequences seems to be aggravated due to the fact now, kthreads are not started in the context of the requestor but requests to do so are queued for "kthreadd" handling which can lead to much trouble if "kthreadd" suffers some issue causing its operations to stop/slow-down.
And this seems to be somewhat the case in your crash-dump :
and even if it seems to move forward as its last activity timestamp is much recent (-1120s) than the one of thread 157540 still stuck with the same stack.
So 1st thing I have to do asap is to push a fix to effectivelly initialize run_gc_task variable/boolean to false, and secondly, I will continue crash-dump analysis in order to understand the reason of "kthreadd" pseudo-hang/slow-operations.
|
|
Faccini Bruno (bruno.faccini@intel.com) uploaded a new patch: https://review.whamcloud.com/31347
Subject: LU-10680 mdd: fix run_gc_task uninitialized
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: df5102382a42a1d366fe38d9da47a1c20ac40dd8
|
|
Bruno,
Wow, what an amazing troubleshooting! Strange that the uninitialized variable wasn't detected by -Wall nor QA/Maloo indeed... I just built new 2.10.3 RPMs with your patch added that I will deploy ASAP.
Thanks much!
|
|
Hmm, I think that I have finally understood what has caused the kthreadd thread to hang and then the whole MDT operations to also become blocked/slow.
We have triggered the following situation/deadlock, where a lot of MDT service threads (mdt[0-9], mdt_rdpg) were stuck in uninterruptible state and waiting for kthreadd to spawn with the following kinds of stacks :
either trying to spawn new service threads, or due to previous described problem of having one changelog garbage collection thread being spawned for each new changelog record.
But as I have already indicated, kthreadd is stuck with the following stack :
as upon trying to launch a new thread, it has unfortunately triggered memory reclaim condition with the consequence of shrinkers to be called, including the one for the lu_cache in order to drain unreferenced objects, and doing so it tries to update quotas in quota slave file, but is being blocked waiting to grant journal credits because the current/running transaction has still not committed. And this is because the transaction is awaiting for a lot of its attached/started handles to complete (jbd2_journal_stop!), but this will never occur as they are almost all from the previous threads waiting for kthreadd. Hence the deadlock.
I think that to fix and prevent such unexpected scenario to re-occur, I need to find a way to start changelog garbage-collection thread outside of the interval/section-of-code where a journal transaction is being filled.
I will push a new/2nd patch soon to implement this.
|
|
Thinking more about it, it seems to me that khreadd should be excluded to run the memory reclaim mechanism in its context, in this case it would be better to do nothing (and leave next thread that will try to allocate some memory to trigger the same conditions/threshold and start to reclaim in its context) or to simply/only wake-up kswapd to do the job asynchronously ?
But anyway, we need to protect against such possible cases, and only request for changelog garbage-collection thread creation, outside of any current journal transaction/handle.
|
|
Thanks Bruno! Hope you'll find a way to fix this race condition.
|
|
Faccini Bruno (bruno.faccini@intel.com) uploaded a new patch: https://review.whamcloud.com/31376
Subject: LU-10680 mdd: create gc thread when no current transaction
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 2985625ebbb404c01f88ada84427d5b4386fbfa4
|
|
Oleg Drokin (oleg.drokin@intel.com) merged in patch https://review.whamcloud.com/31347/
Subject: LU-10680 mdd: fix run_gc_task uninitialized
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 25cdbbb475b8a42e3a1f594898d2ac1406b466f6
|
|
Hello Stephane,
Just one more comment I have in mind and to explain why you have been able to trigger the 2nd problem/deadlock.
As part of LU-10709 I understand that you are running with vm.zone_reclaim_mode=0 also on MDS, so, according to mm code in this area, this seem to be definitely the reason why you have triggered memory-reclaim, with shrinkers run, during khreadd create of new kthread, instead to grab new memory/pages from preferred/current node+zone free-list.
Hopefully this specific case should be handled and fixed by my 2nd fix for this ticket.
|
|
Hey Bruno,
Thanks for the update! And yes, this happened with vm.zone_reclaim_mode=0 on MDS.
|
|
John L. Hammond (john.hammond@intel.com) uploaded a new patch: https://review.whamcloud.com/31552
Subject: LU-10680 mdd: disable changelog garbage collection by default
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 62e4519de3dcb588b88311950e8c6b7fefcca6a8
|
|
Oleg Drokin (oleg.drokin@intel.com) merged in patch https://review.whamcloud.com/31552/
Subject: LU-10680 mdd: disable changelog garbage collection by default
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 57719d0c8833b8a8a8b6516d3bd4f2ad2b226285
|
|
Moving over to 2.12 now that the GC feature is no longer enabled by default, and the failing tests have been disabled. The remaining patch "LU-10680 mdd: create gc thread when no current transaction" for this ticket can land when it is ready, but no longer blocks the 2.11 release.
|
|
Oleg Drokin (oleg.drokin@intel.com) merged in patch https://review.whamcloud.com/31376/
Subject: LU-10680 mdd: create gc thread when no current transaction
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 31fef6845e8be39ae8dfd242714a84001925b7ad
|
|
Landed for 2.12
|
|
"Xing Huang <hxing@ddn.com>" uploaded a new patch: https://review.whamcloud.com/c/fs/lustre-release/+/53773
Subject: LU-10680 tests: fix interop for sanity test_160h
Project: fs/lustre-release
Branch: b2_15
Current Patch Set: 1
Commit: 32f7dd91985cd43e6ad2ed9854f9bed114a0e640
|
Generated at Sat Feb 10 02:37:15 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
foreach_bt-oak-md1-s2-2018-02-16-11-02-21.txt