Bug 28399 - ANR in native code while creating activity
Summary: ANR in native code while creating activity
Status: RESOLVED ANSWERED
Alias: None
Product: Android
Classification: Xamarin
Component: Mono runtime / AOT Compiler ()
Version: 4.20.0
Hardware: PC Windows
: Normal normal
Target Milestone: ---
Assignee: Jonathan Pryor
URL:
Depends on:
Blocks:
 
Reported: 2015-03-25 05:16 UTC by Roman Cervenak
Modified: 2015-03-27 10:39 UTC (History)
2 users (show)

Tags:
Is this bug a regression?: ---
Last known good build:

Notice (2018-05-24): bugzilla.xamarin.com is now in read-only mode.

Please join us on Visual Studio Developer Community and in the Xamarin and Mono organizations on GitHub to continue tracking issues. Bugzilla will remain available for reference in read-only mode. We will continue to work on open Bugzilla bugs, copy them to the new locations as needed for follow-up, and add the new items under Related Links.

Our sincere thanks to everyone who has contributed on this bug tracker over the years. Thanks also for your understanding as we make these adjustments and improvements for the future.


Please create a new report on Developer Community or GitHub with your current version information, steps to reproduce, and relevant error messages or log files if you are hitting an issue that looks similar to this resolved bug and you do not yet see a matching new report.

Related Links:
Status:
RESOLVED ANSWERED

Description Roman Cervenak 2015-03-25 05:16:11 UTC
In Google Play developer console for our app (already in production) I can see many instances of the ANR keyDispatchingTimedOut (AFAIK, this means app didnt processed user touch for 5 seconds and user got ANR dialog). It seems to be stuck "inside" native code in base.onCreate(). All traces are from android 4.1 or 4.2 (on many different devices, no pattern here)

Here is the main thread:

DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)

"main" prio=5 tid=1 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x410cca18 self=0x57016010
| sysTid=28631 nice=0 sched=0/0 cgrp=apps handle=1074526300
| state=S schedstat=( 1909206589 252336483 1639 ) utm=164 stm=26 core=1
#00 pc 000217a8 /system/lib/libc.so (__futex_syscall3+8)
#01 pc 0000e09c /system/lib/libc.so (__pthread_cond_timedwait_relative+48)
#02 pc 0000e0f8 /system/lib/libc.so (__pthread_cond_timedwait+60)
#03 pc 001c9130 /data/app-lib/com.sygic.speedcamapp-2/libmonosgen-2.0.so
at speedcamapp.activities.MainActivity.n_onCreate(Native Method)
at speedcamapp.activities.MainActivity.onCreate(MainActivity.java:38)
at android.app.Activity.performCreate(Activity.java:5122)
at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1081)
at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2270)
at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2358)
at android.app.ActivityThread.access$600(ActivityThread.java:156)
at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1340)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loop(Looper.java:153)
at android.app.ActivityThread.main(ActivityThread.java:5297)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:511)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:833)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:600)
at dalvik.system.NativeStart.main(Native Method)
Comment 1 Jonathan Pryor 2015-03-25 14:11:47 UTC
What does MainActivity.OnCreate() do?

Based on the native call stack, it looks like MainActivity.OnCreate() is (indirectly?) calling a method which blocks on a WaitHandle of some form.
Comment 2 Roman Cervenak 2015-03-26 05:15:34 UTC
Does not this line:

at speedcamapp.activities.MainActivity.n_onCreate(Native Method)

means that the wait is actually not in my onCreate, but in base.onCreate (which is out of my control)?

My onCreate is doing various stuff, SetContentView, setup paging adapter etc. but does not waiting on anything. There is one async task used, but is not awaited, like this

Task t = DoStuffAsync(...).ContinueWith(() => DoOtherStuff());
Comment 3 Jonathan Pryor 2015-03-26 10:22:07 UTC
> Does not this line...means that the wait is actually not in my onCreate,
> but in base.onCreate (which is out of my control)?

No. A method with an `n_` prefix (usually) means it's an Android Callable Wrapper Java `native` method declaration, e.g.

    class MainActivity {
        protected void onCreate (Bundle b) {
            n_onCreate(b);
        }
        native void n_onCreate (Bundle b);
    }

