Re: [PATCH v2 0/2] printk_ringbuffer: don't needlessly wrap data blocks around

Petr Mladek
2025-09-11T15:55:50Z

On Thu 2025-09-11 17:30:36, Petr Mladek wrote:
> On Fri 2025-09-05 17:41:50, Daniil Tatianin wrote:
> > This series fixes the issue where data blocks would wrap in cases where the last
> > data block perfectly fits the ring. This caused whatever was at the beginning of
> > the ring to get discarded in this case, and the data block would get put there
> > even though it could be put at the end of the data ring just fine without
> > discarding anything.
> >
> > Fixing this issue also allows to simplify the check in data_check_size,
> > previously it would ensure there's space for a trailing id, which we
> > don't need anymore.
> >
> > v0->v1:
> > - Fix severely broken code alignment
> >
> > v1->v2:
> > - Rename & invert get_next_lpos -> is_blk_wrapped
> > - Add a new commit for changing the logic in data_check_size
>
> The patchset looks good to me. But I wanted to do some tests
> and it failed. I did the following:
>
> 1. Applied this patchset on top of printk/linux.git, branch for-next,
> https://git.kernel.org/pub/scm/linux/kernel/git/printk/linux.git/log/?h=for-next
>
> I this branch because it contains a new KUnit test for the printk
> ring buffer.

The KUnit test fails even without this patchset, see below.

> 2. I applied the following patch:
>
> + It reduces the size of the data ring. If I count it correctly
> it should be 256 (2 << 8).
>
> + It increases the maximal size of the text so that the maximal
> record size is 256.
>
> 3. I built it with Kasan enabled:
>
> $> grep KASAN .config
> CONFIG_KASAN_SHADOW_OFFSET=0xdffffc0000000000
> CONFIG_HAVE_ARCH_KASAN=y
> CONFIG_HAVE_ARCH_KASAN_VMALLOC=y
> CONFIG_CC_HAS_KASAN_GENERIC=y
> CONFIG_CC_HAS_KASAN_SW_TAGS=y
> CONFIG_KASAN=y
> CONFIG_CC_HAS_KASAN_MEMINTRINSIC_PREFIX=y
> CONFIG_KASAN_GENERIC=y
> # CONFIG_KASAN_OUTLINE is not set
> CONFIG_KASAN_INLINE=y
> CONFIG_KASAN_STACK=y
> CONFIG_KASAN_VMALLOC=y
> # CONFIG_KASAN_KUNIT_TEST is not set
> # CONFIG_KASAN_EXTRA_INFO is not set
>
>
> 4. I loaded the test module:
>
> # depmod
> # modprobe printk_ringbuffer_kunit_test
>
> I am not sure if it is caused by this patchset or

Hmm, the KUnit test fails even after reverting this patchset.
I havn't hit the WARN_ON_ONCE() in get_data() yet.
But the data seem to be corrupted.

This is from two runs:

