Return-Path: <linux-kernel-owner@vger.kernel.org>
Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand
	id S1758954AbcCDPQH (ORCPT <rfc822;w@1wt.eu>);
	Fri, 4 Mar 2016 10:16:07 -0500
Received: from aserp1040.oracle.com ([141.146.126.69]:28933 "EHLO
	aserp1040.oracle.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org
	with ESMTP id S1756538AbcCDPQB (ORCPT
	<rfc822;linux-kernel@vger.kernel.org>);
	Fri, 4 Mar 2016 10:16:01 -0500
Subject: Re: Soft lockups in v3.18.27
To: Jaegeuk Kim <jaegeuk@kernel.org>
References: <20160303215712.GA15737@jaegeuk.hsd1.ca.comcast.net>
Cc: Chris Mason <clm@fb.com>, linux-kernel@vger.kernel.org,
        stable@vger.kernel.org
From: Sasha Levin <sasha.levin@oracle.com>
Message-ID: <56D9A6A9.9070705@oracle.com>
Date: Fri, 4 Mar 2016 10:15:53 -0500
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:38.0) Gecko/20100101
 Thunderbird/38.4.0
MIME-Version: 1.0
In-Reply-To: <20160303215712.GA15737@jaegeuk.hsd1.ca.comcast.net>
Content-Type: text/plain; charset=windows-1252
Content-Transfer-Encoding: 7bit
X-Source-IP: aserv0021.oracle.com [141.146.126.233]
Sender: linux-kernel-owner@vger.kernel.org
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org
Content-Length: 4525
Lines: 72

On 03/03/2016 04:57 PM, Jaegeuk Kim wrote:
> 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@fb.com>
> Date:   Fri Sep 18 13:35:08 2015 -0400
> 
>     fs-writeback: unplug before cond_resched in writeback_sb_inodes

Added. Thanks for the report!


Thanks,
Sasha