On Thu, 2017-03-09 at 18:43 +0100, Thomas Gleixner wrote:
> On Thu, 9 Mar 2017, Bart Van Assche wrote:
> > INFO: task systemd-udevd:748 blocked for more than 480 seconds.
> > Tainted: G IO 4.11.0-rc1-dbg+ #1
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > systemd-udevd D 0 748 518 0x00000104
> > Call Trace:
> > __schedule+0x302/0xc30
> > schedule+0x38/0x90
> > schedule_timeout+0x255/0x490
> > wait_for_completion+0x103/0x170
> > cpuhp_issue_call+0xb9/0xe0
> > __cpuhp_setup_state+0xf6/0x180
> > coretemp_init+0x8d/0x1000 [coretemp]
> > do_one_initcall+0x3e/0x170
> > do_init_module+0x5a/0x1ed
> > load_module+0x2339/0x2a40
> > SYSC_finit_module+0xbc/0xf0
> > SyS_finit_module+0x9/0x10
> > do_syscall_64+0x57/0x140
> > entry_SYSCALL64_slow_path+0x25/0x25
> > Showing all locks held in the system:
> > 2 locks held by khungtaskd/91:
> > #0: (rcu_read_lock){......}, at: [<ffffffff8111a6f0>] watchdog+0xa0/0x5d0
> > #1: (tasklist_lock){.+.?..}, at: [<ffffffff810bf36d>]
> > debug_show_all_locks+0x3d/0x1a0
> > 1 lock held by systemd-udevd/748:
> > #0: (cpu_hotplug.dep_map){++++++}, at: [<ffffffff8106712d>]
> > get_online_cpus+0x2d/0x80
>
> Ok, so it's random. Now it would be interesting what the rest of the system
> does when this happens. I still have no idea why that IOAT setting has any
> influence.
Hello Thomas,
The following lines started to appear in the system log during boot after I
started testing kernels after v4.9 and appear before every cpuhp_issue_call()
complaint so this is probably related what causes the hang:
systemd-udevd[553]: seq 2998 '/devices/system/cpu/cpu0' killed
systemd-udevd[553]: seq 3009 '/devices/system/cpu/cpu9' killed
systemd-udevd[553]: seq 3008 '/devices/system/cpu/cpu8' killed
systemd-udevd[553]: seq 3007 '/devices/system/cpu/cpu7' killed
systemd-udevd[553]: seq 2999 '/devices/system/cpu/cpu1' killed
systemd-udevd[553]: seq 3006 '/devices/system/cpu/cpu6' killed
systemd-udevd[553]: seq 3001 '/devices/system/cpu/cpu11' killed
systemd-udevd[553]: seq 3004 '/devices/system/cpu/cpu4' killed
systemd-udevd[553]: seq 3003 '/devices/system/cpu/cpu3' killed
systemd-udevd[553]: seq 3002 '/devices/system/cpu/cpu2' killed
systemd-udevd[553]: seq 3005 '/devices/system/cpu/cpu5' killed
systemd-udevd[553]: seq 3000 '/devices/system/cpu/cpu10' killed
systemd-udevd[553]: worker [748] terminated by signal 9 (Killed)
systemd-udevd[553]: worker [748] failed while handling
'/devices/system/cpu/cpu4'
systemd-udevd[553]: worker [710] terminated by signal 9 (Killed)
systemd-udevd[553]: worker [710] failed while handling
'/devices/system/cpu/cpu1'
systemd-udevd[553]: worker [750] terminated by signal 9 (Killed)
systemd-udevd[553]: worker [750] failed while handling
'/devices/system/cpu/cpu5'
systemd-udevd[553]: worker [690] terminated by signal 9 (Killed)
systemd-udevd[553]: worker [690] failed while handling
'/devices/system/cpu/cpu0'
systemd-udevd[553]: worker [747] terminated by signal 9 (Killed)
systemd-udevd[553]: worker [747] failed while handling
'/devices/system/cpu/cpu8'
systemd-udevd[553]: worker [770] terminated by signal 9 (Killed)
systemd-udevd[553]: worker [770] failed while handling
'/devices/system/cpu/cpu2'
systemd-udevd[553]: worker [772] terminated by signal 9 (Killed)
systemd-udevd[553]: worker [772] failed while handling
'/devices/system/cpu/cpu10'
systemd-udevd[553]: worker [774] terminated by signal 9 (Killed)
systemd-udevd[553]: worker [774] failed while handling
'/devices/system/cpu/cpu6'
systemd-udevd[553]: worker [782] terminated by signal 9 (Killed)
systemd-udevd[553]: worker [782] failed while handling
'/devices/system/cpu/cpu9'
systemd-udevd[553]: worker [807] terminated by signal 9 (Killed)
systemd-udevd[553]: worker [807] failed while handling
'/devices/system/cpu/cpu11'
systemd-udevd[553]: worker [816] terminated by signal 9 (Killed)
systemd-udevd[553]: worker [816] failed while handling
'/devices/system/cpu/cpu7'
Since this seems to reproduce easier than the hang I will try to use this to
guide a new bisect attempt.
Bart.
