Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1296794 > unrolled thread

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

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [PATCH 1/7] printk: Hand over printing to console if printing  too long Jan Kara <jack@suse.cz> - 2015-12-22 14:50 +0100
    Re: [PATCH 1/7] printk: Hand over printing to console if printing  too long Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2015-12-22 16:00 +0100
    Re: [PATCH 1/7] printk: Hand over printing to console if printing  too long Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2015-12-23 03:00 +0100
      Re: [PATCH 1/7] printk: Hand over printing to console if printing  too long Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2015-12-23 04:40 +0100
        Re: [PATCH 1/7] printk: Hand over printing to console if printing  too long Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2015-12-23 05:00 +0100
          Re: [PATCH 1/7] printk: Hand over printing to console if printing  too long Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2015-12-23 05:20 +0100
    Re: [PATCH 1/7] printk: Hand over printing to console if printing  too long Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2015-12-31 03:50 +0100
      Re: [PATCH 1/7] printk: Hand over printing to console if printing  too long Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2015-12-31 04:20 +0100
        Re: [PATCH 1/7] printk: Hand over printing to console if printing  too long Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2015-12-31 06:00 +0100

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

[Multipart message — attachments visible in raw view] — view raw

On Thu 10-12-15 23:52:51, Sergey Senozhatsky wrote:
> Hello,
> 
> *** in this email and in every later emails ***
>     Sorry, if I messed up with Cc list or message-ids. It's suprisingly
> hard to jump in into a loop that has never been in your inbox. It took
> some `googling' effort.
> 
> I haven't tested the patch set yet, I just 'ported' it to linux-next.
> I reverted 073696a8bc7779b ("printk: do cond_resched() between lines while
> outputting to consoles") as a first step, but it comes in later again. I can
> send out the updated series (off list is OK).
> 
> > Currently, console_unlock() prints messages from kernel printk buffer to
> > console while the buffer is non-empty. When serial console is attached,
> > printing is slow and thus other CPUs in the system have plenty of time
> > to append new messages to the buffer while one CPU is printing. Thus the
> > CPU can spend unbounded amount of time doing printing in console_unlock().
> > This is especially serious problem if the printk() calling
> > console_unlock() was called with interrupts disabled.
> >
> > In practice users have observed a CPU can spend tens of seconds printing
> > in console_unlock() (usually during boot when hundreds of SCSI devices
> > are discovered) resulting in RCU stalls (CPU doing printing doesn't
> > reach quiescent state for a long time), softlockup reports (IPIs for the
> > printing CPU don't get served and thus other CPUs are spinning waiting
> > for the printing CPU to process IPIs), and eventually a machine death
> > (as messages from stalls and lockups append to printk buffer faster than
> > we are able to print). So these machines are unable to boot with serial
> > console attached. Also during artificial stress testing SATA disk
> > disappears from the system because its interrupts aren't served for too
> > long.
> >
> > This patch implements a mechanism where after printing specified number
> > of characters (tunable as a kernel parameter printk.offload_chars), CPU
> > doing printing asks for help by waking up one of dedicated kthreads.  As
> > soon as the printing CPU notices kthread got scheduled and is spinning
> > on print_lock dedicated for that purpose, it drops console_sem,
> > print_lock, and exits console_unlock(). Kthread then takes over printing
> > instead. This way no CPU should spend printing too long even if there
> > is heavy printk traffic.
> >
> > Signed-off-by: Jan Kara <jack@suse.cz>
> 
> I think we better use raw_spin_lock as a print_lock; and, apart from that,
> seems that we don't re-init in zap_lock(). So I ended up with the following
> patch on top of yours (to be folded):
> 
> - use raw_spin_lock
> - do not forget to re-init `print_lock' in zap_locks()

Thanks for looking into my patches and sorry for replying with a delay. As
I wrote in my previous email [1] even the referenced patches are not quite
enough. Over last few days I have worked on redoing the stuff as we
discussed with Linus and Andrew at Kernel Summit and I have new patches
which are working fine for me. I still want to test them on some machines
having real issues with udev during boot but so far stress-testing with
serial console slowed down to ~1000 chars/sec on other machines and VMs
looks promising.

