Re: [tracing] 06e0a548ba: WARNING:at_kernel/trace/ring_buffer.c:#ring_buffer_iter_peek

[Sven Schnelle]

Hi Steve,

On Wed, Apr 29, 2020 at 05:05:09PM +0800, kernel test robot wrote:
> 
> kern  :warn  : [  886.763510] WARNING: CPU: 70 PID: 22584 at kernel/trace/ring_buffer.c:4067 ring_buffer_iter_peek+0x13c/0x1d0
> kern  :warn  : [  886.776216] Modules linked in: test_firmware intel_rapl_msr intel_rapl_common skx_edac nfit libnvdimm btrfs x86_pkg_temp_thermal intel_powerclamp blake2b_generic xor zstd_decompress zstd_compress coretemp ast kvm_intel kvm raid6_pq drm_vram_helper drm_ttm_helper libcrc32c irqbypass ttm crct10dif_pclmul crc32_pclmul drm_kms_helper snd_pcm crc32c_intel ghash_clmulni_intel ahci snd_timer syscopyarea libahci aesni_intel ipmi_ssif sysfillrect snd crypto_simd sysimgblt cryptd nvme fb_sys_fops mei_me soundcore ipmi_si glue_helper pcspkr drm nvme_core ioatdma ipmi_devintf t10_pi libata mei i2c_i801 joydev lpc_ich dca ipmi_msghandler wmi acpi_pad acpi_power_meter ip_tables
> kern  :warn  : [  886.838112] CPU: 70 PID: 22584 Comm: cat Not tainted 5.6.0-rc4-00017-g06e0a548bad0f #1
> kern  :warn  : [  886.846573] RIP: 0010:ring_buffer_iter_peek+0x13c/0x1d0
> kern  :warn  : [  886.852355] Code: 41 5e 41 5f c3 83 38 1d 0f 85 98 00 00 00 48 89 df e8 78 cb ff ff e9 32 ff ff ff 80 3c 24 00 75 c8 49 8b 44 24 10 f0 ff 40 08 <0f> 0b 4c 89 f6 4c 89 ef e8 37 8c 8f 00 48 83 c4 08 31 c0 5b 5d 41
> kern  :warn  : [  886.872239] RSP: 0018:ffffc900213e7d78 EFLAGS: 00010002
> kern  :warn  : [  886.878030] RAX: ffff889883ea7740 RBX: ffff88a3fbd93720 RCX: ffff88a42101b700
> kern  :warn  : [  886.885731] RDX: ffff88a415c02e00 RSI: ffff88a42101b440 RDI: ffff88a3fbd93720
> kern  :warn  : [  886.893432] RBP: 0000000000000000 R08: 000000ce959ae6ab R09: ffff88a42101bb80
> kern  :warn  : [  886.901129] R10: ffff88a3e99e2300 R11: 0000000000000178 R12: ffff88a415c02e00
> kern  :warn  : [  886.908831] R13: ffff88a415c02e18 R14: 0000000000000296 R15: ffffc900213e7df8
> kern  :warn  : [  886.916521] FS:  00007f12d51d2640(0000) GS:ffff88a44f780000(0000) knlGS:0000000000000000
> kern  :warn  : [  886.925179] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> kern  :warn  : [  886.931495] CR2: 00007f12d4e36000 CR3: 00000023e901e006 CR4: 00000000007606e0
> kern  :warn  : [  886.939194] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> kern  :warn  : [  886.946896] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> kern  :warn  : [  886.954588] PKRU: 55555554
> kern  :warn  : [  886.957858] Call Trace:
> kern  :warn  : [  886.960866]  peek_next_entry+0x22/0x70
> kern  :warn  : [  886.965165]  __find_next_entry+0xaf/0x180
> kern  :warn  : [  886.969714]  trace_find_next_entry_inc+0x1e/0x80
> kern  :warn  : [  886.974863]  s_next+0x49/0x70
> kern  :warn  : [  886.978355]  seq_read+0x23f/0x400
> kern  :warn  : [  886.982193]  vfs_read+0x9b/0x160
> kern  :warn  : [  886.985937]  ksys_read+0xa1/0xe0
> kern  :warn  : [  886.989677]  do_syscall_64+0x5b/0x1f0
> kern  :warn  : [  886.993853]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
> kern  :warn  : [  886.999408] RIP: 0033:0x7f12d50f559e
> kern  :warn  : [  887.003479] Code: c0 e9 c6 fe ff ff 50 48 8d 3d 36 fc 09 00 e8 e9 e7 01 00 66 0f 1f 84 00 00 00 00 00 64 8b 04 25 18 00 00 00 85 c0 75 14 0f 05 <48> 3d 00 f0 ff ff 77 5a c3 66 0f 1f 84 00 00 00 00 00 48 83 ec 28
> kern  :warn  : [  887.023260] RSP: 002b:00007ffdab31acd8 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
> kern  :warn  : [  887.031350] RAX: ffffffffffffffda RBX: 0000000000020000 RCX: 00007f12d50f559e
> kern  :warn  : [  887.039006] RDX: 0000000000020000 RSI: 00007f12d4e36000 RDI: 0000000000000005
> kern  :warn  : [  887.046657] RBP: 00007f12d4e36000 R08: 00007f12d4e35010 R09: 0000000000000000
> kern  :warn  : [  887.054305] R10: fffffffffffffc4d R11: 0000000000000246 R12: 00007f12d4e36000
> kern  :warn  : [  887.061958] R13: 0000000000000005 R14: 0000000000020000 R15: 0000000000000f93
> kern  :warn  : [  887.069608] ---[ end trace 507492ef8332a5b4 ]---
> 

Did you had a chance to look into this? I can easily reproduce this both on x86
and s390 by doing:

cd /sys/kernel/tracing
cat /dev/zero >/dev/null & # generate some load
echo function >current_tracer
# wait a few seconds to fill the buffer
cat trace

Usually it will print the warn after a few seconds.

I haven't digged through all the ring buffer code yet, so i thought i might ask
whether you have an idea what's going on.

Thanks
Sven