From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1758241AbcGKK0P (ORCPT ); Mon, 11 Jul 2016 06:26:15 -0400 Received: from mx2.suse.de ([195.135.220.15]:42554 "EHLO mx2.suse.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753073AbcGKK0N (ORCPT ); Mon, 11 Jul 2016 06:26:13 -0400 Date: Mon, 11 Jul 2016 12:26:03 +0200 From: Jan Kara To: Viresh Kumar Cc: Tejun Heo , Greg Kroah-Hartman , Linux Kernel Mailing List , 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 Subject: Re: [Query] Preemption (hogging) of the work handler Message-ID: <20160711102603.GI12410@quack2.suse.cz> References: <20160701165959.GR12473@ubuntu> <20160701172232.GD28719@htj.duckdns.org> <20160706182842.GS2671@ubuntu> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20160706182842.GS2671@ubuntu> User-Agent: Mutt/1.5.24 (2015-08-30) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 SUSE Labs, CR