Re: [PATCH] printk: deduplicate print_prefix() calls

[Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>]

On (11/24/18 23:28), Tetsuo Handa wrote:
> Since /sys/module/printk/parameters/time can change from N to Y between
> "msg_print_text() called print_prefix() with buf == NULL" and
> "msg_print_text() again calls print_prefix() with buf != NULL", it is not
> safe for print_time() to unconditionally return 0 if printk_time == false.
> 
> But print_prefix() is called by only msg_print_text(), and print_prefix()
> is called once more for calculating output length of prefix, and there is
> no need to recalculate it when one log entry contains multiple lines.

Good catch.

> Since max output length for syslog marker and timestamp are known to be
> small enough, let's close this race by deduplicating print_prefix() calls.
> 
> Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>

Or we can change printk_time under logbuf lock? So msg_print_text will
not race with it.

Or we can "copy" the value of printk_time and use it in print_prefix(),
and we will pick up an updated value next time we do msg_print_text()?

Example:

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1b2a029360b7..4c57f5d5b0b6 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1211,13 +1211,14 @@ static inline void boot_delay_msec(int level)
 #endif
 
 static bool printk_time = IS_ENABLED(CONFIG_PRINTK_TIME);
+static bool printk_time_saved;
 module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
 
 static size_t print_time(u64 ts, char *buf)
 {
 	unsigned long rem_nsec;
 
-	if (!printk_time)
+	if (!printk_time_saved)
 		return 0;
 
 	rem_nsec = do_div(ts, 1000000000);
@@ -1258,6 +1259,8 @@ static size_t msg_print_text(const struct printk_log *msg, bool syslog, char *bu
 	size_t text_size = msg->text_len;
 	size_t len = 0;
 
+	printk_time_saved = printk_time;
+
 	do {
 		const char *next = memchr(text, '\n', text_size);
 		size_t text_len;