2021-05-05 14:54:51

by kernel test robot

[permalink] [raw]
Subject: [iov_iter] 8db1c12ebc: WARNING:at_lib/iov_iter.c:#iov_iter_revert



Greeting,

FYI, we noticed the following commit (built with gcc-9):

commit: 8db1c12ebcc0efbeab58c3d9bd414db20a209eca ("iov_iter: replace iov_iter_copy_from_user_atomic() with iterator-advancing variant")
https://git.kernel.org/cgit/linux/kernel/git/viro/vfs.git untested.iov_iter-3


in testcase: fio-basic
version: fio-x86_64-3.15-1_20200907
with following parameters:

runtime: 300s
disk: 1HDD
fs: btrfs
nr_task: 100%
test_size: 128G
rw: write
bs: 4k
ioengine: io_uring
cpufreq_governor: performance
ucode: 0x42e

test-description: Fio is a tool that will spawn a number of threads or processes doing a particular type of I/O action as specified by the user.
test-url: https://github.com/axboe/fio


on test machine: 48 threads 2 sockets Intel(R) Xeon(R) CPU E5-2697 v2 @ 2.70GHz with 112G 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]>


[ 47.232212] WARNING: CPU: 5 PID: 3339 at lib/iov_iter.c:1147 iov_iter_revert (kbuild/src/consumer/lib/iov_iter.c:1147 (discriminator 1))
[ 47.241667] Modules linked in: dm_mod xfs btrfs blake2b_generic xor zstd_compress raid6_pq libcrc32c sd_mod t10_pi sg intel_rapl_msr intel_rapl_common sb_edac x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul mgag200 crc32c_intel ghash_clmulni_intel drm_kms_helper isci rapl libsas syscopyarea ipmi_si sysfillrect ahci sysimgblt fb_sys_fops scsi_transport_sas libahci intel_cstate mei_me ipmi_devintf ioatdma intel_uncore drm ipmi_msghandler libata mei dca wmi joydev ip_tables
[ 47.296355] CPU: 5 PID: 3339 Comm: iou-wrk-2334 Not tainted 5.12.0-rc4-00066-g8db1c12ebcc0 #1
[ 47.306546] Hardware name: Intel Corporation S2600WP/S2600WP, BIOS SE5C600.86B.02.02.0002.122320131210 12/23/2013
[ 47.318711] RIP: 0010:iov_iter_revert (kbuild/src/consumer/lib/iov_iter.c:1147 (discriminator 1))
[ 47.324591] Code: 41 8b 48 f8 48 83 c0 02 4c 89 4f 20 48 39 ce 76 da 48 83 ea 10 48 29 ce 8b 4a 08 48 89 47 20 48 83 c0 01 48 39 f1 72 e9 eb c1 <0f> 0b c3 41 55 41 54 55 53 4c 8b 67 18 8b 5f 20 48 8b 57 08 41 8b
All code
========
0: 41 8b 48 f8 mov -0x8(%r8),%ecx
4: 48 83 c0 02 add $0x2,%rax
8: 4c 89 4f 20 mov %r9,0x20(%rdi)
c: 48 39 ce cmp %rcx,%rsi
f: 76 da jbe 0xffffffffffffffeb
11: 48 83 ea 10 sub $0x10,%rdx
15: 48 29 ce sub %rcx,%rsi
18: 8b 4a 08 mov 0x8(%rdx),%ecx
1b: 48 89 47 20 mov %rax,0x20(%rdi)
1f: 48 83 c0 01 add $0x1,%rax
23: 48 39 f1 cmp %rsi,%rcx
26: 72 e9 jb 0x11
28: eb c1 jmp 0xffffffffffffffeb
2a:* 0f 0b ud2 <-- trapping instruction
2c: c3 retq
2d: 41 55 push %r13
2f: 41 54 push %r12
31: 55 push %rbp
32: 53 push %rbx
33: 4c 8b 67 18 mov 0x18(%rdi),%r12
37: 8b 5f 20 mov 0x20(%rdi),%ebx
3a: 48 8b 57 08 mov 0x8(%rdi),%rdx
3e: 41 rex.B
3f: 8b .byte 0x8b

