[PATCH] printk: Add printk log prefix information.

[PATCH] printk: Add printk log prefix information.

[chunlei.wang]

Add prefix status/cpu_id/pid/process_name to each kernel log.
example:
[ 8408.806432] (4)[19963:kworker/4:1]wifi_fw: ring_emi_seg.sz=4164,
ring_cache_pt=000000004f5ca8fa, ring_cache_seg.sz=4164
[ 8408.806729]-(4)[19963:kworker/4:1]connlog_log_data_handler: 1
callbacks suppressed
Status now only include irq status. If in ISR print too much log, will
cause performance issue, we can check the log to find which module. We
also can expand the status in future.
cpu_id mean which cpu print this log, we can check specific cpu's
action.
pocess_name show the log process id and name.
These information is very useful in embedded system, it can provide more
information to analyze issue.

Feature: printk
Signed-off-by: Chunlei Wang <chunlei.wang@mediatek.com>
---
 kernel/printk/printk.c | 52 ++++++++++++++++++++++++++++++++++++++++--
 lib/Kconfig.debug      |  9 ++++++++
 2 files changed, 59 insertions(+), 2 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1ef6f75d92f1..9cb2a4c2157b 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -60,6 +60,11 @@
 #include "braille.h"
 #include "internal.h"
 
+
+#ifdef CONFIG_PRINTK_PREFIX_ENHANCE
+static DEFINE_PER_CPU(char, printk_state);
+#endif
+
 int console_printk[4] = {
        CONSOLE_LOGLEVEL_DEFAULT,       /* console_loglevel */
        MESSAGE_LOGLEVEL_DEFAULT,       /* default_message_loglevel */
@@ -610,8 +615,35 @@ static int log_store(u32 caller_id, int facility,
int level,
        u32 size, pad_len;
        u16 trunc_msg_len = 0;
 
-       /* number of '\0' padding bytes to next message */
-       size = msg_used_size(text_len, dict_len, &pad_len);
+#ifdef CONFIG_PRINTK_PREFIX_ENHANCE
+       int this_cpu = smp_processor_id();
+       char state = this_cpu_read(printk_state);
+       char tbuf[50];
+       unsigned int tlen = 0;
+#endif
+
+#ifdef CONFIG_PRINTK_PREFIX_ENHANCE
+               if (state == 0) {
+                       this_cpu_write(printk_state, ' ');
+                       state = ' ';
+               }
+               if (!(flags & LOG_CONT)) {
+                       if (console_suspended == 0)
+                               tlen = snprintf(tbuf, sizeof(tbuf),
+                                       "%c(%x)[%d:%s]", state,
this_cpu,
+                                       current->pid, current->comm);
+                       else
+                               tlen = snprintf(tbuf, sizeof(tbuf), "%
c(%x)",
+                                       state, this_cpu);
+               }
+#endif
+
+               /* number of '\0' padding bytes to next message */
+#ifdef CONFIG_PRINTK_PREFIX_ENHANCE
+               size = msg_used_size(text_len + tlen, dict_len,
&pad_len);
+#else
+               size = msg_used_size(text_len, dict_len, &pad_len);
+#endif
 
        if (log_make_free_space(size)) {
                /* truncate the message if it is too long for empty
buffer */
@@ -634,7 +666,16 @@ static int log_store(u32 caller_id, int facility,
int level,
 
        /* fill message */
        msg = (struct printk_log *)(log_buf + log_next_idx);
+#ifdef CONFIG_PRINTK_PREFIX_ENHANCE
+       memcpy(log_text(msg), tbuf, tlen);
+       if (tlen + text_len > LOG_LINE_MAX)
+               text_len = LOG_LINE_MAX - tlen;
+
+       memcpy(log_text(msg) + tlen, text, text_len);
+       text_len += tlen;
+#else
        memcpy(log_text(msg), text, text_len);
+#endif
        msg->text_len = text_len;
        if (trunc_msg_len) {
                memcpy(log_text(msg) + text_len, trunc_msg,
trunc_msg_len);
@@ -1964,6 +2005,13 @@ asmlinkage int vprintk_emit(int facility, int
level,
        if (unlikely(suppress_printk))
                return 0;
 
+#ifdef CONFIG_PRINTK_PREFIX_ENHANCE
+       if (irqs_disabled())
+               this_cpu_write(printk_state, '-');
+       else
+               this_cpu_write(printk_state, ' ');
+#endif
+
        if (level == LOGLEVEL_SCHED) {
                level = LOGLEVEL_DEFAULT;
                in_sched = true;
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index d1842fe756d5..6e6c783cd570 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -35,6 +35,15 @@ config PRINTK_CALLER
          no option to enable/disable at the kernel command line
parameter or
          sysfs interface.
 
+config PRINTK_PREFIX_ENHANCE
+       bool "Prefix cpu_id/status/pid/process_name to each kernel log"
+       depends on PRINTK
+       help
+         PRINTK_PREFIX_ENHANCE which is used to control whether to show
+         other information about this log. The information include
+         which cpu about this process in, whether in isr, pid and
thread
+         name. These information can help to analyze issue.
+
 config CONSOLE_LOGLEVEL_DEFAULT
        int "Default console loglevel (1-15)"
        range 1 15
-- 
2.18.0

_______________________________________________
Linux-mediatek mailing list
Linux-mediatek@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-mediatek

[PATCH] printk: Add printk log prefix information.

[chunlei.wang]

Add prefix status/cpu_id/pid/process_name to each kernel log.
example:
[ 8408.806432] (4)[19963:kworker/4:1]wifi_fw: ring_emi_seg.sz=4164,
ring_cache_pt=000000004f5ca8fa, ring_cache_seg.sz=4164
[ 8408.806729]-(4)[19963:kworker/4:1]connlog_log_data_handler: 1
callbacks suppressed
Status now only include irq status. If in ISR print too much log, will
cause performance issue, we can check the log to find which module. We
also can expand the status in future.
cpu_id mean which cpu print this log, we can check specific cpu's
action.
pocess_name show the log process id and name.
These information is very useful in embedded system, it can provide more
information to analyze issue.

Feature: printk
Signed-off-by: Chunlei Wang <chunlei.wang@mediatek.com>
---
 kernel/printk/printk.c | 52 ++++++++++++++++++++++++++++++++++++++++--
 lib/Kconfig.debug      |  9 ++++++++
 2 files changed, 59 insertions(+), 2 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1ef6f75d92f1..9cb2a4c2157b 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -60,6 +60,11 @@
 #include "braille.h"
 #include "internal.h"
 
+
+#ifdef CONFIG_PRINTK_PREFIX_ENHANCE
+static DEFINE_PER_CPU(char, printk_state);
+#endif
+
 int console_printk[4] = {
        CONSOLE_LOGLEVEL_DEFAULT,       /* console_loglevel */
        MESSAGE_LOGLEVEL_DEFAULT,       /* default_message_loglevel */
@@ -610,8 +615,35 @@ static int log_store(u32 caller_id, int facility,
int level,
        u32 size, pad_len;
        u16 trunc_msg_len = 0;
 
-       /* number of '\0' padding bytes to next message */
-       size = msg_used_size(text_len, dict_len, &pad_len);
+#ifdef CONFIG_PRINTK_PREFIX_ENHANCE
+       int this_cpu = smp_processor_id();
+       char state = this_cpu_read(printk_state);
+       char tbuf[50];
+       unsigned int tlen = 0;
+#endif
+
+#ifdef CONFIG_PRINTK_PREFIX_ENHANCE
+               if (state == 0) {
+                       this_cpu_write(printk_state, ' ');
+                       state = ' ';
+               }
+               if (!(flags & LOG_CONT)) {
+                       if (console_suspended == 0)
+                               tlen = snprintf(tbuf, sizeof(tbuf),
+                                       "%c(%x)[%d:%s]", state,
this_cpu,
+                                       current->pid, current->comm);
+                       else
+                               tlen = snprintf(tbuf, sizeof(tbuf), "%
c(%x)",
+                                       state, this_cpu);
+               }
+#endif
+
+               /* number of '\0' padding bytes to next message */
+#ifdef CONFIG_PRINTK_PREFIX_ENHANCE
+               size = msg_used_size(text_len + tlen, dict_len,
&pad_len);
+#else
+               size = msg_used_size(text_len, dict_len, &pad_len);
+#endif
 
        if (log_make_free_space(size)) {
                /* truncate the message if it is too long for empty
buffer */
@@ -634,7 +666,16 @@ static int log_store(u32 caller_id, int facility,
int level,
 
        /* fill message */
        msg = (struct printk_log *)(log_buf + log_next_idx);
+#ifdef CONFIG_PRINTK_PREFIX_ENHANCE
+       memcpy(log_text(msg), tbuf, tlen);
+       if (tlen + text_len > LOG_LINE_MAX)
+               text_len = LOG_LINE_MAX - tlen;
+
+       memcpy(log_text(msg) + tlen, text, text_len);
+       text_len += tlen;
+#else
        memcpy(log_text(msg), text, text_len);
+#endif
        msg->text_len = text_len;
        if (trunc_msg_len) {
                memcpy(log_text(msg) + text_len, trunc_msg,
trunc_msg_len);
@@ -1964,6 +2005,13 @@ asmlinkage int vprintk_emit(int facility, int
level,
        if (unlikely(suppress_printk))
                return 0;
 
+#ifdef CONFIG_PRINTK_PREFIX_ENHANCE
+       if (irqs_disabled())
+               this_cpu_write(printk_state, '-');
+       else
+               this_cpu_write(printk_state, ' ');
+#endif
+
        if (level == LOGLEVEL_SCHED) {
                level = LOGLEVEL_DEFAULT;
                in_sched = true;
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index d1842fe756d5..6e6c783cd570 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -35,6 +35,15 @@ config PRINTK_CALLER
          no option to enable/disable at the kernel command line
parameter or
          sysfs interface.
 
+config PRINTK_PREFIX_ENHANCE
+       bool "Prefix cpu_id/status/pid/process_name to each kernel log"
+       depends on PRINTK
+       help
+         PRINTK_PREFIX_ENHANCE which is used to control whether to show
+         other information about this log. The information include
+         which cpu about this process in, whether in isr, pid and
thread
+         name. These information can help to analyze issue.
+
 config CONSOLE_LOGLEVEL_DEFAULT
        int "Default console loglevel (1-15)"
        range 1 15
-- 
2.18.0

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: [PATCH] printk: Add printk log prefix information.

[Sergey Senozhatsky]

On (20/04/24 14:21), chunlei.wang wrote:
> Add prefix status/cpu_id/pid/process_name to each kernel log.
> example:
> [ 8408.806432] (4)[19963:kworker/4:1]wifi_fw: ring_emi_seg.sz=4164,
> ring_cache_pt=000000004f5ca8fa, ring_cache_seg.sz=4164
> [ 8408.806729]-(4)[19963:kworker/4:1]connlog_log_data_handler: 1
> callbacks suppressed

It seems that CONFIG_PRINTK_CALLER does this already.

	-ss

_______________________________________________
Linux-mediatek mailing list
Linux-mediatek@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-mediatek

Re: [PATCH] printk: Add printk log prefix information.

[Sergey Senozhatsky]

On (20/04/24 14:21), chunlei.wang wrote:
> Add prefix status/cpu_id/pid/process_name to each kernel log.
> example:
> [ 8408.806432] (4)[19963:kworker/4:1]wifi_fw: ring_emi_seg.sz=4164,
> ring_cache_pt=000000004f5ca8fa, ring_cache_seg.sz=4164
> [ 8408.806729]-(4)[19963:kworker/4:1]connlog_log_data_handler: 1
> callbacks suppressed

It seems that CONFIG_PRINTK_CALLER does this already.

	-ss

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

[PATCH] Fix prb_next_seq() performance issue

[chunlei.wang]

Subject: [PATCH] Fix prb_next_seq() performance issue.

prb_next_seq() function have a performance issue, in bad case it will
check all the seqs. If log buffer is 256K, the number of while loop
is 8K, 512K is 16K, 2M is 64K, it will cause performance issue.
we have a process use do_syslog poll&read method to read kernel log,
sometime the cpu loading is 50%. So we add old_seq to reduce the
loop time. It only check new log times.

Signed-off-by: Chunlei Wang <chunlei.wang@mediatek.com>
---
 kernel/printk/printk.c            | 12 ++++++------
 kernel/printk/printk_ringbuffer.c |  4 ++--
 kernel/printk/printk_ringbuffer.h |  2 +-
 3 files changed, 9 insertions(+), 9 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index a8d0a58deebc..9c6d4d617a95 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -801,7 +801,7 @@ static loff_t devkmsg_llseek(struct file *file,
loff_t offset, int whence)
                break;
        case SEEK_END:
                /* after the last record */
-               atomic64_set(&user->seq, prb_next_seq(prb));
+               atomic64_set(&user->seq, prb_next_seq(prb,
latched_seq_read_nolock(&clear_seq)));
                break;
        default:
                ret = -EINVAL;
@@ -1155,9 +1155,9 @@ void __init setup_log_buf(int early)
                        free -= text_size;
        }

-       if (seq != prb_next_seq(&printk_rb_static)) {
+       if (seq != prb_next_seq(&printk_rb_static, seq)) {
                pr_err("dropped %llu messages\n",
-                      prb_next_seq(&printk_rb_static) - seq);
+                      prb_next_seq(&printk_rb_static, seq) - seq);
        }

        pr_info("log_buf_len: %u bytes\n", log_buf_len);
@@ -1625,7 +1625,7 @@ static int syslog_print_all(char __user *buf, int
size, bool clear)
 static void syslog_clear(void)
 {
        mutex_lock(&syslog_lock);
-       latched_seq_write(&clear_seq, prb_next_seq(prb));
+       latched_seq_write(&clear_seq, prb_next_seq(prb, 0));
        mutex_unlock(&syslog_lock);
 }

@@ -1714,7 +1714,7 @@ int do_syslog(int type, char __user *buf, int
len, int source)
                         * for pending data, not the size; return the
count of
                         * records, not the length.
                         */
-                       error = prb_next_seq(prb) - syslog_seq;
+                       error = prb_next_seq(prb, syslog_seq) -
syslog_seq;
                } else {
                        bool time = syslog_partial ? syslog_time :
printk_time;
                        unsigned int line_count;
@@ -3573,7 +3573,7 @@ EXPORT_SYMBOL_GPL(kmsg_dump_get_buffer);
 void kmsg_dump_rewind(struct kmsg_dump_iter *iter)
 {
        iter->cur_seq = latched_seq_read_nolock(&clear_seq);
-       iter->next_seq = prb_next_seq(prb);
+       iter->next_seq = prb_next_seq(prb, iter->cur_seq);
 }
 EXPORT_SYMBOL_GPL(kmsg_dump_rewind);

diff --git a/kernel/printk/printk_ringbuffer.c
b/kernel/printk/printk_ringbuffer.c
index 8a7b7362c0dd..a910b79d9341 100644
--- a/kernel/printk/printk_ringbuffer.c
+++ b/kernel/printk/printk_ringbuffer.c
@@ -2003,9 +2003,9 @@ u64 prb_first_valid_seq(struct printk_ringbuffer
*rb)
  * Return: The sequence number of the next newest (not yet available)
record
  *         for readers.
  */
-u64 prb_next_seq(struct printk_ringbuffer *rb)
+u64 prb_next_seq(struct printk_ringbuffer *rb, u64 old_seq)
 {
-       u64 seq = 0;
+       u64 seq = old_seq;

        /* Search forward from the oldest descriptor. */
        while (_prb_read_valid(rb, &seq, NULL, NULL))
diff --git a/kernel/printk/printk_ringbuffer.h
b/kernel/printk/printk_ringbuffer.h
index 73cc80e01cef..0729b21a9d34 100644
--- a/kernel/printk/printk_ringbuffer.h
+++ b/kernel/printk/printk_ringbuffer.h
@@ -377,6 +377,6 @@ bool prb_read_valid_info(struct printk_ringbuffer
*rb, u64 seq,
                         struct printk_info *info, unsigned int
*line_count);

 u64 prb_first_valid_seq(struct printk_ringbuffer *rb);
-u64 prb_next_seq(struct printk_ringbuffer *rb);
+u64 prb_next_seq(struct printk_ringbuffer *rb, u64 seq);

 #endif /* _KERNEL_PRINTK_RINGBUFFER_H */
--
2.18.0
_______________________________________________
Linux-mediatek mailing list
Linux-mediatek@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-mediatek

[PATCH] Fix prb_next_seq() performance issue

[chunlei.wang]

Subject: [PATCH] Fix prb_next_seq() performance issue.

prb_next_seq() function have a performance issue, in bad case it will
check all the seqs. If log buffer is 256K, the number of while loop
is 8K, 512K is 16K, 2M is 64K, it will cause performance issue.
we have a process use do_syslog poll&read method to read kernel log,
sometime the cpu loading is 50%. So we add old_seq to reduce the
loop time. It only check new log times.

Signed-off-by: Chunlei Wang <chunlei.wang@mediatek.com>
---
 kernel/printk/printk.c            | 12 ++++++------
 kernel/printk/printk_ringbuffer.c |  4 ++--
 kernel/printk/printk_ringbuffer.h |  2 +-
 3 files changed, 9 insertions(+), 9 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index a8d0a58deebc..9c6d4d617a95 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -801,7 +801,7 @@ static loff_t devkmsg_llseek(struct file *file,
loff_t offset, int whence)
                break;
        case SEEK_END:
                /* after the last record */
-               atomic64_set(&user->seq, prb_next_seq(prb));
+               atomic64_set(&user->seq, prb_next_seq(prb,
latched_seq_read_nolock(&clear_seq)));
                break;
        default:
                ret = -EINVAL;
@@ -1155,9 +1155,9 @@ void __init setup_log_buf(int early)
                        free -= text_size;
        }

-       if (seq != prb_next_seq(&printk_rb_static)) {
+       if (seq != prb_next_seq(&printk_rb_static, seq)) {
                pr_err("dropped %llu messages\n",
-                      prb_next_seq(&printk_rb_static) - seq);
+                      prb_next_seq(&printk_rb_static, seq) - seq);
        }

        pr_info("log_buf_len: %u bytes\n", log_buf_len);
@@ -1625,7 +1625,7 @@ static int syslog_print_all(char __user *buf, int
size, bool clear)
 static void syslog_clear(void)
 {
        mutex_lock(&syslog_lock);
-       latched_seq_write(&clear_seq, prb_next_seq(prb));
+       latched_seq_write(&clear_seq, prb_next_seq(prb, 0));
        mutex_unlock(&syslog_lock);
 }

@@ -1714,7 +1714,7 @@ int do_syslog(int type, char __user *buf, int
len, int source)
                         * for pending data, not the size; return the
count of
                         * records, not the length.
                         */
-                       error = prb_next_seq(prb) - syslog_seq;
+                       error = prb_next_seq(prb, syslog_seq) -
syslog_seq;
                } else {
                        bool time = syslog_partial ? syslog_time :
printk_time;
                        unsigned int line_count;
@@ -3573,7 +3573,7 @@ EXPORT_SYMBOL_GPL(kmsg_dump_get_buffer);
 void kmsg_dump_rewind(struct kmsg_dump_iter *iter)
 {
        iter->cur_seq = latched_seq_read_nolock(&clear_seq);
-       iter->next_seq = prb_next_seq(prb);
+       iter->next_seq = prb_next_seq(prb, iter->cur_seq);
 }
 EXPORT_SYMBOL_GPL(kmsg_dump_rewind);

diff --git a/kernel/printk/printk_ringbuffer.c
b/kernel/printk/printk_ringbuffer.c
index 8a7b7362c0dd..a910b79d9341 100644
--- a/kernel/printk/printk_ringbuffer.c
+++ b/kernel/printk/printk_ringbuffer.c
@@ -2003,9 +2003,9 @@ u64 prb_first_valid_seq(struct printk_ringbuffer
*rb)
  * Return: The sequence number of the next newest (not yet available)
record
  *         for readers.
  */
-u64 prb_next_seq(struct printk_ringbuffer *rb)
+u64 prb_next_seq(struct printk_ringbuffer *rb, u64 old_seq)
 {
-       u64 seq = 0;
+       u64 seq = old_seq;

        /* Search forward from the oldest descriptor. */
        while (_prb_read_valid(rb, &seq, NULL, NULL))
diff --git a/kernel/printk/printk_ringbuffer.h
b/kernel/printk/printk_ringbuffer.h
index 73cc80e01cef..0729b21a9d34 100644
--- a/kernel/printk/printk_ringbuffer.h
+++ b/kernel/printk/printk_ringbuffer.h
@@ -377,6 +377,6 @@ bool prb_read_valid_info(struct printk_ringbuffer
*rb, u64 seq,
                         struct printk_info *info, unsigned int
*line_count);

 u64 prb_first_valid_seq(struct printk_ringbuffer *rb);
-u64 prb_next_seq(struct printk_ringbuffer *rb);
+u64 prb_next_seq(struct printk_ringbuffer *rb, u64 seq);

 #endif /* _KERNEL_PRINTK_RINGBUFFER_H */
--
2.18.0
_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: [PATCH] Fix prb_next_seq() performance issue

[Petr Mladek]

On Mon 2021-10-25 13:51:07, chunlei.wang wrote:
> 
> Subject: [PATCH] Fix prb_next_seq() performance issue.
> 
> prb_next_seq() function have a performance issue, in bad case it will
> check all the seqs. If log buffer is 256K, the number of while loop
> is 8K, 512K is 16K, 2M is 64K, it will cause performance issue.
> we have a process use do_syslog poll&read method to read kernel log,
> sometime the cpu loading is 50%. So we add old_seq to reduce the
> loop time. It only check new log times.

The patch looks good and probably helps in the described use-case.

But the search might still be quite slow because @clear_seq or
@sysrq_seq might be far behind the last_seq.

I am going to send alternative patch that stores @id of the last
finalized message. It starts the search from there. All the tricks
will be hidden in the ring buffer code, so that it will be
easier to use. Also it should be more reliable.

Best Regards,
Petr

_______________________________________________
Linux-mediatek mailing list
Linux-mediatek@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-mediatek

Re: [PATCH] Fix prb_next_seq() performance issue

[Petr Mladek]

On Mon 2021-10-25 13:51:07, chunlei.wang wrote:
> 
> Subject: [PATCH] Fix prb_next_seq() performance issue.
> 
> prb_next_seq() function have a performance issue, in bad case it will
> check all the seqs. If log buffer is 256K, the number of while loop
> is 8K, 512K is 16K, 2M is 64K, it will cause performance issue.
> we have a process use do_syslog poll&read method to read kernel log,
> sometime the cpu loading is 50%. So we add old_seq to reduce the
> loop time. It only check new log times.

The patch looks good and probably helps in the described use-case.

But the search might still be quite slow because @clear_seq or
@sysrq_seq might be far behind the last_seq.

I am going to send alternative patch that stores @id of the last
finalized message. It starts the search from there. All the tricks
will be hidden in the ring buffer code, so that it will be
easier to use. Also it should be more reliable.

Best Regards,
Petr

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

[PATCH] printk: ringbuffer: Improve prb_next_seq() performance

[Petr Mladek]

prb_next_seq() always iterates from the first known sequence number.
In the worst case, it might loop 8k times for 256kB buffer,
15k times for 512kB buffer, and 64k times for 2MB buffer.

It was reported that pooling and reading using syslog interface
might occupy 50% of CPU.

Speedup the search by storing @id of the last finalized descriptor.

The loop is still needed because the @id is stored and read in the best
effort way. An atomic variable is used to keep the @id consistent.
But the stores and reads are not serialized against each other.
The descriptor could get reused in the meantime. The related sequence
number will be used only when it is still valid.

An invalid value should be read _only_ when there is a flood of messages
and the ringbuffer is rapidly reused. The performance is the least
problem in this case.

Reported-by: Chunlei Wang <chunlei.wang@mediatek.com>
Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk_ringbuffer.c | 46 ++++++++++++++++++++++++++++---
 kernel/printk/printk_ringbuffer.h |  2 ++
 2 files changed, 44 insertions(+), 4 deletions(-)

diff --git a/kernel/printk/printk_ringbuffer.c b/kernel/printk/printk_ringbuffer.c
index 8a7b7362c0dd..7e0c11be07c8 100644
--- a/kernel/printk/printk_ringbuffer.c
+++ b/kernel/printk/printk_ringbuffer.c
@@ -474,8 +474,10 @@ static enum desc_state desc_read(struct prb_desc_ring *desc_ring,
 	 * state has been re-checked. A memcpy() for all of @desc
 	 * cannot be used because of the atomic_t @state_var field.
 	 */
-	memcpy(&desc_out->text_blk_lpos, &desc->text_blk_lpos,
-	       sizeof(desc_out->text_blk_lpos)); /* LMM(desc_read:C) */
+	if (desc_out) {
+		memcpy(&desc_out->text_blk_lpos, &desc->text_blk_lpos,
+		       sizeof(desc_out->text_blk_lpos)); /* LMM(desc_read:C) */
+	}
 	if (seq_out)
 		*seq_out = info->seq; /* also part of desc_read:C */
 	if (caller_id_out)
@@ -1449,6 +1451,9 @@ static void desc_make_final(struct prb_desc_ring *desc_ring, unsigned long id)
 
 	atomic_long_cmpxchg_relaxed(&d->state_var, prev_state_val,
 			DESC_SV(id, desc_finalized)); /* LMM(desc_make_final:A) */
+
+	/* Best effort to remember the last finalized @id. */
+	atomic_long_set(&desc_ring->last_finalized_id, id);
 }
 
 /**
@@ -1657,7 +1662,12 @@ void prb_commit(struct prb_reserved_entry *e)
  */
 void prb_final_commit(struct prb_reserved_entry *e)
 {
+	struct prb_desc_ring *desc_ring = &e->rb->desc_ring;
+
 	_prb_commit(e, desc_finalized);
+
+	/* Best effort to remember the last finalized @id. */
+	atomic_long_set(&desc_ring->last_finalized_id, e->id);
 }
 
 /*
@@ -1988,6 +1998,30 @@ u64 prb_first_valid_seq(struct printk_ringbuffer *rb)
 	return seq;
 }
 
+/* Try to read seq from the last known location. */
+static u64 prb_last_finalized_seq(struct printk_ringbuffer *rb)
+{
+	struct prb_desc_ring *desc_ring = &rb->desc_ring;
+	enum desc_state d_state;
+	unsigned long id;
+	u64 seq = 0;
+
+	/* Check if the cached @id still points to a valid @seq. */
+	id = atomic_long_read(&desc_ring->last_finalized_id);
+	d_state = desc_read(desc_ring, id, NULL, &seq, NULL);
+
+	if (d_state == desc_finalized || d_state == desc_reusable)
+		return seq;
+
+	/*
+	 * The information about the last finalized sequence number
+	 * has gone. It should happen only when there is a flood of
+	 * new messages and the ringbuffer is rapidly recycled.
+	 * Give up and start from the beginning.
+	 */
+	return 0;
+}
+
 /**
  * prb_next_seq() - Get the sequence number after the last available record.
  *
@@ -2005,9 +2039,12 @@ u64 prb_first_valid_seq(struct printk_ringbuffer *rb)
  */
 u64 prb_next_seq(struct printk_ringbuffer *rb)
 {
-	u64 seq = 0;
+	u64 seq = prb_last_finalized_seq(rb);
 
-	/* Search forward from the oldest descriptor. */
+	/*
+	 * The information about the last finalized @seq might be inaccurate.
+	 * Search forward to find the current one.
+	 */
 	while (_prb_read_valid(rb, &seq, NULL, NULL))
 		seq++;
 
@@ -2044,6 +2081,7 @@ void prb_init(struct printk_ringbuffer *rb,
 	rb->desc_ring.infos = infos;
 	atomic_long_set(&rb->desc_ring.head_id, DESC0_ID(descbits));
 	atomic_long_set(&rb->desc_ring.tail_id, DESC0_ID(descbits));
+	atomic_long_set(&rb->desc_ring.last_finalized_id, DESC0_ID(descbits));
 
 	rb->text_data_ring.size_bits = textbits;
 	rb->text_data_ring.data = text_buf;
diff --git a/kernel/printk/printk_ringbuffer.h b/kernel/printk/printk_ringbuffer.h
index 73cc80e01cef..18cd25e489b8 100644
--- a/kernel/printk/printk_ringbuffer.h
+++ b/kernel/printk/printk_ringbuffer.h
@@ -75,6 +75,7 @@ struct prb_desc_ring {
 	struct printk_info	*infos;
 	atomic_long_t		head_id;
 	atomic_long_t		tail_id;
+	atomic_long_t		last_finalized_id;
 };
 
 /*
@@ -258,6 +259,7 @@ static struct printk_ringbuffer name = {							\
 		.infos		= &_##name##_infos[0],						\
 		.head_id	= ATOMIC_INIT(DESC0_ID(descbits)),				\
 		.tail_id	= ATOMIC_INIT(DESC0_ID(descbits)),				\
+		.last_finalized_id = ATOMIC_INIT(DESC0_ID(descbits)),				\
 	},											\
 	.text_data_ring = {									\
 		.size_bits	= (avgtextbits) + (descbits),					\
-- 
2.26.2


_______________________________________________
Linux-mediatek mailing list
Linux-mediatek@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-mediatek

[PATCH] printk: ringbuffer: Improve prb_next_seq() performance

[Petr Mladek]

prb_next_seq() always iterates from the first known sequence number.
In the worst case, it might loop 8k times for 256kB buffer,
15k times for 512kB buffer, and 64k times for 2MB buffer.

It was reported that pooling and reading using syslog interface
might occupy 50% of CPU.

Speedup the search by storing @id of the last finalized descriptor.

The loop is still needed because the @id is stored and read in the best
effort way. An atomic variable is used to keep the @id consistent.
But the stores and reads are not serialized against each other.
The descriptor could get reused in the meantime. The related sequence
number will be used only when it is still valid.

An invalid value should be read _only_ when there is a flood of messages
and the ringbuffer is rapidly reused. The performance is the least
problem in this case.

Reported-by: Chunlei Wang <chunlei.wang@mediatek.com>
Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk_ringbuffer.c | 46 ++++++++++++++++++++++++++++---
 kernel/printk/printk_ringbuffer.h |  2 ++
 2 files changed, 44 insertions(+), 4 deletions(-)

diff --git a/kernel/printk/printk_ringbuffer.c b/kernel/printk/printk_ringbuffer.c
index 8a7b7362c0dd..7e0c11be07c8 100644
--- a/kernel/printk/printk_ringbuffer.c
+++ b/kernel/printk/printk_ringbuffer.c
@@ -474,8 +474,10 @@ static enum desc_state desc_read(struct prb_desc_ring *desc_ring,
 	 * state has been re-checked. A memcpy() for all of @desc
 	 * cannot be used because of the atomic_t @state_var field.
 	 */
-	memcpy(&desc_out->text_blk_lpos, &desc->text_blk_lpos,
-	       sizeof(desc_out->text_blk_lpos)); /* LMM(desc_read:C) */
+	if (desc_out) {
+		memcpy(&desc_out->text_blk_lpos, &desc->text_blk_lpos,
+		       sizeof(desc_out->text_blk_lpos)); /* LMM(desc_read:C) */
+	}
 	if (seq_out)
 		*seq_out = info->seq; /* also part of desc_read:C */
 	if (caller_id_out)
@@ -1449,6 +1451,9 @@ static void desc_make_final(struct prb_desc_ring *desc_ring, unsigned long id)
 
 	atomic_long_cmpxchg_relaxed(&d->state_var, prev_state_val,
 			DESC_SV(id, desc_finalized)); /* LMM(desc_make_final:A) */
+
+	/* Best effort to remember the last finalized @id. */
+	atomic_long_set(&desc_ring->last_finalized_id, id);
 }
 
 /**
@@ -1657,7 +1662,12 @@ void prb_commit(struct prb_reserved_entry *e)
  */
 void prb_final_commit(struct prb_reserved_entry *e)
 {
+	struct prb_desc_ring *desc_ring = &e->rb->desc_ring;
+
 	_prb_commit(e, desc_finalized);
+
+	/* Best effort to remember the last finalized @id. */
+	atomic_long_set(&desc_ring->last_finalized_id, e->id);
 }
 
 /*
@@ -1988,6 +1998,30 @@ u64 prb_first_valid_seq(struct printk_ringbuffer *rb)
 	return seq;
 }
 
+/* Try to read seq from the last known location. */
+static u64 prb_last_finalized_seq(struct printk_ringbuffer *rb)
+{
+	struct prb_desc_ring *desc_ring = &rb->desc_ring;
+	enum desc_state d_state;
+	unsigned long id;
+	u64 seq = 0;
+
+	/* Check if the cached @id still points to a valid @seq. */
+	id = atomic_long_read(&desc_ring->last_finalized_id);
+	d_state = desc_read(desc_ring, id, NULL, &seq, NULL);
+
+	if (d_state == desc_finalized || d_state == desc_reusable)
+		return seq;
+
+	/*
+	 * The information about the last finalized sequence number
+	 * has gone. It should happen only when there is a flood of
+	 * new messages and the ringbuffer is rapidly recycled.
+	 * Give up and start from the beginning.
+	 */
+	return 0;
+}
+
 /**
  * prb_next_seq() - Get the sequence number after the last available record.
  *
@@ -2005,9 +2039,12 @@ u64 prb_first_valid_seq(struct printk_ringbuffer *rb)
  */
 u64 prb_next_seq(struct printk_ringbuffer *rb)
 {
-	u64 seq = 0;
+	u64 seq = prb_last_finalized_seq(rb);
 
-	/* Search forward from the oldest descriptor. */
+	/*
+	 * The information about the last finalized @seq might be inaccurate.
+	 * Search forward to find the current one.
+	 */
 	while (_prb_read_valid(rb, &seq, NULL, NULL))
 		seq++;
 
@@ -2044,6 +2081,7 @@ void prb_init(struct printk_ringbuffer *rb,
 	rb->desc_ring.infos = infos;
 	atomic_long_set(&rb->desc_ring.head_id, DESC0_ID(descbits));
 	atomic_long_set(&rb->desc_ring.tail_id, DESC0_ID(descbits));
+	atomic_long_set(&rb->desc_ring.last_finalized_id, DESC0_ID(descbits));
 
 	rb->text_data_ring.size_bits = textbits;
 	rb->text_data_ring.data = text_buf;
diff --git a/kernel/printk/printk_ringbuffer.h b/kernel/printk/printk_ringbuffer.h
index 73cc80e01cef..18cd25e489b8 100644
--- a/kernel/printk/printk_ringbuffer.h
+++ b/kernel/printk/printk_ringbuffer.h
@@ -75,6 +75,7 @@ struct prb_desc_ring {
 	struct printk_info	*infos;
 	atomic_long_t		head_id;
 	atomic_long_t		tail_id;
+	atomic_long_t		last_finalized_id;
 };
 
 /*
@@ -258,6 +259,7 @@ static struct printk_ringbuffer name = {							\
 		.infos		= &_##name##_infos[0],						\
 		.head_id	= ATOMIC_INIT(DESC0_ID(descbits)),				\
 		.tail_id	= ATOMIC_INIT(DESC0_ID(descbits)),				\
+		.last_finalized_id = ATOMIC_INIT(DESC0_ID(descbits)),				\
 	},											\
 	.text_data_ring = {									\
 		.size_bits	= (avgtextbits) + (descbits),					\
-- 
2.26.2


_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: [PATCH] printk: ringbuffer: Improve prb_next_seq() performance

[John Ogness]

Hi Petr,

I am OK with this new best effort cache. But I do have some minor
comments about the implementation...

On 2021-10-25, Petr Mladek <pmladek@suse.com> wrote:
> prb_next_seq() always iterates from the first known sequence number.
> In the worst case, it might loop 8k times for 256kB buffer,
> 15k times for 512kB buffer, and 64k times for 2MB buffer.
>
> It was reported that pooling and reading using syslog interface
> might occupy 50% of CPU.
>
> Speedup the search by storing @id of the last finalized descriptor.
>
> The loop is still needed because the @id is stored and read in the best
> effort way. An atomic variable is used to keep the @id consistent.
> But the stores and reads are not serialized against each other.
> The descriptor could get reused in the meantime. The related sequence
> number will be used only when it is still valid.
>
> An invalid value should be read _only_ when there is a flood of messages
> and the ringbuffer is rapidly reused. The performance is the least
> problem in this case.
>
> Reported-by: Chunlei Wang <chunlei.wang@mediatek.com>
> Signed-off-by: Petr Mladek <pmladek@suse.com>
> ---
>  kernel/printk/printk_ringbuffer.c | 46 ++++++++++++++++++++++++++++---
>  kernel/printk/printk_ringbuffer.h |  2 ++
>  2 files changed, 44 insertions(+), 4 deletions(-)
>
> diff --git a/kernel/printk/printk_ringbuffer.c b/kernel/printk/printk_ringbuffer.c
> index 8a7b7362c0dd..7e0c11be07c8 100644
> --- a/kernel/printk/printk_ringbuffer.c
> +++ b/kernel/printk/printk_ringbuffer.c
> @@ -474,8 +474,10 @@ static enum desc_state desc_read(struct prb_desc_ring *desc_ring,
>  	 * state has been re-checked. A memcpy() for all of @desc
>  	 * cannot be used because of the atomic_t @state_var field.
>  	 */
> -	memcpy(&desc_out->text_blk_lpos, &desc->text_blk_lpos,
> -	       sizeof(desc_out->text_blk_lpos)); /* LMM(desc_read:C) */
> +	if (desc_out) {
> +		memcpy(&desc_out->text_blk_lpos, &desc->text_blk_lpos,
> +		       sizeof(desc_out->text_blk_lpos)); /* LMM(desc_read:C) */
> +	}
>  	if (seq_out)
>  		*seq_out = info->seq; /* also part of desc_read:C */
>  	if (caller_id_out)
> @@ -1449,6 +1451,9 @@ static void desc_make_final(struct prb_desc_ring *desc_ring, unsigned long id)
>  
>  	atomic_long_cmpxchg_relaxed(&d->state_var, prev_state_val,
>  			DESC_SV(id, desc_finalized)); /* LMM(desc_make_final:A) */
> +
> +	/* Best effort to remember the last finalized @id. */
> +	atomic_long_set(&desc_ring->last_finalized_id, id);
>  }
>  
>  /**
> @@ -1657,7 +1662,12 @@ void prb_commit(struct prb_reserved_entry *e)
>   */
>  void prb_final_commit(struct prb_reserved_entry *e)
>  {
> +	struct prb_desc_ring *desc_ring = &e->rb->desc_ring;
> +
>  	_prb_commit(e, desc_finalized);
> +
> +	/* Best effort to remember the last finalized @id. */
> +	atomic_long_set(&desc_ring->last_finalized_id, e->id);
>  }
>  
>  /*
> @@ -1988,6 +1998,30 @@ u64 prb_first_valid_seq(struct printk_ringbuffer *rb)
>  	return seq;
>  }
>  
> +/* Try to read seq from the last known location. */
> +static u64 prb_last_finalized_seq(struct printk_ringbuffer *rb)
> +{
> +	struct prb_desc_ring *desc_ring = &rb->desc_ring;
> +	enum desc_state d_state;
> +	unsigned long id;
> +	u64 seq = 0;

It is not necessary to initialize @seq.

> +
> +	/* Check if the cached @id still points to a valid @seq. */
> +	id = atomic_long_read(&desc_ring->last_finalized_id);
> +	d_state = desc_read(desc_ring, id, NULL, &seq, NULL);
> +
> +	if (d_state == desc_finalized || d_state == desc_reusable)
> +		return seq;
> +
> +	/*
> +	 * The information about the last finalized sequence number
> +	 * has gone. It should happen only when there is a flood of
> +	 * new messages and the ringbuffer is rapidly recycled.
> +	 * Give up and start from the beginning.
> +	 */
> +	return 0;

Returning 0 is a bit odd here. For the problem this patch is solving it
would work, but if this new helper is ever used anywhere else, it would
be a bizarre exception since 0 can also mean success. See my suggestion
below.

> +}
> +
>  /**
>   * prb_next_seq() - Get the sequence number after the last available record.
>   *
> @@ -2005,9 +2039,12 @@ u64 prb_first_valid_seq(struct printk_ringbuffer *rb)
>   */
>  u64 prb_next_seq(struct printk_ringbuffer *rb)
>  {
> -	u64 seq = 0;
> +	u64 seq = prb_last_finalized_seq(rb);

If prb_last_finalized_seq() was successful (which can also be 0 on
success) then there is no point reading that record. We already know
that it must be higher.

I suggest implementing everything within prb_next_seq() instead of
adding the helper function prb_last_finalized_seq(). IMHO this cleanly
handles the case of a failed read for the last finalized id and avoids
an unnecessary descriptor read.

u64 prb_next_seq(struct printk_ringbuffer *rb)
{
	struct prb_desc_ring *desc_ring = &rb->desc_ring;
	enum desc_state d_state;
	unsigned long id;
	u64 seq;

	/* Check if the cached @id still points to a valid @seq. */
	id = atomic_long_read(&desc_ring->last_finalized_id);
	d_state = desc_read(desc_ring, id, NULL, &seq, NULL);

	if (d_state == desc_finalized || d_state == desc_reusable) {
		/* Begin searching after the last finalized record. */
		seq++;
	} else {
		/*
		 * The information about the last finalized sequence number
		 * has gone. It should happen only when there is a flood of
		 * new messages and the ringbuffer is rapidly recycled.
		 * Give up and start from the beginning.
		 */
		seq = 0;
	}

	/*
	 * The information about the last finalized @seq might be inaccurate.
	 * Search forward to find the current one.
	 */
	while (_prb_read_valid(rb, &seq, NULL, NULL))
		seq++;

	return seq;
}

>  
> -	/* Search forward from the oldest descriptor. */
> +	/*
> +	 * The information about the last finalized @seq might be inaccurate.
> +	 * Search forward to find the current one.
> +	 */
>  	while (_prb_read_valid(rb, &seq, NULL, NULL))
>  		seq++;
>  

John Ogness

_______________________________________________
Linux-mediatek mailing list
Linux-mediatek@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-mediatek

Re: [PATCH] printk: ringbuffer: Improve prb_next_seq() performance

[John Ogness]

Hi Petr,

I am OK with this new best effort cache. But I do have some minor
comments about the implementation...

On 2021-10-25, Petr Mladek <pmladek@suse.com> wrote:
> prb_next_seq() always iterates from the first known sequence number.
> In the worst case, it might loop 8k times for 256kB buffer,
> 15k times for 512kB buffer, and 64k times for 2MB buffer.
>
> It was reported that pooling and reading using syslog interface
> might occupy 50% of CPU.
>
> Speedup the search by storing @id of the last finalized descriptor.
>
> The loop is still needed because the @id is stored and read in the best
> effort way. An atomic variable is used to keep the @id consistent.
> But the stores and reads are not serialized against each other.
> The descriptor could get reused in the meantime. The related sequence
> number will be used only when it is still valid.
>
> An invalid value should be read _only_ when there is a flood of messages
> and the ringbuffer is rapidly reused. The performance is the least
> problem in this case.
>
> Reported-by: Chunlei Wang <chunlei.wang@mediatek.com>
> Signed-off-by: Petr Mladek <pmladek@suse.com>
> ---
>  kernel/printk/printk_ringbuffer.c | 46 ++++++++++++++++++++++++++++---
>  kernel/printk/printk_ringbuffer.h |  2 ++
>  2 files changed, 44 insertions(+), 4 deletions(-)
>
> diff --git a/kernel/printk/printk_ringbuffer.c b/kernel/printk/printk_ringbuffer.c
> index 8a7b7362c0dd..7e0c11be07c8 100644
> --- a/kernel/printk/printk_ringbuffer.c
> +++ b/kernel/printk/printk_ringbuffer.c
> @@ -474,8 +474,10 @@ static enum desc_state desc_read(struct prb_desc_ring *desc_ring,
>  	 * state has been re-checked. A memcpy() for all of @desc
>  	 * cannot be used because of the atomic_t @state_var field.
>  	 */
> -	memcpy(&desc_out->text_blk_lpos, &desc->text_blk_lpos,
> -	       sizeof(desc_out->text_blk_lpos)); /* LMM(desc_read:C) */
> +	if (desc_out) {
> +		memcpy(&desc_out->text_blk_lpos, &desc->text_blk_lpos,
> +		       sizeof(desc_out->text_blk_lpos)); /* LMM(desc_read:C) */
> +	}
>  	if (seq_out)
>  		*seq_out = info->seq; /* also part of desc_read:C */
>  	if (caller_id_out)
> @@ -1449,6 +1451,9 @@ static void desc_make_final(struct prb_desc_ring *desc_ring, unsigned long id)
>  
>  	atomic_long_cmpxchg_relaxed(&d->state_var, prev_state_val,
>  			DESC_SV(id, desc_finalized)); /* LMM(desc_make_final:A) */
> +
> +	/* Best effort to remember the last finalized @id. */
> +	atomic_long_set(&desc_ring->last_finalized_id, id);
>  }
>  
>  /**
> @@ -1657,7 +1662,12 @@ void prb_commit(struct prb_reserved_entry *e)
>   */
>  void prb_final_commit(struct prb_reserved_entry *e)
>  {
> +	struct prb_desc_ring *desc_ring = &e->rb->desc_ring;
> +
>  	_prb_commit(e, desc_finalized);
> +
> +	/* Best effort to remember the last finalized @id. */
> +	atomic_long_set(&desc_ring->last_finalized_id, e->id);
>  }
>  
>  /*
> @@ -1988,6 +1998,30 @@ u64 prb_first_valid_seq(struct printk_ringbuffer *rb)
>  	return seq;
>  }
>  
> +/* Try to read seq from the last known location. */
> +static u64 prb_last_finalized_seq(struct printk_ringbuffer *rb)
> +{
> +	struct prb_desc_ring *desc_ring = &rb->desc_ring;
> +	enum desc_state d_state;
> +	unsigned long id;
> +	u64 seq = 0;

It is not necessary to initialize @seq.

> +
> +	/* Check if the cached @id still points to a valid @seq. */
> +	id = atomic_long_read(&desc_ring->last_finalized_id);
> +	d_state = desc_read(desc_ring, id, NULL, &seq, NULL);
> +
> +	if (d_state == desc_finalized || d_state == desc_reusable)
> +		return seq;
> +
> +	/*
> +	 * The information about the last finalized sequence number
> +	 * has gone. It should happen only when there is a flood of
> +	 * new messages and the ringbuffer is rapidly recycled.
> +	 * Give up and start from the beginning.
> +	 */
> +	return 0;

Returning 0 is a bit odd here. For the problem this patch is solving it
would work, but if this new helper is ever used anywhere else, it would
be a bizarre exception since 0 can also mean success. See my suggestion
below.

> +}
> +
>  /**
>   * prb_next_seq() - Get the sequence number after the last available record.
>   *
> @@ -2005,9 +2039,12 @@ u64 prb_first_valid_seq(struct printk_ringbuffer *rb)
>   */
>  u64 prb_next_seq(struct printk_ringbuffer *rb)
>  {
> -	u64 seq = 0;
> +	u64 seq = prb_last_finalized_seq(rb);

If prb_last_finalized_seq() was successful (which can also be 0 on
success) then there is no point reading that record. We already know
that it must be higher.

I suggest implementing everything within prb_next_seq() instead of
adding the helper function prb_last_finalized_seq(). IMHO this cleanly
handles the case of a failed read for the last finalized id and avoids
an unnecessary descriptor read.

u64 prb_next_seq(struct printk_ringbuffer *rb)
{
	struct prb_desc_ring *desc_ring = &rb->desc_ring;
	enum desc_state d_state;
	unsigned long id;
	u64 seq;

	/* Check if the cached @id still points to a valid @seq. */
	id = atomic_long_read(&desc_ring->last_finalized_id);
	d_state = desc_read(desc_ring, id, NULL, &seq, NULL);

	if (d_state == desc_finalized || d_state == desc_reusable) {
		/* Begin searching after the last finalized record. */
		seq++;
	} else {
		/*
		 * The information about the last finalized sequence number
		 * has gone. It should happen only when there is a flood of
		 * new messages and the ringbuffer is rapidly recycled.
		 * Give up and start from the beginning.
		 */
		seq = 0;
	}

	/*
	 * The information about the last finalized @seq might be inaccurate.
	 * Search forward to find the current one.
	 */
	while (_prb_read_valid(rb, &seq, NULL, NULL))
		seq++;

	return seq;
}

>  
> -	/* Search forward from the oldest descriptor. */
> +	/*
> +	 * The information about the last finalized @seq might be inaccurate.
> +	 * Search forward to find the current one.
> +	 */
>  	while (_prb_read_valid(rb, &seq, NULL, NULL))
>  		seq++;
>  

John Ogness

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: [PATCH] printk: ringbuffer: Improve prb_next_seq() performance

[John Ogness]

On 2021-10-26, John Ogness <john.ogness@linutronix.de> wrote:
> If prb_last_finalized_seq() was successful (which can also be 0 on
> success) then there is no point reading that record. We already know
> that it must be higher.
>
> I suggest implementing everything within prb_next_seq() instead of
> adding the helper function prb_last_finalized_seq(). IMHO this cleanly
> handles the case of a failed read for the last finalized id and avoids
> an unnecessary descriptor read.
>
> u64 prb_next_seq(struct printk_ringbuffer *rb)
> {
> 	struct prb_desc_ring *desc_ring = &rb->desc_ring;
> 	enum desc_state d_state;
> 	unsigned long id;
> 	u64 seq;
>
> 	/* Check if the cached @id still points to a valid @seq. */
> 	id = atomic_long_read(&desc_ring->last_finalized_id);
> 	d_state = desc_read(desc_ring, id, NULL, &seq, NULL);
>
> 	if (d_state == desc_finalized || d_state == desc_reusable) {
> 		/* Begin searching after the last finalized record. */
> 		seq++;

I just realized that this doesn't work for the case when the ringbuffer
is empty (due to hack#2 of the bootstrapping). That would need to be
handled here. Something like:

 		/*
 		 * Begin searching after the last finalized record.
 		 * (On 0, the search must begin at 0 because of hack#2
 		 * of the bootstrapping phase it is not known if a
 		 * record at index 0 exists.)
 		 */
 		if (seq != 0)
 			seq++;

> 	} else {
> 		/*
> 		 * The information about the last finalized sequence number
> 		 * has gone. It should happen only when there is a flood of
> 		 * new messages and the ringbuffer is rapidly recycled.
> 		 * Give up and start from the beginning.
> 		 */
> 		seq = 0;
> 	}
>
> 	/*
> 	 * The information about the last finalized @seq might be inaccurate.
> 	 * Search forward to find the current one.
> 	 */
> 	while (_prb_read_valid(rb, &seq, NULL, NULL))
> 		seq++;
>
> 	return seq;
> }

John Ogness

_______________________________________________
Linux-mediatek mailing list
Linux-mediatek@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-mediatek

Re: [PATCH] printk: ringbuffer: Improve prb_next_seq() performance

[John Ogness]

On 2021-10-26, John Ogness <john.ogness@linutronix.de> wrote:
> If prb_last_finalized_seq() was successful (which can also be 0 on
> success) then there is no point reading that record. We already know
> that it must be higher.
>
> I suggest implementing everything within prb_next_seq() instead of
> adding the helper function prb_last_finalized_seq(). IMHO this cleanly
> handles the case of a failed read for the last finalized id and avoids
> an unnecessary descriptor read.
>
> u64 prb_next_seq(struct printk_ringbuffer *rb)
> {
> 	struct prb_desc_ring *desc_ring = &rb->desc_ring;
> 	enum desc_state d_state;
> 	unsigned long id;
> 	u64 seq;
>
> 	/* Check if the cached @id still points to a valid @seq. */
> 	id = atomic_long_read(&desc_ring->last_finalized_id);
> 	d_state = desc_read(desc_ring, id, NULL, &seq, NULL);
>
> 	if (d_state == desc_finalized || d_state == desc_reusable) {
> 		/* Begin searching after the last finalized record. */
> 		seq++;

I just realized that this doesn't work for the case when the ringbuffer
is empty (due to hack#2 of the bootstrapping). That would need to be
handled here. Something like:

 		/*
 		 * Begin searching after the last finalized record.
 		 * (On 0, the search must begin at 0 because of hack#2
 		 * of the bootstrapping phase it is not known if a
 		 * record at index 0 exists.)
 		 */
 		if (seq != 0)
 			seq++;

> 	} else {
> 		/*
> 		 * The information about the last finalized sequence number
> 		 * has gone. It should happen only when there is a flood of
> 		 * new messages and the ringbuffer is rapidly recycled.
> 		 * Give up and start from the beginning.
> 		 */
> 		seq = 0;
> 	}
>
> 	/*
> 	 * The information about the last finalized @seq might be inaccurate.
> 	 * Search forward to find the current one.
> 	 */
> 	while (_prb_read_valid(rb, &seq, NULL, NULL))
> 		seq++;
>
> 	return seq;
> }

John Ogness

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel