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

From: Jan Kara <jack@suse.cz>
To: Viresh Kumar <viresh.kumar@linaro.org>
Cc: Tejun Heo <tj@kernel.org>,
	Greg Kroah-Hartman <gregkh@linuxfoundation.org>,
	Linux Kernel Mailing List <linux-kernel@vger.kernel.org>,
	vlevenetz@mm-sol.com, vaibhav.hiremath@linaro.org,
	alex.elder@linaro.org, johan@kernel.org,
	akpm@linux-foundation.org, jack@suse.cz, rostedt@goodmis.org,
	Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Subject: Re: [Query] Preemption (hogging) of the work handler
Date: Mon, 11 Jul 2016 12:26:03 +0200	[thread overview]
Message-ID: <20160711102603.GI12410@quack2.suse.cz> (raw)
In-Reply-To: <20160706182842.GS2671@ubuntu>

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@suse.com>
SUSE Labs, CR