Message-ID: <008801d684f9$43e1c140$cba543c0$@samsung.com>
Date:   Mon, 7 Sep 2020 18:28:37 +0900
From:   ±èâ±â <changki.kim@...sung.com>
To:     "'John Ogness'" <john.ogness@...utronix.de>,
        "'Petr Mladek'" <pmladek@...e.com>
Cc:     <sergey.senozhatsky@...il.com>, <rostedt@...dmis.org>,
        <changbin.du@...el.com>, <masahiroy@...nel.org>,
        <rd.dunlap@...il.com>, <gregkh@...uxfoundation.org>,
        <krzk@...nel.org>, <linux-kernel@...r.kernel.org>
Subject: RE: printk: Add process name information to printk() output.

> On 2020-09-04, Petr Mladek <pmladek@...e.com> wrote:
> >>> I am currently playing with support for all three timestamps based
> >>> on
> >>> https://lore.kernel.org/lkml/20200814101933.574326079@linutronix.de/
> >>>
> >>> And I got the following idea:
> >>>
> >>> 1. Storing side:
> >>>
> >>>    Create one more ring/array for storing the optional metadata.
> >>>    It might eventually replace dict ring, see below.
> >>>
> >>>    struct struct printk_ext_info {
> >>> 	u64 ts_boot;			/* timestamp from boot clock */
> >>> 	u64 ts_real;			/* timestamp from real clock */
> >>> 	char process[TASK_COMM_LEN];	/* process name */
> >>>    };
> >>>
> >>>    It must be in a separate array so that struct prb_desc stay stable
> >>>    and crashdump tools do not need to be updated so often.
> >>>
> >>>    But the number of these structures must be the same as descriptors.
> >>>    So it might be:
> >>>
> >>>    struct prb_desc_ring {
> >>> 	unsigned int		count_bits;
> >>> 	struct prb_desc		*descs;
> >>> 	struct printk_ext_info  *ext_info
> >>> 	atomic_long_t		head_id;
> >>> 	atomic_long_t		tail_id;
> >>>    };
> >>>
> >>>    One huge advantage is that these extra information would not block
> >>>    pushing lockless printk buffer upstream.
> >>>
> >>>    It might be even possible to get rid of dict ring and just
> >>>    add two more elements into struct printk_ext_info:
> >>>
> >>> 	  char subsystem[16];	/* for SUBSYSTEM= dict value */
> >>> 	  char device[48];	/* for DEVICE= dict value */
> >
> > From my POV, if we support 3 timestamps then they must be stored
> > reliably. And dict ring is out of the game.
> 
> Agreed. I am just trying to think of how to better manage the strings,
> which currently are rare and optional. That is where the dict_ring becomes
> interesting.
> 
> Perhaps we should use both the fixed structs with the variable dict_ring.
> printk_ext_info could look like this:
> 
> struct struct printk_ext_info {
>     u64 ts_boot;
>     u64 ts_real;
>     char *process;
>     char *subsystem;
>     char *device;
> };
> 
> And @process, @subsystem, @device could all point to null-terminated
> trings within the dict_ring. So printk.c code looks something like this:
> 
> size_t process_sz = strlen(process) + 1; size_t subsystem_sz =
> strlen(subsystem) + 1; size_t device_sz = strlen(device) + 1; struct
> prb_reserved_entry e; struct printk_record r; char *p;
> 
> prb_rec_init_wr(&r, text_len, process_sz + subsystem_sz + device_sz);
> prb_reserve(&e, prb, &r);
> 
> memcpy(r.text_buf, text, text_len);
> r.info->text_len = text_len;
> 
> /* guaranteed ext data */
> r.ext_info->ts_boot = time_boot();
> r.ext_info->ts_real = time_real();
> 
> /* optional ext data */
> if (r.dict_buf) {
>     p = r.dict_buf;
> 
>     memcpy(p, process, process_sz);
>     r.ext_info->process = p;
>     p += process_sz;
> 
>     memcpy(p, subsystem, subsystem_sz);
>     r.ext_info->subsystem = p;
>     p += subsystem_sz;
> 
>     memcpy(p, device, device_sz);
>     r.ext_info->device = p;
> 
>     r.info->dict_len = process_sz + subsystem_sz + device_sz; }
> 
> > And I am not comfortable even with the current dictionary handling.
> > I already wrote this somewhere. The following command is supposed to
> > show all kernel messages printed by "pci" subsystem:
> >
> > 	$> journalctl _KERNEL_SUBSYSTEM=pci
> >
> > It will be incomplete when the dictionary metadata were not saved.
> 
> In that case, perhaps @subsystem should be a static array in
> printk_ext_info instead.
> 
> > Regarding the waste of space. The dict ring currently has the same
> > size as the text ring. It is likely a waste of space as well. Any
> > tuning is complicated because it depends on the use case.
> 
> The whole point of the dict_ring is that it allows for variable length
> _optional_ data to be stored. If we decide there is no optional data, then
> dict_ring is not needed.
> 
> > The advantage of the fixed @ext_info[] array is that everything is
> > clear, simple, and predictable (taken space and name length limits).
> > We could easily tell users what they will get for a given cost.
> 
> Agreed. For non-optional data (such as your timestamps), I am in full
> agreement that a fixed array is the way to go. And it would only require a
> couple lines of code added to the ringbuffer.
> 
> My concern is if we need to guarantee space for all possible dictionary
> data of all records. I think the dict_ring can be very helpful here.
> 
> John Ogness

To be honest, This patch is made based on kernel 5.4.
So I haven't fully figured out the printk ring buffer yet.
When I see the code, dict_buf didn't print out into prefix. Right?
I want to print out the information into prefix.

When I developed the kernel in Android,
we could modify prefix of kernel log format. Because we should be able to
obtain a lot of information with just a kernel log.
But now, we can't modify the prefix due to GKI. So We need a printk where
we can freely modify the prefix.
The prefix doesn't need to be saved to log_buf. It only needs to be printed
out.

It would be great if printk.format is possible.

printk.format=ts,cpu,comm,pid,in_atomic

Changki Kim.

Powered by blists - more mailing lists