powered by Jive Software

Smack 4.4.0 Synchronized (selector) access in SmackReactor class is holding back normal process execution; leading to android OS "Long monitor contention"

During aTalk debug, android logcat constantly highlighting long process execution held by synchronized (selector) access in SmackReactor:

Actually from aTalk field report, users are facing ANRs (Android No Response) quite frequently. I am not sure if this is due to aTalk design or SmackReactor may help to alleviate this problm; I have included 2 cases of ANRs below for reference.

================ aTalk logcat ===============
2019-09-25 12:32:50.086 32602-804/org.atalk.android W/g.atalk.androi: Long monitor contention with owner Smack DefaultReactor Thread #0 (803) at int sun.nio.ch.PollArrayWrapper.poll0(long, int, long)(PollArrayWrapper.java:-2) waiters=0 in void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect() for 841ms

2019-09-25 12:32:51.441 32602-804/org.atalk.android W/g.atalk.androi: Long monitor contention with owner Smack DefaultReactor Thread #0 (803) at void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect()(SmackReactor.java:225) waiters=0 in void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect() for 874ms

2019-09-25 12:33:21.878 32602-803/org.atalk.android W/g.atalk.androi: Long monitor contention with owner Smack DefaultReactor Thread #1 (804) at void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect()(SmackReactor.java:225) waiters=0 in void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect() for 30.013s

2019-09-25 12:36:51.484 32602-803/org.atalk.android W/g.atalk.androi: Long monitor contention with owner Smack DefaultReactor Thread #1 (804) at void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect()(SmackReactor.java:225) waiters=0 in void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect() for 209.604s

2019-09-25 12:36:54.492 32602-803/org.atalk.android W/g.atalk.androi: Long monitor contention with owner Smack DefaultReactor Thread #1 (804) at void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect()(SmackReactor.java:225) waiters=0 in void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect() for 3.006s

2019-09-25 12:38:54.591 32602-804/org.atalk.android W/g.atalk.androi: Long monitor contention with owner Smack DefaultReactor Thread #0 (803) at void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect()(SmackReactor.java:225) waiters=0 in void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect() for 120.062s

2019-09-25 12:40:54.619 32602-804/org.atalk.android W/g.atalk.androi: Long monitor contention with owner Smack DefaultReactor Thread #0 (803) at void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect()(SmackReactor.java:225) waiters=0 in void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect() for 120.027s
......

Below are aTalk field feedback on ANRs:


Case #1 Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)

###

Sep 17, 6:59 AM on app version 1105

[Huawei P20 lite (HWANE)](https://play.google.com/apps/publish/?account=5361614842362677306#DeviceCatalogPlace:p=org.atalk.android&appid=4973553957992441993&deviceId=HWANE&originPlace=CRASHES_PAGE), Android 9

Report  **1**  of  **1**

EXPAND ALL

"main" tid=1 TimedWaiting

"main" prio=5 tid=1 TimedWaiting | group="main" sCount=1 dsCount=0 flags=1 obj=0x765c2b30 self=0x7f29415c00 | sysTid=6184 nice=-10 cgrp=default sched=0/0 handle=0x7fafcb0548 | state=S schedstat=( 2710788062 235377054 3260 ) utm=218 stm=53 core=2 HZ=100 | stack=0x7ff8956000-0x7ff8958000 stackSize=8MB | held mutexes=

at java.lang.Object.wait (Native method)

- waiting on <0x0c803e99> (a org.jivesoftware.smack.StanzaCollector)

at java.lang.Object.wait (Object.java:422)

at org.jivesoftware.smack.StanzaCollector.nextResult (StanzaCollector.java:206)

- locked <0x0c803e99> (a org.jivesoftware.smack.StanzaCollector)

at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow (StanzaCollector.java:270)

at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow (StanzaCollector.java:228)

at org.jivesoftware.smackx.disco.ServiceDiscoveryManager.discoverInfo (ServiceDiscoveryManager.java:531)

at org.jivesoftware.smackx.disco.ServiceDiscoveryManager.discoverInfo (ServiceDiscoveryManager.java:505)

at org.jivesoftware.smackx.disco.ServiceDiscoveryManager.supportsFeatures (ServiceDiscoveryManager.java:656)

at org.jivesoftware.smackx.disco.ServiceDiscoveryManager.supportsFeatures (ServiceDiscoveryManager.java:652)

at org.jivesoftware.smackx.disco.ServiceDiscoveryManager.supportsFeature (ServiceDiscoveryManager.java:648)

at org.jivesoftware.smackx.receipts.DeliveryReceiptManager.isSupported (DeliveryReceiptManager.java:217)

at org.atalk.android.gui.chat.MetaContactChatTransport.checkDeliveryReceiptSupport (MetaContactChatTransport.java:164)

at org.atalk.android.gui.chat.MetaContactChatTransport.<init> (MetaContactChatTransport.java:140)

at org.atalk.android.gui.chat.MetaContactChatSession.addChatTransports (MetaContactChatSession.java:585)

at org.atalk.android.gui.chat.MetaContactChatSession.initChatTransports (MetaContactChatSession.java:276)

at org.atalk.android.gui.chat.MetaContactChatSession.<init> (MetaContactChatSession.java:70)

at org.atalk.android.gui.chat.ChatSessionManager.createChat (ChatSessionManager.java:722)

at org.atalk.android.gui.chat.ChatSessionManager.createChatForChatId (ChatSessionManager.java:426)

- locked <0x08efcd3f> (a java.lang.Class<org.atalk.android.gui.chat.ChatSessionManager>)

at org.atalk.android.gui.chat.ChatActivity.handleIntent (ChatActivity.java:200)

at org.atalk.android.gui.chat.ChatActivity.onCreate (ChatActivity.java:168)

at android.app.Activity.performCreate (Activity.java:7458)

at android.app.Activity.performCreate (Activity.java:7448)

at android.app.Instrumentation.callActivityOnCreate (Instrumentation.java:1286)

at android.app.ActivityThread.performLaunchActivity (ActivityThread.java:3409)

at android.app.ActivityThread.handleLaunchActivity (ActivityThread.java:3614)

at android.app.servertransaction.LaunchActivityItem.execute (LaunchActivityItem.java:86)

at android.app.servertransaction.TransactionExecutor.executeCallbacks (TransactionExecutor.java:108)

at android.app.servertransaction.TransactionExecutor.execute (TransactionExecutor.java:68)

at android.app.ActivityThread$H.handleMessage (ActivityThread.java:2199)

at android.os.Handler.dispatchMessage (Handler.java:112)

at android.os.Looper.loop (Looper.java:216)

at android.app.ActivityThread.main (ActivityThread.java:7625)

at java.lang.reflect.Method.invoke (Native method)

at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:524)

at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:987)

"Smack DefaultReactor Thread #0" tid=21 Native
"Smack DefaultReactor Thread #0" daemon prio=5 tid=21 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x138c1198 self=0x7f0bda8000
  | sysTid=6311 nice=0 cgrp=default sched=0/0 handle=0x7f0abe64f0
  | state=S schedstat=( 5354687 4320312 31 ) utm=0 stm=0 core=1 HZ=100
  | stack=0x7f0aae3000-0x7f0aae5000 stackSize=1041KB
  | held mutexes=
  #00  pc 000000000006fdcc  /system/lib64/libc.so (__ppoll+8)
  #01  pc 000000000002c310  /system/lib64/libc.so (poll+88)
  #02  pc 000000000001d638  /system/lib64/libopenjdk.so (Java_sun_nio_ch_PollArrayWrapper_poll0+132)
  at sun.nio.ch.PollArrayWrapper.poll0 (Native method)
  at sun.nio.ch.PollArrayWrapper.poll (PollArrayWrapper.java:115)
  at sun.nio.ch.PollSelectorImpl.doSelect (PollSelectorImpl.java:73)
  at sun.nio.ch.SelectorImpl.lockAndDoSelect (SelectorImpl.java:86)
- locked <0x003c87a4> (a sun.nio.ch.PollSelectorImpl)
  at sun.nio.ch.SelectorImpl.select (SelectorImpl.java:97)
  at org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect (SmackReactor.java:252)
- locked <0x003c87a4> (a sun.nio.ch.PollSelectorImpl)
  at org.jivesoftware.smack.SmackReactor$Reactor.reactorLoop (SmackReactor.java:183)
  at org.jivesoftware.smack.SmackReactor$Reactor.run (SmackReactor.java:168)

"Smack DefaultReactor Thread #1" tid=22 Blocked
"Smack DefaultReactor Thread #1" daemon prio=5 tid=22 Blocked
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x138c14b0 self=0x7f0bda8c00
  | sysTid=6312 nice=0 cgrp=default sched=0/0 handle=0x7f0aae04f0
  | state=S schedstat=( 39042185 9210936 143 ) utm=2 stm=1 core=1 HZ=100
  | stack=0x7f0a9dd000-0x7f0a9df000 stackSize=1041KB
  | held mutexes=
  at org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect (SmackReactor.java:209)
- waiting to lock <0x003c87a4> (a sun.nio.ch.PollSelectorImpl) held by thread 21
  at org.jivesoftware.smack.SmackReactor$Reactor.reactorLoop (SmackReactor.java:183)
  at org.jivesoftware.smack.SmackReactor$Reactor.run (SmackReactor.java:168)

case #2:
Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago. Wait queue length: 15. Wait queue head age: 10567.2ms.)

###

Sep 17, 11:08 PM on app version 1105

[LGE LG Stylo 4 (cv7a)](https://play.google.com/apps/publish/?account=5361614842362677306#DeviceCatalogPlace:p=org.atalk.android&appid=4973553957992441993&deviceId=cv7a&originPlace=CRASHES_PAGE), Android 8.1

Report  **1**  of  **1**

EXPAND ALL

"main" tid=1 Native

"main" prio=5 tid=1 Native | group="main" sCount=1 dsCount=0 flags=1 obj=0x723714b8 self=0xa43e2000 | sysTid=9809 nice=-10 cgrp=default sched=0/0 handle=0xa83c24a4 | state=S schedstat=( 9838489964 1082049633 15598 ) utm=723 stm=260 core=4 HZ=100 | stack=0xbe7e8000-0xbe7ea000 stackSize=8MB | held mutexes=

#00 pc 000000000001907c /system/lib/libc.so (syscall+28)

#01 pc 00000000000b73dd /system/lib/libart.so (art::ConditionVariable::WaitHoldingLocks(art::Thread*)+80)

#02 pc 00000000003e05a9 /system/lib/libart.so (art::GoToRunnable(art::Thread*)+300)

#03 pc 00000000003e044d /system/lib/libart.so (art::JniMethodEnd(unsigned int, art::Thread*)+8)

#04 pc 0000000000790901 /system/framework/arm/boot-framework.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+144)

at android.os.BinderProxy.transactNative (Native method)

at android.os.BinderProxy.transact (Binder.java:782)

at android.app.IActivityManager$Stub$Proxy.activityPaused (IActivityManager.java:4767)

at android.app.ActivityThread.handlePauseActivity (ActivityThread.java:3909)

at android.app.ActivityThread.-wrap15 (ActivityThread.java)

at android.app.ActivityThread$H.handleMessage (ActivityThread.java:1623)

at android.os.Handler.dispatchMessage (Handler.java:106)

at android.os.Looper.loop (Looper.java:164)

at android.app.ActivityThread.main (ActivityThread.java:6651)

at java.lang.reflect.Method.invoke (Native method)

at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:438)

at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:810)

"Smack DefaultReactor Thread #0" tid=21 Native
"Smack DefaultReactor Thread #0" daemon prio=5 tid=21 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x13e41c68 self=0x85aa4e00
  | sysTid=10252 nice=0 cgrp=default sched=0/0 handle=0x858ff970
  | state=S schedstat=( 15160365 1185157 37 ) utm=1 stm=0 core=4 HZ=100
  | stack=0x857fd000-0x857ff000 stackSize=1038KB
  | held mutexes=
  #00  pc 000000000004acbc  /system/lib/libc.so (__ppoll+20)
  #01  pc 000000000001fa8d  /system/lib/libc.so (poll+48)
  #02  pc 0000000000014041  /system/lib/libopenjdk.so (Java_sun_nio_ch_PollArrayWrapper_poll0+80)
  #03  pc 000000000043a73d  /system/framework/arm/boot.oat (Java_sun_nio_ch_PollArrayWrapper_poll0__JIJ+108)
  at sun.nio.ch.PollArrayWrapper.poll0 (Native method)
  at sun.nio.ch.PollArrayWrapper.poll (PollArrayWrapper.java:115)
  at sun.nio.ch.PollSelectorImpl.doSelect (PollSelectorImpl.java:73)
  at sun.nio.ch.SelectorImpl.lockAndDoSelect (SelectorImpl.java:86)
- locked <0x00365e43> (a sun.nio.ch.PollSelectorImpl)
  at sun.nio.ch.SelectorImpl.select (SelectorImpl.java:97)
  at org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect (SmackReactor.java:252)
- locked <0x00365e43> (a sun.nio.ch.PollSelectorImpl)
  at org.jivesoftware.smack.SmackReactor$Reactor.reactorLoop (SmackReactor.java:183)
  at org.jivesoftware.smack.SmackReactor$Reactor.run (SmackReactor.java:168)

"Smack DefaultReactor Thread #1" tid=22 Blocked
"Smack DefaultReactor Thread #1" daemon prio=5 tid=22 Blocked
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x13e42508 self=0x85aa5400
  | sysTid=10253 nice=0 cgrp=default sched=0/0 handle=0x857fa970
  | state=S schedstat=( 5328332 1465103 22 ) utm=0 stm=0 core=3 HZ=100
  | stack=0x856f8000-0x856fa000 stackSize=1038KB
  | held mutexes=
  at org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect (SmackReactor.java:209)
- waiting to lock <0x00365e43> (a sun.nio.ch.PollSelectorImpl) held by thread 21
  at org.jivesoftware.smack.SmackReactor$Reactor.reactorLoop (SmackReactor.java:183)
  at org.jivesoftware.smack.SmackReactor$Reactor.run (SmackReactor.java:168)

That is by design and a false positive. I would even say the message is wrong: The monitor is not contented. If you look at Smack source you will find that inside the Reactor there is a small critical section in which a reactor thread may block on select(), this causes all other reactor threads to block on the monitor object that is guarding the critical section. As soon as the select() returns, the reactor thread will leave the critical section and another thread is allowed to enter.

It is due aTalk’s design. And examination of your provided stacktraces shows that aTalks performs a blocking operation (StanzaCollector.nextResult()) from the main/UI thread ChatActivity.onCreate(). You need to decouple that.

The second case is probably similar, although there is no Smack invovled.

Thanks for the clarification.

Sorry, case #1 is a bad example get included. Actually I know the cause and already put the checkDeliveryReceiptSupport() on a new thread so it does not interfere with the main thread.

As for case #2, I am still unable to figure out what is holding back. However further down in the traces, both thread #21 and #22 are blocked and involved smackReactor?
Any advice how to find the cause?


“Smack DefaultReactor Thread #1” tid=22 Blocked

  • waiting to lock <0x00365e43> (a sun.nio.ch.PollSelectorImpl) held by thread 21

“Smack DefaultReactor Thread #0” tid=21 Native
at org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect (SmackReactor.java:252)

=================================
By the way I see there is no update on topics below. Did your team manage to find the cause of the ping problem and fix. aTalk is still using last proposed patch for ping to work. I would like to remove the patch if it has been fixed by other mean.

I was investigating and trying to find the reason why aTalk gets disconnected a couple of times during android device standby, for no apparent reason after upgraded to smack 4.4.0-alpha-SNAPSHOT. While checking the aTalk pings (set to 240S interval), like before android OS regularly throws Long monitor contention. One strange thing is that the sum of all the Long monitor contention’s for each occurrence of ping always add up to the 240S ping interval.

No sure if the info can shake some light why the SmackReactor failed to trigger at the set interval to send ping without the patch below.

SmackReactor2.patch (2.3 KB)

Note: aTalk SmackReactor has the patch applied all the time. The problem of aTalk disconnection is still under investigation

Update: Found the cause: the disconnection has nothing to do with smack. The disconnection is because of second instance login from my old phone, that I have forgotten to disable it.

========= aTalk disconnection =========
2019-10-06 04:03:16.266 22228-22556/org.atalk.android D/SMACK: RECV (0): 
    <stream:error>
      <conflict xmlns='urn:ietf:params:xml:ns:xmpp-streams'/>
      <text xml:lang='en' xmlns='urn:ietf:params:xml:ns:xmpp-streams'>
        Replaced by new connection
      </text>
    </stream:error>
2019-10-06 04:03:16.297 22228-12720/org.atalk.android W/aTalk: [35003] org.jivesoftware.smack.AbstractXMPPConnection.callConnectionClosedOnErrorListener() Connection XMPPTCPConnection[swordfish@atalk.org/atalk] (0) closed with error
    org.jivesoftware.smack.XMPPException$StreamErrorException: conflict You can read more about the meaning of this stream error at http://xmpp.org/rfcs/rfc6120.html#streams-error-conditions
    <stream:error><conflict xmlns='urn:ietf:params:xml:ns:xmpp-streams'/><text xml:lang='en'>Replaced by new connection</text></stream:error>
        at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader.parsePackets(XMPPTCPConnection.java:951)
        at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader.access$300(XMPPTCPConnection.java:882)
        at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader$1.run(XMPPTCPConnection.java:902)
        at java.lang.Thread.run(Thread.java:764)
============ aTalk debug log for Ping with patch ===================
2019-10-05 21:49:25.464 22228-22555/org.atalk.android D/SMACK: SENT (0): 
    <a xmlns='urn:xmpp:sm:3' h='37'/>
2019-10-05 21:49:54.326 22228-22548/org.atalk.android W/g.atalk.androi: Long monitor contention with owner Smack DefaultReactor Thread #1 (22549) at void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect()(SmackReactor.java:209) waiters=0 in void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect() for 29.870s
2019-10-05 21:53:24.394 22228-22548/org.atalk.android W/g.atalk.androi: Long monitor contention with owner Smack DefaultReactor Thread #1 (22549) at void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect()(SmackReactor.java:209) waiters=0 in void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect() for 209.936s
2019-10-05 21:53:26.395 22228-22548/org.atalk.android W/g.atalk.androi: Long monitor contention with owner Smack DefaultReactor Thread #1 (22549) at void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect()(SmackReactor.java:209) waiters=0 in void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect() for 1.999s
2019-10-05 21:53:26.407 22228-22555/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='HJDPZ-119' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>


2019-10-05 21:55:26.449 22228-22549/org.atalk.android W/g.atalk.androi: Long monitor contention with owner Smack DefaultReactor Thread #0 (22548) at void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect()(SmackReactor.java:209) waiters=0 in void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect() for 119.981s
2019-10-05 21:57:26.483 22228-22549/org.atalk.android W/g.atalk.androi: Long monitor contention with owner Smack DefaultReactor Thread #0 (22548) at void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect()(SmackReactor.java:209) waiters=0 in void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect() for 120.032s
2019-10-05 21:57:26.491 22228-22555/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='HJDPZ-121' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>

2019-10-05 21:59:26.576 22228-22548/org.atalk.android W/g.atalk.androi: Long monitor contention with owner Smack DefaultReactor Thread #1 (22549) at void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect()(SmackReactor.java:209) waiters=0 in void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect() for 120.016s
2019-10-05 22:01:26.577 22228-22548/org.atalk.android W/g.atalk.androi: Long monitor contention with owner Smack DefaultReactor Thread #1 (22549) at void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect()(SmackReactor.java:209) waiters=0 in void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect() for 120s
2019-10-05 22:01:26.579 22228-22555/org.atalk.android D/SMACK: SENT (0): 
    <iq to='atalk.org' id='HJDPZ-123' type='get'>
      <ping xmlns='urn:xmpp:ping'/>
    </iq>
....