Re: printk: what is going on with additional newlines?

From: Sergey Senozhatsky
Date: Tue Sep 05 2017 - 10:22:26 EST


On (09/05/17 21:35), Tetsuo Handa wrote:
[..]
> > Well, what do you think about the extra printed information?
> > For example:
> >
> > <timestamp> <PID> <context> message
> >
> > It looks straightforward to me. These information
> > might be helpful on its own. So, it might be a
> > win-win solution.
>
> Yes, if buffering multiple lines will not be implemented, I do want
> printk context identifier field for each line. I think <PID> <context>
> part will be something like TASK#pid (if outside interrupt) or
> CPU#cpunum/#irqlevel (if inside interrupt).

well, depending on what's your aim.

it's not always printk() that causes troubles, but console_unlock().
which is busy because of printk()-s. and those are not necessarily
running on the same CPU. so if you want to have a full picture (don't
know what for) then you need to log both vprintk_emit() and
console_unlock() sides. vprintk_emit() side requires changes to
`struct printk_log', console_unlock() does not - you can just sprintf()
the required data to `text' buffer.

for example, I do the following on my PC boxes to keep track the
behaviour of printk kthread offloading.

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index a4e3f84ef365..ac1fd606d6c5 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2493,15 +2493,16 @@ void console_unlock(void)
seen_seq = log_next_seq;
}

+ len = sprintf(text, "{%s/%d/%d}", current->comm,
+ smp_processor_id(), do_cond_resched);
+
if (console_seq < log_first_seq) {
- len = sprintf(text, "** %u printk messages dropped ** ",
+ len += sprintf(text + len, "** %u printk messages dropped ** ",
(unsigned)(log_first_seq - console_seq));

/* messages are gone, move to first one */
console_seq = log_first_seq;
console_idx = log_first_idx;
- } else {
- len = 0;
}
skip:
if (did_offload || console_seq == log_next_seq)