[PATCH v1] printk: Improve memory usage logging during boot

[PATCH v1] printk: Improve memory usage logging during boot

[Isaac J. Manjarres]

When the initial printk ring buffer size is updated, setup_log_buf()
allocates a new ring buffer, as well as a set of meta-data structures
for the new ring buffer. The function also emits the new size of the
ring buffer, but not the size of the meta-data structures.

This makes it difficult to assess how changing the log buffer size
impacts memory usage during boot.

For instance, increasing the ring buffer size from 512 KB to 1 MB
through the command line yields an increase of 2304 KB in reserved
memory at boot, while the only obvious change is the 512 KB
difference in the ring buffer sizes:

log_buf_len=512K:

printk: log_buf_len: 524288 bytes
Memory: ... (... 733252K reserved ...)

log_buf_len=1M:

printk: log_buf_len: 1048576 bytes
Memory: ... (... 735556K reserved ...)

This is because of how the size of the meta-data structures scale with
the size of the ring buffer.

Even when there aren't changes to the printk ring buffer size (i.e. the
initial size ==  1 << CONFIG_LOG_BUF_SHIFT), it is impossible to tell
how much memory is consumed by the printk ring buffer during boot.

Therefore, unconditionally log the sizes of the printk ring buffer
and its meta-data structures, so that it's easier to understand
how changing the log buffer size (either through the command line or
by changing CONFIG_LOG_BUF_SHIFT) affects boot time memory usage.

With the new logs, it is much easier to see exactly why the memory
increased by 2304 KB:

log_buf_len=512K:

printk: log_buf_len: 524288 bytes
printk: prb_descs size: 393216 bytes
printk: printk_infos size: 1441792 bytes
Memory: ... (... 733252K reserved ...)

log_buf_len=1M:

printk: log_buf_len: 1048576 bytes
printk: prb_descs size: 786432 bytes
printk: printk_infos size: 2883584 bytes
Memory: ... (... 735556K reserved ...)

Signed-off-by: Isaac J. Manjarres <isaacmanjarres@google.com>
---
 kernel/printk/printk.c | 21 +++++++++++++++++----
 1 file changed, 17 insertions(+), 4 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index beb808f4c367..0c169c28fa37 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1156,6 +1156,17 @@ static unsigned int __init add_to_rb(struct printk_ringbuffer *rb,
 
 static char setup_text_buf[PRINTKRB_RECORD_MAX] __initdata;
 
+static void print_log_buf_usage_stats(void)
+{
+	unsigned int descs_count = log_buf_len >> PRB_AVGBITS;
+	size_t descs_size = descs_count * sizeof(struct prb_desc);
+	size_t infos_size = descs_count * sizeof(struct printk_info);
+
+	pr_info("log_buf_len: %u bytes\n", log_buf_len);
+	pr_info("prb_descs size: %zu bytes\n", descs_size);
+	pr_info("printk_infos size: %zu bytes\n", infos_size);
+}
+
 void __init setup_log_buf(int early)
 {
 	struct printk_info *new_infos;
@@ -1186,19 +1197,19 @@ void __init setup_log_buf(int early)
 		log_buf_add_cpu();
 
 	if (!new_log_buf_len)
-		return;
+		goto out;
 
 	new_descs_count = new_log_buf_len >> PRB_AVGBITS;
 	if (new_descs_count == 0) {
 		pr_err("new_log_buf_len: %lu too small\n", new_log_buf_len);
-		return;
+		goto out;
 	}
 
 	new_log_buf = memblock_alloc(new_log_buf_len, LOG_ALIGN);
 	if (unlikely(!new_log_buf)) {
 		pr_err("log_buf_len: %lu text bytes not available\n",
 		       new_log_buf_len);
-		return;
+		goto out;
 	}
 
 	new_descs_size = new_descs_count * sizeof(struct prb_desc);
@@ -1261,7 +1272,7 @@ void __init setup_log_buf(int early)
 		       prb_next_seq(&printk_rb_static) - seq);
 	}
 