I'm attaching them in case you want to have a look. They are on top of
Tejun's patch adding cond_resched() (which is essential). I'll officially
submit the patches once the testing is finished (but I'm not sure when I
get to the problematic HW...).

								Honza

[1] http://www.spinics.net/lists/stable/msg111535.html
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

[toc] | [next] | [standalone]

#1296823

On (12/22/15 14:47), Jan Kara wrote:
[..]
> Thanks for looking into my patches and sorry for replying with a delay. As
> I wrote in my previous email [1] even the referenced patches are not quite
> enough. Over last few days I have worked on redoing the stuff as we
> discussed with Linus and Andrew at Kernel Summit and I have new patches
> which are working fine for me. I still want to test them on some machines
> having real issues with udev during boot but so far stress-testing with
> serial console slowed down to ~1000 chars/sec on other machines and VMs
> looks promising.
> 
> I'm attaching them in case you want to have a look. They are on top of
> Tejun's patch adding cond_resched() (which is essential). I'll officially
> submit the patches once the testing is finished (but I'm not sure when I
> get to the problematic HW...).
> 

Hello,

Thanks a lot! Will take a look.

	-ss

> From 2e9675abbfc0df4a24a8c760c58e8150b9a31259 Mon Sep 17 00:00:00 2001
> From: Jan Kara <jack@suse.cz>
> Date: Mon, 21 Dec 2015 13:10:31 +0100
> Subject: [PATCH 1/2] printk: Make printk() completely async
> 
> Currently, printk() sometimes waits for message to be printed to console
> and sometimes it does not (when console_sem is held by some other
> process). In case printk() grabs console_sem and starts printing to
> console, it prints messages from kernel printk buffer until the buffer
> is empty. When serial console is attached, printing is slow and thus
> other CPUs in the system have plenty of time to append new messages to
> the buffer while one CPU is printing. Thus the CPU can spend unbounded
> amount of time doing printing in console_unlock().  This is especially
> serious problem if the printk() calling console_unlock() was called with
> interrupts disabled.
> 
> In practice users have observed a CPU can spend tens of seconds printing
> in console_unlock() (usually during boot when hundreds of SCSI devices
> are discovered) resulting in RCU stalls (CPU doing printing doesn't
> reach quiescent state for a long time), softlockup reports (IPIs for the
> printing CPU don't get served and thus other CPUs are spinning waiting
> for the printing CPU to process IPIs), and eventually a machine death
> (as messages from stalls and lockups append to printk buffer faster than
> we are able to print). So these machines are unable to boot with serial
> console attached. Another observed issue is that due to slow printk,
> hardware discovery is slow and udev times out before kernel manages to
> discover all the attached HW. Also during artificial stress testing SATA
> disk disappears from the system because its interrupts aren't served for
> too long.
> 
> This patch makes printk() completely asynchronous (similar to what
> printk_deferred() did until now). It appends message to the kernel
> printk buffer and queues work to do the printing to console. This has
> the advantage that printing always happens from a schedulable contex and
> thus we don't lockup any particular CPU or even interrupts. Also it has
> the advantage that printk() is fast and thus kernel booting is not
> slowed down by slow serial console. Disadvantage of this method is that
> in case of crash there is higher chance that important messages won't
> appear in console output (we may need working scheduling to print
> message to console). We somewhat mitigate this risk by switching printk
> to the original method of immediate printing to console if oops is in
> progress.  Also for debugging purposes we provide printk.synchronous
> kernel parameter which resorts to the original printk behavior.
> 
> Signed-off-by: Jan Kara <jack@suse.cz>
> ---
>  Documentation/kernel-parameters.txt |  10 +++
>  kernel/printk/printk.c              | 144 +++++++++++++++++++++---------------
>  2 files changed, 95 insertions(+), 59 deletions(-)
> 
> diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt
> index 742f69d18fc8..4cf1bddeffc7 100644
> --- a/Documentation/kernel-parameters.txt
> +++ b/Documentation/kernel-parameters.txt
> @@ -3000,6 +3000,16 @@ bytes respectively. Such letter suffixes can also be entirely omitted.
>  	printk.time=	Show timing data prefixed to each printk message line
>  			Format: <bool>  (1/Y/y=enable, 0/N/n=disable)
>  
> +	printk.synchronous=
> +			By default kernel messages are printed to console
> +			asynchronously (except during early boot or when oops
> +			is happening). That avoids kernel stalling behind slow
> +			serial console and thus avoids softlockups, interrupt
> +			timeouts, or userspace timing out during heavy printing.
> +			However for debugging problems, printing messages to
> +			console immediately may be desirable. This option
> +			enables such behavior.
> +
>  	processor.max_cstate=	[HW,ACPI]
>  			Limit processor to maximum C-state
>  			max_cstate=9 overrides any DMI blacklist limit.
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 299c2f0e7350..d455d1bd0d2c 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -283,6 +283,73 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
>  static char *log_buf = __log_buf;
>  static u32 log_buf_len = __LOG_BUF_LEN;
>  
> +/*
> + * When true, printing to console will happen synchronously unless someone else
> + * is already printing messages.
> + */
> +static bool __read_mostly printk_sync;
> +module_param_named(synchronous, printk_sync, bool, S_IRUGO | S_IWUSR);
> +MODULE_PARM_DESC(synchronous, "make printing to console synchronous");
> +
> +#define PRINTK_PENDING_WAKEUP	0x01
> +#define PRINTK_PENDING_OUTPUT	0x02
> +
> +static DEFINE_PER_CPU(int, printk_pending);
> +
> +static void printing_work_func(struct work_struct *work)
> +{
> +	console_lock();
> +	console_unlock();
> +}
> +
> +static DECLARE_WORK(printing_work, printing_work_func);
> +
> +static void wake_up_klogd_work_func(struct irq_work *irq_work)
> +{
> +	int pending = __this_cpu_xchg(printk_pending, 0);
> +
> +	/*
> +	 * We just schedule regular work to do the printing from irq work. We
> +	 * don't want to do printing here directly as that happens with
> +	 * interrupts disabled and thus is bad for interrupt latency. We also
> +	 * don't want to queue regular work from vprintk_emit() as that gets
> +	 * called in various difficult contexts where schedule_work() could
> +	 * deadlock.
> +	 */
> +	if (pending & PRINTK_PENDING_OUTPUT)
> +		schedule_work(&printing_work);
> +
> +	if (pending & PRINTK_PENDING_WAKEUP)
> +		wake_up_interruptible(&log_wait);
> +}
> +
> +static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
> +	.func = wake_up_klogd_work_func,
> +	.flags = IRQ_WORK_LAZY,
> +};
> +
> +void wake_up_klogd(void)
> +{
> +	preempt_disable();
> +	if (waitqueue_active(&log_wait)) {
> +		this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
> +		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> +	}
> +	preempt_enable();
> +}
> +
> +int printk_deferred(const char *fmt, ...)
> +{
> +	va_list args;
> +	int r;
> +
> +	va_start(args, fmt);
> +	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
> +	va_end(args);
> +
> +	return r;
> +}
> +
>  /* Return log buffer address */
>  char *log_buf_addr_get(void)
>  {
> @@ -1668,15 +1735,14 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	unsigned long flags;
>  	int this_cpu;
>  	int printed_len = 0;
> -	bool in_sched = false;
> +	bool sync_print = printk_sync;
>  	/* cpu currently holding logbuf_lock in this function */
>  	static unsigned int logbuf_cpu = UINT_MAX;
>  
>  	if (level == LOGLEVEL_SCHED) {
>  		level = LOGLEVEL_DEFAULT;
> -		in_sched = true;
> +		sync_print = false;
>  	}
> -
>  	boot_delay_msec(level);
>  	printk_delay();
>  
> @@ -1803,10 +1869,24 @@ 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
> +		sync_print = true;
>  	local_irq_restore(flags);
>  
> -	/* If called from the scheduler, we can not call up(). */
> -	if (!in_sched) {
> +	if (sync_print) {
>  		lockdep_off();
>  		/*
>  		 * Disable preemption to avoid being preempted while holding
> @@ -2688,60 +2768,6 @@ late_initcall(printk_late_init);
>  
>  #if defined CONFIG_PRINTK
>  /*
> - * Delayed printk version, for scheduler-internal messages:
> - */
> -#define PRINTK_PENDING_WAKEUP	0x01
> -#define PRINTK_PENDING_OUTPUT	0x02
> -
> -static DEFINE_PER_CPU(int, printk_pending);
> -
> -static void wake_up_klogd_work_func(struct irq_work *irq_work)
> -{
> -	int pending = __this_cpu_xchg(printk_pending, 0);
> -
> -	if (pending & PRINTK_PENDING_OUTPUT) {
> -		/* If trylock fails, someone else is doing the printing */
> -		if (console_trylock())
> -			console_unlock();
> -	}
> -
> -	if (pending & PRINTK_PENDING_WAKEUP)
> -		wake_up_interruptible(&log_wait);
> -}
> -
> -static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
> -	.func = wake_up_klogd_work_func,
> -	.flags = IRQ_WORK_LAZY,
> -};
> -
> -void wake_up_klogd(void)
> -{
> -	preempt_disable();
> -	if (waitqueue_active(&log_wait)) {
> -		this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
> -		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> -	}
> -	preempt_enable();
> -}
> -
> -int printk_deferred(const char *fmt, ...)
> -{
> -	va_list args;
> -	int r;
> -
> -	preempt_disable();
> -	va_start(args, fmt);
> -	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
> -	va_end(args);
> -
> -	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
> -	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> -	preempt_enable();
> -
> -	return r;
> -}
> -
> -/*
>   * printk rate limiting, lifted from the networking subsystem.
>   *
>   * This enforces a rate limit: not more than 10 kernel messages
> -- 
> 2.6.2
> 

> From be116ae18f15f0d2d05ddf0b53eaac184943d312 Mon Sep 17 00:00:00 2001
> From: Jan Kara <jack@suse.cz>
> Date: Mon, 21 Dec 2015 14:26:13 +0100
> Subject: [PATCH 2/2] printk: Skip messages on oops
> 
> When there are too many messages in the kernel printk buffer it can take
> very long to print them to console (especially when using slow serial
> console). This is undesirable during oops so when we encounter oops and
> there are more than 100 messages to print, print just the newest 100
> messages and then the oops message.
> 
> Signed-off-by: Jan Kara <jack@suse.cz>
> ---
>  kernel/printk/printk.c | 34 +++++++++++++++++++++++++++++++++-
>  1 file changed, 33 insertions(+), 1 deletion(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index d455d1bd0d2c..fc67ab70e9c7 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -262,6 +262,9 @@ static u64 console_seq;
>  static u32 console_idx;
>  static enum log_flags console_prev;
>  
> +/* current record sequence when oops happened */
> +static u64 oops_start_seq;
> +
>  /* the next printk record to read after the last 'clear' command */
>  static u64 clear_seq;
>  static u32 clear_idx;
> @@ -1783,6 +1786,8 @@ asmlinkage int vprintk_emit(int facility, int level,
>  					 NULL, 0, recursion_msg,
>  					 strlen(recursion_msg));
>  	}
> +	if (oops_in_progress && !sync_print && !oops_start_seq)
> +		oops_start_seq = log_next_seq;
>  
>  	/*
>  	 * The printf needs to come first; we need the syslog
> @@ -2292,6 +2297,12 @@ out:
>  	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
>  }
>  
> +/*
> + * When oops happens and there are more messages to be printed in the printk
> + * buffer that this, skip some mesages and print only this many newest messages.
> + */
> +#define PRINT_MSGS_BEFORE_OOPS 100
> +
>  /**
>   * console_unlock - unlock the console system
>   *
> @@ -2348,7 +2359,28 @@ again:
>  			seen_seq = log_next_seq;
>  		}
>  
> -		if (console_seq < log_first_seq) {
> +		/*
> +		 * If oops happened and there are more than
> +		 * PRINT_MSGS_BEFORE_OOPS messages pending before oops message,
> +		 * skip them to make oops appear faster.
> +		 */
> +		if (oops_start_seq &&
> +		    console_seq + PRINT_MSGS_BEFORE_OOPS < oops_start_seq) {
> +			len = sprintf(text,
> +				"** %u printk messages dropped due to oops ** ",
> +				(unsigned)(oops_start_seq - console_seq -
> +					   PRINT_MSGS_BEFORE_OOPS));
> +			if (console_seq < log_first_seq) {
> +				console_seq = log_first_seq;
> +				console_idx = log_first_idx;
> +			}
> +			while (console_seq <
> +			       oops_start_seq - PRINT_MSGS_BEFORE_OOPS) {
> +				console_idx = log_next(console_idx);
> +				console_seq++;
> +			}
> +			console_prev = 0;
> +		} else if (console_seq < log_first_seq) {
>  			len = sprintf(text, "** %u printk messages dropped ** ",
>  				      (unsigned)(log_first_seq - console_seq));
>  
> -- 
> 2.6.2
> 

--
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/

[toc] | [prev] | [next] | [standalone]

#1297208

Hi,

slowly looking through the patches.

On (12/22/15 14:47), Jan Kara wrote:
[..]
> @@ -1803,10 +1869,24 @@ 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
> +		sync_print = true;
>  	local_irq_restore(flags);

can we replace this oops_in_progress check with something more reliable?

CPU0                                CPU1 - CPUN
panic()
 local_irq_disable()                executing foo() with irqs disabled,
 console_verbose()                  or processing an extremely long irq handler.
 bust_spinlocks()
    oops_in_progress++

 smp_send_stop()

 bust_spinlocks()
    oops_in_progress--              ok, IPI arrives
                                    dump_stack()/printk()/etc from IPI_CPU_STOP
			            "while (1) cpu_relax()" with irq/fiq disabled/halt/etc.

smp_send_stop() wrapped in `oops_in_progress++/oops_in_progress--' is arch specific,
and some platforms don't do any IPI-delivered (e.g. via num_online_cpus()) checks at
all. Some do. For example, arm/arm64:

void smp_send_stop(void)
...
        /* Wait up to one second for other CPUs to stop */
        timeout = USEC_PER_SEC;
        while (num_online_cpus() > 1 && timeout--)
                udelay(1);

        if (num_online_cpus() > 1)
                pr_warn("SMP: failed to stop secondary CPUs\n");
...


so there are non-zero chances that IPI will arrive to CPU after 'oops_in_progress--',
and thus dump_stack()/etc. happening on that/those cpu/cpus will be lost.


bust_spinlocks(0) does
...
	if (--oops_in_progress == 0)
		wake_up_klogd();
...

but local cpu has irqs disabled and `panic_timeout' can be zero.

How about setting 'sync_print' to 'true' in...
  bust_spinlocks() /* only set to true */
or
  console_verbose() /* um... may be... */
or
  having a separate one-liner for that

void console_panic_mode(void)
{
	sync_print = true;
}

and call it early in panic(), before we send out IPI_STOP.

	-ss
--
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/

[toc] | [prev] | [next] | [standalone]

#1297231

On (12/23/15 10:54), Sergey Senozhatsky wrote:
> On (12/22/15 14:47), Jan Kara wrote:
> [..]
> > @@ -1803,10 +1869,24 @@ 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
> > +		sync_print = true;

oops, didn't have enough coffee... missed that `else sync_print = true' :(

	-ss

> >  	local_irq_restore(flags);
> 
> can we replace this oops_in_progress check with something more reliable?
> 
> CPU0                                CPU1 - CPUN
> panic()
>  local_irq_disable()                executing foo() with irqs disabled,
>  console_verbose()                  or processing an extremely long irq handler.
>  bust_spinlocks()
>     oops_in_progress++
> 
>  smp_send_stop()
> 
>  bust_spinlocks()
>     oops_in_progress--              ok, IPI arrives
>                                     dump_stack()/printk()/etc from IPI_CPU_STOP
> 			            "while (1) cpu_relax()" with irq/fiq disabled/halt/etc.
> 
> smp_send_stop() wrapped in `oops_in_progress++/oops_in_progress--' is arch specific,
> and some platforms don't do any IPI-delivered (e.g. via num_online_cpus()) checks at
> all. Some do. For example, arm/arm64:
> 
> void smp_send_stop(void)
> ...
>         /* Wait up to one second for other CPUs to stop */
>         timeout = USEC_PER_SEC;
>         while (num_online_cpus() > 1 && timeout--)
>                 udelay(1);
> 
>         if (num_online_cpus() > 1)
>                 pr_warn("SMP: failed to stop secondary CPUs\n");
> ...
> 
> 
> so there are non-zero chances that IPI will arrive to CPU after 'oops_in_progress--',
> and thus dump_stack()/etc. happening on that/those cpu/cpus will be lost.
> 
> 
> bust_spinlocks(0) does
> ...
> 	if (--oops_in_progress == 0)
> 		wake_up_klogd();
> ...
> 
> but local cpu has irqs disabled and `panic_timeout' can be zero.
> 
> How about setting 'sync_print' to 'true' in...
>   bust_spinlocks() /* only set to true */
> or
>   console_verbose() /* um... may be... */
> or
>   having a separate one-liner for that
> 
> void console_panic_mode(void)
> {
> 	sync_print = true;
> }
> 
> and call it early in panic(), before we send out IPI_STOP.
> 
> 	-ss
> 
--
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/

[toc] | [prev] | [next] | [standalone]

#1297236

On (12/23/15 12:37), Sergey Senozhatsky wrote:
> Date: Wed, 23 Dec 2015 12:37:24 +0900
> From: Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
> To: Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
> Cc: Jan Kara <jack@suse.cz>, Sergey Senozhatsky
>  <sergey.senozhatsky@gmail.com>, Andrew Morton <akpm@linux-foundation.org>,
>  Petr Mladek <pmladek@suse.cz>, KY Sri nivasan <kys@microsoft.com>, Steven
>  Rostedt <rostedt@goodmis.org>, linux-kernel@vger.kernel.org
> Subject: Re: [PATCH 1/7] printk: Hand over printing to console if printing
>  too long
> User-Agent: Mutt/1.5.24 (2015-08-30)
> 
> On (12/23/15 10:54), Sergey Senozhatsky wrote:
> > On (12/22/15 14:47), Jan Kara wrote:
> > [..]
> > > @@ -1803,10 +1869,24 @@ 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
> > > +		sync_print = true;
> 
> oops, didn't have enough coffee... missed that `else sync_print = true' :(
> 

ah, never mind my previous email... it's a local variable, so the very next printk()
happening right after bust_spinlocks(0) will irq_work_queue(). I'd prefer CPUs to
print stacks rather than burn cpu cycles in `while (1) cpu_relax()' loop.

so

else {
	printk_sync = true;
	sync_print = true; /* and remove this local variable entirely may be*/
}

> > can we replace this oops_in_progress check with something more reliable?
> > 
> > CPU0                                CPU1 - CPUN
> > panic()
> >  local_irq_disable()                executing foo() with irqs disabled,
> >  console_verbose()                  or processing an extremely long irq handler.
> >  bust_spinlocks()
> >     oops_in_progress++

					or we huge enough number of CPUs, `deep' stack
					traces, slow serial and CPU doing dump_stack()
					under raw_spin_lock(&stop_lock), so it can take
					longer than 1 second to print the stacks and
					thus panic CPU will set oops_in_progress back
					to 0.

> >  smp_send_stop()
> > 
> >  bust_spinlocks()
> >     oops_in_progress--              ok, IPI arrives
> >                                     dump_stack()/printk()/etc from IPI_CPU_STOP
> > 			            "while (1) cpu_relax()" with irq/fiq disabled/halt/etc.
> > 
> > smp_send_stop() wrapped in `oops_in_progress++/oops_in_progress--' is arch specific,
> > and some platforms don't do any IPI-delivered (e.g. via num_online_cpus()) checks at
> > all. Some do. For example, arm/arm64:
> > 
> > void smp_send_stop(void)
> > ...
> >         /* Wait up to one second for other CPUs to stop */
> >         timeout = USEC_PER_SEC;
> >         while (num_online_cpus() > 1 && timeout--)
> >                 udelay(1);
> > 
> >         if (num_online_cpus() > 1)
> >                 pr_warn("SMP: failed to stop secondary CPUs\n");
> > ...
> > 
> > 
> > so there are non-zero chances that IPI will arrive to CPU after 'oops_in_progress--',
> > and thus dump_stack()/etc. happening on that/those cpu/cpus will be lost.
> > 
> > 
> > bust_spinlocks(0) does
> > ...
> > 	if (--oops_in_progress == 0)
> > 		wake_up_klogd();
> > ...
> > 
> > but local cpu has irqs disabled and `panic_timeout' can be zero.
> > 
> > How about setting 'sync_print' to 'true' in...
> >   bust_spinlocks() /* only set to true */
> > or
> >   console_verbose() /* um... may be... */
> > or
> >   having a separate one-liner for that
> > 
> > void console_panic_mode(void)
> > {
> > 	sync_print = true;

	printk_sync = true;

> > }
> > 
> > and call it early in panic(), before we send out IPI_STOP.


	-ss
--
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/

[toc] | [prev] | [next] | [standalone]

#1297238

On (12/23/15 12:57), Sergey Senozhatsky wrote:
[..]
> > > can we replace this oops_in_progress check with something more reliable?
> > > 
> > > CPU0                                CPU1 - CPUN
> > > panic()
> > >  local_irq_disable()                executing foo() with irqs disabled,
> > >  console_verbose()                  or processing an extremely long irq handler.
> > >  bust_spinlocks()
> > >     oops_in_progress++
> 
> 					or we huge enough number of CPUs, `deep' stack
> 					traces, slow serial and CPU doing dump_stack()
> 					under raw_spin_lock(&stop_lock), so it can take
> 					longer than 1 second to print the stacks and
> 					thus panic CPU will set oops_in_progress back
> 					to 0.
> 
> > >  smp_send_stop()
> > > 
> > >  bust_spinlocks()
> > >     oops_in_progress--              ok, IPI arrives
> > >                                     dump_stack()/printk()/etc from IPI_CPU_STOP
> > > 			            "while (1) cpu_relax()" with irq/fiq disabled/halt/etc.
> > > 
> > > smp_send_stop() wrapped in `oops_in_progress++/oops_in_progress--' is arch specific,
> > > and some platforms don't do any IPI-delivered (e.g. via num_online_cpus()) checks at
> > > all. Some do. For example, arm/arm64:
> > > 
> > > void smp_send_stop(void)
> > > ...
> > >         /* Wait up to one second for other CPUs to stop */
> > >         timeout = USEC_PER_SEC;
> > >         while (num_online_cpus() > 1 && timeout--)
> > >                 udelay(1);
> > > 
> > >         if (num_online_cpus() > 1)
> > >                 pr_warn("SMP: failed to stop secondary CPUs\n");
> > > ...
> > > 
> > > 
> > > so there are non-zero chances that IPI will arrive to CPU after 'oops_in_progress--',
> > > and thus dump_stack()/etc. happening on that/those cpu/cpus will be lost.
> > > 
> > > 
> > > bust_spinlocks(0) does
> > > ...
> > > 	if (--oops_in_progress == 0)
> > > 		wake_up_klogd();
> > > ...
> > > 
> > > but local cpu has irqs disabled and `panic_timeout' can be zero.

well, if panic_timeout != 0, then wake_up_klogd() calls irq_work_queue() which
schedule_work. what if we have the following

CPU0						CPU1 - CPUN

foo
preempt_disable
	bar
		panic				irq/fiq disable
			schedule_work		while (1) cpu_relax

	-ss
--
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/

[toc] | [prev] | [next] | [standalone]

#1299556

Hello,

On (12/22/15 14:47), Jan Kara wrote:
[..]
> +int printk_deferred(const char *fmt, ...)
> +{
> +	va_list args;
> +	int r;
> +
> +	va_start(args, fmt);
> +	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
> +	va_end(args);
> +
> +	return r;
> +}
[..]
> @@ -1803,10 +1869,24 @@ 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
> +		sync_print = true;
>  	local_irq_restore(flags);

So this fixes printk() and printk_deferred(), but it doesn't address any of the
direct and indirect console_lock/console_unlock callers.

for example, direct:
~/_mmots$ git grep console_unlock | egrep -v "printk\.c|panic\.c|console\.h" | wc -l
199

indirect (e.g. via console_devices()):
~/_mmots$ git grep console_device | egrep -v "printk\.c|panic\.c|console\.h|_console_device" | wc -l
4

One of those indirect callers is tty_lookup_driver(), called from tty_open(). Which
is quite big to ignore, I suspect.

A user space process opening a tty can end up doing that while (1) call_console_drivers()
loop, I suspect. At least nothing prevents it, at a glance.

A side note, isn't it too often to cond_resched() from console_unlock()? What if
we have 10000000 very short printk() messages (e.g. no more than 32 chars).

	-ss
--
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/

[toc] | [prev] | [next] | [standalone]

#1299564

On (12/31/15 11:44), Sergey Senozhatsky wrote:
> On (12/22/15 14:47), Jan Kara wrote:
> [..]
> > +int printk_deferred(const char *fmt, ...)
> > +{
> > +	va_list args;
> > +	int r;
> > +
> > +	va_start(args, fmt);
> > +	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
> > +	va_end(args);
> > +
> > +	return r;
> > +}
> [..]
> > @@ -1803,10 +1869,24 @@ 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
> > +		sync_print = true;
> >  	local_irq_restore(flags);
> 
> So this fixes printk() and printk_deferred(), but it doesn't address any of the
> direct and indirect console_lock/console_unlock callers.
> 
> for example, direct:
> ~/_mmots$ git grep console_unlock | egrep -v "printk\.c|panic\.c|console\.h" | wc -l
> 199
> 
> indirect (e.g. via console_devices()):
> ~/_mmots$ git grep console_device | egrep -v "printk\.c|panic\.c|console\.h|_console_device" | wc -l
> 4
> 
> One of those indirect callers is tty_lookup_driver(), called from tty_open(). Which
> is quite big to ignore, I suspect.
>
> 
> A user space process opening a tty can end up doing that while (1) call_console_drivers()
> loop, I suspect. At least nothing prevents it, at a glance.

d'oh... sorry. that cold that I have is affecting me... no more emails for today.


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.

	-ss

> A side note, isn't it too often to cond_resched() from console_unlock()? What if
> we have 10000000 very short printk() messages (e.g. no more than 32 chars).
--
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/

[toc] | [prev] | [next] | [standalone]

#1299575

[Multipart message — attachments visible in raw view] — view raw

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.

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.

	-ss

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web