[RFC,v2] : Issues implementing clock handling mechanism within UART driver

Commit Message

Govindraj R July 29, 2011, 3:13 p.m. UTC

On Fri, Jul 29, 2011 at 7:32 PM, Felipe Balbi <[e-mail]> 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 <[e-mail]> 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:

<<SNIP>>

 		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);
+			}
 		}


<<SNIP>>


>
> 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

Comments

Felipe Balbi Aug. 1, 2011, 9:03 a.m. UTC | #1

Hi,

On Fri, Jul 29, 2011 at 08:43:49PM +0530, Govindraj wrote:

[giant snip]

> Actually there is much more than this:
> 
> <<SNIP>>
> 
> 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

trailing... but you know that :-p

> @@ -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());

this hunk is unnecessary. Clocks are always on when they are called.

> @@ -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);

these two is ok.

> 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

trailing.

> @@ -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);

instead of doing checks, you could move the print to the end of the
function, when clocks are already enabled. When doind that, of course,
update the comment to say "%s: clocks enabled\n".

> @@ -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);

check not needed, clocks are still on.

> 
>  	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);

move it further down.

> @@ -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);

instead of adding check, move the print before _disable_clocks(oh).

> @@ -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);

I believe clocks are still on here too, no checks needed.

> 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

trailing.

> @@ -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);

move it to the end of the function.

> @@ -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);

move it further down.

> 
>  		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);

->activate_func() has already been called here, clocks are already on.

> @@ -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);

clocks are still on here.

> @@ -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);

I'll leave this to Kevin to decide what to do, but clocks are off
here...

>  		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);
> +			}

and here...

Govindraj.R Aug. 1, 2011, 9:56 a.m. UTC | #2

On Mon, Aug 1, 2011 at 2:33 PM, Felipe Balbi <[e-mail]> wrote:

> Hi,
>
> On Fri, Jul 29, 2011 at 08:43:49PM +0530, Govindraj wrote:
>
> [giant snip]
>
> > Actually there is much more than this:
> >
> > <<SNIP>>
> >
> > 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
>
> trailing... but you know that :-p
>

yes true.


> > @@ -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());
>
> this hunk is unnecessary. Clocks are always on when they are called.
>

The problem is:

[1]:

runtime_put -> *power.lock* - > rpm->suspend -> above pr_debug ->
console_write -> get_sync

-> *power.lock* -> rpm resume

power.lock contention.



>
> > @@ -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);
>
> these two is ok.
>
> > 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
>
> trailing.
>
> > @@ -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);
>
> instead of doing checks, you could move the print to the end of the
> function, when clocks are already enabled. When doind that, of course,
> update the comment to say "%s: clocks enabled\n".
>


the problem is the prints causing power.lock contention same as
the scenario in [1] above.



>
> > @@ -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);
>
> check not needed, clocks are still on.
>

scenario [1]



>
> >
> >       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);
>
> move it further down.
>
> > @@ -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);
>
> instead of adding check, move the print before _disable_clocks(oh).
>
> > @@ -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);
>
> I believe clocks are still on here too, no checks needed.
>
> > 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
>
> trailing.
>
> > @@ -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);
>
> move it to the end of the function.
>
> > @@ -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);
>
> move it further down.
>
> >
> >               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);
>
> ->activate_func() has already been called here, clocks are already on.
>
> > @@ -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
> );
>
> clocks are still on here.
>
> > @@ -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);
>
> I'll leave this to Kevin to decide what to do, but clocks are off
> here...
>

Yes fine.

Since most of these prints will be printed if DEBUG macro
is defined in respective files and *debug* is used in command line.

Can't leave uart clocks active always on debug cases.
[If *debug*  used as command line]
and gate uart clocks only for non debug cases.

With this approach at least we can have a clean solution
in uart driver also without adding clock gating from idle path.

Not sure if this agreeable.

As of now gating from idle path seems to be only clean approach.

Govindraj R Aug. 1, 2011, 10 a.m. UTC | #3