-	pr_info("log_buf_len: %u bytes\n", log_buf_len);
+	print_log_buf_usage_stats();
 	pr_info("early log buf free: %u(%u%%)\n",
 		free, (free * 100) / __LOG_BUF_LEN);
 	return;
@@ -1270,6 +1281,8 @@ void __init setup_log_buf(int early)
 	memblock_free(new_descs, new_descs_size);
 err_free_log_buf:
 	memblock_free(new_log_buf, new_log_buf_len);
+out:
+	print_log_buf_usage_stats();
 }
 
 static bool __read_mostly ignore_loglevel;
-- 
2.46.1.824.gd892dcdcdd-goog

Re: [PATCH v1] printk: Improve memory usage logging during boot

[Petr Mladek]

On Wed 2024-09-25 18:12:01, Isaac J. Manjarres wrote:
> When the initial printk ring buffer size is updated, setup_log_buf()
> allocates a new ring buffer, as well as a set of meta-data structures
> for the new ring buffer. The function also emits the new size of the
> ring buffer, but not the size of the meta-data structures.
> 
> This makes it difficult to assess how changing the log buffer size
> impacts memory usage during boot.
> 
> For instance, increasing the ring buffer size from 512 KB to 1 MB
> through the command line yields an increase of 2304 KB in reserved
> memory at boot, while the only obvious change is the 512 KB
> difference in the ring buffer sizes:

Good point.

> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1156,6 +1156,17 @@ static unsigned int __init add_to_rb(struct printk_ringbuffer *rb,
>  
>  static char setup_text_buf[PRINTKRB_RECORD_MAX] __initdata;
>  
> +static void print_log_buf_usage_stats(void)
> +{
> +	unsigned int descs_count = log_buf_len >> PRB_AVGBITS;
> +	size_t descs_size = descs_count * sizeof(struct prb_desc);
> +	size_t infos_size = descs_count * sizeof(struct printk_info);
> +
> +	pr_info("log_buf_len: %u bytes\n", log_buf_len);
> +	pr_info("prb_descs size: %zu bytes\n", descs_size);
> +	pr_info("printk_infos size: %zu bytes\n", infos_size);
> +}

I would make the information more user friendly. Also a single line
might be enough. Something like:

static void print_log_buf_usage_stats(void)
{
	unsigned int descs_count = log_buf_len >> PRB_AVGBITS;
	size_t meta_data_size;

	meta_data_size = descs_count *
		(sizeof(struct prb_desc) + sizeof(struct printk_info));

	pr_info("log buffer data + meta data: %u + %zu = %zu bytes\n",
		log_buf_len, meta_data_size, log_buf_len + meta_data_size);
}

> +
>  void __init setup_log_buf(int early)
>  {
>  	struct printk_info *new_infos;
> @@ -1186,19 +1197,19 @@ void __init setup_log_buf(int early)
>  		log_buf_add_cpu();
>  
>  	if (!new_log_buf_len)
> -		return;
> +		goto out;

The same information is printed twice when the default buffer is used.
We should do something like:

	if (!new_log_buf_len) {
		if (early)
			goto out;
		return;
	}

>  	new_descs_count = new_log_buf_len >> PRB_AVGBITS;
>  	if (new_descs_count == 0) {
>  		pr_err("new_log_buf_len: %lu too small\n", new_log_buf_len);
> -		return;
> +		goto out;
>  	}
>  

Best Regards,
Petr

Re: [PATCH v1] printk: Improve memory usage logging during boot

[Isaac Manjarres]

On Mon, Sep 30, 2024 at 03:38:46PM +0200, Petr Mladek wrote:
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -1156,6 +1156,17 @@ static unsigned int __init add_to_rb(struct printk_ringbuffer *rb,
> >  
> >  static char setup_text_buf[PRINTKRB_RECORD_MAX] __initdata;
> >  
> > +static void print_log_buf_usage_stats(void)
> > +{
> > +	unsigned int descs_count = log_buf_len >> PRB_AVGBITS;
> > +	size_t descs_size = descs_count * sizeof(struct prb_desc);
> > +	size_t infos_size = descs_count * sizeof(struct printk_info);
> > +
> > +	pr_info("log_buf_len: %u bytes\n", log_buf_len);
> > +	pr_info("prb_descs size: %zu bytes\n", descs_size);
> > +	pr_info("printk_infos size: %zu bytes\n", infos_size);
> > +}
> 
> I would make the information more user friendly. Also a single line
> might be enough. Something like:
> 
> static void print_log_buf_usage_stats(void)
> {
> 	unsigned int descs_count = log_buf_len >> PRB_AVGBITS;
> 	size_t meta_data_size;
> 
> 	meta_data_size = descs_count *
> 		(sizeof(struct prb_desc) + sizeof(struct printk_info));
> 
> 	pr_info("log buffer data + meta data: %u + %zu = %zu bytes\n",
> 		log_buf_len, meta_data_size, log_buf_len + meta_data_size);
> }
Thanks for suggesting this! I'll do this for the 2nd version of the
patch.

> > +
> >  void __init setup_log_buf(int early)
> >  {
> >  	struct printk_info *new_infos;
> > @@ -1186,19 +1197,19 @@ void __init setup_log_buf(int early)
> >  		log_buf_add_cpu();
> >  
> >  	if (!new_log_buf_len)
> > -		return;
> > +		goto out;
> 
> The same information is printed twice when the default buffer is used.
> We should do something like:
> 
> 	if (!new_log_buf_len) {
> 		if (early)
> 			goto out;
> 		return;
> 	}
> 
Thank you for pointing this out. I'll do something very similar to this
in the 2nd version of the patch, but I'll use "!early" instead. The
rationale is that if I use just use "early", then the memory usage
stats don't get emitted at all on my machine (arm64) when it uses the
default buffer, because setup_log_buf() is called only once with
early == 0.

Using !early in the check there should fix that, and also emit the
memory stats only once on machines that invoke setup_log_buf()
multiple times and end up using the default buffer.

Thanks,
Isaac

Re: [PATCH v1] printk: Improve memory usage logging during boot

[Petr Mladek]

On Mon 2024-09-30 11:33:52, Isaac Manjarres wrote:
> On Mon, Sep 30, 2024 at 03:38:46PM +0200, Petr Mladek wrote:
> > > --- a/kernel/printk/printk.c
> > > +++ b/kernel/printk/printk.c
> > > @@ -1156,6 +1156,17 @@ static unsigned int __init add_to_rb(struct printk_ringbuffer *rb,
> > > +
> > >  void __init setup_log_buf(int early)
> > >  {
> > >  	struct printk_info *new_infos;
> > > @@ -1186,19 +1197,19 @@ void __init setup_log_buf(int early)
> > >  		log_buf_add_cpu();
> > >  
> > >  	if (!new_log_buf_len)
> > > -		return;
> > > +		goto out;
> > 
> > The same information is printed twice when the default buffer is used.
> > We should do something like:
> > 
> > 	if (!new_log_buf_len) {
> > 		if (early)
> > 			goto out;
> > 		return;
> > 	}
> > 
> Thank you for pointing this out. I'll do something very similar to this
> in the 2nd version of the patch, but I'll use "!early" instead. The
> rationale is that if I use just use "early", then the memory usage
> stats don't get emitted at all on my machine (arm64) when it uses the
> default buffer, because setup_log_buf() is called only once with
> early == 0.

I see. setup_log_buf(1) is used only on x86_64. Great catch!

> Using !early in the check there should fix that, and also emit the
> memory stats only once on machines that invoke setup_log_buf()
> multiple times and end up using the default buffer.

Yup.

Best Regards,
Petr