Created attachment 303941 [details]
kernel 5.17.11 dmesg

Created attachment 303942 [details]
kernel 6.2.5 dmesg

Created attachment 303943 [details]
kernel 6.2.6 dmesg (same as OP)

(switched to email.  Please respond via emailed reply-to-all, not via the
bugzilla web interface).

On Tue, 14 Mar 2023 05:23:31 +0000 bugzilla-daemon@kernel.org wrote:

> https://bugzilla.kernel.org/show_bug.cgi?id=217191
> 
>             Bug ID: 217191
>            Summary: test_meminit: failures: 70 out of 130 / reference
>                     already released.

Alexander, could you please take a look?  Thanks.

>            Product: Memory Management
>            Version: 2.5
>     Kernel Version: 6.2.6, 6.2.5, 5.17.11
>           Hardware: All
>                 OS: Linux
>               Tree: Mainline
>             Status: NEW
>           Severity: normal
>           Priority: P1
>          Component: Other
>           Assignee: akpm@linux-foundation.org
>           Reporter: correabuscar+kernAlbugs@gmail.com
>         Regression: No
> 
> With CONFIG_TEST_MEMINIT=y (at least), looks like this has been happening
> since, at least 5.17.11 kernel, on Gentoo, and I've only noticed it since
> 6.2.5
> and now on 6.2.6 kernel as well.
> 
> I've some logs saved from previous kernels, if needed.
> 
> ```
> [    0.000000] Linux version 6.2.6-gentoo-x86_64 (_kernelbuilder@i87k) (gcc
> (Gentoo 12.2.1_p20230304 p13) 12.2.1 20230304, GNU ld (Gentoo 2.40 p3)
> 2.40.0)
> #1 SMP Tue Mar 14 05:47:58 CET 2023
> ...
> [   25.431948] test_uuid: all 18 tests passed
> [   25.432064] test_memcat_p: test passed
> [   25.435701] test_meminit: test_pages failed 10 out of 10 times
> [   25.437724] test_meminit: test_kvmalloc failed 40 out of 40 times
> [   25.447595] test_meminit: test_kmemcache failed 20 out of 70 times
> [   25.447797] test_meminit: all 10 tests in test_rcu_persistent passed
> [   25.447912] test_meminit: failures: 70 out of 130
> [   25.448044] reference already released.
> [   25.448153] allocated in:
> [   25.448260]  test_ref_tracker_init+0xa6/0x1e0
> [   25.448374]  do_one_initcall+0xb1/0x210
> [   25.448485]  kernel_init_freeable+0x197/0x250
> [   25.448597]  kernel_init+0x11/0x1d0
> [   25.448708]  ret_from_fork+0x1f/0x30
> [   25.448818] freed in:
> [   25.448925]  test_ref_tracker_init+0x185/0x1e0
> [   25.449885]  do_one_initcall+0xb1/0x210
> [   25.449885]  kernel_init_freeable+0x197/0x250
> [   25.449885]  kernel_init+0x11/0x1d0
> [   25.449885]  ret_from_fork+0x1f/0x30
> [   25.451220] ------------[ cut here ]------------
> [   25.451331] WARNING: CPU: 2 PID: 1 at lib/ref_tracker.c:136
> ref_tracker_free+0x233/0x2a0
> [   25.451464] Modules linked in:
> [   25.451572] CPU: 2 PID: 1 Comm: swapper/0 Tainted: G     U          TN
> 6.2.6-gentoo-x86_64 #1 644473e507c86b163c18e9f84729e44d3514c8d0
> [   25.451710] Hardware name: System manufacturer System Product Name/PRIME
> Z370-A, BIOS 3004 07/12/2021
> [   25.451843] RIP: 0010:ref_tracker_free+0x233/0x2a0
> [   25.451956] Code: e9 71 ff ff ff 48 c7 c7 e8 88 d7 9b e8 96 3d a5 ff 8b 55
> 14 85 d2 75 51 8b 45 18 85 c0 75 34 4c 89 e6 48 89 df e8 6d e7 b2 00 <0f> 0b
> b8
> ea ff ff ff e9 42 ff ff ff 48 8d 7b 08 b8 ff ff ff ff f0
> [   25.452119] RSP: 0000:ffffb4c68000bdf8 EFLAGS: 00010246
> [   25.452232] RAX: 0000000000000000 RBX: ffffffff9d200ee0 RCX:
> 0000000000000000
> [   25.452361] RDX: 0000000000000000 RSI: 0000000000000000 RDI:
> 0000000000000000
> [   25.452490] RBP: ffff9ac5c0989900 R08: 0000000000000000 R09:
> 0000000000000000
> [   25.452618] R10: 0000000000000000 R11: 0000000000000000 R12:
> 0000000000000246
> [   25.452747] R13: 0000000004500000 R14: 0000000000000000 R15:
> 0000000000000000
> [   25.452876] FS:  0000000000000000(0000) GS:ffff9ad51a280000(0000)
> knlGS:0000000000000000
> [   25.453006] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [   25.453119] CR2: 0000000000000000 CR3: 000000040200b001 CR4:
> 00000000003706e0
> [   25.453258] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
> 0000000000000000
> [   25.453387] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7:
> 0000000000000400
> [   25.453515] Call Trace:
> [   25.453622]  <TASK>
> [   25.453729]  ? test_ref_tracker_init+0x19a/0x1e0
> [   25.453841]  ? do_one_initcall+0xb1/0x210
> [   25.453952]  ? kernel_init_freeable+0x197/0x250
> [   25.454065]  ? kernel_init+0x11/0x1d0
> [   25.454175]  ? ret_from_fork+0x1f/0x30
> [   25.454285]  ? test_meminit_init+0x940/0x940
> [   25.454396]  test_ref_tracker_init+0x19a/0x1e0
> [   25.454508]  do_one_initcall+0xb1/0x210
> [   25.454619]  kernel_init_freeable+0x197/0x250
> [   25.454731]  ? rest_init+0xa0/0xa0
> [   25.454841]  kernel_init+0x11/0x1d0
> [   25.454952]  ret_from_fork+0x1f/0x30
> [   25.455062]  </TASK>
> [   25.455169] ---[ end trace 0000000000000000 ]---
> [   25.455281] leaked reference.
> [   25.455389]  test_ref_tracker_timer_func+0x18/0x30
> [   25.455502]  call_timer_fn.constprop.0+0xe/0x80
> [   25.455614]  __run_timers+0x22b/0x270
> [   25.455724]  run_timer_softirq+0x14/0x30
> [   25.455835]  __do_softirq+0xb9/0x210
> [   25.455945] leaked reference.
> [   25.456053]  test_ref_tracker_init+0x9a/0x1e0
> [   25.456165]  do_one_initcall+0xb1/0x210
> [   25.456275]  kernel_init_freeable+0x197/0x250
> [   25.456386]  kernel_init+0x11/0x1d0
> [   25.456496]  ret_from_fork+0x1f/0x30
> [   25.456610] ------------[ cut here ]------------
> [   25.456721] WARNING: CPU: 2 PID: 1 at lib/ref_tracker.c:39
> ref_tracker_dir_exit+0x110/0x180
> [   25.456854] Modules linked in:
> [   25.456962] CPU: 2 PID: 1 Comm: swapper/0 Tainted: G     U  W       TN
> 6.2.6-gentoo-x86_64 #1 644473e507c86b163c18e9f84729e44d3514c8d0
> [   25.457101] Hardware name: System manufacturer System Product Name/PRIME
> Z370-A, BIOS 3004 07/12/2021
> [   25.457233] RIP: 0010:ref_tracker_dir_exit+0x110/0x180
> [   25.457347] Code: 48 89 c5 48 c7 c7 a3 88 d7 9b e8 3b 40 a5 ff 41 8b 7e 14
> 85 ff 74 a7 e8 8e fd ff ff eb a0 48 8b 34 24 48 89 df e8 10 ea b2 00 <0f> 0b
> 8b
> 43 08 83 f8 01 75 35 8b 43 0c 83 f8 01 75 37 48 83 c4 08
> [   25.457509] RSP: 0000:ffffb4c68000be70 EFLAGS: 00010246
> [   25.457622] RAX: ffffffff9d200ef8 RBX: ffffffff9d200ee0 RCX:
> 0000000000000000
> [   25.457751] RDX: 0000000000000000 RSI: 0000000000000000 RDI:
> 0000000000000000
> [   25.457880] RBP: ffffffff9d200ef8 R08: 0000000000000000 R09:
> 0000000000000000
> [   25.458008] R10: 0000000000000000 R11: 0000000000000000 R12:
> ffffffff9d200ef8
> [   25.458136] R13: ffffffff9d200ef8 R14: ffffffff9d200ef8 R15:
> dead000000000100
> [   25.458265] FS:  0000000000000000(0000) GS:ffff9ad51a280000(0000)
> knlGS:0000000000000000
> [   25.458396] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [   25.458509] CR2: 0000000000000000 CR3: 000000040200b001 CR4:
> 00000000003706e0
> [   25.458637] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
> 0000000000000000
> [   25.458766] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7:
> 0000000000000400
> [   25.458894] Call Trace:
> [   25.459001]  <TASK>
> [   25.459108]  ? test_meminit_init+0x940/0x940
> [   25.459220]  test_ref_tracker_init+0x1c4/0x1e0
> [   25.459332]  do_one_initcall+0xb1/0x210
> [   25.459442]  kernel_init_freeable+0x197/0x250
> [   25.459554]  ? rest_init+0xa0/0xa0
> [   25.459664]  kernel_init+0x11/0x1d0
> [   25.459774]  ret_from_fork+0x1f/0x30
> [   25.459886]  </TASK>
> [   25.459992] ---[ end trace 0000000000000000 ]---
> [   25.460106] test_div64: Starting 64bit/32bit division and modulo test
> [   25.460858] test_div64: Completed 64bit/32bit division and modulo test,
> 0.000637198s elapsed
> [   25.461843] crc32: CRC_LE_BITS = 64, CRC_BE BITS = 64
> [   25.461955] crc32: self tests passed, processed 225944 bytes in 108224
> nsec
> [   25.462193] crc32c: CRC_LE_BITS = 64
> [   25.462302] crc32c: self tests passed, processed 112972 bytes in 54045
> nsec
> [   25.471308] crc32_combine: 8373 self tests passed
> [   25.480294] crc32c_combine: 8373 self tests passed
> [   25.480908] atomic64_test: passed for x86-64 platform with CX8 and with
> SSE
> [   25.481038] interval tree insert/remove
> [   25.483347]  -> 8535 cycles
> [   25.483564] interval tree search
> [   25.500073]  -> 61061 cycles (2692 results)
> [   25.500346] pciehp: pcie_port_service_register = 0
> ```
> 
> -- 
> You may reply to this email to add a comment.
> 
> You are receiving this mail because:
> You are the assignee for the bug.

Created attachment 303952 [details]
attachment-20554-0.html

Hi Emmanuel,

Can you please share the kernel config where the problem is reproducible,
along with the full dmesg?

I think "test_meminit: failures: 70 out of 130" is a red herring, the
kernel probably does not enable memory initialization, that's why the tests
are failing.
We could see that from the "mem auto-init" line in the dmesg, but it got
stripped away.
The leaked reference probably belongs to lib/test_ref_tracker.c, which is a
completely different test suite.

Created attachment 303954 [details]
626.config

On Wed, Mar 15, 2023 at 2:58 PM Alexander Potapenko <glider@google.com>
wrote:

> Hi Emmanuel,
>
> hello, thank you for looking into this.

> Can you please share the kernel config where the problem is reproducible,
> along with the full dmesg?
>
attached both

>
> I think "test_meminit: failures: 70 out of 130" is a red herring, the
> kernel probably does not enable memory initialization, that's why the tests
> are failing.
> We could see that from the "mem auto-init" line in the dmesg, but it got
> stripped away.
> The leaked reference probably belongs to lib/test_ref_tracker.c, which is
> a completely different test suite.
>

Created attachment 303955 [details]
dmesg626.log

and of course, I forgot to switch to the already-added-in-gmail alias-email-address(the one that I've used here in bugzilla) before sending the above email, thus the real/original email address got leaked above...

Created attachment 303956 [details]
attachment-15654-0.html

On Wed, Mar 15, 2023 at 6:22 PM Emanuel Attila Czirai <
corre.a.buscar@gmail.com> wrote:

>
>
> On Wed, Mar 15, 2023 at 2:58 PM Alexander Potapenko <glider@google.com>
> wrote:
>
>> Hi Emmanuel,
>>
>> hello, thank you for looking into this.
>
>> Can you please share the kernel config where the problem is reproducible,
>> along with the full dmesg?
>>
> attached both
>
>>
>>
>>
Ok, so according to your dmesg, heap initialization is disabled:
  mem auto-init: stack:all(zero), heap alloc:off, heap free:off
, which causes the test failures.

The warnings indeed originate from CONFIG_TEST_REF_TRACKER=y, and seem to
be yielding the desired output for that test (ccing Eric who wrote it).
Perhaps that test could print something about its expectations to dmesg,
but anyway there's nothing to fix in the kernel.

May I ask what is the purpose of the config in question?

Created attachment 303963 [details]
626_heap_init.config

On Wed, Mar 15, 2023 at 6:47 PM Alexander Potapenko <glider@google.com>
wrote:

>
>
> On Wed, Mar 15, 2023 at 6:22 PM Emanuel Attila Czirai <
> corre.a.buscar@gmail.com> wrote:
>
>>
>>
>> On Wed, Mar 15, 2023 at 2:58 PM Alexander Potapenko <glider@google.com>
>> wrote:
>>
>>> Hi Emmanuel,
>>>
>>> hello, thank you for looking into this.
>>
>>> Can you please share the kernel config where the problem is
>>> reproducible, along with the full dmesg?
>>>
>> attached both
>>
>>>
>>>
>>>
> Ok, so according to your dmesg, heap initialization is disabled:
>   mem auto-init: stack:all(zero), heap alloc:off, heap free:off
> , which causes the test failures.
>
Looks like I've set page_poison=1 which is why I've also set init_on_free=0
init_on_alloc=0 otherwise they're considered to be =0 due to the former
being 1, as per:
[ 22.533779] mem auto-init: CONFIG_PAGE_POISONING is on, will take
precedence over init_on_alloc and init_on_free
[ 22.535704] mem auto-init: stack:all(zero), heap alloc:off, heap free:off
^ that's dmesg when i try them all =1

However if I do enable heap initialization by /proc/cmdline having:
page_poison=0 init_on_free=1 init_on_alloc=1
then:
[ 25.467867] test_meminit: all 130 tests passed!
(attached dmesg for this case)

and the ref_tracker issue remains, but as you've said below, it's expected
to give that output as if to show that it's able to "track" the reference
properly, and it makes sense to me now. I'll do CONFIG_TEST_REF_TRACKER=n
and make a note about it.


> The warnings indeed originate from CONFIG_TEST_REF_TRACKER=y, and seem to
> be yielding the desired output for that test (ccing Eric who wrote it).
> Perhaps that test could print something about its expectations to dmesg,
> but anyway there's nothing to fix in the kernel.
>
Alright, thank you for taking a look at this. I didn't realize there were
two unrelated issues here.


> May I ask what is the purpose of the config in question?
>
it's what I use on my home desktop PC(but merged the laptop .config into
it, didn't have the time to test it on laptop so far yet) and I've enabled
all tests to catch things early in the hopes of avoiding some potential
btrfs filesystem corruption(for a third time, so far) if nothing else...
but otherwise it'd be just reassuring to know that things are performing
within their expected parameters (with tests passing and all). I don't
remember why I've tried to keep modules at a minimum though.

Best regards!

Comment on attachment 303963 [details]
626_heap_init.config

re 626_heap_init.config 

this .config should be .log, as it's dmesg, not .config
I've named it wrong(ly).

Created attachment 303964 [details]
renamed to .log as it's dmesg when heap init is on

Created attachment 303967 [details]
attachment-10690-0.html

>
>
>
>
>> May I ask what is the purpose of the config in question?
>>
> it's what I use on my home desktop PC(but merged the laptop .config into
> it, didn't have the time to test it on laptop so far yet) and I've enabled
> all tests to catch things early in the hopes of avoiding some potential
> btrfs filesystem corruption(for a third time, so far) if nothing else...
> but otherwise it'd be just reassuring to know that things are performing
> within their expected parameters (with tests passing and all). I don't
> remember why I've tried to keep modules at a minimum though.
>

I see, thanks for the explanation.
I think many tests in lib/ may produce strange warnings that are meant to
be parsed by human devs that know what to expect.
It would be nice to have them converted to KUNIT, but that's a long way to
go.