linux-kernel - Soft lockups in v3.18.27

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [thread-next>] [day] [month] [year] [list]

Date:	Thu, 3 Mar 2016 13:57:12 -0800
From:	Jaegeuk Kim <jaegeuk@...nel.org>
To:	sasha.levin@...cle.com
Cc:	Chris Mason <clm@...com>, linux-kernel@...r.kernel.org,
	stable@...r.kernel.org
Subject: Soft lockups in v3.18.27

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@...com>
Date:   Fri Sep 18 13:35:08 2015 -0400

    fs-writeback: unplug before cond_resched in writeback_sb_inodes

Thanks,