> Hi,
>
> On Fri, Jul 29, 2011 at 08:43:49PM +0530, Govindraj wrote:
>
> [giant snip]
>
> > Actually there is much more than this:
> >
> > <<SNIP>>
> >
> > 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
>
> trailing... but you know that :-p
>

yes true.


> > @@ -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());
>
> this hunk is unnecessary. Clocks are always on when they are called.
>

The problem is:

[1]:

runtime_put -> *power.lock* - > rpm->suspend -> above pr_debug ->
console_write -> get_sync

-> *power.lock* -> rpm resume

power.lock contention.



>
> > @@ -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);
>
> these two is ok.
>
> > 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
>
> trailing.
>
> > @@ -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);
>
> instead of doing checks, you could move the print to the end of the
> function, when clocks are already enabled. When doind that, of course,
> update the comment to say "%s: clocks enabled\n".
>


the problem is the prints causing power.lock contention same as
the scenario in [1] above.



>
> > @@ -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);
>
> check not needed, clocks are still on.
>

scenario [1]



>
> >
> >       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);
>
> move it further down.
>
> > @@ -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);
>
> instead of adding check, move the print before _disable_clocks(oh).
>
> > @@ -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);
>
> I believe clocks are still on here too, no checks needed.
>
> > 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
>
> trailing.
>
> > @@ -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);
>
> move it to the end of the function.
>
> > @@ -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);
>
> move it further down.
>
> >
> >               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);
>
> ->activate_func() has already been called here, clocks are already on.
>
> > @@ -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
> );
>
> clocks are still on here.
>
> > @@ -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);
>
> I'll leave this to Kevin to decide what to do, but clocks are off
> here...
>

Yes fine.

Since most of these prints will be printed if DEBUG macro
is defined in respective files and *debug* is used in command line.

Can't leave uart clocks active always on debug cases.
[If *debug*  used as command line]
and gate uart clocks only for non debug cases.

With this approach at least we can have a clean solution
in uart driver also without adding clock gating from idle path.

Not sure if this agreeable.

As of now gating from idle path seems to be only clean approach.

Felipe Balbi Aug. 1, 2011, 10:02 a.m. UTC | #4

Hi,

(fix your mailer dude)

On Mon, Aug 01, 2011 at 03:26:52PM +0530, Raja, Govindraj wrote:
>      > @@ -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());
> 
>      this hunk is unnecessary. Clocks are always on when they are called.
> 
>    The problem is:
>    [1]:
>    runtime_put -> *power.lock* - > rpm->suspend -> above pr_debug ->
>    console_write -> get_sync
>    -> *power.lock* -> rpm resume
>    power.lock contention.

