kernel test robot
2024-Nov-07 14:25 UTC
[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 at intel.com>
| Closes: https://lore.kernel.org/oe-lkp/202411072207.b2321310-oliver.sang at
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
at intel.com
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
Steven Rostedt
2024-Nov-07 15:40 UTC
[linux-next:master] [tracing] 49e4154f4b: INFO:task_blocked_for_more_than#seconds
On Thu, 7 Nov 2024 22:25:23 +0800 kernel test robot <oliver.sang at intel.com> wrote:> 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: bootThe commit in question does not even get executed in the boot process (unless you have tracing on boot enabled). So I'll simply ignore this. -- Steve