The implementation of MainActivity.n_onCreate() will then invoke your overriding MainActivity.OnCreate().

If the `base.OnCreate()` invocation were failing, you'd instead see a stack frame of:

> at android.app.Activity.onCreate(Activity.java:...)
> at speedcamapp.activities.MainActivity.n_onCreate(Native Method)
> at speedcamapp.activities.MainActivity.onCreate(MainActivity.java:38)

i.e. n_onCreate() would be calling Activity.onCreate(), which is NOT what you reported.

If you're able to reproduce this, I would suggest stepping through your MainActivity.OnCreate() method in a debugger (or Console.WriteLine()...) to see where it stops executing.

If you can't reproduce this, I'd suggest looking deeply at everything that could be involved. Could any static constructors block? Does DoStuffAsync() block *before* creating and returning the Task? (Just because a Task is involved doesn't mean that all execution is asynchronous).
Comment 4 Roman Cervenak 2015-03-26 10:36:20 UTC
Thanks for clarification about the n_onCreate. Unfortunately, I cant reproduce this ANR myself, so I can only guess. So, this question comes to mind: since there is no line between these two lines

> #03 pc 001c9130 /data/app-lib/com.sygic.speedcamapp-2/libmonosgen-2.0.so
> at speedcamapp.activities.MainActivity.n_onCreate(Native Method)

can I assume that whatever causing the wait is DIRECTLY in the onCreate method, and not in some other method called from onCreate? If so, I am really puzzled, cause there is nothing risky here. If not so, why there is not the line for this method in stack?

The async "DoStuffAsync" is just creating HttpClient and awaiting httpClient.PostAsync(...). No heavy constructor logic or similar stuff. Is it possible that onCreate "cannot end" because of this Task created and started inside it, even when it is not awaited? That seems weird to me, but at this point, I am starting to suspect everything and everyone :)
Comment 5 Jonathan Pryor 2015-03-26 11:38:59 UTC
> can I assume that whatever causing the wait is DIRECTLY in the onCreate method,
> and not in some other method called from onCreate?

Alas, no.

The Android native stack walking code seems to be "stupid" -- or maybe it's the ARM stack walking ABI which is stupid, whichever; *something* is stupid -- because all stack frames from JIT'd code are always missing from the Java-side stack traces such as this.

For example, consider the stack trace on Bug #16019:

> UNHANDLED EXCEPTION: Android.Views.InflateException: Exception of type 'Android.Views.InflateException' was thrown.
> at Android.Runtime.JNIEnv.CallNonvirtualVoidMethod (intptr,intptr,intptr,Android.Runtime.JValue[]) [0x00024] in /Users/builder/data/lanes/monodroid-mlion-monodroid-4.8.2-branch/a25a31d0/source/monodroid/src/Mono.Android/src/Runtime/JNIEnv.g.cs:616
> at Android.App.Activity.SetContentView (int) [0x00070] in /Users/builder/data/lanes/monodroid-mlion-monodroid-4.8.2-branch/a25a31d0/source/monodroid/src/Mono.Android/platforms/android-14/src/generated/Android.App.Activity.cs:3824
> at SimpleMapDemo.BasicDemoActivity.OnCreate (Android.OS.Bundle) [0x00009] in c:\Users\ABULH\Documents\monodroid-samples-master\monodroid-samples-master\MapsAndLocationDemo_v2\SimpleMapDemo\BasicDemoActivity.cs:13
> at Android.App.Activity.n_OnCreate_Landroid_os_Bundle_ (intptr,intptr,intptr) [0x00011] in /Users/builder/data/lanes/monodroid-mlion-monodroid-4.8.2-branch/a25a31d0/source/monodroid/src/Mono.Android/platforms/android-14/src/generated/Android.App.Activity.cs:1937
> at (wrapper dynamic-method) object.419404b5-c8ce-463f-9a6b-decd4e9cb53f (intptr,intptr,intptr) <IL 0x00017, 0x0001f>
> 
>   --- End of managed exception stack trace ---
> android.view.InflateException: Binary XML file line #1: Error inflating class fragment
>     at android.view.LayoutInflater.createViewFromTag(LayoutInflater.java:704)
>     at android.view.LayoutInflater.rInflate(LayoutInflater.java:746)
>     at android.view.LayoutInflater.inflate(LayoutInflater.java:489)
>     at android.view.LayoutInflater.inflate(LayoutInflater.java:396)
>     at android.view.LayoutInflater.inflate(LayoutInflater.java:352)
>     at com.android.internal.policy.impl.PhoneWindow.setContentView(PhoneWindow.java:270)
>     at android.app.Activity.setContentView(Activity.java:1881)
>     at simplemapdemo.BasicDemoActivity.n_onCreate(Native Method)
>     at simplemapdemo.BasicDemoActivity.onCreate(BasicDemoActivity.java:28)
>     at android.app.Activity.performCreate(Activity.java:5104)
>     at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1080)
>     at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2144)
>     at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2230)
>     at android.app.ActivityThread.access$600(ActivityThread.java:141)
>     at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1234)
>     at android.os.Handler.dispatchMessage(Handler.java:99)
>     at android.os.Looper.loop(Looper.java:137)
>     at android.app.ActivityThread.main(ActivityThread.java:5039)
>     at java.lang.reflect.Method.invokeNative(Native Method)
>     at java.lang.reflect.Method.invoke(Method.java:511)
>     at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:793)
>     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:560)
>     at dalvik.system.NativeStart.main(Native Method)

