Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S932899AbaFKPec (ORCPT ); Wed, 11 Jun 2014 11:34:32 -0400 Received: from mailout32.mail01.mtsvc.net ([216.70.64.70]:58210 "EHLO n23.mail01.mtsvc.net" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S932412AbaFKPeb (ORCPT ); Wed, 11 Jun 2014 11:34:31 -0400 Message-ID: <53987704.3030703@hurleysoftware.com> Date: Wed, 11 Jun 2014 11:34:28 -0400 From: Peter Hurley User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:24.0) Gecko/20100101 Thunderbird/24.5.0 MIME-Version: 1.0 To: Sasha Levin , Jan Kara CC: pmladek@suse.cz, Andrew Morton , Jet Chen , LKML , Linus Torvalds Subject: Re: console: lockup on boot References: <5388838B.8070802@oracle.com> <53888E76.5040101@hurleysoftware.com> <20140530140757.GC2419@quack.suse.cz> <53921116.5050804@oracle.com> <53972B5C.5020605@hurleysoftware.com> <53986DFB.9030006@oracle.com> In-Reply-To: <53986DFB.9030006@oracle.com> Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 7bit X-Authenticated-User: 990527 peter@hurleysoftware.com X-MT-ID: 8FA290C2A27252AACF65DBC4A42F3CE3735FB2A4 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On 06/11/2014 10:55 AM, Sasha Levin wrote: > On 06/10/2014 11:59 AM, Peter Hurley wrote: >> On 06/06/2014 03:05 PM, Sasha Levin wrote: >>> On 05/30/2014 10:07 AM, Jan Kara wrote: >>>> On Fri 30-05-14 09:58:14, Peter Hurley wrote: >>>>>> On 05/30/2014 09:11 AM, Sasha Levin wrote: >>>>>>>> Hi all, >>>>>>>> >>>>>>>> I sometime see lockups when booting my KVM guest with the latest -next kernel, >>>>>>>> it basically hangs right when it should start 'init', and after a while I get >>>>>>>> the following spew: >>>>>>>> >>>>>>>> [ 30.790833] BUG: spinlock lockup suspected on CPU#1, swapper/1/0 >>>>>> >>>>>> Maybe related to this report: https://lkml.org/lkml/2014/5/30/26 >>>>>> from Jet Chen which was bisected to >>>>>> >>>>>> commit bafe980f5afc7ccc693fd8c81c8aa5a02fbb5ae0 >>>>>> Author: Jan Kara >>>>>> AuthorDate: Thu May 22 10:43:35 2014 +1000 >>>>>> Commit: Stephen Rothwell >>>>>> CommitDate: Thu May 22 10:43:35 2014 +1000 >>>>>> >>>>>> printk: enable interrupts before calling console_trylock_for_printk() >>>>>> We need interrupts disabled when calling console_trylock_for_printk() only >>>>>> so that cpu id we pass to can_use_console() remains valid (for other >>>>>> things console_sem provides all the exclusion we need and deadlocks on >>>>>> console_sem due to interrupts are impossible because we use >>>>>> down_trylock()). However if we are rescheduled, we are guaranteed to run >>>>>> on an online cpu so we can easily just get the cpu id in >>>>>> can_use_console(). >>>>>> We can lose a bit of performance when we enable interrupts in >>>>>> vprintk_emit() and then disable them again in console_unlock() but OTOH it >>>>>> can somewhat reduce interrupt latency caused by console_unlock() >>>>>> especially since later in the patch series we will want to spin on >>>>>> console_sem in console_trylock_for_printk(). >>>>>> Signed-off-by: Jan Kara >>>>>> Signed-off-by: Andrew Morton >>>>>> >>>>>> ? >>>> Yeah, very likely. I think I see the problem, I'll send the fix shortly. >>> >>> Hi Jan, >>> >>> It seems that the issue I'm seeing is different from the "[prink] BUG: spinlock >>> lockup suspected on CPU#0, swapper/1". >>> >>> Is there anything else I could try here? The issue is very common during testing. >> >> Sasha, >> >> Is this bisectable? Maybe that's the best way forward here. > > I've ran a bisection again and ended up at the same commit as Jet Chen (the commit > unfortunately already made it to Linus's tree). > > Note that I did try Jan's proposed fix and that didn't solve the issue for me, I > believe we're seeing different issues caused by the same commit. > > > 939f04bec1a4ef6ba4370b0f34b01decc844b1b1 is the first bad commit > commit 939f04bec1a4ef6ba4370b0f34b01decc844b1b1 > Author: Jan Kara > Date: Wed Jun 4 16:11:37 2014 -0700 > > printk: enable interrupts before calling console_trylock_for_printk() > > We need interrupts disabled when calling console_trylock_for_printk() > only so that cpu id we pass to can_use_console() remains valid (for > other things console_sem provides all the exclusion we need and > deadlocks on console_sem due to interrupts are impossible because we use > down_trylock()). However if we are rescheduled, we are guaranteed to > run on an online cpu so we can easily just get the cpu id in > can_use_console(). > > We can lose a bit of performance when we enable interrupts in > vprintk_emit() and then disable them again in console_unlock() but OTOH > it can somewhat reduce interrupt latency caused by console_unlock() > especially since later in the patch series we will want to spin on > console_sem in console_trylock_for_printk(). > > Signed-off-by: Jan Kara > Signed-off-by: Andrew Morton > Signed-off-by: Linus Torvalds I apologize; I didn't look at the patch very closely, but now that I do, this sticks out: @@ -1597,17 +1599,22 @@ asmlinkage int vprintk_emit(int facility, int level, logbuf_cpu = UINT_MAX; raw_spin_unlock(&logbuf_lock); + lockdep_on(); + local_irq_restore(flags); + What prevents cpu migration right here? If nothing, then logbuf_cpu is now stale and the recursion test at the top of vprintk_emit is doing nothing to prevent recursion. + /* + * Disable preemption to avoid being preempted while holding + * console_sem which would prevent anyone from printing to console + */ + preempt_disable(); /* * Try to acquire and then immediately release the console semaphore. * The release will print out buffers and wake up /dev/kmsg and syslog() * users. */ - if (console_trylock_for_printk(this_cpu)) + if (console_trylock_for_printk()) console_unlock(); Regards, Peter Hurley -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/