Re: [PATCH 1/7] printk: Hand over printing to console if printing too long

[Jan Kara <jack@suse.cz>]

On Thu 31-12-15 13:58:59, Sergey Senozhatsky wrote:
> On (12/31/15 12:13), Sergey Senozhatsky wrote:
> [..]
> > cond_resched() does its job there, of course. well, a user process still can
> > do a lot of call_console_drivers() calls. may be we can check who is calling
> > console_unlock() and if we have "!printk_sync && !oops_in_progress" (or just printk_sync
> > test) AND a user process then return from console_unlock() doing irq_work_queue()
> > and set PRINTK_PENDING_OUTPUT pending bit, the way vprintk_emit() does it.
> 
> attached two patches, I ended up having on top of yours. just in case.
> 
>     printk: factor out can_printk_async()
>     
>     console_unlock() can be called directly or indirectly by a user
>     space process, so it can end up doing call_console_drivers() loop,
>     which will hold it from returning back to user-space from a syscall
>     for unpredictable amount of time.
>     
>     Factor out can_printk_async() function, which queues an irq work and
>     sets a PRINTK_PENDING_OUTPUT pending bit (if we can do async printk).
>     vprintk_emit() already does it, add can_printk_async() call to
>     console_unlock() for !PF_KTHREAD processes.

I'd be cautious about changing this userspace visible behavior. Someone may
be relying on it... I agree that sometimes we can block userspace process
in kernel for a long time (e.g. in my testing I often see syslog process
doing the printing) but so far I didn't see / was notified about some real
problem with this. So unless I see some real user issues with user
processes doing printing for too long I would not touch this.
 
> and
> 
>     printk: introduce console_sync_mode
>     
>     console_sync_mode() should be called early in panic() to switch
>     printk from async mode to sync. Otherwise, STOP IPIs can arrive
>     to other CPUs too late and those CPUs will see oops_in_progress
>     being 0 again.

So as I wrote, I like this in principle but there are much more places
calling console_verbose() and all of them want console_sync_mode() as well.
So I prefer hiding the sync printing in console_verbose() and possibly
renaming it to something better but I'm not sure renaming is worth it.

								Honza

> 
> 	-ss

> From c3fc955809adab8f497cdc7581e67e1fa29d6517 Mon Sep 17 00:00:00 2001
> From: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> Date: Wed, 30 Dec 2015 20:39:12 +0900
> Subject: [PATCH 1/2] printk: introduce console_sync_mode
> 
> console_sync_mode() should be called early in panic() to switch
> printk from async mode to sync. Otherwise, STOP IPIs can arrive
> to other CPUs too late and those CPUs will see oops_in_progress
> being 0 again.
> ---
>  include/linux/console.h | 1 +
>  kernel/panic.c          | 1 +
>  kernel/printk/printk.c  | 5 +++++
>  3 files changed, 7 insertions(+)
> 
> diff --git a/include/linux/console.h b/include/linux/console.h
> index bd19434..f068985 100644
> --- a/include/linux/console.h
> +++ b/include/linux/console.h
> @@ -150,6 +150,7 @@ extern int console_trylock(void);
>  extern void console_unlock(void);
>  extern void console_conditional_schedule(void);
>  extern void console_unblank(void);
> +extern void console_sync_mode(void);
>  extern struct tty_driver *console_device(int *);
>  extern void console_stop(struct console *);
>  extern void console_start(struct console *);
> diff --git a/kernel/panic.c b/kernel/panic.c
> index b333380..04c8ff4 100644
> --- a/kernel/panic.c
> +++ b/kernel/panic.c
> @@ -117,6 +117,7 @@ void panic(const char *fmt, ...)
>  	if (old_cpu != PANIC_CPU_INVALID && old_cpu != this_cpu)
>  		panic_smp_self_stop();
>  
> +	console_sync_mode();
>  	console_verbose();
>  	bust_spinlocks(1);
>  	va_start(args, fmt);
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index de9d31b..47a70a2 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2501,6 +2501,11 @@ void console_unblank(void)
>  	console_unlock();
>  }
>  
> +void console_sync_mode(void)
> +{
> +	printk_sync = true;
> +}
> +
>  /*
>   * Return the console tty driver structure and its associated index
>   */
> -- 
> 2.6.4
> 

> From 92f2c0f2a5ed015caa2757dcfec4407d708f8628 Mon Sep 17 00:00:00 2001
> From: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> Date: Thu, 31 Dec 2015 13:39:58 +0900
> Subject: [PATCH 2/2] printk: factor out can_printk_async()
> 
> console_unlock() can be called directly or indirectly by a user
> space process, so it can end up doing call_console_drivers() loop,
> which will hold it from returning back to user-space from a syscall
> for unpredictable amount of time.
> 
> Factor out can_printk_async() function, which queues an irq work and
> sets a PRINTK_PENDING_OUTPUT pending bit (if we can do async printk).
> vprintk_emit() already does it, add can_printk_async() call to
> console_unlock() for !PF_KTHREAD processes.
> ---
>  kernel/printk/printk.c | 42 ++++++++++++++++++++++++++++--------------
>  1 file changed, 28 insertions(+), 14 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 47a70a2..7d3a8e1 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -355,6 +355,26 @@ int printk_deferred(const char *fmt, ...)
>  	return r;
>  }
>  
> +static bool can_printk_async(bool sync)
> +{
> +	/*
> +	 * By default we print message to console asynchronously so that kernel
> +	 * doesn't get stalled due to slow serial console. That can lead to
> +	 * softlockups, lost interrupts, or userspace timing out under heavy
> +	 * printing load.
> +	 *
> +	 * However we resort to synchronous printing of messages during early
> +	 * boot, when oops is in progress, or when synchronous printing was
> +	 * explicitely requested by kernel parameter.
> +	 */
> +	if (keventd_up() && !oops_in_progress && !sync) {
> +		__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
> +		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> +		return true;
> +	}
> +	return false;
> +}
> +
>  /* Return log buffer address */
>  char *log_buf_addr_get(void)
>  {
> @@ -1889,20 +1909,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	logbuf_cpu = UINT_MAX;
>  	raw_spin_unlock(&logbuf_lock);
>  	lockdep_on();
> -	/*
> -	 * By default we print message to console asynchronously so that kernel
> -	 * doesn't get stalled due to slow serial console. That can lead to
> -	 * softlockups, lost interrupts, or userspace timing out under heavy
> -	 * printing load.
> -	 *
> -	 * However we resort to synchronous printing of messages during early
> -	 * boot, when oops is in progress, or when synchronous printing was
> -	 * explicitely requested by kernel parameter.
> -	 */
> -	if (keventd_up() && !oops_in_progress && !sync_print) {
> -		__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
> -		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> -	} else
> +	if (!can_printk_async(sync_print))
>  		sync_print = true;
>  	local_irq_restore(flags);
>  
> @@ -2328,6 +2335,13 @@ void console_unlock(void)
>  		return;
>  	}
>  
> +	if (!(current->flags & PF_KTHREAD) &&
> +			can_printk_async(printk_sync)) {
> +		console_locked = 0;
> +		up_console_sem();
> +		return;
> +	}
> +
>  	/*
>  	 * Console drivers are called under logbuf_lock, so
>  	 * @console_may_schedule should be cleared before; however, we may
> -- 
> 2.6.4
> 

-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR