kernel/printk/printk.c | 21 +++++++++++++++++---- 1 file changed, 17 insertions(+), 4 deletions(-)
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-googOn 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
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
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
© 2016 - 2024 Red Hat, Inc.