linux-kernel - Re: [Query] Preemption (hogging) of the work handler

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: <20160711102603.GI12410@quack2.suse.cz>
Date:	Mon, 11 Jul 2016 12:26:03 +0200
From:	Jan Kara <jack@...e.cz>
To:	Viresh Kumar <viresh.kumar@...aro.org>
Cc:	Tejun Heo <tj@...nel.org>,
	Greg Kroah-Hartman <gregkh@...uxfoundation.org>,
	Linux Kernel Mailing List <linux-kernel@...r.kernel.org>,
	vlevenetz@...sol.com, vaibhav.hiremath@...aro.org,
	alex.elder@...aro.org, johan@...nel.org, akpm@...ux-foundation.org,
	jack@...e.cz, rostedt@...dmis.org,
	Sergey Senozhatsky <sergey.senozhatsky@...il.com>
Subject: Re: [Query] Preemption (hogging) of the work handler

On Wed 06-07-16 11:28:42, Viresh Kumar wrote:
> On 01-07-16, 12:22, Tejun Heo wrote:
> I enabled traces with '-e all' to look at everything happening on the
> CPU.
> 
> Following is what starts in the middle of the delayed-work handler:
> 
>     kworker/0:1H-40    [000] d..1  2994.918766: console: [ 2994.918754] ***
>     kworker/0:1H-40    [000] d..1  2994.923057: console: [ 2994.918817] ***
>     kworker/0:1H-40    [000] d..1  2994.935639: console: [ 2994.918842] ***
> 
> ... (more messages)
> 
>     kworker/0:1H-40    [000] d..1  2996.264372: console: [ 2994.943074] ***
>     kworker/0:1H-40    [000] d..1  2996.268622: console: [ 2994.943410] ***
>     kworker/0:1H-40    [000] d..1  2996.275050: ipi_entry: (Rescheduling interrupts)
> 
> 
> (*** are some specific errors to our usecase and aren't relevant here)
> 
> These print messages continue from 2994.918 to 2996.268 (1.35 seconds)
> and they hog the work-handler for that long, which results in watchdog
> reboot in our setup. The 3.10 kernel implementation of the printk
> looks like this (if I am not wrong):
> 
>         local_irq_save();
>         flush-console-buffer(); //console_unlock()
>         local_irq_restore();
> 
> So, the current CPU will try to print all the messages from the
> buffer, before enabling the interrupts again on the local CPU and so I
> don't see the hrtimer fire at all for almost a second.
> 
> 
> I tried looking at if something related to this changed between 3.10
> and mainline, and found few patches at least. One of the important
> ones is:
> 
> commit 5874af2003b1 ("printk: enable interrupts before calling
> console_trylock_for_printk()")
> 
> I wasn't able to backport it cleanly to 3.10 yet to see it makes thing
> work better though. But it looks like it was targeting similar
> problems.
> 
> @Jan Kara, Right ?

Yes. We have similar problems as you observe on machines when they do a lot
of printing (usually due to device discovery or similar reasons). The
problem is not fully solved even upstream as Andrew is reluctant to merge
the patches. Sergey (added to CC) has the latest version of the series [1].
If you are interested, I can send you the patches for 3.12 kernel which we
carry in SLES kernels and which fixes the issue for us. It is significanly
different from current upstream version but it works good enough for us.

								Honza

[1] https://lkml.org/lkml/2016/5/13/275
-- 
Jan Kara <jack@...e.com>
SUSE Labs, CR