Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
Date:   Tue, 17 Mar 2020 11:18:18 +0900
From:   Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
To:     Eugeniu Rosca <roscaeugeniu@gmail.com>
Cc:     linux-kernel@vger.kernel.org, Petr Mladek <pmladek@suse.com>,
        Sergey Senozhatsky <sergey.senozhatsky@gmail.com>,
        Steven Rostedt <rostedt@goodmis.org>,
        Ingo Molnar <mingo@kernel.org>,
        Thomas Gleixner <tglx@linutronix.de>,
        Peter Zijlstra <peterz@infradead.org>,
        Jisheng Zhang <Jisheng.Zhang@synaptics.com>,
        Valdis Kletnieks <valdis.kletnieks@vt.edu>,
        Sebastian Andrzej Siewior <bigeasy@linutronix.de>,
        Andrew Gabbasov <andrew_gabbasov@mentor.com>,
        Dirk Behme <dirk.behme@de.bosch.com>,
        Eugeniu Rosca <erosca@de.adit-jv.com>
Subject: Re: [RFC PATCH 3/3] watchdog: Turn console verbosity on when
 reporting softlockup
Message-ID: <20200317021818.GD219881@google.com>
References: <20200315170903.17393-1-erosca@de.adit-jv.com>
 <20200315170903.17393-4-erosca@de.adit-jv.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20200315170903.17393-4-erosca@de.adit-jv.com>
User-Agent: Mutt/1.12.2 (2019-09-21)
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

On (20/03/15 18:09), Eugeniu Rosca wrote:

[..]

> @@ -428,6 +428,8 @@ static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer)
>  			}
>  		}
>  
> +		console_verbose_start();
> +
>  		pr_emerg("BUG: soft lockup - CPU#%d stuck for %us! [%s:%d]\n",
>  			smp_processor_id(), duration,
>  			current->comm, task_pid_nr(current));
> @@ -453,6 +455,8 @@ static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer)
>  		if (softlockup_panic)
>  			panic("softlockup: hung tasks");
>  		__this_cpu_write(soft_watchdog_warn, true);
> +
> +		console_verbose_end();
>  	} else
>  		__this_cpu_write(soft_watchdog_warn, false);


I'm afraid, as of now, this approach is not going to work the way it's
supposed to work in 100% of cases. Because the only thing that printk()
call sort of guarantees is that the message will be stored somewhere.
Either in the main kernel log buffer, on in one of auxiliary per-CPU
log buffers. It does not guarantee, generally speaking, that the message
will be printed on the console immediately.

Consider the following example:

	CPU0				CPU1
	console_lock();
	schedule();

					watchdog()
					 console_verbose_start();
					  printk()
					   log_store()
					    if (!console_trylock())
					      return;
					 console_verbose_end();

	...
	console_unlock()
	 print logbuf messages to the consoles
	 we missed the console_verbose_start/end
	 on CPU1


IIRC, we had a similar approach in the past. See commit 375899cddcbb26
("printk: make sure to print log on console"). And we reverted it, see
a6ae928c25835 ("Revert "printk: make sure to print log on console.").

	-ss