Use the record extending feature of the ringbuffer to implement
continuous messages. This preserves the existing continuous message
behavior.
Signed-off-by: John Ogness <[email protected]>
Reviewed-by: Petr Mladek <[email protected]>
---
kernel/printk/printk.c | 98 +++++++++---------------------------------
1 file changed, 20 insertions(+), 78 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 964b5701688f..9a2e23191576 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -535,7 +535,10 @@ static int log_store(u32 caller_id, int facility, int level,
r.info->caller_id = caller_id;
/* insert message */
- prb_commit(&e);
+ if ((flags & LOG_CONT) || !(flags & LOG_NEWLINE))
+ prb_commit(&e);
+ else
+ prb_final_commit(&e);
return (text_len + trunc_msg_len);
}
@@ -1084,7 +1087,7 @@ static unsigned int __init add_to_rb(struct printk_ringbuffer *rb,
dest_r.info->ts_nsec = r->info->ts_nsec;
dest_r.info->caller_id = r->info->caller_id;
- prb_commit(&e);
+ prb_final_commit(&e);
return prb_record_text_space(&e);
}
@@ -1884,87 +1887,26 @@ static inline u32 printk_caller_id(void)
0x80000000 + raw_smp_processor_id();
}
-/*
- * Continuation lines are buffered, and not committed to the record buffer
- * until the line is complete, or a race forces it. The line fragments
- * though, are printed immediately to the consoles to ensure everything has
- * reached the console in case of a kernel crash.
- */
-static struct cont {
- char buf[LOG_LINE_MAX];
- size_t len; /* length == 0 means unused buffer */
- u32 caller_id; /* printk_caller_id() of first print */
- u64 ts_nsec; /* time of first print */
- u8 level; /* log level of first message */
- u8 facility; /* log facility of first message */
- enum log_flags flags; /* prefix, newline flags */
-} cont;
-
-static void cont_flush(void)
-{
- if (cont.len == 0)
- return;
-
- log_store(cont.caller_id, cont.facility, cont.level, cont.flags,
- cont.ts_nsec, NULL, 0, cont.buf, cont.len);
- cont.len = 0;
-}
-
-static bool cont_add(u32 caller_id, int facility, int level,
- enum log_flags flags, const char *text, size_t len)
-{
- /* If the line gets too long, split it up in separate records. */
- if (cont.len + len > sizeof(cont.buf)) {
- cont_flush();
- return false;
- }
-
- if (!cont.len) {
- cont.facility = facility;
- cont.level = level;
- cont.caller_id = caller_id;
- cont.ts_nsec = local_clock();
- cont.flags = flags;
- }
-
- memcpy(cont.buf + cont.len, text, len);
- cont.len += len;
-
- // The original flags come from the first line,
- // but later continuations can add a newline.
- if (flags & LOG_NEWLINE) {
- cont.flags |= LOG_NEWLINE;
- cont_flush();
- }
-
- return true;
-}
-
static size_t log_output(int facility, int level, enum log_flags lflags, const char *dict, size_t dictlen, char *text, size_t text_len)
{
const u32 caller_id = printk_caller_id();
- /*
- * If an earlier line was buffered, and we're a continuation
- * write from the same context, try to add it to the buffer.
- */
- if (cont.len) {
- if (cont.caller_id == caller_id && (lflags & LOG_CONT)) {
- if (cont_add(caller_id, facility, level, lflags, text, text_len))
- return text_len;
- }
- /* Otherwise, make sure it's flushed */
- cont_flush();
- }
-
- /* Skip empty continuation lines that couldn't be added - they just flush */
- if (!text_len && (lflags & LOG_CONT))
- return 0;
-
- /* If it doesn't end in a newline, try to buffer the current line */
- if (!(lflags & LOG_NEWLINE)) {
- if (cont_add(caller_id, facility, level, lflags, text, text_len))
+ if (lflags & LOG_CONT) {
+ struct prb_reserved_entry e;
+ struct printk_record r;
+
+ prb_rec_init_wr(&r, text_len, 0);
+ if (prb_reserve_in_last(&e, prb, &r, caller_id)) {
+ memcpy(&r.text_buf[r.info->text_len], text, text_len);
+ r.info->text_len += text_len;
+ if (lflags & LOG_NEWLINE) {
+ r.info->flags |= LOG_NEWLINE;
+ prb_final_commit(&e);
+ } else {
+ prb_commit(&e);
+ }
return text_len;
+ }
}
/* Store it in the record log */
--
2.20.1
Hi again,
On 25.09.2020 21:08, Marek Szyprowski wrote:
> Hi John,
>
> On 14.09.2020 14:33, John Ogness wrote:
>> Use the record extending feature of the ringbuffer to implement
>> continuous messages. This preserves the existing continuous message
>> behavior.
>>
>> Signed-off-by: John Ogness <[email protected]>
>> Reviewed-by: Petr Mladek <[email protected]>
>
> This patch landed recently in linux-next as commit f5f022e53b87
> ("printk: reimplement log_cont using record extension"). I've noticed
> that it causes a regression on my test system (ARM 32bit Samsung
> Exynos 4412-based Trats2 board). The messages are printed correctly on
> the serial console during boot, but then when I run 'dmesg' command,
> the log is truncated.
>
> Here is are the last lines of the dmesg log after this patch:
>
> [ 6.649018] Waiting 2 sec before mounting root device...
> [ 6.766423] dwc2 12480000.hsotg: new device is high-speed
> [ 6.845290] dwc2 12480000.hsotg: new device is high-speed
> [ 6.914217] dwc2 12480000.hsotg: new address 51
> [ 8.710351] RAMDISK: squashfs filesystem found at block 0
>
> The corresponding dmesg lines before applying this patch:
>
> [ 8.864320] RAMDISK: squashfs filesystem found at block 0
> [ 8.868410] RAMDISK: Loading 37692KiB [1 disk] into ram disk... /
> [ 9.071670] /
> [ 9.262498] /
> [ 9.540711] /
> [ 9.818031] done.
> [ 10.660074] VFS: Mounted root (squashfs filesystem) readonly on
> device 1:0.
> [ 10.739525] EXT4-fs (mmcblk0p1): INFO: recovery required on
> readonly filesystem
> [ 10.745347] EXT4-fs (mmcblk0p1): write access will be enabled
> during recovery
> [ 10.861129] EXT4-fs (mmcblk0p1): recovery complete
> [ 10.878150] EXT4-fs (mmcblk0p1): mounted filesystem with ordered
> data mode. Opts: (null)
> [ 10.881811] VFS: Mounted root (ext4 filesystem) readonly on device
> 179:49.
> [ 10.889858] Trying to move old root to /initrd ...
> [ 10.895192] okay
> [ 10.914411] devtmpfs: mounted
> [ 10.925087] Freeing unused kernel memory: 1024K
> [ 10.933222] Run /sbin/init as init process
> [ 10.941723] with arguments:
> [ 10.949890] /sbin/init
> [ 10.949900] with environment:
> [ 10.949909] HOME=/
> [ 10.949917] TERM=linux
> [ 12.415991] random: systemd-udevd: uninitialized urandom read (16
> bytes read)
> [ 12.425361] random: systemd-udevd: uninitialized urandom read (16
> bytes read)
> [ 12.438578] random: systemd-udevd: uninitialized urandom read (16
> bytes read)
>
> ...
>
> I can provide a complete logs if that helps.
One more information - this issue happens only if the kernel is compiled
from exynos_defconfig. If use multi_v7_defconfig, the dmesg works fine
on that board. exynos_defconfig has quite a lots of debugging options
enabled...
Best regards
--
Marek Szyprowski, PhD
Samsung R&D Institute Poland
Hi John,
On 14.09.2020 14:33, John Ogness wrote:
> Use the record extending feature of the ringbuffer to implement
> continuous messages. This preserves the existing continuous message
> behavior.
>
> Signed-off-by: John Ogness <[email protected]>
> Reviewed-by: Petr Mladek <[email protected]>
This patch landed recently in linux-next as commit f5f022e53b87
("printk: reimplement log_cont using record extension"). I've noticed
that it causes a regression on my test system (ARM 32bit Samsung Exynos
4412-based Trats2 board). The messages are printed correctly on the
serial console during boot, but then when I run 'dmesg' command, the log
is truncated.
Here is are the last lines of the dmesg log after this patch:
[ 6.649018] Waiting 2 sec before mounting root device...
[ 6.766423] dwc2 12480000.hsotg: new device is high-speed
[ 6.845290] dwc2 12480000.hsotg: new device is high-speed
[ 6.914217] dwc2 12480000.hsotg: new address 51
[ 8.710351] RAMDISK: squashfs filesystem found at block 0
The corresponding dmesg lines before applying this patch:
[ 8.864320] RAMDISK: squashfs filesystem found at block 0
[ 8.868410] RAMDISK: Loading 37692KiB [1 disk] into ram disk... /
[ 9.071670] /
[ 9.262498] /
[ 9.540711] /
[ 9.818031] done.
[ 10.660074] VFS: Mounted root (squashfs filesystem) readonly on
device 1:0.
[ 10.739525] EXT4-fs (mmcblk0p1): INFO: recovery required on readonly
filesystem
[ 10.745347] EXT4-fs (mmcblk0p1): write access will be enabled during
recovery
[ 10.861129] EXT4-fs (mmcblk0p1): recovery complete
[ 10.878150] EXT4-fs (mmcblk0p1): mounted filesystem with ordered data
mode. Opts: (null)
[ 10.881811] VFS: Mounted root (ext4 filesystem) readonly on device
179:49.
[ 10.889858] Trying to move old root to /initrd ...
[ 10.895192] okay
[ 10.914411] devtmpfs: mounted
[ 10.925087] Freeing unused kernel memory: 1024K
[ 10.933222] Run /sbin/init as init process
[ 10.941723] with arguments:
[ 10.949890] /sbin/init
[ 10.949900] with environment:
[ 10.949909] HOME=/
[ 10.949917] TERM=linux
[ 12.415991] random: systemd-udevd: uninitialized urandom read (16
bytes read)
[ 12.425361] random: systemd-udevd: uninitialized urandom read (16
bytes read)
[ 12.438578] random: systemd-udevd: uninitialized urandom read (16
bytes read)
...
I can provide a complete logs if that helps.
Best regards
--
Marek Szyprowski, PhD
Samsung R&D Institute Poland
On 2020-09-25, Marek Szyprowski <[email protected]> wrote:
> This patch landed recently in linux-next as commit f5f022e53b87
> ("printk: reimplement log_cont using record extension"). I've noticed
> that it causes a regression on my test system (ARM 32bit Samsung Exynos
> 4412-based Trats2 board). The messages are printed correctly on the
> serial console during boot, but then when I run 'dmesg' command, the log
> is truncated.
>
> Here is are the last lines of the dmesg log after this patch:
>
> [ 6.649018] Waiting 2 sec before mounting root device...
> [ 6.766423] dwc2 12480000.hsotg: new device is high-speed
> [ 6.845290] dwc2 12480000.hsotg: new device is high-speed
> [ 6.914217] dwc2 12480000.hsotg: new address 51
> [ 8.710351] RAMDISK: squashfs filesystem found at block 0
>
> The corresponding dmesg lines before applying this patch:
>
> [ 8.864320] RAMDISK: squashfs filesystem found at block 0
> [ 8.868410] RAMDISK: Loading 37692KiB [1 disk] into ram disk... /
> [ 9.071670] /
> [ 9.262498] /
> [ 9.540711] /
> [ 9.818031] done.
Ah. One of the more creative printk users...
init/do_mounts_rd.c:rd_load_image(). This is a set of LOG_CONT messages
that try to display a rotating line, complete with '\b' control
characters. The code is totally broken, but that is no excuse for printk
to break. It should be easy to reproduce on any architecture. I will
investigate it further. Thanks for reporting.
John Ogness