linux-kernel - [linux-next:master] [tracing] 49e4154f4b: INFO:task_blocked_for_more

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [thread-next>] [day] [month] [year] [list]
Message-ID: <202411072207.b2321310-oliver.sang@intel.com>
Date: Thu, 7 Nov 2024 22:25:23 +0800
From: kernel test robot <oliver.sang@...el.com>
To: Zheng Yejian <zhengyejian@...weicloud.com>
CC: <oe-lkp@...ts.linux.dev>, <lkp@...el.com>, Steven Rostedt
	<rostedt@...dmis.org>, <linux-kernel@...r.kernel.org>,
	<linux-trace-kernel@...r.kernel.org>, <nouveau@...ts.freedesktop.org>,
	<oliver.sang@...el.com>
Subject: [linux-next:master] [tracing]  49e4154f4b:
 INFO:task_blocked_for_more_than#seconds



Hello,

kernel test robot noticed "INFO:task_blocked_for_more_than#seconds" on:

commit: 49e4154f4b16345da5e219b23ed9737a6e735bc1 ("tracing: Remove TRACE_EVENT_FL_FILTERED logic")
https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master

[test failed on linux-next/master 850f22c42f4b0a14a015aecc26f46f9948ded6dd]

in testcase: boot

config: i386-randconfig-003-20241103
compiler: clang-19
test machine: qemu-system-i386 -enable-kvm -cpu SandyBridge -smp 2 -m 4G

(please refer to attached dmesg/kmsg for entire log/backtrace)


we don't have clear idea how this commit raises issues, so we run tests
up to 300 times. we observe various issues on this commit but parent keeps
clean.

2aa746ec0240dcbe 49e4154f4b16345da5e219b23ed
---------------- ---------------------------
       fail:runs  %reproduction    fail:runs
           |             |             |
           :300         15%          46:300   dmesg.BUG:kernel_hang_in_boot_stage
           :300         14%          42:300   dmesg.BUG:workqueue_lockup-pool
           :300          1%           3:300   dmesg.EIP:lock_acquire
           :300          0%           1:300   dmesg.INFO:rcu_preempt_detected_stalls_on_CPUs/tasks
           :300          5%          15:300   dmesg.INFO:task_blocked_for_more_than#seconds



If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <oliver.sang@...el.com>
| Closes: https://lore.kernel.org/oe-lkp/202411072207.b2321310-oliver.sang@intel.com


