Greeting,
FYI, we noticed the following commit (built with gcc-9):
commit: 9a6944fee68e25084130386c608c5ac8db487581 ("tracing: Add a verifier to check string pointers for trace events")
https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master
in testcase: ltp
version: ltp-x86_64-14c1f76-1_20210506
with following parameters:
test: tracing
ucode: 0x21
test-description: The LTP testsuite contains a collection of tools for testing the Linux kernel and related features.
test-url: http://linux-test-project.github.io/
on test machine: 4 threads 1 sockets Intel(R) Core(TM) i3-3220 CPU @ 3.30GHz with 8G memory
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <[email protected]>
user :notice: [ 66.505494] INFO: creating /lkp/benchmarks/ltp/output directory
user :notice: [ 66.516773] INFO: creating /lkp/benchmarks/ltp/results directory
user :notice: [ 66.526731] Checking for required user/group ids
user :notice: [ 66.543650] 'nobody' user id and group found.
user :notice: [ 66.552776] 'bin' user id and group found.
user :notice: [ 66.561578] 'daemon' user id and group found.
user :notice: [ 66.569557] Users group found.
user :notice: [ 66.577171] Sys group found.
user :notice: [ 66.585007] Required users/groups exist.
user :notice: [ 66.594540] If some fields are empty or look unusual you may have an old version.
user :notice: [ 66.604091] Compare to the current minimal requirements in Documentation/Changes.
user :notice: [ 66.618481] /etc/os-release
user :notice: [ 66.626798] PRETTY_NAME="Debian GNU/Linux 10 (buster)"
user :notice: [ 66.634219] NAME="Debian GNU/Linux"
user :notice: [ 66.641163] VERSION_ID="10"
user :notice: [ 66.648325] VERSION="10 (buster)"
user :notice: [ 66.655516] VERSION_CODENAME=buster
user :notice: [ 66.661858] ID=debian
user :notice: [ 66.669030] HOME_URL="https://www.debian.org/"
user :notice: [ 66.676713] SUPPORT_URL="https://www.debian.org/support"
user :notice: [ 66.684091] BUG_REPORT_URL="https://bugs.debian.org/"
user :notice: [ 66.695535] uname:
user :notice: [ 66.704982] Linux lkp-ivb-d02 5.12.0-rc3-00014-g9a6944fee68e #1 SMP Fri May 7 16:22:42 CST 2021 x86_64 GNU/Linux
user :notice: [ 66.716804] /proc/cmdline
kern :warn : [ 67.379069] ------------[ cut here ]------------
kern :warn : [ 67.379895] fmt: 'bdi %s: ino=%lu state=%s flags=%s
' current_buffer: ' cat-4413 [001] ...1 67.121270: sys_openat -> 0x4
cat-4413 [001] ...1 67.121270: <user stack trace>
=> <00007f1cb9ad8641>
=> <00007f1cb9a172c8>
=> <00007f1cb9a166df>
=> <000055dce7ed6da1>
cat-4413 [001] ...1 67.121272: sys_exit: NR 257 = 4
cat-4413 [001] ...1 67.121272: <user stack trace>
=> <00007f1cb9ad8641>
=> <00007f1cb9a172c8>
=> <00007f1cb9a166df>
=> <000055dce7ed6da1>
cat-4413 [001] ...1 67.121275: sys_newfstat(fd: 4, statbuf: 7ffcf3dad040)
cat-4413 [001] ...1 67.121276: <user stack trace>
=> <00007f1cb9ad2af3>
=> <00007f1cb9a172c8>
=> <00007f1cb9a166df>
=> <000055dce7ed6da1>
cat-4413 [001] ...1 67.121277: sys_enter: NR 5 (4, 7ffcf3dad040, 7ffcf3dad040, 0, f, 55dce909ca20)
cat-4413 [001] ...1 67.121277: <user stack trace>
=> <00007f1cb9ad
kern :warn : [ 67.379916] WARNING: CPU: 1 PID: 3760 at kernel/trace/trace.c:3731 trace_check_vprintf (kbuild/src/consumer/kernel/trace/trace.c:3731)
kern :warn : [ 67.394939] Modules linked in: netconsole btrfs blake2b_generic xor zstd_compress raid6_pq libcrc32c intel_rapl_msr intel_rapl_common sd_mod x86_pkg_temp_thermal t10_pi sg intel_powerclamp coretemp i915 kvm_intel kvm irqbypass intel_gtt crct10dif_pclmul drm_kms_helper crc32_pclmul crc32c_intel ghash_clmulni_intel syscopyarea rapl sysfillrect ahci sysimgblt fb_sys_fops libahci drm intel_cstate libata intel_uncore ipmi_devintf ipmi_msghandler mei_me joydev mei video ip_tables
kern :warn : [ 67.399156] CPU: 1 PID: 3760 Comm: cat Not tainted 5.12.0-rc3-00014-g9a6944fee68e #1
kern :warn : [ 67.400249] Hardware name: Hewlett-Packard p6-1451cx/2ADA, BIOS 8.15 02/05/2013
kern :warn : [ 67.401365] RIP: 0010:trace_check_vprintf (kbuild/src/consumer/kernel/trace/trace.c:3731)
kern :warn : [ 67.402453] Code: 48 39 c8 72 31 39 c8 74 2d c6 04 0a 00 49 8b 96 b0 20 00 00 48 8b 74 24 10 48 c7 c7 78 32 56 82 44 89 54 24 18 e8 8e d2 9b 00 <0f> 0b 44 8b 54 24 18 e9 9f fe ff ff c6 44 02 ff 00 49 8b 96 b0 20
All code
========
0: 48 39 c8 cmp %rcx,%rax
3: 72 31 jb 0x36
5: 39 c8 cmp %ecx,%eax
7: 74 2d je 0x36
9: c6 04 0a 00 movb $0x0,(%rdx,%rcx,1)
d: 49 8b 96 b0 20 00 00 mov 0x20b0(%r14),%rdx
14: 48 8b 74 24 10 mov 0x10(%rsp),%rsi
19: 48 c7 c7 78 32 56 82 mov $0xffffffff82563278,%rdi
20: 44 89 54 24 18 mov %r10d,0x18(%rsp)
25: e8 8e d2 9b 00 callq 0x9bd2b8
2a:* 0f 0b ud2 <-- trapping instruction
2c: 44 8b 54 24 18 mov 0x18(%rsp),%r10d
31: e9 9f fe ff ff jmpq 0xfffffffffffffed5
36: c6 44 02 ff 00 movb $0x0,-0x1(%rdx,%rax,1)
3b: 49 rex.WB
3c: 8b .byte 0x8b
3d: 96 xchg %eax,%esi
3e: b0 20 mov $0x20,%al
Code starting with the faulting instruction
===========================================
0: 0f 0b ud2
2: 44 8b 54 24 18 mov 0x18(%rsp),%r10d
7: e9 9f fe ff ff jmpq 0xfffffffffffffeab
c: c6 44 02 ff 00 movb $0x0,-0x1(%rdx,%rax,1)
11: 49 rex.WB
12: 8b .byte 0x8b
13: 96 xchg %eax,%esi
14: b0 20 mov $0x20,%al
kern :warn : [ 67.404903] RSP: 0018:ffffc900013c7d38 EFLAGS: 00010282
kern :warn : [ 67.406040] RAX: 0000000000000000 RBX: 0000000000000011 RCX: 0000000000000027
kern :warn : [ 67.407360] RDX: 0000000000000027 RSI: 00000000ffff7fff RDI: ffff88821fa977f8
kern :warn : [ 67.408721] RBP: ffffffff8257bf7e R08: ffff88821fa977f0 R09: ffffc900013c7b50
kern :warn : [ 67.409981] R10: 0000000000000001 R11: 0000000000000001 R12: 0000000000004343
kern :warn : [ 67.411260] R13: ffffffff8257bf6e R14: ffff88820d4bc000 R15: ffff88820d4bd0b0
kern :warn : [ 67.412534] FS: 00007f7ac32aa540(0000) GS:ffff88821fa80000(0000) knlGS:0000000000000000
kern :warn : [ 67.413844] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
kern :warn : [ 67.415055] CR2: 0000000000000001 CR3: 000000021193a005 CR4: 00000000001706e0
kern :warn : [ 67.416323] Call Trace:
kern :warn : [ 67.417564] trace_event_printf (kbuild/src/consumer/kernel/trace/trace_output.c:322)
kern :warn : [ 67.418864] ? trace_print_flags_seq (kbuild/src/consumer/kernel/trace/trace_output.c:99)
kern :warn : [ 67.420198] trace_raw_output_writeback_dirty_inode_template (kbuild/src/consumer/include/trace/events/writeback.h:95 (discriminator 2))
kern :warn : [ 67.421593] print_trace_line (kbuild/src/consumer/kernel/trace/trace.c:4233 kbuild/src/consumer/kernel/trace/trace.c:4398)
kern :warn : [ 67.422908] tracing_read_pipe (kbuild/src/consumer/kernel/trace/trace.c:6601)
kern :warn : [ 67.424211] vfs_read (kbuild/src/consumer/fs/read_write.c:494)
kern :warn : [ 67.425491] ksys_read (kbuild/src/consumer/fs/read_write.c:634)
kern :warn : [ 67.426775] do_syscall_64 (kbuild/src/consumer/arch/x86/entry/common.c:46)
kern :warn : [ 67.428048] entry_SYSCALL_64_after_hwframe (kbuild/src/consumer/arch/x86/entry/entry_64.S:112)
kern :warn : [ 67.429352] RIP: 0033:0x7f7ac31d2461
kern :warn : [ 67.430578] Code: fe ff ff 50 48 8d 3d fe d0 09 00 e8 e9 03 02 00 66 0f 1f 84 00 00 00 00 00 48 8d 05 99 62 0d 00 8b 00 85 c0 75 13 31 c0 0f 05 <48> 3d 00 f0 ff ff 77 57 c3 66 0f 1f 44 00 00 41 54 49 89 d4 55 48
All code
========
0: fe (bad)
1: ff (bad)
2: ff 50 48 callq *0x48(%rax)
5: 8d 3d fe d0 09 00 lea 0x9d0fe(%rip),%edi # 0x9d109
b: e8 e9 03 02 00 callq 0x203f9
10: 66 0f 1f 84 00 00 00 nopw 0x0(%rax,%rax,1)
17: 00 00
19: 48 8d 05 99 62 0d 00 lea 0xd6299(%rip),%rax # 0xd62b9
20: 8b 00 mov (%rax),%eax
22: 85 c0 test %eax,%eax
24: 75 13 jne 0x39
26: 31 c0 xor %eax,%eax
28: 0f 05 syscall
2a:* 48 3d 00 f0 ff ff cmp $0xfffffffffffff000,%rax <-- trapping instruction
30: 77 57 ja 0x89
32: c3 retq
33: 66 0f 1f 44 00 00 nopw 0x0(%rax,%rax,1)
39: 41 54 push %r12
3b: 49 89 d4 mov %rdx,%r12
3e: 55 push %rbp
3f: 48 rex.W
Code starting with the faulting instruction
===========================================
0: 48 3d 00 f0 ff ff cmp $0xfffffffffffff000,%rax
6: 77 57 ja 0x5f
8: c3 retq
9: 66 0f 1f 44 00 00 nopw 0x0(%rax,%rax,1)
f: 41 54 push %r12
11: 49 89 d4 mov %rdx,%r12
14: 55 push %rbp
15: 48 rex.W
kern :warn : [ 67.433466] RSP: 002b:00007fff53c43788 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
kern :warn : [ 67.434862] RAX: ffffffffffffffda RBX: 0000000000020000 RCX: 00007f7ac31d2461
kern :warn : [ 67.436248] RDX: 0000000000020000 RSI: 00007f7ac2f1f000 RDI: 0000000000000004
kern :warn : [ 67.437690] RBP: 00007f7ac2f1f000 R08: 00000000ffffffff R09: 0000000000000000
kern :warn : [ 67.439179] R10: fffffffffffffb9c R11: 0000000000000246 R12: 00007f7ac2f1f000
kern :warn : [ 67.440666] R13: 0000000000000004 R14: 0000000000000fd6 R15: 0000000000020000
kern :warn : [ 67.442154] ---[ end trace 111907d32e944db5 ]---
user :notice: [ 73.663747] ip=::::lkp-ivb-d02::dhcp root=/dev/ram0 user=lkp job=/lkp/jobs/scheduled/lkp-ivb-d02/ltp-tracing-ucode=0x21-debian-10.4-x86_64-20200603.cgz-9a6944fee68e25084130386c608c5ac8db487581-20210507-28413-btefsg-3.yaml ARCH=x86_64 kconfig=x86_64-rhel-8.3 branch=linus/master commit=9a6944fee68e25084130386c608c5ac8db487581 BOOT_IMAGE=/pkg/linux/x86_64-rhel-8.3/gcc-9/9a6944fee68e25084130386c608c5ac8db487581/vmlinuz-5.12.0-rc3-00014-g9a6944fee68e max_uptime=2100 RESULT_ROOT=/result/ltp/tracing-ucode=0x21/lkp-ivb-d02/debian-10.4-x86_64-20200603.cgz/x86_64-rhel-8.3/gcc-9/9a6944fee68e25084130386c608c5ac8db487581/4 LKP_SERVER=internal-lkp-server nokaslr selinux=0 debug apic=debug sysrq_always_enabled rcupdate.rcu_cpu_stall_timeout=100 net.ifnames=0 printk.devkmsg=on panic=-1 softlockup_panic=1 nmi_watchdog=panic oops=panic load_ramdisk=2 prompt_ramdisk=0 drbd.minor_count=8 systemd.log_level=err ignore_l
user :notice: [ 77.704925] Gnu C gcc (Debian 8.3.0-6) 8.3.0
user :notice: [ 77.716244] Clang
user :notice: [ 77.727745] Gnu make 4.2.1
user :notice: [ 77.738801] util-linux 2.33.1
user :notice: [ 81.495940] mount linux 2.33.1 (libmount 2.33.1: selinux, smack, btrfs, namespaces, assert, debug)
user :notice: [ 81.505144] modutils 26
user :notice: [ 81.514181] e2fsprogs 1.44.5
user :notice: [ 81.523248] Linux C Library > libc.2.28
user :notice: [ 81.530829] Dynamic linker (ldd) 2.28
user :notice: [ 81.537497] Procps 3.3.15
user :notice: [ 81.544273] Net-tools 2.10-alpha
user :notice: [ 81.551273] iproute2 iproute2-ss190107
user :notice: [ 81.558277] iputils iputils-s20180629
user :notice: [ 81.564776] ethtool 4.19
user :notice: [ 81.574843] Kbd 119:
user :notice: [ 81.581528] Sh-utils 8.30
user :notice: [ 95.012211] Modules Loaded netconsole btrfs blake2b_generic xor zstd_compress raid6_pq libcrc32c intel_rapl_msr intel_rapl_common sd_mod x86_pkg_temp_thermal t10_pi sg intel_powerclamp coretemp i915 kvm_intel kvm irqbypass intel_gtt crct10dif_pclmul drm_kms_helper crc32_pclmul crc32c_intel ghash_clmulni_intel syscopyarea rapl sysfillrect ahci sysimgblt fb_sys_fops libahci drm intel_cstate libata intel_uncore ipmi_devintf ipmi_msghandler mei_me joydev mei video ip_tables
user :notice: [ 95.038003] free reports:
user :notice: [ 95.048893] total used free shared buff/cache available
user :notice: [ 95.060064] Mem: 8024612 296536 5171728 13384 2556348 5067056
user :notice: [ 95.069333] Swap: 0 0 0
user :notice: [ 95.083410] cpuinfo:
user :notice: [ 95.091601] Architecture: x86_64
To reproduce:
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp install job.yaml # job file is attached in this email
bin/lkp split-job --compatible job.yaml # generate the yaml file for lkp run
bin/lkp run generated-yaml-file
---
0DAY/LKP+ Test Infrastructure Open Source Technology Center
https://lists.01.org/hyperkitty/list/[email protected] Intel Corporation
Thanks,
Oliver Sang