From mboxrd@z Thu Jan  1 00:00:00 1970
Return-Path: <linux-kernel-owner@vger.kernel.org>
Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand
	id S1751940AbcGONME (ORCPT <rfc822;w@1wt.eu>);
	Fri, 15 Jul 2016 09:12:04 -0400
Received: from mail-pa0-f67.google.com ([209.85.220.67]:33937 "EHLO
	mail-pa0-f67.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org
	with ESMTP id S1751082AbcGONMB (ORCPT
	<rfc822;linux-kernel@vger.kernel.org>);
	Fri, 15 Jul 2016 09:12:01 -0400
Date: Fri, 15 Jul 2016 22:11:33 +0900
From: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
To: Viresh Kumar <viresh.kumar@linaro.org>
Cc: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>,
        Petr Mladek <pmladek@suse.com>,
        Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>,
        Jan Kara <jack@suse.cz>, 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,
        rostedt@goodmis.org
Subject: Re: [Query] Preemption (hogging) of the work handler
Message-ID: <20160715131011.GA579@swordfish>
References: <20160701165959.GR12473@ubuntu>
 <20160701172232.GD28719@htj.duckdns.org>
 <20160706182842.GS2671@ubuntu>
 <20160711102603.GI12410@quack2.suse.cz>
 <20160711154438.GA528@swordfish>
 <20160711223501.GI4695@ubuntu>
 <20160712093805.GA498@swordfish>
 <20160712125243.GA8597@pathway.suse.cz>
 <20160712140300.GA520@swordfish>
 <20160714235246.GI3057@ubuntu>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20160714235246.GI3057@ubuntu>
User-Agent: Mutt/1.6.2 (2016-07-01)
Sender: linux-kernel-owner@vger.kernel.org
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

Hello,

On (07/14/16 16:52), Viresh Kumar wrote:
> On 12-07-16, 23:03, Sergey Senozhatsky wrote:
> > so, I'm looking at this thing now:
> > 
> > : [   12.874909] sched: RT throttling activated for rt_rq ffffffc0ac13fcd0 (cpu 0)
> > : [   12.874909] potential CPU hogs:
> > : [   12.874909]  printk (292)
> > 
[..]
> - But before that it dumps the kernel-messages from last boot and the prints
>   looked like this:

kmsg_dump()? a wild guess... any chance that you kmsg dumper iterates
log_buf records under logbuf_lock long enough to cause throttling on
other CPU, because printk_kthread is simply has to spin on logbuf_lock?

something like

CPU0						CPU1

console_unlock()				kmsg_dump()
{						{
							kmsg_dump_get_buffer()
							{
								spin_lock(&logbuf_lock)

	spin_lock(&logbuf_lock)					while (....) {
							 	^^^^^^^^^^^^^^ long enough
									...
								}
								spin_unlock(&logbuf_lock)
							}
	....					}
	spin_unlock(&logbuf_lock)

	call_console_drivers()

	cond_resched()
		RT throttling
			printk_deferred("RT throttling")
}

	-ss


>   [   12.805180] [    7.919623] **Some Kernel Messages here**
> 
> Double time-stamp here, because one was already present in the last KMSG (logs
> from previous boot).
> 
> After around 100 lines got printed, we had this throttling messages (without the
> double timestamp), and we continue to print things after it as well.
> 
> -- 
> viresh
>