From: Bart Van Assche <Bart.VanAssche@sandisk.com>
To: "tglx@linutronix.de" <tglx@linutronix.de>
CC: "torvalds@linux-foundation.org" <torvalds@linux-foundation.org>,
        "mingo@kernel.org" <mingo@kernel.org>,
        "linux-kernel@vger.kernel.org" <linux-kernel@vger.kernel.org>,
        "hpa@zytor.com" <hpa@zytor.com>,
        "akpm@linux-foundation.org" <akpm@linux-foundation.org>
Subject: Re: [GIT pull] CPU hotplug updates for 4.9
Thread-Topic: [GIT pull] CPU hotplug updates for 4.9
Thread-Index: AQHSmeXfd1DaQuUGd0+jkuqus7MkRw==
Date: Fri, 10 Mar 2017 21:32:52 +0000
Message-ID: <1489181559.2548.9.camel@sandisk.com>
References: <alpine.DEB.2.20.1610031929360.5278@nanos>
            <1488851515.6858.2.camel@sandisk.com>
            <alpine.DEB.2.20.1703071027340.3584@nanos>
           <1488925949.2739.3.camel@sandisk.com>
           <alpine.DEB.2.20.1703080922530.3521@nanos>
          <1489001551.2813.3.camel@sandisk.com>
         <alpine.DEB.2.20.1703091118230.3521@nanos>
         <1489080026.2597.7.camel@sandisk.com>
         <alpine.DEB.2.20.1703091829530.3521@nanos>
In-Reply-To: <alpine.DEB.2.20.1703091829530.3521@nanos>
Accept-Language: nl-NL, en-US
Content-Language: en-US
Content-Type: text/plain; charset="iso-8859-1"
Content-ID: <BEDBF4678755654CBEF6F4F2F95B852B@sandisk.com>
MIME-Version: 1.0
WDCIPOUTBOUND: EOP-TRUE
SpamDiagnosticOutput: 1:99
SpamDiagnosticMetadata: NSPM
X-MS-Exchange-CrossTenant-OriginalArrivalTime: 10 Mar 2017 21:32:56.9066
 (UTC)
X-MS-Exchange-CrossTenant-Id: b61c8803-16f3-4c35-9b17-6f65f441df86
X-MS-Exchange-CrossTenant-OriginalAttributedTenantConnectingIp: TenantId=b61c8803-16f3-4c35-9b17-6f65f441df86;Ip=[74.221.232.55];Helo=[sacsmgep15.sandisk.com]
X-MS-Exchange-CrossTenant-FromEntityHeader: HybridOnPrem
X-MS-Exchange-Transport-CrossTenantHeadersStamped: CY1PR0401MB1503
Sender: linux-kernel-owner@vger.kernel.org
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org
Content-Transfer-Encoding: 8bit
X-MIME-Autoconverted: from quoted-printable to 8bit by mail.home.local id v2ALXC7H032699
Content-Length: 4104
Lines: 77

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.