[ 45.808363] printk_ringbuffer_kunit_test: module verification failed: signature and/or required key missing - tainting kernel
[ 45.820389] KTAP version 1
[ 45.820682] 1..1
[ 45.822088] KTAP version 1
[ 45.822387] # Subtest: printk-ringbuffer
[ 45.822729] # module: printk_ringbuffer_kunit_test
[ 45.822759] 1..1
[ 45.824001] # test_readerwriter: running for 10000 ms
[ 45.825762] # test_readerwriter: start thread 001 (writer)
[ 45.826187] # test_readerwriter: start thread 002 (writer)
[ 45.826607] # test_readerwriter: start thread 003 (writer)
[ 45.826881] # test_readerwriter: start thread 004 (writer)
[ 45.827193] # test_readerwriter: start thread 005 (writer)
[ 45.827512] # test_readerwriter: start thread 006 (writer)
[ 45.827724] # test_readerwriter: start thread 007 (writer)
[ 45.827951] # test_readerwriter: start thread 008 (writer)
[ 45.828200] # test_readerwriter: start thread 009 (writer)
[ 45.828353] # test_readerwriter: start thread 010 (writer)
[ 45.828548] # test_readerwriter: starting test
[ 45.828553] # test_readerwriter: start thread 011 (writer)
[ 45.828575] # test_readerwriter: start reader
[ 45.828662] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=15 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB\x80O\x81\x88\xff\xff
[ 45.835013] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=16 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB\x01
[ 45.837261] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=17 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB\x01
[ 45.837415] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=18 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[ 45.841872] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=19 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[ 45.844515] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=20 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[ 45.844663] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=21 size=1111638594 text=
[ 45.844816] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=22 size=1111638594 text=
[ 45.849842] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=23 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[ 45.849990] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=24 size=1111638594 text=
[ 55.841113] # test_readerwriter: end reader: read=14 seq=28
[ 55.841869] # test_readerwriter: completed test
[ 55.846197] # test_readerwriter: end thread 011: wrote=15338812
[ 55.847027] # test_readerwriter: end thread 010: wrote=13113829
[ 55.847838] # test_readerwriter: end thread 009: wrote=16786746
[ 55.848469] # test_readerwriter: end thread 008: wrote=14555662
[ 55.849240] # test_readerwriter: end thread 007: wrote=13117536
[ 55.849873] # test_readerwriter: end thread 006: wrote=13147885
[ 55.850478] # test_readerwriter: end thread 005: wrote=16799892
[ 55.851085] # test_readerwriter: end thread 004: wrote=14468908
[ 55.851692] # test_readerwriter: end thread 003: wrote=16795798
[ 55.852311] # test_readerwriter: end thread 002: wrote=15430923
[ 55.852918] # test_readerwriter: end thread 001: wrote=13106357
[ 55.853645] # test_readerwriter.speed: slow
[ 55.853681] not ok 1 test_readerwriter
[ 55.854080] not ok 1 printk-ringbuffer
[ 202.098871] KTAP version 1
[ 202.099389] # Subtest: printk-ringbuffer
[ 202.099901] # module: printk_ringbuffer_kunit_test
[ 202.100039] 1..1
[ 202.103458] # test_readerwriter: running for 10000 ms
[ 202.105324] # test_readerwriter: start thread 001 (writer)
[ 202.106870] # test_readerwriter: start thread 002 (writer)
[ 202.107413] # test_readerwriter: start thread 003 (writer)
[ 202.107805] # test_readerwriter: start thread 004 (writer)
[ 202.108256] # test_readerwriter: start thread 005 (writer)
[ 202.108486] # test_readerwriter: start thread 006 (writer)
[ 202.108777] # test_readerwriter: start thread 007 (writer)
[ 202.109017] # test_readerwriter: start thread 008 (writer)
[ 202.109608] # test_readerwriter: start thread 009 (writer)
[ 202.110028] # test_readerwriter: starting test
[ 202.110039] # test_readerwriter: start thread 011 (writer)
[ 202.110054] # test_readerwriter: start reader
[ 202.110138] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=5 size=1111638594 text=
[ 202.110279] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=8 size=1111638594 text=
[ 202.110407] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=9 size=94 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[ 202.110792] # test_readerwriter: start thread 010 (writer)
[ 202.111323] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=10 size=1111638594 text=
[ 202.120582] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=12 size=1111638594 text=
[ 212.257479] # test_readerwriter: end reader: read=12 seq=16
[ 212.258233] # test_readerwriter: completed test
[ 212.259613] # test_readerwriter: end thread 011: wrote=13062252
[ 212.260418] # test_readerwriter: end thread 010: wrote=13059061
[ 212.261766] # test_readerwriter: end thread 009: wrote=16683360
[ 212.262379] # test_readerwriter: end thread 008: wrote=16680568
[ 212.263016] # test_readerwriter: end thread 007: wrote=16687096
[ 212.263644] # test_readerwriter: end thread 006: wrote=16646963
[ 212.264265] # test_readerwriter: end thread 005: wrote=16708452
[ 212.264878] # test_readerwriter: end thread 004: wrote=13065967
[ 212.265531] # test_readerwriter: end thread 003: wrote=13090840
[ 212.266098] # test_readerwriter: end thread 002: wrote=13074259
[ 212.266695] # test_readerwriter: end thread 001: wrote=13083747
[ 212.267471] # test_readerwriter.speed: slow
[ 212.267502] not ok 1 test_readerwriter
[ 212.268136] not ok 1 printk-ringbuffer

It is interesting that it did read the same size=XXX values for
several seq= numbers. It was 1111638594 in two independent runs.

1st run:

BAD RECORD: seq=15 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB\x80O\x81\x88\xff\xff
[ 45.835013] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=16 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB\x01
[ 45.837261] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=17 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB\x01
[ 45.837415] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=18 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[ 45.841872] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=19 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[ 45.844515] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=20 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[ 45.844663] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=21 size=1111638594 text=
[ 45.844816] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=22 size=1111638594 text=
[ 45.849842] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=23 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[ 45.849990] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=24 size=1111638594 text=

2nd run: triggered by: echo 1 > /sys/kernel/debug/kunit/printk-ringbuffer/run

BAD RECORD: seq=5 size=1111638594 text=
[ 202.110279] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=8 size=1111638594 text=
[ 202.110407] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=9 size=94 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[ 202.110792] # test_readerwriter: start thread 010 (writer)
[ 202.111323] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=10 size=1111638594 text=
[ 202.120582] # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
BAD RECORD: seq=12 size=1111638594 text=

Best Regards,
Petr