From patchwork Wed Oct 17 23:06:54 2012 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Kevin Hilman X-Patchwork-Id: 1607891 Return-Path: X-Original-To: patchwork-linux-arm@patchwork.kernel.org Delivered-To: patchwork-process-083081@patchwork1.kernel.org Received: from merlin.infradead.org (merlin.infradead.org [205.233.59.134]) by patchwork1.kernel.org (Postfix) with ESMTP id 8D0C23FD4F for ; Wed, 17 Oct 2012 23:08:45 +0000 (UTC) Received: from localhost ([::1] helo=merlin.infradead.org) by merlin.infradead.org with esmtp (Exim 4.76 #1 (Red Hat Linux)) id 1TOchL-00034d-9V; Wed, 17 Oct 2012 23:06:47 +0000 Received: from mail-pa0-f49.google.com ([209.85.220.49]) by merlin.infradead.org with esmtps (Exim 4.76 #1 (Red Hat Linux)) id 1TOchI-000347-1P for linux-arm-kernel@lists.infradead.org; Wed, 17 Oct 2012 23:06:44 +0000 Received: by mail-pa0-f49.google.com with SMTP id bi5so7937807pad.36 for ; Wed, 17 Oct 2012 16:06:41 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=20120113; h=from:to:cc:subject:organization:references:date:in-reply-to :message-id:user-agent:mime-version:content-type:x-gm-message-state; bh=J7+Cly2OtdTT4NyuJINQbqm1ioHVB3AgqfjWQjkk6Ug=; b=KKRXC259e5pP0KKrz8B2+e3Zc+LVRwdR0XADAGb5Oo8Py8NGMNOTCn/CCbB/0WLt71 4LrcnP0YNf1lAYhR9UpOL4SBV0E88TAaAk1iVLjubdVl+9oW4tl4ib/Gt3bYPK7+2m2V GgbMrSVH6TI6ME+ZVuuytIbTKw4+IEG2uUHw2fqR5z+5+JeDaxAy6qfeMPSjGrvZo8NP 7ygU5hehq24mdVu7jRsLEfmsXIwmBqDby9wgZBbHz9Bqij6V3HbeFxxIX9WFrjibg0N5 W6imx2BcqZGrIALo0t+kM5U4WfTOLgc+DufcorgIIznsfgyEnDKPDfX+EBB2XMyERPr4 zLbA== Received: by 10.66.77.201 with SMTP id u9mr54429811paw.6.1350515201021; Wed, 17 Oct 2012 16:06:41 -0700 (PDT) Received: from localhost (c-24-19-7-36.hsd1.wa.comcast.net. [24.19.7.36]) by mx.google.com with ESMTPS id k4sm13275227pax.7.2012.10.17.16.06.39 (version=TLSv1/SSLv3 cipher=OTHER); Wed, 17 Oct 2012 16:06:39 -0700 (PDT) From: Kevin Hilman To: Subject: Re: RT throttling and suspend/resume (was Re: [PATCH] i2c: omap: revert "i2c: omap: switch to threaded IRQ support") Organization: Deep Root Systems, LLC References: <20121016133356.GG21801@arwen.pp.htv.fi> <87ipaanljt.fsf_-_@deeprootsystems.com> <20121017140002.GI11394@arwen.pp.htv.fi> <20121017143534.GJ11394@arwen.pp.htv.fi> Date: Wed, 17 Oct 2012 16:06:54 -0700 In-Reply-To: <20121017143534.GJ11394@arwen.pp.htv.fi> (Felipe Balbi's message of "Wed, 17 Oct 2012 17:35:34 +0300") Message-ID: <87txtsitpt.fsf@deeprootsystems.com> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/23.3 (gnu/linux) MIME-Version: 1.0 X-Gm-Message-State: ALoCoQmJiIJz55zdlViOXgrDX7+gTNZRnYdxUAsHkMYgVrsVEbCwvwZf7p9jDmKx9986eD/GyKf9 X-Spam-Note: CRM114 invocation failed X-Spam-Score: -2.6 (--) X-Spam-Report: SpamAssassin version 3.3.2 on merlin.infradead.org summary: Content analysis details: (-2.6 points) pts rule name description ---- ---------------------- -------------------------------------------------- -0.7 RCVD_IN_DNSWL_LOW RBL: Sender listed at http://www.dnswl.org/, low trust [209.85.220.49 listed in list.dnswl.org] -1.9 BAYES_00 BODY: Bayes spam probability is 0 to 1% [score: 0.0000] Cc: Paul Walmsley , Peter Zijlstra , Wolfram Sang , Shubhrajyoti Datta , linux-i2c@vger.kernel.org, Ben Dooks , Thomas Gleixner , linux-omap@vger.kernel.org, Shubhrajyoti D , linux-arm-kernel@lists.infradead.org X-BeenThere: linux-arm-kernel@lists.infradead.org X-Mailman-Version: 2.1.14 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Sender: linux-arm-kernel-bounces@lists.infradead.org Errors-To: linux-arm-kernel-bounces+patchwork-linux-arm=patchwork.kernel.org@lists.infradead.org Felipe Balbi writes: > On Wed, Oct 17, 2012 at 05:00:02PM +0300, Felipe Balbi wrote: >> >> On Tue, Oct 16, 2012 at 02:39:50PM -0700, Kevin Hilman wrote: >> > + peterz, tglx >> > >> > Felipe Balbi writes: >> > >> > [...] >> > >> > > The problem I see is that even though we properly return IRQ_WAKE_THREAD >> > > and wake_up_process() manages to wakeup the IRQ thread (it returns 1), >> > > the thread is never scheduled. To make things even worse, ouw irq thread >> > > runs once, but doesn't run on a consecutive call. Here's some (rather >> > > nasty) debug prints showing the problem: >> > >> > [...] >> > >> > >> [ 88.721923] try_to_wake_up 1411 >> > >> [ 88.725189] ===> irq_wake_thread 139: IRQ 72 wake_up_process 0 >> > >> [ 88.731292] [sched_delayed] sched: RT throttling activated >> > >> > This throttling message is the key one. >> > >> > With RT throttling activated, the IRQ thread will not be run (it >> > eventually will be allowed much later on, but by then, the I2C xfers >> > have timed out.) >> > >> > As a quick hack, the throttling can be disabled by seeting the >> > sched_rt_runtime to RUNTIME_INF: >> > >> > # sysctl -w kernel.sched_rt_runtime_us=-1 >> > >> > and a quick test shows that things go back to working as expected. But >> > we still need to figure out why the throttling is hapenning... >> > >> > So I started digging into why the RT runtime was so high, and noticed >> > that time spent in suspend was being counted as RT runtime! >> > >> > So spending time in suspend anywhere near sched_rt_runtime (0.95s) will >> > cause the RT throttling to always be triggered, and thus prevent IRQ >> > threads from running in the resume path. Ouch. >> > >> > I think I'm already in over my head in the RT runtime stuff, but >> > counting the time spent in suspend as RT runtime smells like a bug to >> > me. no? >> > >> > Peter? Thomas? >> >> it looks like removing console output completely (echo 0 > >> /proc/sysrq-trigger) I don't see the issue anymore. Let me just run for >> a few more iterations to make sure what I'm saying is correct. > > Yeah, really looks like removing console output makes the problem go > away. Ran a few iterations and it always worked fine. Full logs attached Removing console output during resume is going to significantly change the timing of what is happening during suspend/resume, so I suspect that combined with all your other debug prints is somehow masking the problem. How log are you letting the system stay in suspend? That being said, I can still easily reproduce the problem, even with console output disabled. With vanilla v3.7-rc1 + the debug patch below[1], with and without console output, I see RT throttling kicking in on resume, and the RT runtime on resume corresponds to the time spent in suspend. Here's an example of debug output of my patch below after ~3 sec in suspend: [ 43.198028] sched_rt_runtime_exceeded: rt_time 2671752930 > runtime 950000000 [ 43.198028] update_curr_rt: RT runtime exceeded: irq/72-omap_i2c [ 43.198059] update_curr_rt: RT runtime exceeded: irq/72-omap_i2c [ 43.203704] [sched_delayed] sched: RT throttling activated I see this rather consistently, and the rt_time value is always roughly the time I spent in suspend. So the primary question remains: is RT runtime supposed to include the time spent suspended? I suspect not. Kevin [1] diff --git a/kernel/sched/rt.c b/kernel/sched/rt.c index 418feb0..39de750 100644 --- a/kernel/sched/rt.c +++ b/kernel/sched/rt.c @@ -891,6 +891,8 @@ static int sched_rt_runtime_exceeded(struct rt_rq *rt_rq) if (!once) { once = true; printk_sched("sched: RT throttling activated\n"); + pr_warn("%s: rt_time %llu > runtime %llu\n", + __func__, rt_rq->rt_time, runtime); } } else { /* @@ -948,8 +950,11 @@ static void update_curr_rt(struct rq *rq) if (sched_rt_runtime(rt_rq) != RUNTIME_INF) { raw_spin_lock(&rt_rq->rt_runtime_lock); rt_rq->rt_time += delta_exec; - if (sched_rt_runtime_exceeded(rt_rq)) + if (sched_rt_runtime_exceeded(rt_rq)) { + pr_warn("%s: RT runtime exceeded: %s\n", + __func__, curr->comm); resched_task(curr); + } raw_spin_unlock(&rt_rq->rt_runtime_lock); } }