On Wed 2018-12-05 19:42:22, Tetsuo Handa wrote:
> From: Tetsuo Handa <penguin-ker...@i-love.sakura.ne.jp>
> Date: Wed, 5 Dec 2018 16:53:08 +0900
> Subject: [PATCH v3] printk: Add caller information to printk() output.
>
> Sometimes we want to print a series of printk() messages to consoles
> without being disturbed by concurrent printk() from interrupts and/or
> other threads. But we can't enforce printk() callers to use their local
> buffers because we need to ask them to make too much changes. Also, even
> buffering up to one line inside printk() might cause failing to emit
> an important clue under critical situation.
>
> Therefore, instead of trying to help buffering, let's try to help
> reconstructing messages by saving caller information as of calling
> log_store() and adding it as "[T$thread_id]" or "[C$processor_id]"
> upon printing to consoles.
>
> Some examples for console output:
>
> [ 1.222773][ T1] x86: Booting SMP configuration:
> [ 2.779635][ T1] pci 0000:00:01.0: PCI bridge to [bus 01]
> [ 5.069193][ T268] Fusion MPT base driver 3.04.20
> [ 9.316504][ C2] random: fast init done
> [ 13.413336][ T3355] Initialized host personality
I like this formating. IMHO, the limit 100000 for the right formating
is good enough. Also I think that the process ID might give a clue.
IMHO, ID reusing is rather rare.
> Some examples for /dev/kmsg output:
>
> 6,496,1222773,-,from=T1;x86: Booting SMP configuration:
> 6,968,2779635,-,from=T1;pci 0000:00:01.0: PCI bridge to [bus 01]
> SUBSYSTEM=pci
> DEVICE=+pci:0000:00:01.0
> 6,1353,5069193,-,from=T268;Fusion MPT base driver 3.04.20
> 5,1526,9316504,-,from=C2;random: fast init done
> 6,1575,13413336,-,from=T3355;Initialized host personality
>
> # Not yet signed-off in order to silence build-bot error reports.
> ---
> kernel/printk/printk.c | 82
> +++++++++++++++++++++++++++++++++-----------------
> lib/Kconfig.debug | 17 +++++++++++
> 2 files changed, 71 insertions(+), 28 deletions(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 4f18472..f9812f6 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -422,8 +425,14 @@ __packed __aligned(4)
> static u64 clear_seq;
> static u32 clear_idx;
>
> +#ifdef CONFIG_PRINTK_FROM
> +#define PREFIX_FROM_MAX 16
> +#define PREFIX_MAX (32 + PREFIX_FROM_MAX)
> +#define LOG_LINE_MAX (1024 - 32)
This looks suspicious. We either need to limit LOG_LINE_MAX
by the real PREFIX_MAX (48). Or we must make sure that
the code is able to handle an eventual overflow.
For example, msg_print_text() would just ignore the line
when it overflows, see:
if (print_prefix(msg, syslog, time, NULL) +
text_len + 1 >= size - len)
break;
BTW: The limit 48 looks right. If I count correctly, the longest
prefix might be:
<2048>[4294967296,xxxxxx][T4294967296]
38 = 6+19+13
IMHO, LOG_LINE_MAX defined as (1024 - 48) is perfectly fine. Most
lines are under 80 characters. I doubt that any goes close
to the existing limit.
> +#else
> #define PREFIX_MAX 32
> #define LOG_LINE_MAX (1024 - PREFIX_MAX)
> +#endif
>
> #define LOG_LEVEL(v) ((v) & 0x07)
> #define LOG_FACILITY(v) ((v) >> 3 & 0xff)
[...]
> @@ -1227,39 +1254,38 @@ static inline void boot_delay_msec(int level)
> static bool printk_time = IS_ENABLED(CONFIG_PRINTK_TIME);
> module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
>
> -static size_t print_time(u64 ts, char *buf)
> -{
> - unsigned long rem_nsec = do_div(ts, 1000000000);
> -
> - if (!buf)
> - return snprintf(NULL, 0, "[%5lu.000000] ", (unsigned long)ts);
> -
> - return sprintf(buf, "[%5lu.%06lu] ",
> - (unsigned long)ts, rem_nsec / 1000);
> -}
> -
> static size_t print_prefix(const struct printk_log *msg, bool syslog,
> bool time, char *buf)
> {
> size_t len = 0;
> - unsigned int prefix = (msg->facility << 3) | msg->level;
> + char tmp[PREFIX_MAX];
>
> + if (!buf)
> + buf = tmp;
Please, add empty lines between the if-sections. It will better
split the logical parts.
I would personally create three helper functions (print_level(),
print_time(), and print_from(). But adding the empty lines
is fine as well.
> if (syslog) {
> - if (buf) {
> - len += sprintf(buf, "<%u>", prefix);
> - } else {
> - len += 3;
> - if (prefix > 999)
> - len += 3;
> - else if (prefix > 99)
> - len += 2;
> - else if (prefix > 9)
> - len++;
> - }
> + unsigned int prefix = (msg->facility << 3) | msg->level;
> +
> + len += sprintf(buf, "<%u>", prefix);
> + }
> + if (time) {
> + u64 ts = msg->ts_nsec;
> + unsigned long rem_nsec = do_div(ts, 1000000000);
> +
> + len += sprintf(buf + len, "[%5lu.%06lu]", (unsigned long)ts,
> + rem_nsec / 1000);
> }
> +#ifdef CONFIG_PRINTK_FROM
> + {
> + u32 id = msg->from_id;
> + char from[12];
>
> - if (time)
> - len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
> + snprintf(from, sizeof(from), "%c%u",
> + id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);
> + len += sprintf(buf + len, "[%6s]", from);
> + }
> +#endif
> + if (IS_ENABLED(CONFIG_PRINTK_FROM) || time)
> + buf[len++] = ' ';
Please, add also the trailing '\0'. I know that it is not strictly
necessary but...
I consider it a good practice. It prevents a potential misuse.
For example, people might want use the output in their own
debug messages.
Otherwise, the patch looks good to me. Please, send the next
revision as a proper patch.
Best Regards,
Petr
