From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S934277AbcHaMxM (ORCPT ); Wed, 31 Aug 2016 08:53:12 -0400 Received: from mail-pa0-f65.google.com ([209.85.220.65]:33452 "EHLO mail-pa0-f65.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S934039AbcHaMxI (ORCPT ); Wed, 31 Aug 2016 08:53:08 -0400 Date: Wed, 31 Aug 2016 21:52:24 +0900 From: Sergey Senozhatsky To: Petr Mladek Cc: Sergey Senozhatsky , Jan Kara , Sergey Senozhatsky , Viresh Kumar , Andrew Morton , Jan Kara , Tejun Heo , Tetsuo Handa , "linux-kernel@vger.kernel.org" , Byungchul Park , vlevenetz@mm-sol.com, Greg Kroah-Hartman Subject: Re: [PATCH v10 1/2] printk: Make printk() completely async Message-ID: <20160831125224.GA572@swordfish> References: <20160819063236.GA584@swordfish> <20160819095455.GR13300@pathway.suse.cz> <20160819190007.GA8275@quack2.suse.cz> <20160820052430.GA695@swordfish> <20160822041520.GA511@swordfish> <20160825210959.GA2273@dhcp128.suse.cz> <20160826015641.GA520@swordfish> <20160830092912.GP4866@pathway.suse.cz> <20160831023134.GA390@swordfish> <20160831093810.GE4554@pathway.suse.cz> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20160831093810.GE4554@pathway.suse.cz> User-Agent: Mutt/1.7.0 (2016-08-17) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On (08/31/16 11:38), Petr Mladek wrote: [..] > Ah, I do not want to discourage you from finding a solution for these > problems. oh, Petr, I didn't mean it. that was a poor/incorrect wording on my side. > I just wanted to point out problems with this particular > path of thinking (more per-CPU buffers, shuffling data between > them and the main buffer and console). sure, and I do appreciate your input. that's a good summary. > Sigh, there are many problems with printk(). I think the we recently > discussed the following problems: > > 1. Hung task or blocked irq handler when preemption/irqs > are disabled and there are too many messages pushed to > the console. 1.1. deferred printing, for instance due to sched throttling 1.2. unlucky printk() from IRQ handler, that succeeded in grabbing the console semaphore via console_trylock(). once there is a moderate printk() flood and some of console_unlock() calls can be executed with preemption disabled, chances of sched throttling do increase. I've seen this many times in the past. > 2. Potential deadlocks when calling wake_up_process() by > async printk and console_unlock(). * there are many reasons to those recursive printk() calls -- some can be addressed, some cannot. for instance, it doesn't matter how many per-CPU buffers we use for alternative printk() once the logbuf_lock is corrupted. another `deadlock' example would be: SyS_ioctl do_vfs_ioctl tty_ioctl n_tty_ioctl tty_mode_ioctl set_termios tty_set_termios uart_set_termios uart_change_speed FOO_serial_set_termios spin_lock_irqsave(&port->lock) // lock the output port .... !! WARN() or pr_err() or printk() vprintk_emit() /* console_trylock() */ console_unlock() call_console_drivers() FOO_write() spin_lock_irqsave(&port->lock) // already locked > 3. Clean up the console handling to split manipulation with > consoles setting and pushing the messages. By other words, > allow to push the console messages only when wanted. yes, that's a hard one. not only console_unlock() may force a completely random task to do the printing loop, but console_lock() will force that task to stay in TASK_UNINTERRUPTIBLE as long as the semaphore is busy. if that task ends up being a user space process that must reply to systemd watchdog (user space) signals then things can get confusing. apart from the fact that that user space process can spend XX seconds printing kernel's messages from console_unlock(). even a single unfortunate console_trylock() and console_unlock() can lockup the system, etc. basically because they void the printk_kthread. so there are several outcomes from reworking console locking, but the results may vary. depending on particular setups. > 4. Messed output with continuous lines. 5. not 100% guaranteed printing on panic not entirely related to printk(), but to console output mechanism in general. we have console_flush_on_panic() which ignores console semaphore state, to increase our chances of seeing the backtrace. however, there are more that just one lock involved: logbuf_lock, serial driver locks. so we may start zap_locks() in console_flush_on_panic() to re-init the logbuf_lock, but underlying serial driver's locks are still in unclear state. most of the drivers (if not all of them) take the port->lock under disabled IRQs, so if panic-CPU is not the one that holds the port->lock then the port->lock owner CPU will probably unlock the spin_lock before processing its STOP_IPI. if it's the port->lock CPU that panic() the system (nmi_panic() or BUG()) then things can be bad. > Our primary target was to solve the 1st problem with the async printk. > It has stalled because we hit the other areas. Let's look at them > from this point of view. > > Ad 2. The potential deadlock with wake_up_process(). It pooped up > with using async printk during the suspend. right... and no per-CPU buffer could have helped here. > But it is not new! up() called by console_unlock() has the > same problem. I thought that it was different because > console_trylock() would prevent recursion but I was wrong. correct. Byungchul hit that problem awhile ago https://lkml.org/lkml/2016/2/17/102 > => If we use normal scheduler for the printk() thread, we should > be on the safe side. The deadlock should get fixed but it > will be enough to fix it later separately. agree. > Ad 4. The problems with messaged continues lines got a bit more > visible with the async printk. yep. I also agree that it might be not so serious to fix it now (if ever). > Did I miss anything? > > I wonder how to separate the problems and make them more manageable. so I was thinking for a moment about doing the recursion detection rework before the async_printk. just because better recursion detection is a nice thing to have in the first place and it probably may help us catching some of the surprises that async_printk might have. but it probably will be more problematic than I thought. then async_printk. I have a refreshed series on my hands, addressing Viresh's reports. it certainly makes things better, but it doesn't eliminate all of the lockups/etc sources. a console_unlock() doing wake_up_process(printk_kthread) would make it better. -ss