New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Deadlock in AppEventsLogger at application starts #360
Comments
Hey, It looks like the deadlock is occurring inside the Google Play store library as you can see in the stack trace here: [...] This operation is the one hanging causing us to deadlock the next time AttributionIdentifiers.getAndroidId is called from the main thread. Can you post the rest of the stack traces from your app at that time (all other threads) so I can debug this further (or report the issue to Google, whichever is applicable)? Thanks! |
Hi Florian, Not wanting to hi-jack this bug report but I two had this issue today! I have the same symptoms and the code works if I comment out the activateApp call. I have attached the thread dump from my device. ----- pid 4929 at 2014-08-03 21:05:13 ----- JNI: CheckJNI is off; workarounds are off; pins=0; globals=293 (plus 16 weak) DALVIK THREADS: "main" prio=5 tid=1 MONITOR
"AsyncTask #1" prio=5 tid=23 WAIT
"FlurryAgent" prio=5 tid=22 WAIT
"CleanupReference" daemon prio=5 tid=21 WAIT
"Thread-6848" prio=5 tid=20 NATIVE "Thread-6847" prio=9 tid=19 NATIVE "SettinsObserver" prio=5 tid=18 NATIVE "Binder_3" prio=5 tid=17 NATIVE "AdWorker #1" prio=5 tid=16 WAIT
"Timer-1" prio=5 tid=15 TIMED_WAIT
"Timer-0" prio=5 tid=14 WAIT
"GAThread" prio=5 tid=13 WAIT
"SoundPoolThread" prio=5 tid=12 NATIVE "SoundPool" prio=5 tid=11 NATIVE "GLThread 6837" prio=5 tid=10 WAIT
"Binder_2" prio=5 tid=9 NATIVE "Binder_1" prio=5 tid=8 NATIVE "FinalizerWatchdogDaemon" daemon prio=5 tid=7 WAIT
"FinalizerDaemon" daemon prio=5 tid=6 WAIT
"ReferenceQueueDaemon" daemon prio=5 tid=5 WAIT
"Compiler" daemon prio=5 tid=4 VMWAIT "Signal Catcher" daemon prio=5 tid=3 RUNNABLE "GC" daemon prio=5 tid=2 VMWAIT NATIVE THREADS: "Chrome_FileThre" sysTid=4970 nice=0 sched=0/0 cgrp=apps "Chrome_FileUser" sysTid=4971 nice=0 sched=0/0 cgrp=apps "Chrome_ProcessL" sysTid=4972 nice=0 sched=0/0 cgrp=apps "Chrome_CacheThr" sysTid=4973 nice=0 sched=0/0 cgrp=apps "IndexedDB" sysTid=4975 nice=0 sched=0/0 cgrp=apps "BrowserBlocking" sysTid=4976 nice=0 sched=0/0 cgrp=apps "Chrome_InProcGp" sysTid=4977 nice=-6 sched=0/0 cgrp=apps "Chrome_ChildIOT" sysTid=4978 nice=-6 sched=0/0 cgrp=apps "MediaStreamDevi" sysTid=4979 nice=0 sched=0/0 cgrp=apps "File Thread" sysTid=4981 nice=0 sched=0/0 cgrp=apps ----- end 4929 ----- ----- pid 582 at 2014-08-03 21:05:13 ----- JNI: CheckJNI is off; workarounds are off; pins=4; globals=2257 (plus 155 weak) DALVIK THREADS: "main" prio=5 tid=1 NATIVE "Binder_10" prio=5 tid=68 NATIVE "Binder_F" prio=5 tid=58 NATIVE "Binder_E" prio=5 tid=67 NATIVE "Binder_D" prio=5 tid=66 NATIVE "Binder_C" prio=5 tid=65 NATIVE "Binder_B" prio=5 tid=64 NATIVE "Binder_A" prio=5 tid=63 NATIVE "SyncHandler-0" prio=5 tid=57 NATIVE "UsbDebuggingManager" prio=5 tid=61 NATIVE "SoundPoolThread" prio=5 tid=60 NATIVE "SoundPool" prio=5 tid=59 NATIVE "Binder_9" prio=5 tid=56 NATIVE "Binder_8" prio=5 tid=55 NATIVE "Binder_7" prio=5 tid=54 NATIVE "Binder_6" prio=5 tid=53 NATIVE "NetworkTimeUpdateService" prio=5 tid=52 NATIVE "FLP Service Callback Thread" prio=6 tid=51 NATIVE "watchdog" prio=5 tid=50 TIMED_WAIT
"CaptivePortalTracker" prio=5 tid=49 NATIVE "AsyncTask #5" prio=5 tid=48 WAIT
"AsyncTask #4" prio=5 tid=47 WAIT
"AsyncTask #3" prio=5 tid=46 WAIT
"AsyncTask #2" prio=5 tid=45 WAIT
"Thread-55" prio=5 tid=43 NATIVE "AsyncTask #1" prio=5 tid=44 WAIT
"backup" prio=5 tid=42 NATIVE "AudioService" prio=5 tid=30 NATIVE "mDnsConnector" prio=5 tid=41 NATIVE "NsdService" prio=5 tid=40 NATIVE "WifiWatchdogStateMachine" prio=5 tid=39 NATIVE "WifiManager" prio=5 tid=38 NATIVE "ConnectivityServiceThread" prio=5 tid=37 NATIVE "WifiService" prio=5 tid=36 NATIVE "WifiStateMachine" prio=5 tid=35 NATIVE "WifiP2pService" prio=5 tid=34 NATIVE "NetworkPolicy" prio=5 tid=33 NATIVE "NetworkStats" prio=5 tid=32 NATIVE "NetdConnector" prio=5 tid=31 NATIVE "VoldConnector" prio=5 tid=29 NATIVE "MountService" prio=5 tid=28 NATIVE "InputReader" prio=10 tid=27 NATIVE "InputDispatcher" prio=10 tid=26 NATIVE "UEventObserver" prio=5 tid=25 NATIVE "AlarmManager" prio=5 tid=24 NATIVE "PowerManagerService" prio=5 tid=23 NATIVE "Binder_5" prio=5 tid=22 NATIVE "Binder_4" prio=5 tid=21 NATIVE "Binder_3" prio=5 tid=20 NATIVE "PackageManager" prio=5 tid=19 NATIVE "FileObserver" prio=5 tid=18 NATIVE "CpuTracker" prio=5 tid=17 TIMED_WAIT
"android.io" prio=5 tid=16 NATIVE "android.ui" prio=5 tid=15 NATIVE "android.fg" prio=5 tid=14 NATIVE "android.bg" prio=5 tid=13 NATIVE "ActivityManager" prio=5 tid=12 SUSPENDED "WindowManager" prio=5 tid=11 NATIVE "SensorService" prio=10 tid=10 NATIVE "Binder_2" prio=5 tid=9 NATIVE "Binder_1" prio=5 tid=8 NATIVE "FinalizerWatchdogDaemon" daemon prio=5 tid=7 TIMED_WAIT "FinalizerDaemon" daemon prio=5 tid=6 WAIT
"ReferenceQueueDaemon" daemon prio=5 tid=5 WAIT
"Compiler" daemon prio=5 tid=4 VMWAIT "Signal Catcher" daemon prio=5 tid=3 RUNNABLE "GC" daemon prio=5 tid=2 VMWAIT NATIVE THREADS: "system_server" sysTid=595 nice=0 sched=0/0 cgrp=apps "system_server" sysTid=641 nice=-2 sched=0/0 cgrp=apps "system_server" sysTid=818 nice=-2 sched=0/0 cgrp=apps "system_server" sysTid=819 nice=-2 sched=0/0 cgrp=apps "android.bg" sysTid=846 nice=10 sched=0/0 cgrp=apps/bg_non_interactive "android.bg" sysTid=847 nice=10 sched=0/0 cgrp=apps/bg_non_interactive "android.bg" sysTid=862 nice=10 sched=0/0 cgrp=apps/bg_non_interactive "android.bg" sysTid=863 nice=10 sched=0/0 cgrp=apps/bg_non_interactive "GL updater" sysTid=5268 nice=-10 sched=0/0 cgrp=apps ----- end 582 ----- ----- pid 849 at 2014-08-03 21:05:14 ----- JNI: CheckJNI is off; workarounds are off; pins=0; globals=281 DALVIK THREADS: "main" prio=5 tid=1 NATIVE "AsyncTask #5" prio=5 tid=15 WAIT
"AsyncTask #4" prio=5 tid=14 WAIT
"AsyncTask #3" prio=5 tid=13 WAIT
"pool-1-thread-1" prio=5 tid=12 WAIT
"AsyncTask #2" prio=5 tid=11 WAIT
"AsyncTask #1" prio=5 tid=10 WAIT
"Binder_2" prio=5 tid=9 NATIVE "Binder_1" prio=5 tid=8 NATIVE "FinalizerWatchdogDaemon" daemon prio=5 tid=7 WAIT
"FinalizerDaemon" daemon prio=5 tid=6 WAIT
"ReferenceQueueDaemon" daemon prio=5 tid=5 WAIT
"Compiler" daemon prio=5 tid=4 VMWAIT "Signal Catcher" daemon prio=5 tid=3 RUNNABLE "GC" daemon prio=5 tid=2 VMWAIT ----- end 849 ----- ----- pid 834 at 2014-08-03 21:05:14 ----- JNI: CheckJNI is off; workarounds are off; pins=1; globals=386 DALVIK THREADS: "main" prio=5 tid=1 NATIVE "AsyncTask #5" prio=5 tid=35 WAIT
"AsyncTask #4" prio=5 tid=34 WAIT
"AsyncTask #3" prio=5 tid=33 WAIT
"AsyncTask #2" prio=5 tid=32 WAIT
"Binder_5" prio=5 tid=31 NATIVE "Stk App Service" prio=5 tid=30 NATIVE "SyncHandler-0" prio=5 tid=29 NATIVE "Thread-53" prio=5 tid=28 NATIVE "Cat Icon Loader" prio=5 tid=27 NATIVE "RilMessageDecoder" prio=5 tid=26 NATIVE "Cat Telephony service" prio=5 tid=25 NATIVE "WifiManager" prio=5 tid=24 NATIVE "SipService.Executor" prio=5 tid=23 NATIVE "Binder_4" prio=5 tid=22 NATIVE "Binder_3" prio=5 tid=21 NATIVE "AudioTrack" prio=10 tid=20 NATIVE |
Hi MonsterOfCookie... We believe the deadlock occurs in some situations when the Google Advertising ID is being accessed from the main thread, and the SDK will do access it from the main thread when activateApp is called form the main thread (which, of course, is a perfectly reasonable and expected thing to do). We're not yet ready to release an update, but would you be amenable to sending me your email address at greg.schechter@fb.com? I'd like to send you a patch you can apply to the SDK that we believe will remove this deadlock. Feedback from you about whether this actually resolves it in your case (since we haven't been able to reliably reproduce it) would also be super-helpful. Thanks! |
+1 got the same problem |
Not sure if this ticket will get updated. But Facebook have a fix for this, and fingers crossed it should be in the next release :) |
Wow, it's awesome there is going to be a fix! Thanks MonsterOfCookie for getting that debugging job done (instead of me) :) |
This issue has now been fixed and is part of the 3.17.1 release up at https://developers.facebook.com/docs/android and https://github.com/facebook/facebook-android-sdk. Many thanks to MonsterOfCookie and 卢路 for helping repro and verify the fix! |
I've caught our application hanging on start several times. The debugger showed that Facebook library threads deadlocked, one in AppEventsLogger.activateApp() called from the main activity onResume() and waiting on a lock in getSessionEventsState() and another one handling a flushTimer handler and waiting in getAdvertisingIdInfo() call. According to this post http://stackoverflow.com/questions/23379879/advertisingidclient-getadvertisingidinfo-hangs-forever getAdvertisingIdInfo() call needs the main context and thus gets blocked in this case.
Note, that the flushTimer is created at activateApp() call and has 0 delay, meaning it would trigger immediately. If context switch happens at this time we can be deadlocked.
Stacktraces:
main
at com.facebook.AppEventsLogger.getSessionEventsState(AppEventsLogger.java:703)
at com.facebook.AppEventsLogger.logEvent(AppEventsLogger.java:642)
at com.facebook.AppEventsLogger.logEvent(AppEventsLogger.java:634)
at com.facebook.AppEventsLogger.logEvent(AppEventsLogger.java:432)
at com.facebook.AppEventsLogger.logEvent(AppEventsLogger.java:397)
at com.facebook.AppEventsLogger.activateApp(AppEventsLogger.java:294)
at com.myapp.main.MainActivity.onResume(MainActivity.java:71)
at android.app.Instrumentation.callActivityOnResume(Instrumentation.java:1282)
at android.app.Activity.performResume(Activity.java:5405)
at android.app.ActivityThread.performResumeActivity(ActivityThread.java:3304)
at android.app.ActivityThread.handleResumeActivity(ActivityThread.java:3359)
at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2658)
at android.app.ActivityThread.access$800(ActivityThread.java:156)
at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1355)
at android.os.Handler.dispatchMessage(Handler.java:102)
at android.os.Looper.loop(Looper.java:157)
at android.app.ActivityThread.main(ActivityThread.java:5872)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:515)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:858)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:674)
at dalvik.system.NativeStart.main(Native Method)
Timer-0
at java.lang.Object.wait(Native Method)
at java.lang.Thread.parkFor(Thread.java:1239)
at sun.misc.Unsafe.park(Unsafe.java:325)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2017)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:410)
at com.google.android.gms.common.a.bg(Unknown Source)
at com.google.android.gms.ads.identifier.AdvertisingIdClient.getAdvertisingIdInfo(Unknown Source)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:515)
at com.facebook.internal.Utility.invokeMethodQuietly(Utility.java:459)
at com.facebook.internal.AttributionIdentifiers.getAndroidId(AttributionIdentifiers.java:77)
at com.facebook.internal.AttributionIdentifiers.getAttributionIdentifiers(AttributionIdentifiers.java:102)
at com.facebook.AppEventsLogger.getSessionEventsState(AppEventsLogger.java:707)
at com.facebook.AppEventsLogger.accumulatePersistedEvents(AppEventsLogger.java:904)
at com.facebook.AppEventsLogger.flushAndWait(AppEventsLogger.java:744)
at com.facebook.AppEventsLogger.access$100(AppEventsLogger.java:106)
at com.facebook.AppEventsLogger$2.run(AppEventsLogger.java:605)
at java.util.Timer$TimerImpl.run(Timer.java:284)
The text was updated successfully, but these errors were encountered: