Below is another strange behavior that I observed this morning:
- @08:50:40.803, new action is received AbstractXMPPConnection$7@f4ff334 for schedule with 120,000ms
- @08:50:40.805, before the new action that added into scheduledActions (as size remains as 5), it proceed with the previous action with time 19,384ms
- @08:50:40.807, #2 get re-executed as a Selector.wakeup was triggered by #1.
- @08:50:40.841, after the ping @8:50:40.808, a new ping action is received
- @08:50:40.844, #3 get re-executed as a result of #4
-
@08:51:00.233, the Selector waitup due to timeout of #5
7.@08:51:00.235, strangely the expired #5 get schedule again with 19,397ms; and not the ping action, its selectWait may have reduce to a very small +ve value???. - @08:51:00.236, #6 wakeup proceed to execute AbstractXMPPConnection$7@694ac9c. Note: this may actual happen before #7 as time delta is only 1ms
The problem again seems to have some race condition where action performed on scheduledActions before it is being properly updated?
Thinking that there may be too many unnecessary interruptions to wake the Selector, I modified the schedule() method as below. But this also does not improve anything.
ScheduledAction schedule(Runnable runnable, long delay, TimeUnit unit)
{
long releaseTimeEpoch = System.currentTimeMillis() + unit.toMillis(delay);
Date releaseTimeDate = new Date(releaseTimeEpoch);
long waitInQueue = 0L;
ScheduledAction queueAction = scheduledActions.peek();
if (queueAction != null)
waitInQueue = queueAction.getTimeToDueMillis();
ScheduledAction scheduledAction = new ScheduledAction(runnable, releaseTimeDate, this);
scheduledActions.add(scheduledAction);
Timber.w("Selector Schedule new action %s (%s): %s",
scheduledAction.getTimeToDueMillis(), waitInQueue, runnable);
if ((scheduledActions.size() < 2) || (scheduledAction.getTimeToDueMillis() <= waitInQueue))
selector.wakeup();
return scheduledAction;
}
2019-06-05 08:50:40.802 9268-9426/org.atalk.android E/(SmackReactor.java:206)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smackx.ping.PingManager$9@cb86561
2019-06-05 08:50:40.803 9268-9426/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 120000 : org.jivesoftware.smack.AbstractXMPPConnection$7@f4ff334
2019-06-05 08:50:40.805 9268-9425/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 5; in: 19384; org.jivesoftware.smack.AbstractXMPPConnection$7@a7eb56e
2019-06-05 08:50:40.806 9268-9425/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 08:50:40.807 9268-9425/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 5; in: 19405; org.jivesoftware.smack.AbstractXMPPConnection$7@694ac9c
2019-06-05 08:50:40.808 9268-9453/org.atalk.android D/SMACK: SENT (0):
<iq to='atalk.org' id='1tIu9-2106' type='get'>
<ping xmlns='urn:xmpp:ping'/>
</iq>
2019-06-05 08:50:40.832 9268-9454/org.atalk.android D/SMACK: RECV (0):
<iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='1tIu9-2106'/>
2019-06-05 08:50:40.837 9268-9454/org.atalk.android D/SMACK: RECV (0):
<r xmlns='urn:xmpp:sm:3'/>
2019-06-05 08:50:40.841 9268-30378/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 20000 : org.jivesoftware.smackx.ping.PingManager$9@cb86561
2019-06-05 08:50:40.842 9268-9453/org.atalk.android D/SMACK: SENT (0):
<a xmlns='urn:xmpp:sm:3' h='1027'/>
2019-06-05 08:50:40.843 9268-9425/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 08:50:40.844 9268-9425/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 6; in: 19368; org.jivesoftware.smack.AbstractXMPPConnection$7@694ac9c
2019-06-05 08:51:00.233 9268-9425/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 08:51:00.235 9268-9426/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 6; in: 19397; org.jivesoftware.smack.AbstractXMPPConnection$7@694ac9c
2019-06-05 08:51:00.236 9268-9425/org.atalk.android E/(SmackReactor.java:206)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smack.AbstractXMPPConnection$7@694ac9c
2019-06-05 08:51:19.656 9268-9426/org.atalk.android E/(SmackReactor.java:258)#handleScheduledActionsOrPerformSelect: Selector wakeup with newSelectedKeyCount: 0
2019-06-05 08:51:19.658 9268-9426/org.atalk.android E/(SmackReactor.java:206)#handleScheduledActionsOrPerformSelect: Selector execute: org.jivesoftware.smackx.ping.PingManager$9@cb86561
2019-06-05 08:51:19.661 9268-9425/org.atalk.android W/(SmackReactor.java:255)#handleScheduledActionsOrPerformSelect: Selector Scheduled next action: size: 4; in: 604; org.jivesoftware.smackx.ping.PingManager$9@cb86561
2019-06-05 08:51:19.663 9268-9426/org.atalk.android W/(SmackReactor.java:155)#schedule: Selector Schedule new action 120000 : org.jivesoftware.smack.AbstractXMPPConnection$7@2dc1ed2
2019-06-05 08:51:19.666 9268-9453/org.atalk.android D/SMACK: SENT (0):
<iq to='atalk.org' id='1tIu9-2108' type='get'>
<ping xmlns='urn:xmpp:ping'/>
</iq>