[  990.007137][   T23] INFO: task swapper:1 blocked for more than 491 seconds.
[  990.056313][   T23]       Not tainted 6.12.0-rc2-00003-g49e4154f4b16 #1
[  990.118200][   T23] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  990.195719][   T23] task:swapper         state:D stack:4480  pid:1     tgid:1     ppid:0      flags:0x00004000
[  990.272724][   T23] Call Trace:
[ 990.330321][ T23] __schedule (kernel/sched/core.c:5318 kernel/sched/core.c:6675) 
[ 990.447142][ T23] schedule (kernel/sched/core.c:6753 kernel/sched/core.c:6767) 
[ 990.491979][ T23] async_synchronize_cookie_domain (kernel/async.c:?) 
[ 990.594686][ T23] ? wake_bit_function (kernel/sched/wait.c:383) 
[ 990.683319][ T23] ? reserve_initrd_mem (init/initramfs.c:756) 
[ 990.747936][ T23] wait_for_initramfs (init/initramfs.c:752) 
[ 990.820345][ T23] populate_rootfs (init/initramfs.c:762) 
[ 990.882071][ T23] do_one_initcall (init/main.c:?) 
[ 990.944599][ T23] ? reserve_initrd_mem (init/initramfs.c:756) 
[ 991.001047][ T23] ? local_clock_noinstr (arch/x86/include/asm/cmpxchg_32.h:139 kernel/sched/clock.c:290 kernel/sched/clock.c:306) 
[ 991.124344][ T23] ? pvclock_clocksource_read_nowd (arch/x86/include/asm/pvclock.h:37 arch/x86/kernel/pvclock.c:79 arch/x86/kernel/pvclock.c:120) 
[ 991.209051][ T23] ? pvclock_clocksource_read_nowd (arch/x86/include/asm/pvclock.h:37 arch/x86/kernel/pvclock.c:79 arch/x86/kernel/pvclock.c:120) 
[ 991.292799][ T23] ? pvclock_clocksource_read_nowd (arch/x86/include/asm/pvclock.h:37 arch/x86/kernel/pvclock.c:79 arch/x86/kernel/pvclock.c:120) 
[ 991.378336][ T23] ? local_clock_noinstr (arch/x86/include/asm/cmpxchg_32.h:139 kernel/sched/clock.c:290 kernel/sched/clock.c:306) 
[ 991.476997][ T23] ? pvclock_clocksource_read_nowd (arch/x86/include/asm/pvclock.h:37 arch/x86/kernel/pvclock.c:79 arch/x86/kernel/pvclock.c:120) 
[ 991.527408][ T23] ? pvclock_clocksource_read_nowd (arch/x86/include/asm/pvclock.h:37 arch/x86/kernel/pvclock.c:79 arch/x86/kernel/pvclock.c:120) 
[ 991.625576][ T23] ? local_clock_noinstr (arch/x86/include/asm/cmpxchg_32.h:139 kernel/sched/clock.c:290 kernel/sched/clock.c:306) 
[ 991.925186][ T23] ? local_clock_noinstr (arch/x86/include/asm/cmpxchg_32.h:139 kernel/sched/clock.c:290 kernel/sched/clock.c:306) 
[ 992.217536][ T23] ? irqentry_exit (kernel/entry/common.c:365) 
[ 992.316602][ T23] ? check_preemption_disabled (lib/smp_processor_id.c:16) 
[ 992.451338][ T23] ? __this_cpu_preempt_check (lib/smp_processor_id.c:67) 
[ 992.545143][ T23] ? lockdep_hardirqs_on (kernel/locking/lockdep.c:4468) 
[ 992.694021][ T23] ? trace_hardirqs_on (kernel/trace/trace_preemptirq.c:63) 
[ 992.817354][ T23] ? irqentry_exit (kernel/entry/common.c:365) 
[ 992.956858][ T23] ? common_interrupt (arch/x86/kernel/irq.c:278) 
[ 993.087472][ T23] ? asm_common_interrupt (init_task.c:?) 
[ 993.298189][ T23] ? next_arg (lib/cmdline.c:273) 
[ 993.545274][ T23] ? parse_args (kernel/params.c:153 kernel/params.c:186) 
[ 993.665571][ T23] ? trace_initcall_level (include/trace/events/initcall.h:10) 
[ 993.755608][ T23] do_initcall_level (init/main.c:1330) 
[ 993.843152][ T23] do_initcalls (init/main.c:1344) 
[ 993.895473][ T23] do_basic_setup (init/main.c:1367) 
[ 993.952283][ T23] kernel_init_freeable (init/main.c:1582) 
[ 994.016012][ T23] ? rest_init (init/main.c:1461) 
[ 994.067853][ T23] ? rest_init (init/main.c:1461) 
[ 994.152226][ T23] kernel_init (init/main.c:1471) 
[ 994.250558][ T23] ret_from_fork (arch/x86/kernel/process.c:153) 
[ 994.358571][ T23] ret_from_fork_asm (??:?) 
[ 994.464814][ T23] entry_INT80_32 (init_task.c:?) 
[ 1024.177579][   T23]
[ 1024.177579][   T23] Showing all locks held in the system:
[ 1024.234410][   T23] 1 lock held by khungtaskd/23:
[ 1024.289399][ T23] #0: c3cd44a4 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire (include/linux/rcupdate.h:336) 
[ 1024.427079][   T23] 2 locks held by kworker/u4:2/25:
[ 1024.482763][   T23]
[ 1024.555465][   T23] =============================================
[ 1024.555465][   T23]
[ 1117.679859][    C0] workqueue: do_cache_clean hogged CPU for >10000us 19 times, consider switching to WQ_UNBOUND
[ 1149.530928][    C0] workqueue: neigh_managed_work hogged CPU for >10000us 67 times, consider switching to WQ_UNBOUND
[ 1155.426086][    C0] workqueue: stop_one_cpu_nowait_workfn hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND
BUG: kernel hang in boot stage



The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20241107/202411072207.b2321310-oliver.sang@intel.com



-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki