Re: Kernel WARNING at lib/vsprintf.c:2721 while running ftrace kernel selftests

[Sachin Sant <sachinp@linux.ibm.com>]

> On 27-Feb-2024, at 9:54 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> On Tue, 27 Feb 2024 21:38:57 +0530
> Sachin Sant <sachinp@linux.ibm.com> wrote:
> 
>> This warning was not triggered.
> 
> Interesting.
> 
>> 
>> I have attached .config
> 
> This is what I was looking for:
> 
>> # CONFIG_PPC_4K_PAGES is not set
>> CONFIG_PPC_64K_PAGES=y
>> CONFIG_PAGE_SIZE_64KB=y
>> CONFIG_PPC_PAGE_SHIFT=16
> 
> So the pages are 64K in size. I wonder if this is causing an issue.
> 
> Can you apply this, and see if it triggers and if it does, print the line
> that has the max size?
> 

With this I see following trace

[   61.327138] ------------[ cut here ]------------
[   61.327159] MAX OUT OF RANGE 63492
[   61.327167] WARNING: CPU: 1 PID: 5180 at kernel/trace/trace_output.c:1592 trace_print_print+0xf4/0x114
[   61.327178] Modules linked in: rpadlpar_io(E) rpaphp(E) xsk_diag(E) nft_fib_inet(E) nft_fib_ipv4(E) nft_fib_ipv6(E) nft_fib(E) nft_reject_inet(E) nf_reject_ipv4(E) nf_reject_ipv6(E) nft_reject(E) nft_ct(E) nft_chain_nat(E) nf_nat(E) nf_conntrack(E) nf_defrag_ipv6(E) nf_defrag_ipv4(E) bonding(E) tls(E) rfkill(E) ip_set(E) nf_tables(E) nfnetlink(E) sunrpc(E) binfmt_misc(E) pseries_rng(E) aes_gcm_p10_crypto(E) drm(E) drm_panel_orientation_quirks(E) xfs(E) libcrc32c(E) sd_mod(E) sr_mod(E) t10_pi(E) crc64_rocksoft_generic(E) cdrom(E) crc64_rocksoft(E) crc64(E) sg(E) ibmvscsi(E) scsi_transport_srp(E) ibmveth(E) vmx_crypto(E) fuse(E)
[   61.327232] CPU: 1 PID: 5180 Comm: awk Kdump: loaded Tainted: G            E      6.8.0-rc5-00329-gab0a97cffa0b-dirty #37
[   61.327238] Hardware name: IBM,9080-HEX POWER10 (raw) 0x800200 0xf000006 of:IBM,FW1060.00 (NH1060_018) hv:phyp pSeries
[   61.327243] NIP:  c00000000032eb7c LR: c00000000032eb78 CTR: 0000000000000000
[   61.327247] REGS: c0000000505cf730 TRAP: 0700   Tainted: G            E       (6.8.0-rc5-00329-gab0a97cffa0b-dirty)
[   61.327253] MSR:  8000000002029033 <SF,VEC,EE,ME,IR,DR,RI,LE>  CR: 48008202  XER: 00000005
[   61.327263] CFAR: c000000000161e7c IRQMASK: 0 
[   61.327263] GPR00: c00000000032eb78 c0000000505cf9d0 c000000001502700 0000000000000016 
[   61.327263] GPR04: 0000000000000000 c0000000505cf7e0 c0000000505cf7d8 00000003bd8c0000 
[   61.327263] GPR08: 0000000000000027 c0000003bfa58110 0000000000000001 0000000000000001 
[   61.327263] GPR12: 0000000000000000 c0000003bffff300 0000000000000000 0000000000000000 
[   61.327263] GPR16: 0000000000000000 0000000000000000 0000000000000000 c000000090080000 
[   61.327263] GPR20: 000000000000064c 0000000000400cc0 c00000005e7377c0 c000000002a6ed98 
[   61.327263] GPR24: c0000000900c0000 c0000000900a0190 c000000009d50008 0000000003b54601 
[   61.327263] GPR28: c000000002a711a8 c0000000900c0000 000000000000f804 0000000000000002 
[   61.327307] NIP [c00000000032eb7c] trace_print_print+0xf4/0x114
[   61.327312] LR [c00000000032eb78] trace_print_print+0xf0/0x114
[   61.327317] Call Trace:
[   61.327319] [c0000000505cf9d0] [c00000000032eb78] trace_print_print+0xf0/0x114 (unreliable)
[   61.327325] [c0000000505cfa50] [c00000000031832c] print_trace_fmt+0x13c/0x26c
[   61.327331] [c0000000505cfb00] [c000000000328488] s_show+0x5c/0x2cc
[   61.327335] [c0000000505cfb90] [c000000000608e88] seq_read_iter+0x500/0x69c
[   61.327342] [c0000000505cfc70] [c000000000609128] seq_read+0x104/0x15c
[   61.327348] [c0000000505cfd10] [c0000000005bf79c] vfs_read+0xdc/0x390
[   61.327353] [c0000000505cfdc0] [c0000000005c076c] ksys_read+0x84/0x144
[   61.327358] [c0000000505cfe10] [c000000000033328] system_call_exception+0x138/0x330
[   61.327365] [c0000000505cfe50] [c00000000000d05c] system_call_vectored_common+0x15c/0x2ec
[   61.327372] --- interrupt: 3000 at 0x7fff97933c74
[   61.327376] NIP:  00007fff97933c74 LR: 00007fff97933c74 CTR: 0000000000000000
[   61.327381] REGS: c0000000505cfe80 TRAP: 3000   Tainted: G            E       (6.8.0-rc5-00329-gab0a97cffa0b-dirty)
[   61.327386] MSR:  800000000000f033 <SF,EE,PR,FP,ME,IR,DR,RI,LE>  CR: 44008408  XER: 00000000
[   61.327395] IRQMASK: 0 
[   61.327395] GPR00: 0000000000000003 00007fffe9723220 0000000106787e00 0000000000000003 
[   61.327395] GPR04: 000000012f0e8150 0000000000010000 fffffffffffffff5 000000000012f0e5 
[   61.327395] GPR08: 0000000000000001 0000000000000000 0000000000000000 0000000000000000 
[   61.327395] GPR12: 0000000000000000 00007fff97f4c940 000000012f0c5a40 00007fffe97236d8 
[   61.327395] GPR16: 000000012f0e3320 000000012f0d3a28 000000012f0e30f0 0000000000000001 
[   61.327395] GPR20: 8000000000000001 0000000000000001 00000000000005d6 00007fffe9723447 
[   61.327395] GPR24: 00007fffe9723448 00007fffe9723448 00007fffe97233a0 0000000000000000 
[   61.327395] GPR28: 00000001066e466c 0000000000000000 00007fffe9723398 000000012f0e8030 
[   61.327437] NIP [00007fff97933c74] 0x7fff97933c74
[   61.327440] LR [00007fff97933c74] 0x7fff97933c74
[   61.327443] --- interrupt: 3000
[   61.327445] Code: 2c090000 4082ffd4 7c0802a6 3c62ffe4 39200001 3d420160 7fc407b4 38635608 992a493c f8010090 4be33281 60000000 <0fe00000> e8010090 38210080 7be30020 
[   61.327459] ---[ end trace 0000000000000000 ]—

Thanks
— Sachin