[PATCH] alarmtimer: add error prints when suspend failed

[PATCH] alarmtimer: add error prints when suspend failed

[Laxman Dewangan]

The alramtimer suspend failed when nearest alarm wakeup time is
less than 2 sec or rtc timer can not start.

In suspend/resume stress testing, we found that sometimes alramtimer
failed to suspend and hence it cancel the suspend ops. Add error prints
in suspend failure to provide more info when failure occurs to help
debugging.

Signed-off-by: Laxman Dewangan <ldewangan@nvidia.com>
---
 kernel/time/alarmtimer.c |    6 +++++-
 1 files changed, 5 insertions(+), 1 deletions(-)

diff --git a/kernel/time/alarmtimer.c b/kernel/time/alarmtimer.c
index f11d83b..eed5646 100644
--- a/kernel/time/alarmtimer.c
+++ b/kernel/time/alarmtimer.c
@@ -249,6 +249,8 @@ static int alarmtimer_suspend(struct device *dev)
 
 	if (ktime_to_ns(min) < 2 * NSEC_PER_SEC) {
 		__pm_wakeup_event(ws, 2 * MSEC_PER_SEC);
+		dev_err(dev,
+			"Nearest alarm wakeup time < 2sec, avoiding suspend\n");
 		return -EBUSY;
 	}
 
@@ -260,8 +262,10 @@ static int alarmtimer_suspend(struct device *dev)
 
 	/* Set alarm, if in the past reject suspend briefly to handle */
 	ret = rtc_timer_start(rtc, &rtctimer, now, ktime_set(0, 0));
-	if (ret < 0)
+	if (ret < 0) {
 		__pm_wakeup_event(ws, MSEC_PER_SEC);
+		dev_err(dev, "RTC timer start failed, %d\n", ret);
+	}
 	return ret;
 }
 #else
-- 
1.7.1.1

Re: [PATCH] alarmtimer: add error prints when suspend failed

[Greg KH]

