Actions
Bug #63298
closedkceph: watchdog: BUG: soft lockup - CPU#8 stuck for 26s! [kworker/8:24:127451]
% Done:
0%
Source:
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Crash signature (v1):
Crash signature (v2):
Description
32887 <0>[63245.381015] watchdog: BUG: soft lockup - CPU#8 stuck for 26s! [kworker/8:24:127451] 32888 <4>[63245.381033] Modules linked in: ceph(E) libceph(E) loop overlay dns_resolver fscache netfs xsk_diag tls snd_seq_dummy snd_hrtimer qrtr rfkill intel_rapl_msr intel_rapl_common snd_intel8x0 intel_pmc_core snd_ac97_codec ac 97_bus rapl snd_seq snd_seq_device snd_pcm pktcdvd snd_timer snd pcspkr soundcore i2c_piix4 xfs libcrc32c sr_mod cdrom sd_mod t10_pi sg ata_generic vmwgfx crct10dif_pclmul drm_ttm_helper crc32_pclmul crc32c_intel ttm virtio_n et ahci drm_kms_helper net_failover video libahci ata_piix failover ghash_clmulni_intel wmi drm libata e1000 serio_raw dm_mirror dm_region_hash dm_log dm_mod fuse [last unloaded: libceph(E)] 32889 <4>[63245.381154] irq event stamp: 0 32890 <4>[63245.381158] hardirqs last enabled at (0): [<0000000000000000>] 0x0 32891 <4>[63245.381171] hardirqs last disabled at (0): [<ffffffff84966873>] copy_process+0xe33/0x2de0 32892 <4>[63245.381185] softirqs last enabled at (0): [<ffffffff84966873>] copy_process+0xe33/0x2de0 32893 <4>[63245.381191] softirqs last disabled at (0): [<0000000000000000>] 0x0 32894 <4>[63245.381196] CPU: 8 PID: 127451 Comm: kworker/8:24 Kdump: loaded Tainted: G EL 6.6.0-rc5+ #16 32895 <4>[63245.381203] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006 32896 <4>[63245.381208] Workqueue: events delayed_work [ceph] 32897 <4>[63245.381314] RIP: 0010:kasan_check_range+0x15/0x1b0 32898 <4>[63245.381322] Code: 0f 1f 44 00 00 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 48 85 f6 0f 84 5e 01 00 00 48 89 f8 41 54 44 0f b6 c2 48 01 f0 <55> 53 72 14 eb 26 cc cc cc 48 b8 ff ff ff ff ff ff ff fe 48 39 c7 32899 <4>[63245.381328] RSP: 0018:ffff888052d0fc50 EFLAGS: 00000286 32900 <4>[63245.381334] RAX: ffff888074aaad44 RBX: ffff888074aaab20 RCX: ffffffff84f38f4f 32901 <4>[63245.381339] RDX: 0000000000000001 RSI: 0000000000000004 RDI: ffff888074aaad40 32902 <4>[63245.381344] RBP: ffff888074aaaba8 R08: 0000000000000001 R09: fffffbfff0f6c484 32903 <4>[63245.381348] R10: ffffffff87b62427 R11: 0000000000000000 R12: ffff888074aab2e0 32904 <4>[63245.381352] R13: ffff888342bfa4e0 R14: ffff888342bfa4e0 R15: ffff888074aaab20 32905 <4>[63245.381366] FS: 0000000000000000(0000) GS:ffff88846ac00000(0000) knlGS:0000000000000000 32906 <4>[63245.381371] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 32907 <4>[63245.381375] CR2: 00007f7a055df010 CR3: 00000001c6f8a005 CR4: 00000000000706e0 32908 <4>[63245.381380] Call Trace: 32909 <4>[63245.381384] <IRQ> 32910 <4>[63245.381388] ? watchdog_timer_fn+0x232/0x2b0 32911 <4>[63245.381396] ? __pfx_watchdog_timer_fn+0x10/0x10 32912 <4>[63245.381403] ? __hrtimer_run_queues+0x107/0x5e0 32913 <4>[63245.381413] ? __pfx___hrtimer_run_queues+0x10/0x10 32914 <4>[63245.381420] ? __pfx_read_tsc+0x10/0x10 32915 <4>[63245.381426] ? ktime_get_update_offsets_now+0xef/0x1f0 32916 <4>[63245.381436] ? hrtimer_interrupt+0x1a0/0x360 32917 <4>[63245.381446] ? __sysvec_apic_timer_interrupt+0x8e/0x240 32918 <4>[63245.381454] ? sysvec_apic_timer_interrupt+0x6a/0x90 32919 <4>[63245.381462] </IRQ> 32920 <4>[63245.381465] <TASK> 32921 <4>[63245.381469] ? asm_sysvec_apic_timer_interrupt+0x16/0x20 32922 <4>[63245.381479] ? igrab+0x3f/0x70 32923 <4>[63245.381486] ? kasan_check_range+0x15/0x1b0 32924 <4>[63245.381494] igrab+0x3f/0x70 32925 <4>[63245.381501] ceph_check_delayed_caps+0x182/0x2f0 [ceph] 32926 <4>[63245.381603] delayed_work+0x25e/0x380 [ceph] 32928 <4>[63245.381716] ? __pfx_process_one_work+0x10/0x10 32929 <4>[63245.381729] ? __list_add_valid_or_report+0x35/0xc0 32930 <4>[63245.381744] worker_thread+0x385/0x670 32931 <4>[63245.381752] ? __kthread_parkme+0xd4/0xf0 32932 <4>[63245.381766] ? __pfx_worker_thread+0x10/0x10 32933 <4>[63245.381772] kthread+0x1a7/0x1f0 32934 <4>[63245.381777] ? kthread+0xf9/0x1f0 32935 <4>[63245.381781] ? __pfx_kthread+0x10/0x10 32936 <4>[63245.381787] ret_from_fork+0x30/0x50 32937 <4>[63245.381800] ? __pfx_kthread+0x10/0x10 32938 <4>[63245.381805] ret_from_fork_asm+0x1b/0x30 32939 <4>[63245.381817] </TASK> 32940 <0>[63273.765347] watchdog: BUG: soft lockup - CPU#8 stuck for 53s! [kworker/8:24:127451] 32941 <4>[63273.765361] Modules linked in: ceph(E) libceph(E) loop overlay dns_resolver fscache netfs xsk_diag tls snd_seq_dummy snd_hrtimer qrtr rfkill intel_rapl_msr intel_rapl_common snd_intel8x0 intel_pmc_core snd_ac97_codec ac 97_bus rapl snd_seq snd_seq_device snd_pcm pktcdvd snd_timer snd pcspkr soundcore i2c_piix4 xfs libcrc32c sr_mod cdrom sd_mod t10_pi sg ata_generic vmwgfx crct10dif_pclmul drm_ttm_helper crc32_pclmul crc32c_intel ttm virtio_n et ahci drm_kms_helper net_failover video libahci ata_piix failover ghash_clmulni_intel wmi drm libata e1000 serio_raw dm_mirror dm_region_hash dm_log dm_mod fuse [last unloaded: libceph(E)] 32942 <4>[63273.765481] irq event stamp: 0 32943 <4>[63273.765484] hardirqs last enabled at (0): [<0000000000000000>] 0x0 32944 <4>[63273.765491] hardirqs last disabled at (0): [<ffffffff84966873>] copy_process+0xe33/0x2de0 32945 <4>[63273.765500] softirqs last enabled at (0): [<ffffffff84966873>] copy_process+0xe33/0x2de0 32946 <4>[63273.765506] softirqs last disabled at (0): [<0000000000000000>] 0x0 32947 <4>[63273.765512] CPU: 8 PID: 127451 Comm: kworker/8:24 Kdump: loaded Tainted: G EL 6.6.0-rc5+ #16 32948 <4>[63273.765519] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006 32949 <4>[63273.765523] Workqueue: events delayed_work [ceph] 32950 <4>[63273.765628] RIP: 0010:__asan_load4+0x0/0x90 32951 <4>[63273.765637] Code: ff 40 38 f0 7e ec c3 cc cc cc cc 48 c1 e8 03 80 3c 10 00 75 ef c3 cc cc cc cc 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 <4c> 8b 04 24 48 83 ff fc 73 62 eb 0f cc cc cc 48 b8 00 00 00 00 00 32952 <4>[63273.765643] RSP: 0018:ffff888052d0fbd0 EFLAGS: 00000246 32953 <4>[63273.765649] RAX: 0000000000000001 RBX: ffff888342bfa4f0 RCX: ffffffff84a67f25 32954 <4>[63273.765654] RDX: ffffed106857f49f RSI: 0000000000000004 RDI: ffff888342bfa4f0 32955 <4>[63273.765658] RBP: 1ffff1100a5a1f7b R08: 0000000000000000 R09: ffffed106857f49e 32956 <4>[63273.765663] R10: ffff888342bfa4f3 R11: 0000000000000000 R12: ffff888342bfa508 32957 <4>[63273.765667] R13: ffff888074aaab20 R14: ffff888342bfa4e0 R15: ffff888074aaab20 32958 <4>[63273.765674] FS: 0000000000000000(0000) GS:ffff88846ac00000(0000) knlGS:0000000000000000 32959 <4>[63273.765687] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 32960 <4>[63273.765692] CR2: 00007f7a055df010 CR3: 00000001c6f8a005 CR4: 00000000000706e0 32961 <4>[63273.765697] Call Trace: 32962 <4>[63273.765701] <IRQ> 32963 <4>[63273.765705] ? watchdog_timer_fn+0x232/0x2b0 32964 <4>[63273.765713] ? __pfx_watchdog_timer_fn+0x10/0x10 32965 <4>[63273.765720] ? __hrtimer_run_queues+0x107/0x5e0 32966 <4>[63273.765730] ? __pfx___hrtimer_run_queues+0x10/0x10 32967 <4>[63273.765737] ? __pfx_read_tsc+0x10/0x10 32968 <4>[63273.765743] ? ktime_get_update_offsets_now+0xef/0x1f0 32969 <4>[63273.765753] ? hrtimer_interrupt+0x1a0/0x360 32970 <4>[63273.765763] ? __sysvec_apic_timer_interrupt+0x8e/0x240 32971 <4>[63273.765771] ? sysvec_apic_timer_interrupt+0x6a/0x90 32972 <4>[63273.765779] </IRQ> 32973 <4>[63273.765782] <TASK> 32974 <4>[63273.765786] ? asm_sysvec_apic_timer_interrupt+0x16/0x20 32975 <4>[63273.765795] ? do_raw_spin_trylock+0x65/0x120 32976 <4>[63273.765804] ? __pfx___asan_load4+0x10/0x10 32977 <4>[63273.765811] do_raw_spin_trylock+0x6d/0x120 32978 <4>[63273.765818] ? __pfx_do_raw_spin_trylock+0x10/0x10 32979 <4>[63273.765825] ? _atomic_dec_and_lock+0x1c/0x80 32980 <4>[63273.765833] _raw_spin_lock+0x39/0x80 32981 <4>[63273.765840] ? ceph_check_delayed_caps+0x1b0/0x2f0 [ceph] 32982 <4>[63273.765938] ceph_check_delayed_caps+0x1b0/0x2f0 [ceph] 32983 <4>[63273.766046] delayed_work+0x25e/0x380 [ceph] 32984 <4>[63273.766161] process_one_work+0x46a/0x910 32985 <4>[63273.766171] ? __pfx_process_one_work+0x10/0x10 32986 <4>[63273.766178] ? __list_add_valid_or_report+0x35/0xc0 32987 <4>[63273.766192] worker_thread+0x385/0x670 32988 <4>[63273.766200] ? __kthread_parkme+0xd4/0xf0 32989 <4>[63273.766208] ? __pfx_worker_thread+0x10/0x10 32990 <4>[63273.766214] kthread+0x1a7/0x1f0 32991 <4>[63273.766219] ? kthread+0xf9/0x1f0 32992 <4>[63273.766224] ? __pfx_kthread+0x10/0x10 32993 <4>[63273.766230] ret_from_fork+0x30/0x50 32994 <4>[63273.766236] ? __pfx_kthread+0x10/0x10 32995 <4>[63273.766242] ret_from_fork_asm+0x1b/0x30 32996 <4>[63273.766253] </TASK> 32997 <6>[63280.415829] libceph: mon0 (1)192.168.0.106:40092 session lost, hunting for new mon 32998 <6>[63280.416965] ceph: [8558cef7-ae1c-4e32-82cd-ec8d54ca8a03 4704] renewed_caps: mds0 caps renewed
With the following debug patch:
diff --git a/fs/ceph/caps.c b/fs/ceph/caps.c
index 324d2f385703..b03afdda6553 100644
--- a/fs/ceph/caps.c
+++ b/fs/ceph/caps.c
@@ -4626,13 +4626,15 @@ unsigned long ceph_check_delayed_caps(struct ceph_mds_client *mdsc)
unsigned long delay_max = opt->caps_wanted_delay_max * HZ;
unsigned long loop_start = jiffies, end;
unsigned long delay = 0;
+ int count = 0;
- doutc(cl, "begin\n");
+ //pr_info("ceph_check_delayed_caps ---> begin\n");
spin_lock(&mdsc->cap_delay_lock);
while (!list_empty(&mdsc->cap_delay_list)) {
ci = list_first_entry(&mdsc->cap_delay_list,
struct ceph_inode_info,
i_cap_delay_list);
+ count++;
/* Do not break the loop if CEPH_I_FLUSH is set. */
if (!(ci->i_ceph_flags & CEPH_I_FLUSH)) {
end = ci->i_hold_caps_max - delay_max;
@@ -4655,9 +4657,11 @@ unsigned long ceph_check_delayed_caps(struct ceph_mds_client *mdsc)
iput(inode);
spin_lock(&mdsc->cap_delay_lock);
}
+ // if (count % 50 == 0)
+ // pr_info(" count : %d\n", count);
}
spin_unlock(&mdsc->cap_delay_lock);
- doutc(cl, "done\n");
+ pr_info("ceph_check_delayed_caps --> done. count : %d\n", count);
return delay;
}
We can see that there are 70181645 items in the cap_delay_list list:
32999 <6>[63280.417161] ceph: ceph_check_delayed_caps --> done. count : 70181645
Updated by Xiubo Li 7 months ago
And even more:
89553 <6>[70434.935748] ceph: ceph_check_delayed_caps --> done. count : 1216951685
And it seems deadlock somewhere and the soft lockup will be shown infinitely:
<0>[70415.318431] watchdog: BUG: soft lockup - CPU#2 stuck for 4177s! [kworker/2:2:155293] <4>[70415.318443] Modules linked in: ceph(E) libceph(E) loop overlay dns_resolver fscache netfs xsk_diag tls snd_seq_dummy snd_hrtimer qrtr rfkill intel_rapl_msr intel_rapl_common snd_intel8x0 intel_pmc_core snd_ac97_codec ac97_bus rapl snd_seq snd_seq_device snd_pcm pktcdvd snd_timer snd pcspkr soundcore i2c_piix4 xfs libcrc32c sr_mod cdrom sd_mod t10_pi sg ata_generic vmwgfx crct10dif_pclmul drm_ttm_helper crc32_pclmul crc32c_intel ttm virtio_net ahci drm_kms_helper net_failover video libahci ata_piix failover ghash_clmulni_intel wmi drm libata e1000 serio_raw dm_mirror dm_region_hash dm_log dm_mod fuse [last unloaded: libceph(E)] <4>[70415.318569] irq event stamp: 0 <4>[70415.318572] hardirqs last enabled at (0): [<0000000000000000>] 0x0 <4>[70415.318579] hardirqs last disabled at (0): [<ffffffff84966873>] copy_process+0xe33/0x2de0 <4>[70415.318587] softirqs last enabled at (0): [<ffffffff84966873>] copy_process+0xe33/0x2de0 <4>[70415.318592] softirqs last disabled at (0): [<0000000000000000>] 0x0 <4>[70415.318597] CPU: 2 PID: 155293 Comm: kworker/2:2 Kdump: loaded Tainted: G EL 6.6.0-rc5+ #16 <4>[70415.318604] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006 <4>[70415.318608] Workqueue: events delayed_work [ceph] <4>[70415.318707] RIP: 0010:__asan_load8+0x2a/0xa0 <4>[70415.318715] Code: 48 8b 0c 24 48 83 ff f8 73 63 eb 0f cc cc cc 48 b8 00 00 00 00 00 00 00 ff eb 0a 48 b8 00 00 00 00 00 80 ff ff 48 39 c7 72 43 <48> 8d 47 07 48 89 c2 83 e2 07 48 83 fa 07 75 1b 48 ba 00 00 00 00 <4>[70415.318721] RSP: 0018:ffff8881463cf990 EFLAGS: 00000202 <4>[70415.318727] RAX: ffff800000000000 RBX: 0000000000000000 RCX: ffffffffc1919973 <4>[70415.318731] RDX: dffffc0000000000 RSI: 1ffff11028c79f50 RDI: ffff88813cbf8040 <4>[70415.318736] RBP: ffff88813cbf8000 R08: ffffffff84a6807a R09: ffffed102025749e <4>[70415.318740] R10: ffff8881012ba4f3 R11: 0000000000000000 R12: ffff88807be6c870 <4>[70415.318744] R13: ffff88807be6c0b0 R14: ffff8881012ba4e0 R15: ffff88807be6c0b0 <4>[70415.318761] FS: 0000000000000000(0000) GS:ffff888469400000(0000) knlGS:0000000000000000 <4>[70415.318766] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 <4>[70415.318770] CR2: 000055ffa4af7000 CR3: 000000040e26c006 CR4: 00000000000706e0 <4>[70415.318774] Call Trace: <4>[70415.318778] <IRQ> <4>[70415.318782] ? watchdog_timer_fn+0x232/0x2b0 <4>[70415.318790] ? __pfx_watchdog_timer_fn+0x10/0x10 <4>[70415.318797] ? __hrtimer_run_queues+0x107/0x5e0 <4>[70415.318806] ? __pfx___hrtimer_run_queues+0x10/0x10 <4>[70415.318813] ? __pfx_read_tsc+0x10/0x10 <4>[70415.318819] ? ktime_get_update_offsets_now+0xef/0x1f0 <4>[70415.318827] ? hrtimer_interrupt+0x1a0/0x360 <4>[70415.318837] ? __sysvec_apic_timer_interrupt+0x8e/0x240 <4>[70415.318845] ? sysvec_apic_timer_interrupt+0x6a/0x90 <4>[70415.318852] </IRQ> <4>[70415.318855] <TASK> <4>[70415.318858] ? asm_sysvec_apic_timer_interrupt+0x16/0x20 <4>[70415.318867] ? do_raw_spin_unlock+0x8a/0x100 <4>[70415.318874] ? ceph_check_caps+0xd3/0xf20 [ceph] <4>[70415.318973] ? __asan_load8+0x2a/0xa0 <4>[70415.318980] ceph_check_caps+0xd3/0xf20 [ceph] <4>[70415.319087] ? kasan_save_stack+0x2e/0x40 <4>[70415.319103] ? process_one_work+0x46a/0x910 <4>[70415.319109] ? worker_thread+0x385/0x670 <4>[70415.319114] ? kthread+0x1a7/0x1f0 <4>[70415.319119] ? ret_from_fork+0x30/0x50 <4>[70415.319125] ? ret_from_fork_asm+0x1b/0x30 <4>[70415.319135] ? delayed_work+0x17b/0x380 [ceph] <4>[70415.319247] ? __pfx_ceph_check_caps+0x10/0x10 [ceph] <4>[70415.319353] ? rcu_is_watching+0x1f/0x50 <4>[70415.319359] ? rcu_is_watching+0x1f/0x50 <4>[70415.319365] ? trace_hardirqs_off_finish+0xc9/0xe0 <4>[70415.319371] ? rcu_is_watching+0x1f/0x50 <4>[70415.319381] ? trace_hardirqs_off_finish+0xc9/0xe0 <4>[70415.319387] ? rcu_is_watching+0x1f/0x50 <4>[70415.319393] ? lockdep_hardirqs_on_prepare+0xc/0x60 <4>[70415.319400] ? trace_hardirqs_on+0x12/0xe0 <4>[70415.319405] ? asm_sysvec_apic_timer_interrupt+0x16/0x20 <4>[70415.319417] ? rcu_is_watching+0x1f/0x50 <4>[70415.319422] ? lock_acquire+0xc7/0x3e0 <4>[70415.319428] ? __pfx_lock_acquire+0x10/0x10 <4>[70415.319434] ? __pfx_lock_acquire+0x10/0x10 <4>[70415.319445] ? do_raw_spin_trylock+0xd0/0x120 <4>[70415.319452] ? __pfx_do_raw_spin_trylock+0x10/0x10 <4>[70415.319458] ? __pfx_do_raw_spin_trylock+0x10/0x10 <4>[70415.319476] ceph_check_delayed_caps+0x19f/0x2f0 [ceph] <4>[70415.319580] delayed_work+0x25e/0x380 [ceph] <4>[70415.319682] process_one_work+0x46a/0x910 <4>[70415.319691] ? __pfx_process_one_work+0x10/0x10 <4>[70415.319697] ? __list_add_valid_or_report+0x35/0xc0 <4>[70415.319711] worker_thread+0x385/0x670 <4>[70415.319720] ? __pfx_worker_thread+0x10/0x10 <4>[70415.319725] kthread+0x1a7/0x1f0 <4>[70415.319730] ? kthread+0xf9/0x1f0 <4>[70415.319734] ? __pfx_kthread+0x10/0x10 <4>[70415.319741] ret_from_fork+0x30/0x50 <4>[70415.319747] ? __pfx_kthread+0x10/0x10 <4>[70415.319752] ret_from_fork_asm+0x1b/0x30 <4>[70415.319762] </TASK> ...
Updated by Xiubo Li 7 months ago
This is a regression from https://patchwork.kernel.org/project/ceph-devel/list/?series=787107&archive=both, and I have remove one patch, which should be okay since the following 2 other
patches could fix the issue well: https://patchwork.kernel.org/project/ceph-devel/list/?series=796228
Actions