Code starting with the faulting instruction
===========================================
0: 0f 0b ud2
2: c3 retq
3: 41 55 push %r13
5: 41 54 push %r12
7: 55 push %rbp
8: 53 push %rbx
9: 4c 8b 67 18 mov 0x18(%rdi),%r12
d: 8b 5f 20 mov 0x20(%rdi),%ebx
10: 48 8b 57 08 mov 0x8(%rdi),%rdx
14: 41 rex.B
15: 8b .byte 0x8b
[ 47.347157] RSP: 0018:ffffc9000d533b38 EFLAGS: 00010286
[ 47.353820] RAX: fffffffffffff000 RBX: ffffea00076b4540 RCX: 0000000000001000
[ 47.362631] RDX: 0000000000001000 RSI: fffffffffffff000 RDI: ffffc9000d533cc8
[ 47.371468] RBP: 0000000000001000 R08: 0000000000000000 R09: ffffea0000000000
[ 47.380276] R10: ffff888f7efa5c28 R11: 0000000000006652 R12: 0000000000000000
[ 47.389109] R13: ffffc9000d533cc8 R14: 0000000000001000 R15: 0000000000001000
[ 47.397936] FS: 00007fe182d4ab80(0000) GS:ffff888f02940000(0000) knlGS:0000000000000000
[ 47.407859] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 47.415201] CR2: 000055d8eb9a8610 CR3: 0000001c32576002 CR4: 00000000001706e0
[ 47.424099] Call Trace:
[ 47.427774] btrfs_copy_from_user (kbuild/src/consumer/fs/btrfs/file.c:417) btrfs
[ 47.434332] btrfs_buffered_write (kbuild/src/consumer/fs/btrfs/file.c:1774) btrfs
[ 47.440949] btrfs_file_write_iter (kbuild/src/consumer/fs/btrfs/file.c:2016) btrfs
[ 47.447709] io_write (kbuild/src/consumer/fs/io_uring.c:3440)
[ 47.452278] ? __free_pages_ok (kbuild/src/consumer/arch/x86/include/asm/irqflags.h:144 kbuild/src/consumer/mm/page_alloc.c:1548)
[ 47.457816] ? __free_slab (kbuild/src/consumer/mm/slub.c:1866)
[ 47.462859] ? unfreeze_partials+0x18e/0x1c0
[ 47.469265] ? update_load_avg (kbuild/src/consumer/kernel/sched/fair.c:3557 kbuild/src/consumer/kernel/sched/fair.c:3788)
[ 47.474708] ? page_counter_cancel (kbuild/src/consumer/mm/page_counter.c:57)
[ 47.480435] io_issue_sqe (kbuild/src/consumer/fs/io_uring.c:6152)
[ 47.485618] ? drain_obj_stock+0x3e/0xc0
[ 47.491662] ? __io_free_req (kbuild/src/consumer/arch/x86/include/asm/preempt.h:80 kbuild/src/consumer/include/linux/rcupdate.h:68 kbuild/src/consumer/include/linux/rcupdate.h:654 kbuild/src/consumer/include/linux/percpu-refcount.h:317 kbuild/src/consumer/include/linux/percpu-refcount.h:338 kbuild/src/consumer/fs/io_uring.c:1722)
[ 47.496812] ? kmem_cache_free (kbuild/src/consumer/mm/slub.c:3149 kbuild/src/consumer/mm/slub.c:3162 kbuild/src/consumer/mm/slub.c:3177)
[ 47.502372] io_wq_submit_work (kbuild/src/consumer/fs/io_uring.c:6196)
[ 47.507846] io_worker_handle_work (kbuild/src/consumer/include/linux/spinlock.h:379 (discriminator 5) kbuild/src/consumer/fs/io-wq.c:409 (discriminator 5) kbuild/src/consumer/fs/io-wq.c:451 (discriminator 5))
[ 47.513807] io_wqe_worker (kbuild/src/consumer/fs/io-wq.c:501)
[ 47.518911] ? io_worker_handle_work (kbuild/src/consumer/fs/io-wq.c:481)
[ 47.525082] ret_from_fork (kbuild/src/consumer/arch/x86/entry/entry_64.S:300)
[ 47.530109] ---[ end trace 3534e5b51c3fdb73 ]---
[ 181.615371] perf: interrupt took too long (2567 > 2500), lowering kernel.perf_event_max_sample_rate to 77000
[ 181.627179] perf: interrupt took too long (3215 > 3208), lowering kernel.perf_event_max_sample_rate to 62000
[ 181.660253] perf: interrupt took too long (4036 > 4018), lowering kernel.perf_event_max_sample_rate to 49000
[ 181.740008] perf: interrupt took too long (5076 > 5045), lowering kernel.perf_event_max_sample_rate to 39000
[ 181.828716] perf: interrupt took too long (6362 > 6345), lowering kernel.perf_event_max_sample_rate to 31000
[ 182.699707] perf: interrupt took too long (7964 > 7952), lowering kernel.perf_event_max_sample_rate to 25000
[ 184.819653] perf: interrupt took too long (9987 > 9955), lowering kernel.perf_event_max_sample_rate to 20000
[ 184.933884] perf: interrupt took too long (12586 > 12483), lowering kernel.perf_event_max_sample_rate to 15000
[ 210.136590] Events enabled
[ 210.136596]
[ 220.138073] [ perf record: Woken up 80 times to write data ]
[ 220.138079]
[ 222.559679] [ perf record: Captured and wrote 213.728 MB /tmp/lkp/perf-sched.data (967993 samples) ]
[ 222.559686]
[ 337.824415] /usr/bin/wget -q --timeout=1800 --tries=1 --local-encoding=UTF-8 http://internal-lkp-server:80/~lkp/cgi-bin/lkp-jobfile-append-var?job_file=/lkp/jobs/scheduled/lkp-ivb-2ep1/fio-basic-4k-performance-1HDD-btrfs-io_uring-100%25-300s-write-128G-ucode=0x42e-monitor=05f94038-debian-10.4-x86_64-20200603.cgz-8-20210505-57196-59mv33-4.yaml&job_state=post_run -O /dev/null
[ 337.824423]
[ 339.421220] kill 1759 vmstat --timestamp -n 10
[ 339.421224]
[ 339.432373] kill 1756 iostat -tkx 1 /dev/sdb
[ 339.432384]
[ 339.445558] kill 1747 dmesg --follow --decode
[ 339.445574]
[ 339.458930] kill 1765 vmstat --timestamp -n 1
[ 339.458947]
[ 339.496271] wait for background processes: 1752 1769 1853 1785 1872 1815 1806 1841 1780 1920 1799 1774 1900 1791 1832 1941 1889 1910 1929 uptime numa-numastat diskstats proc-vmstat cpuidle interrupts slabinfo softirqs numa-meminfo mpstat meminfo numa-vmstat sched_debug proc-stat perf-sched oom-killer turbostat perf-stat perf-profile
[ 339.496275]


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


Attachments:
(No filename) (9.13 kB)
config-5.12.0-rc4-00066-g8db1c12ebcc0 (175.59 kB)
job-script (8.48 kB)
dmesg.xz (26.97 kB)
job.yaml (5.86 kB)
reproduce (740.00 B)
Download all attachments