On Fri, Mar 08, 2013 at 12:57:37AM +0530, Laxman Dewangan wrote:
> The alramtimer suspend failed when nearest alarm wakeup time is
> less than 2 sec or rtc timer can not start.
> 
> In suspend/resume stress testing, we found that sometimes alramtimer
> failed to suspend and hence it cancel the suspend ops. Add error prints
> in suspend failure to provide more info when failure occurs to help
> debugging.
> 
> Signed-off-by: Laxman Dewangan <ldewangan@nvidia.com>
> ---
>  kernel/time/alarmtimer.c |    6 +++++-
>  1 files changed, 5 insertions(+), 1 deletions(-)
> 
> diff --git a/kernel/time/alarmtimer.c b/kernel/time/alarmtimer.c
> index f11d83b..eed5646 100644
> --- a/kernel/time/alarmtimer.c
> +++ b/kernel/time/alarmtimer.c
> @@ -249,6 +249,8 @@ static int alarmtimer_suspend(struct device *dev)
>  
>  	if (ktime_to_ns(min) < 2 * NSEC_PER_SEC) {
>  		__pm_wakeup_event(ws, 2 * MSEC_PER_SEC);
> +		dev_err(dev,
> +			"Nearest alarm wakeup time < 2sec, avoiding suspend\n");

What can userspace now do with this information?  How often is this now
going to spam the syslog and cause confusion?

>  		return -EBUSY;
>  	}
>  
> @@ -260,8 +262,10 @@ static int alarmtimer_suspend(struct device *dev)
>  
>  	/* Set alarm, if in the past reject suspend briefly to handle */
>  	ret = rtc_timer_start(rtc, &rtctimer, now, ktime_set(0, 0));
> -	if (ret < 0)
> +	if (ret < 0) {
>  		__pm_wakeup_event(ws, MSEC_PER_SEC);
> +		dev_err(dev, "RTC timer start failed, %d\n", ret);

Same here, you aren't changing any code paths, just annoying people who
can't do anything about this.

As you want to do this for debugging, make them debugging level messages
please.

thanks,

greg k-h

Re: [PATCH] alarmtimer: add error prints when suspend failed

[Laxman Dewangan]

On Friday 08 March 2013 04:46 AM, Greg KH wrote:
> On Fri, Mar 08, 2013 at 12:57:37AM +0530, Laxman Dewangan wrote:
>> The alramtimer suspend failed when nearest alarm wakeup time is
>> less than 2 sec or rtc timer can not start.
>>
>> In suspend/resume stress testing, we found that sometimes alramtimer
>> failed to suspend and hence it cancel the suspend ops. Add error prints
>> in suspend failure to provide more info when failure occurs to help
>> debugging.
>>
>> Signed-off-by: Laxman Dewangan <ldewangan@nvidia.com>
>> ---
>>   kernel/time/alarmtimer.c |    6 +++++-
>>   1 files changed, 5 insertions(+), 1 deletions(-)
>>
>> diff --git a/kernel/time/alarmtimer.c b/kernel/time/alarmtimer.c
>> index f11d83b..eed5646 100644
>> --- a/kernel/time/alarmtimer.c
>> +++ b/kernel/time/alarmtimer.c
>> @@ -249,6 +249,8 @@ static int alarmtimer_suspend(struct device *dev)
>>   
>>   	if (ktime_to_ns(min) < 2 * NSEC_PER_SEC) {
>>   		__pm_wakeup_event(ws, 2 * MSEC_PER_SEC);
>> +		dev_err(dev,
>> +			"Nearest alarm wakeup time < 2sec, avoiding suspend\n");
> What can userspace now do with this information?  How often is this now
> going to spam the syslog and cause confusion?


When we executed the stress on suspend/resume for system stability, 
occasionally we get such error (3/4 times in 1000 cycle):
[ 235.508010] dpm_run_callback(): platform_pm_suspend+0x0/0x64 returns -16
[ 235.514999] PM: Device alarmtimer failed to suspend: error -16
[ 235.520958] PM: Some devices failed to suspend


After tracing back the failure case, we found that possible reason could 
be above one.
In this case, if any function returns error then always better to print 
the error so that it is easy to findout the cause of the error and analyse.

It should not generate spam as this does happen on some cases.

Re: [PATCH] alarmtimer: add error prints when suspend failed

[John Stultz]

On 03/07/2013 11:24 PM, Laxman Dewangan wrote:
> On Friday 08 March 2013 04:46 AM, Greg KH wrote:
>> On Fri, Mar 08, 2013 at 12:57:37AM +0530, Laxman Dewangan wrote:
>>> The alramtimer suspend failed when nearest alarm wakeup time is
>>> less than 2 sec or rtc timer can not start.
>>>
>>> In suspend/resume stress testing, we found that sometimes alramtimer
>>> failed to suspend and hence it cancel the suspend ops. Add error prints
>>> in suspend failure to provide more info when failure occurs to help
>>> debugging.
>>>
>>> Signed-off-by: Laxman Dewangan <ldewangan@nvidia.com>
>>> ---
>>>   kernel/time/alarmtimer.c |    6 +++++-
>>>   1 files changed, 5 insertions(+), 1 deletions(-)
>>>
>>> diff --git a/kernel/time/alarmtimer.c b/kernel/time/alarmtimer.c
>>> index f11d83b..eed5646 100644
>>> --- a/kernel/time/alarmtimer.c
>>> +++ b/kernel/time/alarmtimer.c
>>> @@ -249,6 +249,8 @@ static int alarmtimer_suspend(struct device *dev)
>>>         if (ktime_to_ns(min) < 2 * NSEC_PER_SEC) {
>>>           __pm_wakeup_event(ws, 2 * MSEC_PER_SEC);
>>> +        dev_err(dev,
>>> +            "Nearest alarm wakeup time < 2sec, avoiding suspend\n");
>> What can userspace now do with this information?  How often is this now
>> going to spam the syslog and cause confusion?
>
>
> When we executed the stress on suspend/resume for system stability, 
> occasionally we get such error (3/4 times in 1000 cycle):
> [ 235.508010] dpm_run_callback(): platform_pm_suspend+0x0/0x64 returns 
> -16
> [ 235.514999] PM: Device alarmtimer failed to suspend: error -16
> [ 235.520958] PM: Some devices failed to suspend
>
>
> After tracing back the failure case, we found that possible reason 
> could be above one.
> In this case, if any function returns error then always better to 
> print the error so that it is easy to findout the cause of the error 
> and analyse.
>
> It should not generate spam as this does happen on some cases.

But if there is a recurring alarm timer that triggers every second, it 
will print out every time.

Greg's concern is that the error message is unhelpful, since it just 
will cause lots of log messages when the system is actually behaving as 
designed. That said, the PM suspend messages are fairly noisy as well, 
even when there are no errors.

Rafael: What are your thoughts here? If the alarmtimer subsystem blocks 
a suspend attempt (returning EBUSY, as a pending alarm will fire soon), 
how verbose should we be, since this isn't really an error case?

thanks
-john

Re: [PATCH] alarmtimer: add error prints when suspend failed

[Rafael J. Wysocki]

On Monday, March 11, 2013 04:51:30 PM John Stultz wrote:
> On 03/07/2013 11:24 PM, Laxman Dewangan wrote:
> > On Friday 08 March 2013 04:46 AM, Greg KH wrote:
> >> On Fri, Mar 08, 2013 at 12:57:37AM +0530, Laxman Dewangan wrote:
> >>> The alramtimer suspend failed when nearest alarm wakeup time is
> >>> less than 2 sec or rtc timer can not start.
> >>>
> >>> In suspend/resume stress testing, we found that sometimes alramtimer
> >>> failed to suspend and hence it cancel the suspend ops. Add error prints
> >>> in suspend failure to provide more info when failure occurs to help
> >>> debugging.
> >>>
> >>> Signed-off-by: Laxman Dewangan <ldewangan@nvidia.com>
> >>> ---
> >>>   kernel/time/alarmtimer.c |    6 +++++-
> >>>   1 files changed, 5 insertions(+), 1 deletions(-)
> >>>
> >>> diff --git a/kernel/time/alarmtimer.c b/kernel/time/alarmtimer.c
> >>> index f11d83b..eed5646 100644
> >>> --- a/kernel/time/alarmtimer.c
> >>> +++ b/kernel/time/alarmtimer.c
> >>> @@ -249,6 +249,8 @@ static int alarmtimer_suspend(struct device *dev)
> >>>         if (ktime_to_ns(min) < 2 * NSEC_PER_SEC) {
> >>>           __pm_wakeup_event(ws, 2 * MSEC_PER_SEC);
> >>> +        dev_err(dev,
> >>> +            "Nearest alarm wakeup time < 2sec, avoiding suspend\n");
> >> What can userspace now do with this information?  How often is this now
> >> going to spam the syslog and cause confusion?
> >
> >
> > When we executed the stress on suspend/resume for system stability, 
> > occasionally we get such error (3/4 times in 1000 cycle):
> > [ 235.508010] dpm_run_callback(): platform_pm_suspend+0x0/0x64 returns 
> > -16
> > [ 235.514999] PM: Device alarmtimer failed to suspend: error -16
> > [ 235.520958] PM: Some devices failed to suspend
> >
> >
> > After tracing back the failure case, we found that possible reason 
> > could be above one.
> > In this case, if any function returns error then always better to 
> > print the error so that it is easy to findout the cause of the error 
> > and analyse.
> >
> > It should not generate spam as this does happen on some cases.
> 
> But if there is a recurring alarm timer that triggers every second, it 
> will print out every time.
> 
> Greg's concern is that the error message is unhelpful, since it just 
> will cause lots of log messages when the system is actually behaving as 
> designed. That said, the PM suspend messages are fairly noisy as well, 
> even when there are no errors.
> 
> Rafael: What are your thoughts here? If the alarmtimer subsystem blocks 
> a suspend attempt (returning EBUSY, as a pending alarm will fire soon), 
> how verbose should we be, since this isn't really an error case?

I wouldn't be too verbose, but that also depends on whether or not autosleep
is used.  I think our suspend messages are too verbose for autosleep anyway,
but for non-autosleep suspends it would be good to know why the system didn't
suspend.

Thanks,
Rafael


-- 
I speak only for myself.
Rafael J. Wysocki, Intel Open Source Technology Center.