From patchwork Fri Jul 29 15:13:49 2011 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 8bit X-Patchwork-Submitter: Govindraj R X-Patchwork-Id: 1020922 Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by demeter2.kernel.org (8.14.4/8.14.4) with ESMTP id p6TFEFOS031420 for ; Fri, 29 Jul 2011 15:14:16 GMT Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751815Ab1G2POM (ORCPT ); Fri, 29 Jul 2011 11:14:12 -0400 Received: from mail-wy0-f174.google.com ([74.125.82.174]:41466 "EHLO mail-wy0-f174.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751758Ab1G2POL convert rfc822-to-8bit (ORCPT ); Fri, 29 Jul 2011 11:14:11 -0400 Received: by wyg8 with SMTP id 8so251280wyg.19 for ; Fri, 29 Jul 2011 08:14:09 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=mime-version:in-reply-to:references:from:date:message-id:subject:to :cc:content-type:content-transfer-encoding; bh=H8VncDxQJAYf59HCu4sgSz5CLTfzkM9XrkrvC7XxAtI=; b=TfBONf5QBAZcy83z0cZUvkWieimpuDYZcf1CNKf+2SmloMPVEIlkwWJQdvqhc/j69U O0kcY0W3SIPyc/P3vM7V8CfoKxavg0I6PyOFOSE7tnz+6CsYjuUf0JTIxS/DJzeiYozP hEkkBoMuN/7rYAoxj6YijLvyxDRjF31wACdhg= Received: by 10.204.17.19 with SMTP id q19mr430458bka.107.1311952449279; Fri, 29 Jul 2011 08:14:09 -0700 (PDT) MIME-Version: 1.0 Received: by 10.204.10.70 with HTTP; Fri, 29 Jul 2011 08:13:49 -0700 (PDT) In-Reply-To: <20110729140210.GT31013@legolas.emea.dhcp.ti.com> References: <1311845395-31917-1-git-send-email-govindraj.raja@ti.com> <20110729095512.GE31013@legolas.emea.dhcp.ti.com> <20110729113713.GK31013@legolas.emea.dhcp.ti.com> <20110729121907.GM31013@legolas.emea.dhcp.ti.com> <20110729140210.GT31013@legolas.emea.dhcp.ti.com> From: Govindraj Date: Fri, 29 Jul 2011 20:43:49 +0530 Message-ID: Subject: Re: [RFC v2]: Issues implementing clock handling mechanism within UART driver To: balbi@ti.com Cc: "Govindraj.R" , linux-omap@vger.kernel.org, linux-serial@vger.kernel.org, linux-pm@lists.linux-foundation.org, "Rafael J. Wysocki" , Paul Walmsley , Kevin Hilman , Vishwanath Sripathy , Partha Basak , Santosh Shilimkar , Rajendra Nayak , Benoit Cousson , Tero Kristo Sender: linux-omap-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-omap@vger.kernel.org X-Greylist: IP, sender and recipient auto-whitelisted, not delayed by milter-greylist-4.2.6 (demeter2.kernel.org [140.211.167.43]); Fri, 29 Jul 2011 15:14:16 +0000 (UTC) On Fri, Jul 29, 2011 at 7:32 PM, Felipe Balbi wrote: > Hi, > > On Fri, Jul 29, 2011 at 06:28:32PM +0530, Govindraj wrote: >> On Fri, Jul 29, 2011 at 5:49 PM, Felipe Balbi wrote: >> > On Fri, Jul 29, 2011 at 05:29:12PM +0530, Govindraj wrote: >> >> Yes fine, But there are scenarios even before first runtime_suspend happens, >> >> >> >> ex: uart_port_configure -> get_sync -> pm_generic_runtime_resume >> >> (omap_device_enable in this case) debug printk -> console_write -> get_sync. >> >> >> >> there are numerous such scenarios where we end from runtime context >> >> to runtime api context again, or jumping from one uart port operation >> >> to uart print operation. >> > >> > calling pm_runtime_get_sync() should not be a problem. It should only >> > increase the usage counters... This sounds like a race condition on the >> > driver, no ? >> >> Actually when we call a API to enable clocks we except the internals of API >> to just enable clocks and return. >> >> *Clock enable API should not cause or trigger to do a _device_driver_operation_ >> even before enabling clocks of the device-driver which called it* >> >> for uart context get_sync can land me to uart driver back >> even before enabling the uart clocks due to printks. > > only if _you_ have prints or _your_ runtime_*() calls, no ? > > Let's say omap_hwmod.c wants to do a print: > > -> printk() >  -> pm_runtime_get_sync >    -> console_write >  -> pm_runtim_put > > now, if you have a printk() on your runtime_resume() before you enable > the clocks, then I can see why you would deadlock: > > -> pm_runtime_get_sync >  -> omap_serial_runtime_resume >    -> printk >      -> pm_runtime_get_sync >        -> omap_serial_runtime_resume >          -> printk >           -> pm_runtime_get_sync >            ..... > > maybe I'm missing something, but can you add a stack dump on your > ->runtime_resume and ->runtime_suspend methods, just so we try to figure > out who's to blame here ? > >> > What you're experiencing, if I understood correctly, is a deadlock ? In >> > that case, can you try to track the locking mechanism on the omap-serial >> > driver to try to find if there isn't anything obviously wrong ? >> > >> >> Yes deadlocks. due to entering from runtime context to runtime context >> or entering from uart_port_operation to uart_console_write ops. >> >> There are already port locks used extensively within the uart driver >> to secure a port operation. >> >> But cannot secure a port operation while using clock_enable API. >> since clock enable API can land the control back to uart_console_write >> operation.. > > but in that case, if clock isn't enabled, why don't you just ignore the > print and enable the clock ?? Just return 0 and continue with > clk_enable() ?? > >> >> So either we should not have those prints from pm_generic layers or suppress >> >> them(seems pretty much a problem for a clean design within the driver >> >> using console_lock/unlock for every get_sync, and for >> >> runtime_put we cannot suppress the prints as it gets scheduled later) >> >> >> >> or if other folks who really need those prints form pm_generic* layers >> >> to debug and analysis then we have no other choice rather control >> >> the clk_enable/disable from outside driver code in idle path. >> > >> > yeah, none of these would be nice :-( >> > >> > I think this needs more debugging to be sure what's exactly going on. >> > What's exactly causing the deadlock ? Which lock is held and never >> > released ? >> > >> >> I had done some investigations, from scenarios it simply boils down to fact >> to handle clock within uart driver, uart driver expects clock enable API* used >> to just enable uart clocks but rather not trigger a _uart_ops_ within which >> kind of unacceptable from the uart_driver context. > > ok, now I see what you mean: > > 113 static int _omap_device_activate(struct omap_device *od, u8 ignore_lat) > 114 { > 115         struct timespec a, b, c; > 116 > 117         pr_debug("omap_device: %s: activating\n", od->pdev.name); > 118 > 119         while (od->pm_lat_level > 0) { > 120                 struct omap_device_pm_latency *odpl; > 121                 unsigned long long act_lat = 0; > 122 > 123                 od->pm_lat_level--; > 124 > 125                 odpl = od->pm_lats + od->pm_lat_level; > 126 > 127                 if (!ignore_lat && > 128                     (od->dev_wakeup_lat <= od->_dev_wakeup_lat_limit)) > 129                         break; > 130 > 131                 read_persistent_clock(&a); > 132 > 133                 /* XXX check return code */ > 134                 odpl->activate_func(od); > 135 > 136                 read_persistent_clock(&b); > 137 > 138                 c = timespec_sub(b, a); > 139                 act_lat = timespec_to_ns(&c); > 140 > 141                 pr_debug("omap_device: %s: pm_lat %d: activate: elapsed time " > 142                          "%llu nsec\n", od->pdev.name, od->pm_lat_level, > 143                          act_lat); > 144 > 145                 if (act_lat > odpl->activate_lat) { > 146                         odpl->activate_lat_worst = act_lat; > 147                         if (odpl->flags & OMAP_DEVICE_LATENCY_AUTO_ADJUST) { > 148                                 odpl->activate_lat = act_lat; > 149                                 pr_warning("omap_device: %s.%d: new worst case " > 150                                            "activate latency %d: %llu\n", > 151                                            od->pdev.name, od->pdev.id, > 152                                            od->pm_lat_level, act_lat); > 153                         } else > 154                                 pr_warning("omap_device: %s.%d: activate " > 155                                            "latency %d higher than exptected. " > 156                                            "(%llu > %d)\n", > 157                                            od->pdev.name, od->pdev.id, > 158                                            od->pm_lat_level, act_lat, > 159                                            odpl->activate_lat); > 160                 } > 161 > 162                 od->dev_wakeup_lat -= odpl->activate_lat; > 163         } > 164 > 165         return 0; > 166 } > > When that first pr_debug() triggers, UART's hwmod could be disabled, and > that would trigger the state I described above where you would keep on > calling pm_runtime_get_sync() forever ;-) > > isn't it enough to patch it like below: > > diff --git a/arch/arm/plat-omap/omap_device.c b/arch/arm/plat-omap/omap_device.c > index b6b4097..560f622 100644 > --- a/arch/arm/plat-omap/omap_device.c > +++ b/arch/arm/plat-omap/omap_device.c > @@ -114,8 +114,6 @@ static int _omap_device_activate(struct omap_device *od, u8 ignore_lat) >  { >        struct timespec a, b, c; > > -       pr_debug("omap_device: %s: activating\n", od->pdev.name); > - >        while (od->pm_lat_level > 0) { >                struct omap_device_pm_latency *odpl; >                unsigned long long act_lat = 0; > @@ -162,6 +160,8 @@ static int _omap_device_activate(struct omap_device *od, u8 ignore_lat) >                od->dev_wakeup_lat -= odpl->activate_lat; >        } > > +       pr_debug("omap_device: %s: activated\n", od->pdev.name); > + >        return 0; >  } > Actually there is much more than this: <> struct omap_device_pm_latency *odpl; @@ -138,25 +140,29 @@ static int _omap_device_activate(struct omap_device *od, u8 ignore_lat) c = timespec_sub(b, a); act_lat = timespec_to_ns(&c); - pr_debug("omap_device: %s: pm_lat %d: activate: elapsed time " - "%llu nsec\n", od->pdev.name, od->pm_lat_level, - act_lat); + if (strcmp(od->hwmods[0]->class->name, "uart")) + pr_debug("omap_device: %s: pm_lat %d: activate: elapsed time " + "%llu nsec\n", od->pdev.name, od->pm_lat_level, + act_lat); if (act_lat > odpl->activate_lat) { odpl->activate_lat_worst = act_lat; if (odpl->flags & OMAP_DEVICE_LATENCY_AUTO_ADJUST) { odpl->activate_lat = act_lat; - pr_warning("omap_device: %s.%d: new worst case " - "activate latency %d: %llu\n", - od->pdev.name, od->pdev.id, - od->pm_lat_level, act_lat); - } else - pr_warning("omap_device: %s.%d: activate " - "latency %d higher than exptected. " - "(%llu > %d)\n", - od->pdev.name, od->pdev.id, - od->pm_lat_level, act_lat, - odpl->activate_lat); + if (strcmp(od->hwmods[0]->class->name, "uart")) + pr_warning("omap_device: %s.%d: new worst case " + "activate latency %d: %llu\n", + od->pdev.name, od->pdev.id, + od->pm_lat_level, act_lat); + } else { + if (strcmp(od->hwmods[0]->class->name, "uart")) + pr_warning("omap_device: %s.%d: activate " + "latency %d higher than exptected. " + "(%llu > %d)\n", + od->pdev.name, od->pdev.id, + od->pm_lat_level, act_lat, + odpl->activate_lat); + } } od->dev_wakeup_lat -= odpl->activate_lat; @@ -183,7 +189,8 @@ static int _omap_device_deactivate(struct omap_device *od, u8 ignore_lat) { struct timespec a, b, c; - pr_debug("omap_device: %s: deactivating\n", od->pdev.name); + if (strcmp(od->hwmods[0]->class->name, "uart")) + pr_debug("omap_device: %s: deactivating\n", od->pdev.name); while (od->pm_lat_level < od->pm_lats_cnt) { struct omap_device_pm_latency *odpl; @@ -206,25 +213,29 @@ static int _omap_device_deactivate(struct omap_device *od, u8 ignore_lat) c = timespec_sub(b, a); deact_lat = timespec_to_ns(&c); - pr_debug("omap_device: %s: pm_lat %d: deactivate: elapsed time " - "%llu nsec\n", od->pdev.name, od->pm_lat_level, - deact_lat); + if (strcmp(od->hwmods[0]->class->name, "uart")) + pr_debug("omap_device: %s: pm_lat %d: deactivate: elapsed time " + "%llu nsec\n", od->pdev.name, od->pm_lat_level, + deact_lat); if (deact_lat > odpl->deactivate_lat) { odpl->deactivate_lat_worst = deact_lat; if (odpl->flags & OMAP_DEVICE_LATENCY_AUTO_ADJUST) { odpl->deactivate_lat = deact_lat; - pr_warning("omap_device: %s.%d: new worst case " - "deactivate latency %d: %llu\n", - od->pdev.name, od->pdev.id, - od->pm_lat_level, deact_lat); - } else - pr_warning("omap_device: %s.%d: deactivate " + if (strcmp(od->hwmods[0]->class->name, "uart")) + pr_warning("omap_device: %s.%d: new worst case " + "deactivate latency %d: %llu\n", + od->pdev.name, od->pdev.id, + od->pm_lat_level, deact_lat); + } else { + if (strcmp(od->hwmods[0]->class->name, "uart")) + pr_warning("omap_device: %s.%d: deactivate " "latency %d higher than exptected. " "(%llu > %d)\n", od->pdev.name, od->pdev.id, od->pm_lat_level, deact_lat, odpl->deactivate_lat); + } } <> > > either the above or something like: > > if (pm_runtime_suspended(dev)) >        return 0; > > on console_write() ?? Consider the scenario where after bootup uart is idled with runtime auto suspend so now state of console uart is RPM_SUSPENDED. Now you connect a pendrive to ehci-port. Missing critical usb host <-> device_enumeration prints? uart_console rpm_suspended state -> usb_device mass storage device found print -> console_write -> return without printing. --- Thanks, Govindraj.R -- To unsubscribe from this list: send the line "unsubscribe linux-omap" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html diff --git a/arch/arm/mach-omap2/clock.c b/arch/arm/mach-omap2/clock.c index 180299e..221ffb9 100644 --- a/arch/arm/mach-omap2/clock.c +++ b/arch/arm/mach-omap2/clock.c @@ -12,7 +12,8 @@ * it under the terms of the GNU General Public License version 2 as * published by the Free Software Foundation. */ -#undef DEBUG +//#undef DEBUG +#define DEBUG #include #include @@ -254,14 +255,14 @@ void omap2_clk_disable(struct clk *clk) return; } - pr_debug("clock: %s: decrementing usecount\n", clk->name); +// pr_debug("clock: %s: decrementing usecount\n", clk->name); clk->usecount--; if (clk->usecount > 0) return; - pr_debug("clock: %s: disabling in hardware\n", clk->name); +// pr_debug("clock: %s: disabling in hardware\n", clk->name); if (clk->ops && clk->ops->disable) { trace_clock_disable(clk->name, 0, smp_processor_id()); @@ -290,14 +291,14 @@ int omap2_clk_enable(struct clk *clk) { int ret; - pr_debug("clock: %s: incrementing usecount\n", clk->name); +// pr_debug("clock: %s: incrementing usecount\n", clk->name); clk->usecount++; if (clk->usecount > 1) return 0; - pr_debug("clock: %s: enabling in hardware\n", clk->name); +// pr_debug("clock: %s: enabling in hardware\n", clk->name); if (clk->parent) { ret = omap2_clk_enable(clk->parent); diff --git a/arch/arm/mach-omap2/omap_hwmod.c b/arch/arm/mach-omap2/omap_hwmod.c index 7ed0479..8ca7d40 100644 --- a/arch/arm/mach-omap2/omap_hwmod.c +++ b/arch/arm/mach-omap2/omap_hwmod.c @@ -124,7 +124,8 @@ * XXX error return values should be checked to ensure that they are * appropriate */ -#undef DEBUG +//#undef DEBUG +#define DEBUG #include #include @@ -597,7 +598,8 @@ static int _enable_clocks(struct omap_hwmod *oh) { int i; - pr_debug("omap_hwmod: %s: enabling clocks\n", oh->name); + if (strcmp(oh->class->name, "uart")) + pr_debug("omap_hwmod: %s: enabling clocks\n", oh->name); if (oh->_clk) clk_enable(oh->_clk); @@ -627,7 +629,8 @@ static int _disable_clocks(struct omap_hwmod *oh) { int i; - pr_debug("omap_hwmod: %s: disabling clocks\n", oh->name); + if (strcmp(oh->class->name, "uart")) + pr_debug("omap_hwmod: %s: disabling clocks\n", oh->name); if (oh->_clk) clk_disable(oh->_clk); @@ -1232,7 +1235,8 @@ static int _enable(struct omap_hwmod *oh) return -EINVAL; } - pr_debug("omap_hwmod: %s: enabling\n", oh->name); + if (strcmp(oh->class->name, "uart")) + pr_debug("omap_hwmod: %s: enabling\n", oh->name); /* * If an IP contains only one HW reset line, then de-assert it in order @@ -1264,8 +1268,9 @@ static int _enable(struct omap_hwmod *oh) } } else { _disable_clocks(oh); - pr_debug("omap_hwmod: %s: _wait_target_ready: %d\n", - oh->name, r); + if (strcmp(oh->class->name, "uart")) + pr_debug("omap_hwmod: %s: _wait_target_ready: %d\n", + oh->name, r); } return r; @@ -1287,7 +1292,8 @@ static int _idle(struct omap_hwmod *oh) return -EINVAL; } - pr_debug("omap_hwmod: %s: idling\n", oh->name); + if (strcmp(oh->class->name, "uart")) + pr_debug("omap_hwmod: %s: idling\n", oh->name); if (oh->class->sysc) _idle_sysc(oh); diff --git a/arch/arm/plat-omap/omap_device.c b/arch/arm/plat-omap/omap_device.c index 49fc0df..7b27704 100644 --- a/arch/arm/plat-omap/omap_device.c +++ b/arch/arm/plat-omap/omap_device.c @@ -75,7 +75,8 @@ * (device must be reinitialized at this point to use it again) * */ -#undef DEBUG +//#undef DEBUG +#define DEBUG #include #include @@ -114,7 +115,8 @@ static int _omap_device_activate(struct omap_device *od, u8 ignore_lat) { struct timespec a, b, c; - pr_debug("omap_device: %s: activating\n", od->pdev.name); + if (strcmp(od->hwmods[0]->class->name, "uart")) + pr_debug("omap_device: %s: activating\n", od->pdev.name); while (od->pm_lat_level > 0) {