linux-kernel - Re: [GIT pull] CPU hotplug updates for 4.9

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-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <1489181559.2548.9.camel@sandisk.com>
Date:   Fri, 10 Mar 2017 21:32:52 +0000
From:   Bart Van Assche <Bart.VanAssche@...disk.com>
To:     "tglx@...utronix.de" <tglx@...utronix.de>
CC:     "torvalds@...ux-foundation.org" <torvalds@...ux-foundation.org>,
        "mingo@...nel.org" <mingo@...nel.org>,
        "linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>,
        "hpa@...or.com" <hpa@...or.com>,
        "akpm@...ux-foundation.org" <akpm@...ux-foundation.org>
Subject: Re: [GIT pull] CPU hotplug updates for 4.9

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.