Soft lockups in v3.18.27

From: Jaegeuk Kim
Date: Thu Mar 03 2016 - 16:57:20 EST


Hi Sasha,

When I test v3.18.27 in the stable line, I'm suffering from the following soft
lockups.
This occurs during xfstests/013, which is 100% reproducile.
I've confirmed that the latest kernel has no problem.

[26459.346781] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [kworker/u2:3:50]
[26458.347037] Modules linked in: seqiv cts f2fs binfmt_misc ppdev crc32_pclmul aesni_intel aes_x86_64 lrw gf128mul glue_helper ablk_helper cryptd serio_raw joydev snd_intel8x0 snd_ac97_codec ac97_bus snd_pcm i2c_piix4 snd_timer snd soundcore parport_pc parport autofs4 hid_generic usbhid hid psmouse ahci libahci e1000 pata_acpi video
[26458.347060] irq event stamp: 1126550
[26458.347061] hardirqs last enabled at (1126549): [<ffffffff8180b7b7>] restore_args+0x0/0x30
[26458.347076] hardirqs last disabled at (1126550): [<ffffffff8180ba9d>] apic_timer_interrupt+0x6d/0x80
[26458.347078] softirqs last enabled at (1126546): [<ffffffff8108440f>] __do_softirq+0x3af/0x640
[26458.347082] softirqs last disabled at (1126541): [<ffffffff810848a5>] irq_exit+0xd5/0xe0
[26458.347087] CPU: 0 PID: 50 Comm: kworker/u2:3 Tainted: G L 3.18.27+ #5
[26458.347089] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[26458.347093] Workqueue: writeback bdi_writeback_workfn (flush-8:16)
[26458.347096] task: ffff880077bc4340 ti: ffff880036174000 task.ti: ffff880036174000
[26458.347098] RIP: 0010:[<ffffffff810d9ac7>] [<ffffffff810d9ac7>] lock_acquire+0xf7/0x2d0
[26458.347102] RSP: 0018:ffff880036177a98 EFLAGS: 00000292
[26458.347103] RAX: ffff880077bc4340 RBX: 0000000000000296 RCX: 0000000000000005
[26458.347104] RDX: ffff880077bc4c00 RSI: 0000000000000000 RDI: 0000000000000292
[26458.347105] RBP: ffff880036177b08 R08: 0000000000070bf0 R09: 3f31fa110447c000
[26458.347106] R10: ffff880077bc4b60 R11: 0000000000000004 R12: ffffffff828893b0
[26458.347107] R13: ffff880077bc4b60 R14: ffff880077bc4340 R15: ffff880077bc4bb0
[26458.347109] FS: 0000000000000000(0000) GS:ffff88007fc00000(0000) knlGS:0000000000000000
[26458.347110] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[26458.347111] CR2: 00007f1de825ca08 CR3: 000000007ad1b000 CR4: 00000000000406f0
[26458.347114] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[26458.347115] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[26458.347116] Stack:
[26458.347117] 0000000000000000 ffffffff8124dd82 ffff880000000000 0000000000000000
[26458.347119] ffffffff81e587c0 0000000000000292 0000000035c99c30 ffff880061a18fb8
[26458.347121] ffff880077bc4340 ffff880061a18fa0 ffff88007aa18800 ffff880061a18f18
[26458.347123] Call Trace:
[26458.347127] [<ffffffff8124dd82>] ? writeback_sb_inodes+0x122/0x5b0
[26458.347131] [<ffffffff818098d9>] _raw_spin_lock+0x39/0x50
[26458.347133] [<ffffffff8124dd82>] ? writeback_sb_inodes+0x122/0x5b0
[26458.347136] [<ffffffff810b0539>] ? __cond_resched_lock+0x39/0x90
[26458.347138] [<ffffffff8124dd82>] writeback_sb_inodes+0x122/0x5b0
[26458.347141] [<ffffffff8124e2b2>] __writeback_inodes_wb+0xa2/0xd0
[26458.347144] [<ffffffff8124e6eb>] wb_writeback+0x40b/0x790
[26458.347146] [<ffffffff8124ee64>] bdi_writeback_workfn+0x144/0x900
[26458.347149] [<ffffffff8109e106>] ? process_one_work+0x166/0x850
[26458.347152] [<ffffffff8109e193>] process_one_work+0x1f3/0x850
[26458.347154] [<ffffffff8109e106>] ? process_one_work+0x166/0x850
[26458.347156] [<ffffffff8109e838>] worker_thread+0x48/0x4b0
[26458.347159] [<ffffffff8109e7f0>] ? process_one_work+0x850/0x850
[26458.347161] [<ffffffff810a47d4>] kthread+0xe4/0x100
[26458.347163] [<ffffffff810aa59d>] ? finish_task_switch+0x7d/0x120
[26458.347165] [<ffffffff810a46f0>] ? kthread_create_on_node+0x220/0x220
[26458.347167] [<ffffffff8180a958>] ret_from_fork+0x58/0x90
[26458.347169] [<ffffffff810a46f0>] ? kthread_create_on_node+0x220/0x220

So, when I took a look at the writeback_sb_inodes in the latest code, there
was a below commit regarding to this issue.

Indeed, after I did cherry-pick this patch, the issue was gone.
Could you consider merging this patch into v3.18 stable line?

commit 590dca3a71875461e8fea3013af74386945191b2
Author: Chris Mason <clm@xxxxxx>
Date: Fri Sep 18 13:35:08 2015 -0400

fs-writeback: unplug before cond_resched in writeback_sb_inodes

Thanks,