Re: [PATCH] printk: Add caller information to printk() output.

[Petr Mladek <pmladek@suse.com>]

On Wed 2018-12-05 19:42:22, Tetsuo Handa wrote:
> From: Tetsuo Handa <penguin-kernel@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