714717 - nsIdleService: timeout event doesn't fire regularly on non polling mode

Status: RESOLVED FIXED

(Core :: Widget, defect)

Description

[Kan-Ru Chen [:kanru] (UTC+9)]

On non-polling mode device like Gonk (Android too?), after first idle event, the timer won't be rescheduled for next check.

Comment 1

[Kan-Ru Chen [:kanru] (UTC+9)]

Attachment: Part 1, Sanity check nextWaitTime

Comment 2

[Kan-Ru Chen [:kanru] (UTC+9)]

Attachment: Part 2, Reschedule timer after non-idle event

Comment 3

[Mike Kristoffersen (:MikeK)]

Hi Kan-Ru, I would like to review this, but it won't be until tonight (CET).

Comment 4

[Mike Kristoffersen (:MikeK)]

Comment on attachment 585355 [details] [diff] [review]
Part 1, Sanity check nextWaitTime

Review of attachment 585355 [details] [diff] [review]:
-----------------------------------------------------------------

Yeah, that will probably work better :)

Comment 5

[Mike Kristoffersen (:MikeK)]

Comment on attachment 585356 [details] [diff] [review]
Part 2, Reschedule timer after non-idle event

>+#include "android/log.h"
>+#define LOG(args...)                                            \
>+    __android_log_print(ANDROID_LOG_INFO, "Gonk" , ## args)
>+#ifdef VERBOSE_LOG_ENABLED
>+# define VERBOSE_LOG(args...)                           \
>+    __android_log_print(ANDROID_LOG_INFO, "Gonk" , ## args)
>+#else
>+# define VERBOSE_LOG(args...)                   \
>+    (void)0
>+#endif
>+

Are you sure you want to add this part to the non-android specific part of the source?

>+    /* If any listeners have entered "non-idle" state, we need to
>+     * recalculate the timeout */
>+    if (notifyList.Count() > 0) {
>+      aNoTimeReset = false;
>+    }
>+

I see where you are going with this, but I'm thinking it might be better to re factor a bit...

The only place the argument (aNoTimeReset) can become true, is from the call from ResetIdleTimeOut, the idea with it, in this context, iirc, is to prevent constant resetting of the timer.

I am aware that your code does not change this behavior, but it is kind of overwriting the purpose of the parameter, so my thoughts are along the lines of getting rid of the parameter all together, and make the detection internally in the function, I'm imagining a logic along the lines of:

---

If (user activity detected)
{
  if (anything idle)
  {
    send "non-idle" events;
    recalc timers;
  }
  else // nothing idle
  {
    bail out; // a timer is already running
  }
}
else // idling
{
  for (any new stuff that has become idle)
  {
   send "idle" event;
  }
  recalc timers
}

And it could probably be made more pretty by splitting it up into a number of smaller functions :)

What do you think about this idea?  If you think it is too time consuming at the moment we could leave your change as a quick fix, and then make a new bug with this and assign it to me, then I can look into it probably within the next week or so, where I'll have some evenings to spare for this.

Comment 6

[Kan-Ru Chen [:kanru] (UTC+9)]

(In reply to Mike Kristoffersen (:MikeK) from comment #5)
> Comment on attachment 585356 [details] [diff] [review]
> Part 2, Reschedule timer after non-idle event
> 
> >+#include "android/log.h"
> >+#define LOG(args...)                                            \
> >+    __android_log_print(ANDROID_LOG_INFO, "Gonk" , ## args)
> >+#ifdef VERBOSE_LOG_ENABLED
> >+# define VERBOSE_LOG(args...)                           \
> >+    __android_log_print(ANDROID_LOG_INFO, "Gonk" , ## args)
> >+#else
> >+# define VERBOSE_LOG(args...)                   \
> >+    (void)0
> >+#endif
> >+
> 
> Are you sure you want to add this part to the non-android specific part of
> the source?

Oops. I didn't mean to include this. It just... slipped in ;)

> >+    /* If any listeners have entered "non-idle" state, we need to
> >+     * recalculate the timeout */
> >+    if (notifyList.Count() > 0) {
> >+      aNoTimeReset = false;
> >+    }
> >+
> 
> I see where you are going with this, but I'm thinking it might be better to
> re factor a bit...
> 
> The only place the argument (aNoTimeReset) can become true, is from the call
> from ResetIdleTimeOut, the idea with it, in this context, iirc, is to
> prevent constant resetting of the timer.
> 
> I am aware that your code does not change this behavior, but it is kind of
> overwriting the purpose of the parameter, so my thoughts are along the lines
> of getting rid of the parameter all together, and make the detection
> internally in the function, I'm imagining a logic along the lines of:
> 
> ---
> 
> If (user activity detected)
> {
>   if (anything idle)
>   {
>     send "non-idle" events;
>     recalc timers;
>   }
>   else // nothing idle
>   {
>     bail out; // a timer is already running
>   }
> }
> else // idling
> {
>   for (any new stuff that has become idle)
>   {
>    send "idle" event;
>   }
>   recalc timers
> }
> 
> And it could probably be made more pretty by splitting it up into a number
> of smaller functions :)
> 
> What do you think about this idea?  If you think it is too time consuming at
> the moment we could leave your change as a quick fix, and then make a new
> bug with this and assign it to me, then I can look into it probably within
> the next week or so, where I'll have some evenings to spare for this.

I agree. At first I also want to remove the parameter all together, but then thought it might be useful to force recalculate the timer, so I took the minimum approach instead.

I will attach an refactored version later.

Comment 7

[Kan-Ru Chen [:kanru] (UTC+9)]

Attachment: Part 2, Reschedule timer after non-idle event, v2

Comment 8

[Mike Kristoffersen (:MikeK)]

Comment on attachment 585698 [details] [diff] [review]
Part 2, Reschedule timer after non-idle event, v2

I like the bootstrapTimer to ensure everything gets up and running :) assuming you tested it on both a system that uses poll mode and one that doesn't then I only have one comment left:

 void
 nsIdleService::ResetIdleTimeOut()
 {
-  // A zero in mLastIdleReset indicates that this function has never been
-  // called.
-  bool calledBefore = mLastIdleReset != 0;
   mLastIdleReset = PR_IntervalToSeconds(PR_IntervalNow());
   if (!mLastIdleReset) mLastIdleReset = 1;
 
   // Now check if this changes anything
   // Note that if we have never been called before, we cannot do the
   // optimization of passing true to CheckAwayState, which avoids
   // calculating the timer (because if we have never been called before,
   // we need to recalculate the timer and start it there).
-  CheckAwayState(calledBefore);
+  CheckAwayState();
 }

The comment here, about passing true to CheckAwayState might be confusing to someone who doesn't know the history of the function ;)

Otherwise it looks fine r+.

Comment 9

[Kan-Ru Chen [:kanru] (UTC+9)]

(In reply to Mike Kristoffersen (:MikeK) from comment #8)
> Comment on attachment 585698 [details] [diff] [review]
> Part 2, Reschedule timer after non-idle event, v2
> 
> I like the bootstrapTimer to ensure everything gets up and running :)
> assuming you tested it on both a system that uses poll mode and one that
> doesn't then I only have one comment left
> [..]

I found we might want reintroduce the parameter to explicit recalculate the timer when new observer is added. Otherwise it might occur in conjunction with user activity then the timer will not be scheduled. One obvious case is when I test it in the web console the observer is added immediately after I hit the enter key.

Comment 10

[Mike Kristoffersen (:MikeK)]

What would happen if you called "RescheduleIdleTimer" after adding an observer?

Comment 11

[Kan-Ru Chen [:kanru] (UTC+9)]

RescheduleIdleTimer needs idleTime to calculate the next wait time, so if I want to call RescheduleIdleTimer in addIdleObserver it would duplicate a large portion of CheckAwayState.

Comment 12

[Kan-Ru Chen [:kanru] (UTC+9)]

Attachment: Part 2, Reschedule timer after non-idle event, v3

how about this one

Comment 13

[Mike Kristoffersen (:MikeK)]

Comment on attachment 585996 [details] [diff] [review]
Part 2, Reschedule timer after non-idle event, v3


>   // Set the time for last user activity.
>   mLastHandledActivity = curTime - idleTime;
> 
>   /**
>+   * Too short since last check.
>+   * Bail out
>+   */
>+  if (!lastTime && !aNewObserver) {
>+    return;
>+  }
>+

Since we only use seconds internally, it might be an idea to move this one up a bit, as this will probably be the most frequent reason for bailing out (think about mouse moves)

>+  bool userActivity = lastTime > idleTime;
>+
>+  if (userActivity) {
>+    if (TryNotifyBackState(idleTime) || idleTime) {
>+      RescheduleIdleTimer(idleTime);
>+    }
>+  }
>+
>+  if (!userActivity || aNewObserver || bootstrapTimer) {
>+    TryNotifyIdleState(idleTime);
>+    RescheduleIdleTimer(idleTime);
>+  }

This took me a while to verify, but I think it is as it should be.

>+bool
>+nsIdleService::TryNotifyBackState(PRUint32 aIdleTime)
>+{
>+  // We need a text string to send with any state change events.
>+  nsAutoString timeStr;
>+  timeStr.AppendInt(aIdleTime);
>+

We actually don't need to create this string unless we find something that should be notified, and usually we won't find anything, so I suggest we make it conditional to whether we find something.

>+bool
>+nsIdleService::TryNotifyIdleState(PRUint32 aIdleTime)
>+{
>+  // We need a text string to send with any state change events.
>+  nsAutoString timeStr;
>+  timeStr.AppendInt(aIdleTime);
>+

Same as above...

----

I tried playing with it locally, I'll attach a diff or it updated to trunk to illustrate what I was thinking...

I can't help to think that the code seems overly complicated, especially that CheckAwayState, it is much better after you split it into several functions, but still... (this is by no means introduced by your patch, it was like that originally) - it might be a rewarding exercise to make it neater - but lets leave that for another time :)

Comment 14

[Mike Kristoffersen (:MikeK)]

Attachment: Suggestion of where things could be moved to

This is a merge of the two parts (attachment 585355 [details] [diff] [review] & 585996) updated to trunk and with an illustration of the edits I suggested in the review.

Comment 15

[Kan-Ru Chen [:kanru] (UTC+9)]

(In reply to Mike Kristoffersen (:MikeK) from comment #14)
> Created attachment 586253 [details] [diff] [review]
> Suggestion of where things could be moved to
> 
> This is a merge of the two parts (attachment 585355 [details] [diff] [review]
> [review] & 585996) updated to trunk and with an illustration of the edits I
> suggested in the review.

Your patch looks great; I think you can land it as is. :)

Comment 16

[Mike Kristoffersen (:MikeK)]

Comment on attachment 585996 [details] [diff] [review]
Part 2, Reschedule timer after non-idle event, v3

Review of attachment 585996 [details] [diff] [review]:
-----------------------------------------------------------------

r+ if updated with my previous comments

Comment 17

[Mike Kristoffersen (:MikeK)]

(In reply to Kan-Ru Chen [:kanru] from comment #15)
> (In reply to Mike Kristoffersen (:MikeK) from comment #14)
> > Created attachment 586253 [details] [diff] [review]
> > Suggestion of where things could be moved to
> > 
> > This is a merge of the two parts (attachment 585355 [details] [diff] [review]
> > [review] & 585996) updated to trunk and with an illustration of the edits I
> > suggested in the review.
> 
> Your patch looks great; I think you can land it as is. :)

But complicate the review logic :) - It's your patch with a few lines moved, besides I think I lost my commit access due to inactivity (I have no idea what the rules for committing are these days).

Comment 18

[Kan-Ru Chen [:kanru] (UTC+9)]

Attachment: Part 1, Sanity check nextWaitTime

--
Attachment #585355 [details] [diff] - Attachment is obsolete: true

Comment 19

[Kan-Ru Chen [:kanru] (UTC+9)]

Attachment: Part 2, Reschedule timer after non-idle event

--
Attachment #585356 [details] [diff] - Attachment is obsolete: true

Comment 20

[Kan-Ru Chen [:kanru] (UTC+9)]

Attachment: Part 1, Sanity check nextWaitTime

Comment 21

[Kan-Ru Chen [:kanru] (UTC+9)]

Attachment: Part 2, Reschedule timer after non-idle event

Comment 22

[Dão Gottwald [:dao]]

Kan-Ru, please make sure to use a proper name as the reviewer in the commit message. "mozstuff" is not such a name.

Comment 23

[Dão Gottwald [:dao]]

http://hg.mozilla.org/integration/mozilla-inbound/rev/e44700517c2d
http://hg.mozilla.org/integration/mozilla-inbound/rev/751ce658ce73

Comment 24

[Matt Brubeck (:mbrubeck)]

https://hg.mozilla.org/mozilla-central/rev/e44700517c2d
https://hg.mozilla.org/mozilla-central/rev/751ce658ce73

Comment 25

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

The changes to the idle service here appear to have drastically increased the frequency of Bug 517482.

Comment 26

[Mike Kristoffersen (:MikeK)]

Hmm... I'll try to see if I can find a reason for this in the coming weekend...

Comment 27

[Mike Kristoffersen (:MikeK)]

Ok, I think I have an idea now...

There are at least two things going on - the random errors that we have had for a long time where the timer isn't timing out within the 1s grace that the test allows is probably due to the fact that the service internally only calculates with a resolution of 1s, that can be fixed by increasing the internal resolution or increasing the grace period in the test, I propose increasing the internal resolution.

The second thing is that some times the service fails to restart it's internal timer, in nsIdleService::CheckAwayState(bool aNewObserver):
if (userActivity) {
    if (TryNotifyBackState(idleTime) || idleTime) {
      RescheduleIdleTimer(idleTime);
    }

here RescheduleIdleTimer isn't called, as the second "if" evaluates to false, I'm not sure why this happens yet, but have been able to provoke it several times in a test environment. 

(However I suspect that it has to do with the service running non-instantly, like, because time is passing while the code is executing)

This could lead to the failing test cases where it complains that there are no call backs.

I'll try to provide a fix for one or both of these one of the coming days.  Maybe we should open new bugs instead of piggybacking it on this one?

Comment 28

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

(In reply to Mike Kristoffersen (:MikeK) from comment #27)
> I'll try to provide a fix for one or both of these one of the coming days. 
> Maybe we should open new bugs instead of piggybacking it on this one?

Yes please!

Comment 29

[Mike Kristoffersen (:MikeK)]

(In reply to Kyle Huey [:khuey] ([e-mail]) from comment #28)
> (In reply to Mike Kristoffersen (:MikeK) from comment #27)
> > I'll try to provide a fix for one or both of these one of the coming days. 
> > Maybe we should open new bugs instead of piggybacking it on this one?
> 
> Yes please!

I have opened bug 720490 and bug 720493 to handle the issues I found.