The Java side stack trace starts after the "--- End of managed exception stack trace ---" line, while the managed stack trace is before.

Unfortunately there's currently no automated way to "stitch" these stack traces together. Fortunately, manually doing so isn't difficult: the n_*() methods from the Java stack trace correspond to similarly named n_*() methods in the managed stack trace. Thus, for the above stack traces, a Unified stack trace would be:

>     at android.view.LayoutInflater.createViewFromTag(LayoutInflater.java:704)
>     at android.view.LayoutInflater.rInflate(LayoutInflater.java:746)
>     at android.view.LayoutInflater.inflate(LayoutInflater.java:489)
>     at android.view.LayoutInflater.inflate(LayoutInflater.java:396)
>     at android.view.LayoutInflater.inflate(LayoutInflater.java:352)
>     at com.android.internal.policy.impl.PhoneWindow.setContentView(PhoneWindow.java:270)
>     at android.app.Activity.setContentView(Activity.java:1881)
>     at Android.Runtime.JNIEnv.CallNonvirtualVoidMethod (intptr,intptr,intptr,Android.Runtime.JValue[])
>     at Android.App.Activity.SetContentView (int)
>     at SimpleMapDemo.BasicDemoActivity.OnCreate (Android.OS.Bundle)
>     at Android.App.Activity.n_OnCreate_Landroid_os_Bundle_ (intptr,intptr,intptr)
>     at (wrapper dynamic-method) object.419404b5-c8ce-463f-9a6b-decd4e9cb53f (intptr,intptr,intptr) <IL 0x00017, 0x0001f>
>     at simplemapdemo.BasicDemoActivity.n_onCreate(Native Method)
>     at simplemapdemo.BasicDemoActivity.onCreate(BasicDemoActivity.java:28)
>     at android.app.Activity.performCreate(Activity.java:5104)
>     at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1080)
>     at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2144)
>     at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2230)

Unfortunately, Google Play doesn't (and can't!) provide the managed stack traces, so all we know for sure from your ANR report is that *some* method called *somewhere* from MainActivity.OnCreate() is blocking.

You'll unfortunately need to review everything callable by MainActivity.OnCreate(). Fortunately, based on the ANR report, it's going to be a managed lock-related construct, such as a `lock` or a System.Threading.WaitHandle, so that might help with your search.
Comment 6 Roman Cervenak 2015-03-27 03:51:13 UTC
Thanks again Jonathan. Still have no idea where is the problem, but since it is in my code somewhere, this "bug" is misleading and you can close it. I just wish it was some blog I can learn about "these things" (or is there?)
Comment 7 Jonathan Pryor 2015-03-27 10:39:35 UTC
One of these days I should restart my blog: "Adventures in Android Debugging ^H^H ARGH!!!!"