Are you sure ? If the device is still on, won't that get_sync() only
increase the pm counter ? Instead of going through everything ?? Oh
well, this is becoming quite racy :-(

>      > @@ -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);
> 
>      these two is ok.
>      > 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
> 
>      trailing.
>      > @@ -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);
> 
>      instead of doing checks, you could move the print to the end of the
>      function, when clocks are already enabled. When doind that, of course,
>      update the comment to say "%s: clocks enabled\n".
> 
>    the problem is the prints causing power.lock contention same as?
>    the?scenario?in [1] above.
>    ?
> 
>      > @@ -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);
> 
>      check not needed, clocks are still on.
> 
>    scenario?[1]
>    ?
> 
>      >
>      > ? ? ? 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);
> 
>      move it further down.
>      > @@ -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);
> 
>      instead of adding check, move the print before _disable_clocks(oh).
>      > @@ -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);
> 
>      I believe clocks are still on here too, no checks needed.
>      > 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
> 
>      trailing.
>      > @@ -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->[2]pdev.name);
>      > + ? ? if (strcmp(od->hwmods[0]->class->name, "uart"))
>      > + ? ? ? ? ? ? pr_debug("omap_device: %s: activating\n",
>      od->[3]pdev.name);
> 
>      move it to the end of the function.
>      > @@ -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->[4]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->[5]pdev.name,
>      od->pm_lat_level,
>      > + ? ? ? ? ? ? ? ? ? ? ? ? ? ? ?act_lat);
> 
>      move it further down.
>      >
>      > ? ? ? ? ? ? ? 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->[6]pdev.name,
>      od->[7]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->[8]pdev.name,
>      od->[9]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->[10]pdev.name,
>      od->[11]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->[12]pdev.name,
>      od->[13]pdev.id,
>      > + ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? od->pm_lat_level,
>      act_lat,
>      > + ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? odpl->activate_lat);
> 
>      ->activate_func() has already been called here, clocks are already on.
>      > @@ -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->[14]pdev.name);
>      > + ? ? if (strcmp(od->hwmods[0]->class->name, "uart"))
>      > + ? ? ? ? ? ? pr_debug("omap_device: %s: deactivating\n",
>      od->[15]pdev.name);
> 
>      clocks are still on here.
>      > @@ -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->[16]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->[17]pdev.name,
>      od->pm_lat_level,
>      > + ? ? ? ? ? ? ? ? ? ? ? ? ? ? ?deact_lat);
> 
>      I'll leave this to Kevin to decide what to do, but clocks are off
>      here...
> 
>    Yes fine.?
>    Since most of these prints will be printed if DEBUG macro
>    is defined in respective files and *debug* is used in command line.
>    Can't leave uart clocks active always on debug cases.
>    [If *debug* ?used as command line]
>    and gate uart clocks only for non debug cases.
>    With this approach?at least?we can have a clean solution
>    in uart driver also without adding clock gating from idle path.
>    Not sure if this?agreeable.
>    As of now gating from idle path seems to be only clean approach.

I see.. that could be one way... let's see how Kevin feels about it
though.

Govindraj R Aug. 1, 2011, 12:46 p.m. UTC | #5

On Mon, Aug 1, 2011 at 3:32 PM, Felipe Balbi <[e-mail]> wrote:
> Hi,
>
> (fix your mailer dude)

Sorry some settings got screwed up with my mailer

>
> On Mon, Aug 01, 2011 at 03:26:52PM +0530, Raja, Govindraj wrote:

[..]

>>      this hunk is unnecessary. Clocks are always on when they are called.
>>
>>    The problem is:
>>    [1]:
>>    runtime_put -> *power.lock* - > rpm->suspend -> above pr_debug ->
>>    console_write -> get_sync
>>    -> *power.lock* -> rpm resume
>>    power.lock contention.
>
> Are you sure ? If the device is still on, won't that get_sync() only
> increase the pm counter ? Instead of going through everything ?? Oh
> well, this is becoming quite racy :-(

Yes true, but before it increments the counter it will take
power.lock

if we look into internals.

pm_runtime_get_sync -> *__pm_runtime_resume* --> rpm_resume

int __pm_runtime_resume(struct device *dev, int rpmflags)
{
 [..]
        spin_lock_irqsave(&dev->power.lock, flags);
        retval = rpm_resume(dev, rpmflags);
        spin_unlock_irqrestore(&dev->power.lock, flags);
[..]
}

Same applicable for runtime_put

[..]
>>      I'll leave this to Kevin to decide what to do, but clocks are off
>>      here...
>>
>>    Yes fine.?
>>    Since most of these prints will be printed if DEBUG macro
>>    is defined in respective files and *debug* is used in command line.
>>    Can't leave uart clocks active always on debug cases.
>>    [If *debug* ?used as command line]
>>    and gate uart clocks only for non debug cases.
>>    With this approach?at least?we can have a clean solution
>>    in uart driver also without adding clock gating from idle path.
>>    Not sure if this?agreeable.
>>    As of now gating from idle path seems to be only clean approach.
>
> I see.. that could be one way... let's see how Kevin feels about it
> though.
>

OK.

--
Thanks,
Govindraj.R

Patch

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 <linux/kernel.h>
 #include <linux/list.h>
@@ -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 <linux/kernel.h>
 #include <linux/errno.h>
@@ -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 <linux/kernel.h>
 #include <linux/platform_device.h>
@@ -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) {