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:   Fri, 19 Jan 2018 14:45:38 +0900
From:   Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
To:     Andi Kleen <ak@linux.intel.com>
Cc:     Dave Young <dyoung@redhat.com>, pmladek@suse.com,
        sergey.senozhatsky@gmail.com, rostedt@goodmis.org,
        linux-kernel@vger.kernel.org, akpm@linux-foundation.org,
        kexec@lists.infradead.org
Subject: Re: [PATCH] print kdump kernel loaded status in stack dump
Message-ID: <20180119054538.GA484@jagdpanzerIV>
References: <20180117045057.GA4994@dhcp-128-65.nay.redhat.com>
 <878tcvt592.fsf@linux.intel.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <878tcvt592.fsf@linux.intel.com>
User-Agent: Mutt/1.9.2 (2017-12-15)
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

On (01/18/18 10:02), Andi Kleen wrote:
> Dave Young <dyoung@redhat.com> writes:
> >  		printk("%sHardware name: %s\n",
> >  		       log_lvl, dump_stack_arch_desc_str);
> > +	if (kexec_crash_loaded())
> > +		printk("%skdump kernel loaded\n", log_lvl);
> 
> Oops/warnings are getting longer and longer, often scrolling away
> from the screen, and if the kernel crashes backscroll does not work
> anymore, so precious information is lost.

true. I even ended up having a console_reflush_on_panic() function. it
simply re-prints with a delay [so I can at least read the oops] logbuf
entries every once in a while, staring with the first oops_in_progress
record.

something like below [it's completely hacked up, but at least gives
an idea]

---

 include/linux/console.h |  1 +
 kernel/panic.c          |  7 +++++++
 kernel/printk/printk.c  | 39 ++++++++++++++++++++++++++++++++++++++-
 3 files changed, 46 insertions(+), 1 deletion(-)

diff --git a/include/linux/console.h b/include/linux/console.h
index b8920a031a3e..502e3f539448 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -168,6 +168,7 @@ extern void console_unlock(void);
 extern void console_conditional_schedule(void);
 extern void console_unblank(void);
 extern void console_flush_on_panic(void);
+extern void console_reflush_on_panic(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 2cfef408fec9..39cd59bbfaab 100644
--- a/kernel/panic.c
+++ b/kernel/panic.c
@@ -137,6 +137,7 @@ void panic(const char *fmt, ...)
 	va_list args;
 	long i, i_next = 0;
 	int state = 0;
+	int reflush_tick = 0;
 	int old_cpu, this_cpu;
 	bool _crash_kexec_post_notifiers = crash_kexec_post_notifiers;
 
@@ -298,6 +299,12 @@ void panic(const char *fmt, ...)
 			i_next = i + 3600 / PANIC_BLINK_SPD;
 		}
 		mdelay(PANIC_TIMER_STEP);
+
+		reflush_tick++;
+		if (reflush_tick == 32) { /* don't reflush too often */
+			console_reflush_on_panic();
+			reflush_tick = 0;
+		}
 	}
 }
 
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 9cb943c90d98..ef3f28d4c741 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -426,6 +426,10 @@ static u32 log_next_idx;
 static u64 console_seq;
 static u32 console_idx;
 
+/* index and sequence number of the record which started the oops print out */
+static u64 log_oops_seq;
+static u32 log_oops_idx;
+
 /* the next printk record to read after the last 'clear' command */
 static u64 clear_seq;
 static u32 clear_idx;
@@ -1736,6 +1740,15 @@ static inline void printk_delay(void)
 	}
 }
 
+/*
+ * Why do we have printk_delay() in vprintk_emit()
+ * and not in console_unlock()?
+ */
+static inline void console_unlock_delay(void)
+{
+	printk_delay();
+}
+
 /*
  * Continuation lines are buffered, and not committed to the record buffer
  * until the line is complete, or a race forces it. The line fragments
@@ -1849,6 +1862,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 	/* This stops the holder of console_sem just where we want him */
 	logbuf_lock_irqsave(flags);
+
 	/*
 	 * The printf needs to come first; we need the syslog
 	 * prefix which might be passed-in as a parameter.
@@ -1890,7 +1904,11 @@ asmlinkage int vprintk_emit(int facility, int level,
 		lflags |= LOG_PREFIX|LOG_NEWLINE;
 
 	printed_len = log_output(facility, level, lflags, dict, dictlen, text, text_len);
-
+	/* Oops... */
+	if (oops_in_progress && !log_oops_seq) {
+		log_oops_seq = log_next_seq;
+		log_oops_idx = log_next_idx;
+	}
 	logbuf_unlock_irqrestore(flags);
 
 	/* If called from the scheduler, we can not call up(). */
@@ -2396,6 +2414,7 @@ void console_unlock(void)
 
 		stop_critical_timings();	/* don't trace print latency */
 		call_console_drivers(ext_text, ext_len, text, len);
+		console_unlock_delay();
 		start_critical_timings();
 
 		if (console_lock_spinning_disable_and_check()) {
@@ -2495,6 +2514,24 @@ void console_flush_on_panic(void)
 	console_unlock();
 }
 
+/**
+ * console_reflush_on_panic - re-flush console content starting from the
+ * first oops_in_progress record
+ */
+void console_reflush_on_panic(void)
+{
+	unsigned long flags;
+
+	logbuf_lock_irqsave(flags);
+	console_seq = log_oops_seq;
+	console_idx = log_oops_idx;
+	logbuf_unlock_irqrestore(flags);
+
+	if (!printk_delay_msec)
+		printk_delay_msec = 273; /* I can't read any faster */
+	console_flush_on_panic();
+}
+
 /*
  * Return the console tty driver structure and its associated index
  */
-- 
2.16.0