From patchwork Thu Apr 20 13:11:54 2017 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Petr Mladek X-Patchwork-Id: 9690351 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 543FF60383 for ; Thu, 20 Apr 2017 13:12:29 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 3CFB1223B2 for ; Thu, 20 Apr 2017 13:12:29 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 31A0828387; Thu, 20 Apr 2017 13:12:29 +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=-1.9 required=2.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID autolearn=unavailable version=3.3.1 Received: from bombadil.infradead.org (bombadil.infradead.org [65.50.211.133]) (using TLSv1.2 with cipher AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.wl.linuxfoundation.org (Postfix) with ESMTPS id 6F9C8223B2 for ; Thu, 20 Apr 2017 13:12:28 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=lists.infradead.org; s=bombadil.20170209; h=Sender: Content-Transfer-Encoding:Content-Type:Cc:List-Subscribe:List-Help:List-Post: List-Archive:List-Unsubscribe:List-Id:In-Reply-To:MIME-Version:References: Message-ID:Subject:To:From:Date:Reply-To:Content-ID:Content-Description: Resent-Date:Resent-From:Resent-Sender:Resent-To:Resent-Cc:Resent-Message-ID: List-Owner; bh=mnTrMprswnwkJYOKkFS6UieLStcN4DfT8PtMDOl0D/E=; b=bWm160MMsnY9oO JDUkBhqYgEcCvNTR3HnGZGJPOVpOZgttRMVIAYiCZhVaXR5qxk0D4h6+X4PGlyuK5yh936wp1rYh8 FY71iqoYPCLclqcz8e6iMtdIy3GDGHYG/rAP/anhDz7enmb1cV5RQGfbMkfEeSrkroIg/7jiziTMl sfwHZ6rqijAbTH0F4ebK8UN399ARa0Fpboz2nLlG1/ZCo7Y8VjAcbkxcfRzVPtWfx7/QONYJQIwCJ 4TG4zfRrJtXXCN5J02CQpZENoMP6vfWp4mmfVvrbwinWxjAgQlkFXH6++WSXEtSdqTOopr0hGqxDV lIP8NiKutEr+/y2IT0EQ==; Received: from localhost ([127.0.0.1] helo=bombadil.infradead.org) by bombadil.infradead.org with esmtp (Exim 4.87 #1 (Red Hat Linux)) id 1d1Bsp-0001CA-UX; Thu, 20 Apr 2017 13:12:27 +0000 Received: from mx2.suse.de ([195.135.220.15] helo=mx1.suse.de) by bombadil.infradead.org with esmtps (Exim 4.87 #1 (Red Hat Linux)) id 1d1Bsi-00018F-AX for linux-arm-kernel@lists.infradead.org; Thu, 20 Apr 2017 13:12:26 +0000 X-Virus-Scanned: by amavisd-new at test-mx.suse.de Received: from relay1.suse.de (charybdis-ext.suse.de [195.135.220.254]) by mx1.suse.de (Postfix) with ESMTP id E1F0CAB45; Thu, 20 Apr 2017 13:11:56 +0000 (UTC) Date: Thu, 20 Apr 2017 15:11:54 +0200 From: Petr Mladek To: Sergey Senozhatsky Subject: Re: [PATCH v5 1/4] printk/nmi: generic solution for safe printk in NMI Message-ID: <20170420131154.GL3452@pathway.suse.cz> References: <1461239325-22779-1-git-send-email-pmladek@suse.com> <1461239325-22779-2-git-send-email-pmladek@suse.com> <20170419131341.76bc7634@gandalf.local.home> <20170420033112.GB542@jagdpanzerIV.localdomain> MIME-Version: 1.0 Content-Disposition: inline In-Reply-To: <20170420033112.GB542@jagdpanzerIV.localdomain> User-Agent: Mutt/1.5.21 (2010-09-15) X-CRM114-Version: 20100106-BlameMichelson ( TRE 0.8.0 (BSD) ) MR-646709E3 X-CRM114-CacheID: sfid-20170420_061220_701695_42FAC11A X-CRM114-Status: GOOD ( 37.13 ) X-BeenThere: linux-arm-kernel@lists.infradead.org X-Mailman-Version: 2.1.21 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: linux-mips@linux-mips.org, Jan Kara , linux-sh@vger.kernel.org, Peter Zijlstra , Benjamin Herrenschmidt , Chris Metcalf , sparclinux@vger.kernel.org, linux-s390@vger.kernel.org, Daniel Thompson , x86@kernel.org, Ingo Molnar , Russell King , adi-buildroot-devel@lists.sourceforge.net, Steven Rostedt , Thomas Gleixner , linux-arm-kernel@lists.infradead.org, Jiri Kosina , linux-cris-kernel@axis.com, linux-kernel@vger.kernel.org, Ralf Baechle , Martin Schwidefsky , Andrew Morton , linuxppc-dev@lists.ozlabs.org, David Miller Sender: "linux-arm-kernel" Errors-To: linux-arm-kernel-bounces+patchwork-linux-arm=patchwork.kernel.org@lists.infradead.org X-Virus-Scanned: ClamAV using ClamSMTP On Thu 2017-04-20 12:31:12, Sergey Senozhatsky wrote: > Hello Steven, > > On (04/19/17 13:13), Steven Rostedt wrote: > > > printk() takes some locks and could not be used a safe way in NMI context. > > > > I just found a problem with this solution. It kills ftrace dumps from > > NMI context :-( > > > > [ 1295.168495] <...>-67423 10dNh1 382171111us : do_raw_spin_lock <-_raw_spin_lock > > [ 1295.168495] <...>-67423 10dNh1 382171111us : sched_stat_runtime: comm=cc1 pid=67423 runtime=96858 [ns] vruntime=11924198270 [ns] > > [ 1295.168496] <...>-67423 10dNh1 382171111us : lock_acquire: ffffffff81c5c940 read rcu_read_lock > > [ 1295.168497] > > [ 1295.168498] Lost 4890096 message(s)! > > [ 1296.805063] ---[ end Kernel panic - not syncing: Hard LOCKUP > > [ 1296.811553] unchecked MSR access error: WRMSR to 0x83f (tried to write 0x00000000000000f6) at rIP: 0xffffffff81046fc7 (native_apic_msr_write+0x27/0x40) > > [ 1296.811553] Call Trace: > > [ 1296.811553] > > > > I was hoping to see a cause of a hard lockup by enabling > > ftrace_dump_on_oops. But as NMIs now have a very small buffer that > > gets flushed, we need to find a new way to print out the full ftrace > > buffer over serial. > > > > Thoughts? > > hmmm... a really tough one. > > well, someone has to say this: > the simplest thing is to have a bigger PRINTK_SAFE_LOG_BUF_SHIFT value :) > > > just thinking (well, sort of) out loud. the problem is that we can't tell if > we already hold any printk related locks ("printk related locks" is not even > well defined term). so printk from NMI can deadlock or it can be OK, we > never know. but looking and vprintk_emit() and console_unlock() it seems that > we have some sort of a hint now, which is this_cpu_read(printk_context) - if > we are not in printk_safe context then we can say that _probably_ (and that's > a Russian roulette) doing "normal" printk() will work. that is a *very-very* > risky (and admittedly dumb) thing to assume, so we will move in a slightly > different direction. checking this_cpu_read(printk_context) only assures us > that we don't hold `logbuf_lock' on this CPU. and that is sort of something, > at least we can be sure that doing printk_deferred() from this CPU is safe. > printk_deferred() means that your NMI messages will end up in the logbuf, > which is a) bigger in size than per-CPU buffer and b) some other CPU can > immediately print those messages (hopefully). > > we also switch to printk_safe mode for call_console_drivers() in > console_unlock(). but we can't make any solid assumptions there - serial > console lock can already be acquired, we don't have any markers for that. > it may be reasonable to assume that if we are not in printk_safe mode on > this CPU then serial console is not locked from this CPU, but there is > nothing that can assure us. Good analyze. I would summarize it that we need to be careful of: + logbug_lock + PRINTK_SAFE_CONTEXT + locks used by console drivers The first two things are easy to check. Except that a check for logbuf_lock might produce false negatives. The last check is very hard. > so at the moment what I can think of is something like > > -- check this_cpu_read(printk_context) in NMI prink > > -- if we are NOT in printk_safe on this CPU, then do printk_deferred() > and bypass `nmi_print_seq' buffer I would add also a check for logbuf_lock. > -- if we are in printk_safe > -- well... bad luck... have a bigger buffer. Yup, we do the best effort while still trying to stay on the safe side. I have cooked up a patch based on this. It uses printk_deferred() in NMI when it is safe. Note that console_flush_on_panic() will try to get them on the console when a kdump is not generated. I believe that it will help Steven. From c530d9dee91c74db5e6a198479e2e63b24cb84a2 Mon Sep 17 00:00:00 2001 From: Petr Mladek Date: Thu, 20 Apr 2017 10:52:31 +0200 Subject: [PATCH] printk: Use the main logbuf in NMI when logbuf_lock is available The commit 42a0bb3f71383b457a7d ("printk/nmi: generic solution for safe printk in NMI") caused that printk stores messages into a temporary buffer in NMI context. The buffer is per-CPU and therefore the size is rather limited. It works quite well for NMI backtraces. But there are longer logs that might get printed in NMI context, for example, lockdep warnings, ftrace_dump_on_oops. The temporary buffer is used to avoid deadlocks caused by logbuf_lock. Also it is needed to avoid races with the other temporary buffer that is used when PRINTK_SAFE_CONTEXT is entered. But the main buffer can be used in NMI if the lock is available and we did not interrupt PRINTK_SAFE_CONTEXT. The lock is checked using raw_spin_is_locked(). It might cause false negatives when the lock is taken on another CPU outside NMI. For this reason, we do the check in printk_nmi_enter(). It makes the handling consistent for the entire NMI handler and avoids reshuffling of the messages. The patch also defines special printk context that allows to use printk_deferred() in NMI. Note that we could not flush the messages to the consoles because console drivers might use many other internal locks. The newly created vprintk_deferred() disables the preemption only around the irq work handling. It is needed there to keep the consistency between the two per-CPU variables. But there is no reason to disable preemption around vprintk_emit(). Finally, the patch patch puts back explicit serialization of the NMI backtraces from different CPUs. It was removed by the commit a9edc88093287183ac934b ("x86/nmi: Perform a safe NMI stack trace on all CPUs"). It was not needed because the flushing of the temporary per-CPU buffers was serialized. Suggested-by: Sergey Senozhatsky Signed-off-by: Petr Mladek --- kernel/printk/internal.h | 6 ++++-- kernel/printk/printk.c | 19 ++++++++++++++----- kernel/printk/printk_safe.c | 25 +++++++++++++++++++++++-- lib/nmi_backtrace.c | 3 +++ 4 files changed, 44 insertions(+), 9 deletions(-) diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h index 1db044f808b7..2a7d04049af4 100644 --- a/kernel/printk/internal.h +++ b/kernel/printk/internal.h @@ -18,12 +18,14 @@ #ifdef CONFIG_PRINTK -#define PRINTK_SAFE_CONTEXT_MASK 0x7fffffff -#define PRINTK_NMI_CONTEXT_MASK 0x80000000 +#define PRINTK_SAFE_CONTEXT_MASK 0x3fffffff +#define PRINTK_NMI_DEFERRED_CONTEXT_MASK 0x40000000 +#define PRINTK_NMI_CONTEXT_MASK 0x80000000 extern raw_spinlock_t logbuf_lock; __printf(1, 0) int vprintk_default(const char *fmt, va_list args); +__printf(1, 0) int vprintk_deferred(const char *fmt, va_list args); __printf(1, 0) int vprintk_func(const char *fmt, va_list args); void __printk_safe_enter(void); void __printk_safe_exit(void); diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 2984fb0f0257..16b519927d35 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -2691,16 +2691,13 @@ void wake_up_klogd(void) preempt_enable(); } -int printk_deferred(const char *fmt, ...) +int vprintk_deferred(const char *fmt, va_list args) { - va_list args; int r; - preempt_disable(); - va_start(args, fmt); r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args); - va_end(args); + preempt_disable(); __this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT); irq_work_queue(this_cpu_ptr(&wake_up_klogd_work)); preempt_enable(); @@ -2708,6 +2705,18 @@ int printk_deferred(const char *fmt, ...) return r; } +int printk_deferred(const char *fmt, ...) +{ + va_list args; + int r; + + va_start(args, fmt); + r = vprintk_deferred(fmt, args); + va_end(args); + + return r; +} + /* * printk rate limiting, lifted from the networking subsystem. * diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c index 033e50a7d706..c3d165bcde42 100644 --- a/kernel/printk/printk_safe.c +++ b/kernel/printk/printk_safe.c @@ -308,12 +308,23 @@ static int vprintk_nmi(const char *fmt, va_list args) void printk_nmi_enter(void) { - this_cpu_or(printk_context, PRINTK_NMI_CONTEXT_MASK); + /* + * The size of the extra per-CPU buffer is limited. Use it + * only when really needed. + */ + if (this_cpu_read(printk_context) & PRINTK_SAFE_CONTEXT_MASK || + raw_spin_is_locked(&logbuf_lock)) { + this_cpu_or(printk_context, PRINTK_NMI_CONTEXT_MASK); + } else { + this_cpu_or(printk_context, PRINTK_NMI_DEFERRED_CONTEXT_MASK); + } } void printk_nmi_exit(void) { - this_cpu_and(printk_context, ~PRINTK_NMI_CONTEXT_MASK); + this_cpu_and(printk_context, + ~(PRINTK_NMI_CONTEXT_MASK || + PRINTK_NMI_DEFERRED_CONTEXT_MASK)); } #else @@ -351,12 +362,22 @@ void __printk_safe_exit(void) __printf(1, 0) int vprintk_func(const char *fmt, va_list args) { + /* Use extra buffer in NMI when logbuf_lock is taken or in safe mode. */ if (this_cpu_read(printk_context) & PRINTK_NMI_CONTEXT_MASK) return vprintk_nmi(fmt, args); + /* Use extra buffer to prevent a recursion deadlock in safe mode. */ if (this_cpu_read(printk_context) & PRINTK_SAFE_CONTEXT_MASK) return vprintk_safe(fmt, args); + /* + * Use the main logbuf when logbuf_lock is available in NMI. + * But avoid calling console drivers that might have their own locks. + */ + if (this_cpu_read(printk_context) & PRINTK_NMI_DEFERRED_CONTEXT_MASK) + return vprintk_deferred(fmt, args); + + /* No obstacles. */ return vprintk_default(fmt, args); } diff --git a/lib/nmi_backtrace.c b/lib/nmi_backtrace.c index 4e8a30d1c22f..0bc0a3535a8a 100644 --- a/lib/nmi_backtrace.c +++ b/lib/nmi_backtrace.c @@ -86,9 +86,11 @@ void nmi_trigger_cpumask_backtrace(const cpumask_t *mask, bool nmi_cpu_backtrace(struct pt_regs *regs) { + static arch_spinlock_t lock = __ARCH_SPIN_LOCK_UNLOCKED; int cpu = smp_processor_id(); if (cpumask_test_cpu(cpu, to_cpumask(backtrace_mask))) { + arch_spin_lock(&lock); if (regs && cpu_in_idle(instruction_pointer(regs))) { pr_warn("NMI backtrace for cpu %d skipped: idling at pc %#lx\n", cpu, instruction_pointer(regs)); @@ -99,6 +101,7 @@ bool nmi_cpu_backtrace(struct pt_regs *regs) else dump_stack(); } + arch_spin_unlock(&lock); cpumask_clear_cpu(cpu, to_cpumask(backtrace_mask)); return true; }