On 2018/8/21 5:46 PM, Stefan Priebe - Profihost AG wrote: > Hi Coly, > > today i had again the following deadlock where the whole systems get > stuck and can't recover: > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666200] BUG: workqueue > lockup - pool cpus=2 node=0 flags=0x1 nice=0 stuck for 35s! > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666228] BUG: workqueue > lockup - pool cpus=4 node=0 flags=0x1 nice=0 stuck for 47s! > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666248] BUG: workqueue > lockup - pool cpus=11 node=0 flags=0x1 nice=0 stuck for 47s! > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666267] Showing busy > workqueues and worker pools: > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666279] workqueue events: > flags=0x0 > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666289] pwq 22: cpus=11 > node=0 flags=0x1 nice=0 active=4/256 > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666305] pending: > mlx5e_rx_am_work [mlx5_core], kernfs_notify_workfn, mlx5e_rx_am_work > [mlx5_core], free_work > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666346] pwq 18: cpus=9 > node=0 flags=0x1 nice=0 active=3/256 > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666362] pending: > free_work, mlx5e_rx_am_work [mlx5_core], mlx5e_rx_am_work [mlx5_core] > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666390] pwq 8: cpus=4 > node=0 flags=0x1 nice=0 active=8/256 > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666405] pending: > journal_write [bcache], mlx5e_rx_am_work [mlx5_core], mlx5e_rx_am_work > [mlx5_core], free_work, rht_deferred_worker, rht_deferred_worker, > rht_deferred_worker, rht_deferred_worker > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666468] pwq 4: cpus=2 > node=0 flags=0x1 nice=0 active=8/256 > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666501] pending: > mlx5e_rx_am_work [mlx5_core], mlx5e_rx_am_work [mlx5_core], > rht_deferred_worker, rht_deferred_worker, rht_deferred_worker, > rht_deferred_worker, vmpressure_work_fn, free_work > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666600] workqueue bcache: > flags=0x8 > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666610] pwq 22: cpus=11 > node=0 flags=0x1 nice=0 active=9/256 MAYDAY > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666626] in-flight: > 375565:bch_data_insert_keys [bcache], 375566:bch_data_insert_keys [bcache] > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666653] pending: > bch_data_insert_keys [bcache], bch_data_insert_keys [bcache], > bch_data_insert_keys [bcache], bch_data_insert_keys [bcache], > bch_data_insert_keys [bcache], bch_data_insert_keys [bcache], > bch_data_insert_keys [bcache] > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666710] pwq 18: cpus=9 > node=0 flags=0x1 nice=0 active=12/256 MAYDAY > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666726] in-flight: > 375501:bch_data_insert_keys [bcache], 373349:bch_data_insert_keys [bcache] > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666753] pending: > bch_data_insert_keys [bcache], bch_data_insert_keys [bcache], > bch_data_insert_keys [bcache], bch_data_insert_keys [bcache], > bch_data_insert_keys [bcache], bch_data_insert_keys [bcache], > bch_data_insert_keys [bcache], bch_data_insert_keys [bcache], > bch_data_insert_keys [bcache], bch_data_insert_keys [bcache] > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666837] pwq 16: cpus=8 > node=0 flags=0x0 nice=0 active=1/256 > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666854] in-flight: > 375294:bch_data_insert_keys [bcache] > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666873] pwq 10: cpus=5 > node=0 flags=0x0 nice=0 active=44/256 > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.666889] in-flight: > 376496:bch_data_insert_keys [bcache], 376501:bch_data_insert_keys > [bcache], 376520:bch_data_insert_keys [bcache], > 376503:bch_data_insert_keys [bcache], 376492:bch_data_insert_keys > [bcache], 376516:bch_data_insert_keys [bcache], > 376526:bch_data_insert_keys [bcache], 376504:bch_data_insert_keys > [bcache], 376524:bch_data_insert_keys [bcache], > 376497:bch_data_insert_keys [bcache], 376507:bch_data_insert_keys > [bcache], 376523:bch_data_insert_keys [bcache], > 376522:bch_data_insert_keys [bcache], 376510:bch_data_insert_keys > [bcache], 376498:bch_data_insert_keys [bcache], > 376518:bch_data_insert_keys [bcache], 376506:bch_data_insert_keys > [bcache], 376493:bch_data_insert_keys [bcache], > 376513:bch_data_insert_keys [bcache], 376530:bch_data_insert_keys > [bcache], 376499:bch_data_insert_keys [bcache] > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.669998] , > 376519:bch_data_insert_keys [bcache], 376512:bch_data_insert_keys > [bcache], 376532:bch_data_insert_keys [bcache], > 376490:bch_data_insert_keys [bcache], 376527:bch_data_insert_keys > [bcache], 376514:bch_data_insert_keys [bcache], > 376491:bch_data_insert_keys [bcache], 376500:bch_data_insert_keys > [bcache], 376502:bch_data_insert_keys [bcache], > 376508:bch_data_insert_keys [bcache], 376525:bch_data_insert_keys > [bcache], 376494:bch_data_insert_keys [bcache], > 376509:bch_data_insert_keys [bcache], 376528:bch_data_insert_keys > [bcache], 376517:bch_data_insert_keys [bcache], > 376521:bch_data_insert_keys [bcache], 376495:bch_data_insert_keys > [bcache], 376515:bch_data_insert_keys [bcache], > 376531:bch_data_insert_keys [bcache], 376505:bch_data_insert_keys > [bcache], 376529:bch_data_insert_keys [bcache] > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.674767] , > 376533:bch_data_insert_keys [bcache], 376511:bch_data_insert_keys [bcache] > Aug 21 00:28:36 cloud1-1472 kernel: [1150884.675501] pwq 8: cpus=4 > node=0 flags=0x1 nice=0 active=256/256 > Aug 21 00:28:37 cloud1-1472 kernel: [1150884.676303] in-flight: > 377020:bch_data_insert_keys [bcache], 375498:bch_data_insert_keys > [bcache], 377015:bch_data_insert_keys [bcache], > 377019:bch_data_insert_keys [bcache], 377010:bch_data_insert_keys > [bcache], 377004:bch_data_insert_keys [bcache], > 377016:bch_data_insert_keys [bcache], 377012:bch_data_insert_keys > [bcache], 377007:bch_data_insert_keys [bcache], > 377014:bch_data_insert_keys [bcache], 377017:bch_data_insert_keys > [bcache], 377013:bch_data_insert_keys [bcache], > 377018:bch_data_insert_keys [bcache], 375496:bch_data_insert_keys > [bcache], 377005:bch_data_insert_keys [bcache], > 377009:bch_data_insert_keys [bcache], 362(RESCUER):bch_data_insert_keys > [bcache] bch_data_insert_keys [bcache] bch_data_insert_keys [bcache] > bch_data_insert_keys [bcache] bch_data_insert_keys [bcache] > bch_data_insert_keys [bcache] > kern Hi Stefan, Thanks for the informative log. I see journal write and key insert key words from the log. So I keep to suspect the potential locking issue in bcache journal code. This issue is on my todo list, and I am looking at this for now. Coly Li > > Am 09.08.2018 um 12:22 schrieb Coly Li: >> On 2018/8/9 6:12 PM, Stefan Priebe - Profihost AG wrote: >>> Hi, >>> Am 09.08.2018 um 08:37 schrieb Coly Li: >>>> On 2018/8/8 7:52 PM, Stefan Priebe - Profihost AG wrote: >>>>> Hi, >>>>> Am 07.08.2018 um 16:35 schrieb Coly Li: >>>>>> On 2018/8/7 3:41 AM, Stefan Priebe - Profihost AG wrote: >>>>>>> Am 06.08.2018 um 16:21 schrieb Coly Li: >>>>>>>> On 2018/8/6 9:33 PM, Stefan Priebe - Profihost AG wrote: >>>>>>>>> Hi Coly, >>>>>>>>> Am 06.08.2018 um 15:06 schrieb Coly Li: >>>>>>>>>> On 2018/8/6 2:33 PM, Stefan Priebe - Profihost AG wrote: >>>>>>>>>>> Hi Coly, >>>>>>>>>>> >>>>>>>>>>> while running the SLES15 kernel i observed a workqueue lockup and a >>>>>>>>>>> totally crashed system today. >>>>>>>>>>> >>>>>>>>>>> dmesg output is about 3,5mb but it seems it just repeats the >>>>>>>>>>> bch_data_insert_keys msg. >>>>>>>>>>> >>>>>>>>>> >>>>>>>>>> Hi Stefan, >>>>>>>>>> >>>>>>>>>> Thanks for your information! >>>>>>>>>> >>>>>>>>>> Could you please to give me any hint on how to reproduce it ? Even it is >>>>>>>>>> not stable reproducible, a detailed procedure may help me a lot. >>>>>>>>> >>>>>>>>> i'm sorry but i can't reproduce it. It happens just out of nothing in >>>>>>>>> our ceph production cluster. >>>>>>>> >>>>>>>> I see. Could you please share the configuration information. E.g. >>>>>>> >>>>>>> sure. >>>>>>> >>>>>>>> - How many CPU cores >>>>>>> 12 >>>>>>> >>>>>>>> - How many physical memory >>>>>>> 64GB >>>>>>> >>>>>>>> - How large the SSD size, NVMe or SATA >>>>>>> bcache cache size: 250GB SATA SSD >>>>>>> >>>>>>>> - How many SSDs >>>>>>> 1x >>>>>>> >>>>>>>> - How large (many) the backing hard drives are >>>>>>> 2x 1TB >>>>>>> >>>>>>>> I try to simulate similar workload with fio, see how lucky I am. >>>>>>> >>>>>>> Thanks! >>>>>>> >>>>>>> Generally the workload at the timeframe was mostly read, fssync inside >>>>>>> guests and fstrim. >>>>>> >>>>>> Hi Stefan, >>>>>> >>>>>> From your information, I suspect this was a journal related deadlocking. >>>>>> >>>>>> If there are too many small I/O to make the btree inside bcache grows >>>>>> too fast, and in turn make the journal space to be exhausted, there is >>>>>> probably a dead-lock-like hang happens. >>>>>> >>>>>> Junhui tries to fix it by increase journal slot size, but the root cause >>>>>> is not fixed yet. The journal operation in bcache is not atomic, that >>>>>> means a btree node write goes into journal firstly, then insert into >>>>>> btree node by journal replay. If the btree node has to be split during >>>>>> the journal replay, the split meta data needs to go into journal first, >>>>>> if journal space is already exhausted, a dead-lock may happen. >>>>>> >>>>>> A real fix is to make bcache journal operation to be atomic, that means, >>>>>> 1, Reserve estimated journal slots before a journal I/O >>>>>> 2, If reservation succeed, go ahead; if failed wait and try again. >>>>>> 3, If journal reply results btree split, journal slot for new meta data >>>>>> is reserved in journal already and never failed. >>>>>> >>>>>> This fix is not simple, and I am currently working on other fixes (4Kn >>>>>> hard drive and big endian...). If no one else helps on the fix, it would >>>>>> be a while before I may focus on it. >>>>>> >>>>>> Because you mentioned fstrim happend in your guests, if the backing >>>>>> device of bcache supports DISCARD/TRIM, bcache will also invalidate the >>>>>> fstrim range in its internal btree, which may generate more btree metata >>>>>> I/O. Therefore I guess it might be related to journal. >>>>>> >>>>>> Hmm, how about I compose a patch to display free journal slot number. If >>>>>> next time such issue happens and you may still access sysfs, let's check >>>>>> and see whether this is a journal issue. Maybe I am wrong, but it's good >>>>>> to try. >>>>> >>>>> I don't believe the journal was full - the workload at that time (02:00 >>>>> AM) is mostly read only and delete / truncate files and the journal is >>>>> pretty big with 250GB. Ceph handles fstrim inside guests as truncate and >>>>> file deletes outside guest. So the real workload for bcache was: >>>>> - read (backup time) >>>>> - delete file (xfs) >>>>> - truncate files (xfs) >>>> >>>> Hi Stefan, >>>> >>>> I guess maybe we talked about different journals. I should explicit say: >>>> bcache journal, sorry for misleading you. >>>> >>>> There is a bcache journal too, which is around 500MB size for meta data. >>>> If there are too many metadata operations, it is quite easy to be full >>>> filled. >>> >>> ah OK perfect. The only problem is, that i wasn't able to connect to the >>> server anymore when this has happened. So i'm unable to get data from >>> sysfs. Would it be possible to add the value to the kprint line we >>> already get? >> >> Hi Stefan, >> >> I see. Now I will try to compose some patches, to display the >> information, and also try to reduce the possibility of such locking >> issue. Give me some time. >> >> Maybe reboot the server and reload bcache and wait for a quite long time >> may have chance to escape from such awkward situation. Sorry that I >> don't have idea how to fix such deadlock on a running system... >> >> Coly Li >> -- >> To unsubscribe from this list: send the line "unsubscribe linux-bcache" in >> the body of a message to majordomo@xxxxxxxxxxxxxxx >> More majordomo info at http://vger.kernel.org/majordomo-info.html >>
