From patchwork Wed Jul 13 05:45:07 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Sergey Senozhatsky X-Patchwork-Id: 9226791 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork.web.codeaurora.org (Postfix) with ESMTP id 0EA376075D for ; Wed, 13 Jul 2016 05:45:32 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id F103E2766D for ; Wed, 13 Jul 2016 05:45:31 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id E325A27C38; Wed, 13 Jul 2016 05:45:31 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-6.8 required=2.0 tests=BAYES_00, DKIM_ADSP_CUSTOM_MED, DKIM_SIGNED, FREEMAIL_FROM, RCVD_IN_DNSWL_HI, T_DKIM_INVALID autolearn=ham version=3.3.1 Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 3742D2766D for ; Wed, 13 Jul 2016 05:45:31 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1750947AbcGMFpS (ORCPT ); Wed, 13 Jul 2016 01:45:18 -0400 Received: from mail-pf0-f195.google.com ([209.85.192.195]:34453 "EHLO mail-pf0-f195.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750852AbcGMFpR (ORCPT ); Wed, 13 Jul 2016 01:45:17 -0400 Received: by mail-pf0-f195.google.com with SMTP id g202so2493258pfb.1; Tue, 12 Jul 2016 22:45:11 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=date:from:to:cc:subject:message-id:references:mime-version :content-disposition:in-reply-to:user-agent; bh=Y09eNNR6yDYPwre/H+J156xBD05ueSp9VYn9aca2pYs=; b=YSDj0ojL9aBuQtl7MXgnW0zmOPeXdVyZ7FF18kZ8HxdQALkc8ZOqR8Nm1j/aDnqiQp ASyR8fhtHC7JVyreBGGqEUKytiKve7nJb4gFYJX858O6E6hOuiWMiyvNwPQg2pKsbMdi R6BMx/ComWPtZTPsk9bCHlROqPDJQ7IGKwr1wgR31/Jn943NJIWYTuX/a2wAGU6x4OQo ngcZwHS1NdgsuIezxOtEAI0HJAilCSWkQq+juHBP09PHgIWwFG/PGv+8cG4ZC7cHLswY On5sUGaF2gY8o3jyeom+e4U48IB+/5zz1xs+kDrxWRLlLZva4sBkvT485r0FYxOdQHzJ uWxA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:date:from:to:cc:subject:message-id:references :mime-version:content-disposition:in-reply-to:user-agent; bh=Y09eNNR6yDYPwre/H+J156xBD05ueSp9VYn9aca2pYs=; b=RksGC2GcRv2c1LeNPpece7HwUpscR3hXw9OSjYl/eBHDE+MWEURtXSHYW1i2kEXXSE 5KJpkxq3ezt4KAm9XpyoffcNtQgWsPgmjk5khjQkhyqUjZ8Eby45OVV3oPevbnITyIDI kjKoo+A4tp7NZNIpkOH3/beVRdEGEFx+xqkAcEdVZ4WKfojfa3HRX+RXlvz/6kJJbvv0 eSzfT6CW6qneXf+x1vimyPK8xyI0/QrhgYZvM2JIJt7scDD1AD3RIQcVXx9i6QfcKNNC KvvvhnJQUAnQwazv/jMHY3aa2RhngKax2H/XBL0rNfKM7OWMd8byWIPqSpYvyqYI1zHT NY4g== X-Gm-Message-State: ALyK8tIJYDJNy6rKpwYXvpuB3LN9YsdqPmD3vgaA5qVf/5JupRLtFaJOyH1dhKaXWQBVJQ== X-Received: by 10.98.82.74 with SMTP id g71mr315791pfb.157.1468388709292; Tue, 12 Jul 2016 22:45:09 -0700 (PDT) Received: from localhost ([110.70.14.107]) by smtp.gmail.com with ESMTPSA id e126sm831300pfc.5.2016.07.12.22.45.07 (version=TLS1_2 cipher=ECDHE-RSA-CHACHA20-POLY1305 bits=256/256); Tue, 12 Jul 2016 22:45:08 -0700 (PDT) Date: Wed, 13 Jul 2016 14:45:07 +0900 From: Sergey Senozhatsky To: Viresh Kumar Cc: Jan Kara , Sergey Senozhatsky , rjw@rjwysocki.net, Tejun Heo , Greg Kroah-Hartman , Linux Kernel Mailing List , vlevenetz@mm-sol.com, vaibhav.hiremath@linaro.org, alex.elder@linaro.org, johan@kernel.org, akpm@linux-foundation.org, rostedt@goodmis.org, Sergey Senozhatsky , linux-pm@vger.kernel.org, Petr Mladek Subject: Re: [Query] Preemption (hogging) of the work handler Message-ID: <20160713054507.GA563@swordfish> References: <20160701165959.GR12473@ubuntu> <20160701172232.GD28719@htj.duckdns.org> <20160706182842.GS2671@ubuntu> <20160711102603.GI12410@quack2.suse.cz> <20160711154438.GA528@swordfish> <20160711223501.GI4695@ubuntu> <20160712231903.GR4695@ubuntu> MIME-Version: 1.0 Content-Disposition: inline In-Reply-To: <20160712231903.GR4695@ubuntu> User-Agent: Mutt/1.6.2 (2016-07-01) Sender: linux-pm-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-pm@vger.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP Cc Petr Mladek. On (07/12/16 16:19), Viresh Kumar wrote: [..] > Okay, we have tracked this BUG and its really interesting. good find! > I hacked the platform's serial driver to implement a putchar() routine > that simply writes to the FIFO in polling mode, that helped us in > tracing on where we are going wrong. > > The problem is that we are running asynchronous printks and we call > wake_up_process() from the last running CPU which has disabled > interrupts. That takes us to: try_to_wake_up(). > > In our case the CPU gets deadlocked on this line in try_to_wake_up(). > > raw_spin_lock_irqsave(&p->pi_lock, flags); yeah, printk() can't handle these types of recursion. it can prevent printk() calls issued from within the logbuf_lock spinlock section, with some limitations: if (unlikely(logbuf_cpu == smp_processor_id())) { recursion_bug = true; return; } raw_spin_lock(&logbuf_lock); logbuf_cpu = this_cpu; ... logbuf_cpu = UINT_MAX; raw_spin_unlock(&logbuf_lock); so should, for instance, raw_spin_unlock() generate spin_dump(), printk() will blow up (both sync and async), because logbuf_cpu is already reset. it may look that async printk added another source of recursion - wake_up(). but, apparently, this is not exactly correct. because there is already a wake_up() call in console_unlock() - up(). printk() if (logbuf_cpu == smp_processor_id()) return; raw_spin_lock(&logbuf_lock); logbuf_cpu = this_cpu; ... logbuf_cpu = UINT_MAX; raw_spin_unlock(&logbuf_lock); console_trylock() raw_spin_lock_irqsave(&sem->lock) << *** raw_spin_unlock_irqsave(&sem->lock) << *** console_unlock() up() raw_spin_lock_irqsave(&sem->lock) << *** __up() wake_up_process() try_to_wake_up() << *** in may places *** a printk() call from here will kill the system. either it will recurse printk(), or spin forever in 'nested' printk() on one of the already taken spin locks. I had an idea of waking up a printk_kthread under logbuf_lock, so `logbuf_cpu == smp_processor_id()' test would help here. But it turned out to introduce a regression in printk() behaviour. apart from that, it didn't fix any of the existing recursion printks. there is printk_deferred() printk that is supposed to be used for printing under scheduler locks, but it won't help in all of the cases. printk() has many issues. > I will explain how: > > The try_to_wake_up() function takes us through the scheduler code (RT > sched), to the hrtimer code, where we eventually call ktime_get() (for > the MONOTONIC clock used for hrtimer). And this function has this: > > WARN_ON(timekeeping_suspended); > > This starts another printk while we are in the middle of > wake_up_process() and the CPU tries to take the above lock again and > gets stuck there :) > > This doesn't happen everytime because we don't always call ktime_get() > and it is called only if hrtimer_active() returns false. > > This happened because of a WARN_ON() but it can happen anyway. Think > about this case: > > - offline all CPUs, except 0 > - call any routine that prints messages after disabling interrupts, > etc. > - If any of the function within wake_up_process() does a print, we are > screwed. > > So the thing is that we can't really call wake_up_process() in cases > where the last CPU disables interrupts. And that's why my fixup patch > (which moved to synchronous prints after suspend) really works. > > @Jan and Sergey: I would expect a patch from you guys to fix this > properly :) > > Maybe something more in can_print_async() routine, like: > > only-one-cpu-online + irqs_disabled() > right. adding only (num_online_cpus() > 1) check to can_printk_async() *in theory* can break some cases. for example, SMP system, with only one online CPU, active rt_sched throttling (not necessarily because of printk kthread, any other task will do), and some of interrupts services by CPU0 keep calling printk(), so deferred printk IRQ will stay busy: echo 0 > /sys/..../cpu{1..NR_CPUS}/online # only CPU0 is active CPU0 sched() printk_deferred() IRQ wake_up_klogd_work_func() console_trylock() console_unlock() IRQ printk() IRQ printk() .... IRQ printk() ... console_sem_up() return with async printk here we can offload printing from IRQ. the warning that you see is WARN_ON(timekeeping_suspended), so we have timekeeping_suspended, checking for irqs_disabled() is a _bit_ non-intuitive, I think, but in the existing scheme of things can work (at least tick_suspend() comment suggests so). correct me if I'm wrong. so... I think we can switch to sync printk mode in suspend_console() and enable async printk from resume_console(). IOW, suspend/kexec are now executed under sync printk mode. we already call console_unlock() during suspend, which is synchronous, many times (e.g. console_cpu_notify()). something like below, perhaps. will this work for you? Tested-by: Viresh Kumar --- kernel/printk/printk.c | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index bbb4180..786690e 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -288,6 +288,11 @@ static u32 log_buf_len = __LOG_BUF_LEN; /* Control whether printing to console must be synchronous. */ static bool __read_mostly printk_sync = true; +/* + * Force sync printk mode during suspend/kexec, regardless whether + * console_suspend_enabled permits console suspend. + */ +static bool __read_mostly force_printk_sync; /* Printing kthread for async printk */ static struct task_struct *printk_kthread; /* When `true' printing thread has messages to print */ @@ -295,7 +300,7 @@ static bool printk_kthread_need_flush_console; static inline bool can_printk_async(void) { - return !printk_sync && printk_kthread; + return !printk_sync && printk_kthread && !force_printk_sync; } /* Return log buffer address */ @@ -2027,6 +2032,7 @@ static bool suppress_message_printing(int level) { return false; } /* Still needs to be defined for users */ DEFINE_PER_CPU(printk_func_t, printk_func); +static bool __read_mostly force_printk_sync; #endif /* CONFIG_PRINTK */ @@ -2163,6 +2169,8 @@ MODULE_PARM_DESC(console_suspend, "suspend console during suspend" */ void suspend_console(void) { + force_printk_sync = true; + if (!console_suspend_enabled) return; printk("Suspending console(s) (use no_console_suspend to debug)\n"); @@ -2173,6 +2181,8 @@ void suspend_console(void) void resume_console(void) { + force_printk_sync = false; + if (!console_suspend_enabled) return; down_console_sem();