onActivityResumed breadcrumb contributes to ANR

elihart commented 3 years ago

Describe the bug

We had an ANR reported by bugsnag that shows bugsnag's internal ActivityBreadcrumbCollector in the trace. This was Bugsnag's automatic logging of a breadcrumb on activity resumed.

Note that this is fairly rare, so it's not a big problem for us, but of course we'd prefer if this was optimized. Also we do have similar ANR stacktraces showing other libraries that use the onActivityResumed application hook to do their own things, and these all together contribute.

Environment

Android version: 7.1.1
Bugsnag version: 5.9.1
Emulator or physical device: physical device (motorola_Moto G Play)

ANR
 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: 4.  Wait queue head age: 6096.4ms.)

    /system/lib/libart.so:1218528 
    /system/lib/libart.so:1180525 art::DexFile::FindClassDef(char const*, unsigned int) const
    /system/lib/libart.so:890917 art::ClassLinker::FindClassInPathClassLoader(art::ScopedObjectAccessAlreadyRunnable&, art::Thread*, char const*, unsigned int, art::Handle<art::mirror::ClassLoader>, art::mirror::Class**)
    /system/lib/libart.so:894451 art::ClassLinker::FindClass(art::Thread*, char const*, art::Handle<art::mirror::ClassLoader>)
    /system/lib/libart.so:817937 art::ClassLinker::ResolveType(art::DexFile const&, unsigned short, art::Handle<art::mirror::DexCache>, art::Handle<art::mirror::ClassLoader>)
    /system/lib/libart.so:982043 art::ClassLinker::ResolveFieldJLS(art::DexFile const&, unsigned int, art::Handle<art::mirror::DexCache>, art::Handle<art::mirror::ClassLoader>)
    /system/lib/libart.so:4073787 artGetObjStaticFromCode
    /system/lib/libart.so:594836 ExecuteMterpImpl
    /system/lib/libart.so:1839295 
    /system/lib/libart.so:1858599 art::interpreter::ArtInterpreterToInterpreterBridge(art::Thread*, art::DexFile::CodeItem const*, art::ShadowFrame*, art::JValue*)
    /system/lib/libart.so:1957243 bool art::interpreter::DoCall<false, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)
    /system/lib/libart.so:4145609 MterpInvokeStatic
    /system/lib/libart.so:596760 ExecuteMterpImpl
    /system/lib/libart.so:1839295 
    /system/lib/libart.so:1858599 art::interpreter::ArtInterpreterToInterpreterBridge(art::Thread*, art::DexFile::CodeItem const*, art::ShadowFrame*, art::JValue*)
    /system/lib/libart.so:1957243 bool art::interpreter::DoCall<false, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)
    /system/lib/libart.so:4151851 MterpInvokeVirtualQuick
    /system/lib/libart.so:612120 ExecuteMterpImpl
    /system/lib/libart.so:1839295 
    /system/lib/libart.so:1858599 art::interpreter::ArtInterpreterToInterpreterBridge(art::Thread*, art::DexFile::CodeItem const*, art::ShadowFrame*, art::JValue*)
    /system/lib/libart.so:1957243 bool art::interpreter::DoCall<false, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)
    /system/lib/libart.so:4144363 MterpInvokeInterface
    /system/lib/libart.so:596888 ExecuteMterpImpl
    /system/lib/libart.so:1839295 
    /system/lib/libart.so:1858599 art::interpreter::ArtInterpreterToInterpreterBridge(art::Thread*, art::DexFile::CodeItem const*, art::ShadowFrame*, art::JValue*)
    /system/lib/libart.so:1960775 bool art::interpreter::DoCall<true, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)
    /system/lib/libart.so:4152391 MterpInvokeVirtualQuickRange
    /system/lib/libart.so:612248 ExecuteMterpImpl
    /system/lib/libart.so:1839295 
    /system/lib/libart.so:1858599 art::interpreter::ArtInterpreterToInterpreterBridge(art::Thread*, art::DexFile::CodeItem const*, art::ShadowFrame*, art::JValue*)
    /system/lib/libart.so:1960775 bool art::interpreter::DoCall<true, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)
    /system/lib/libart.so:4151057 MterpInvokeStaticRange
    /system/lib/libart.so:597528 ExecuteMterpImpl
    /system/lib/libart.so:1839295 
    /system/lib/libart.so:1858449 art::interpreter::EnterInterpreterFromEntryPoint(art::Thread*, art::DexFile::CodeItem const*, art::ShadowFrame*)
    /system/lib/libart.so:4106747 artQuickToInterpreterBridge
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    /system/lib/libart.so:669079 
    Unknown:-2 com.bugsnag.android.ndk.NativeBridge.addBreadcrumb
    NativeBridge:105 com.bugsnag.android.ndk.NativeBridge.update
    Observable.java:161 java.util.Observable.notifyObservers
    BaseObservable:8 com.bugsnag.android.BaseObservable.notifyObservers
    BreadcrumbState:39 com.bugsnag.android.BreadcrumbState.add
    Client:828 com.bugsnag.android.Client.leaveBreadcrumb
    Client:180 com.bugsnag.android.Client$2.invoke
    Client:176 com.bugsnag.android.Client$2.invoke
    ActivityBreadcrumbCollector:46 com.bugsnag.android.ActivityBreadcrumbCollector.leaveBreadcrumb
    ActivityBreadcrumbCollector:36 com.bugsnag.android.ActivityBreadcrumbCollector.leaveBreadcrumb$default$bf8b81
    ActivityBreadcrumbCollector:20 com.bugsnag.android.ActivityBreadcrumbCollector.onActivityResumed
    Application.java:216 android.app.Application.dispatchActivityResumed
    Activity.java:1255 android.app.Activity.onResume
    FragmentActivity:455 androidx.fragment.app.FragmentActivity.onResume

mattdyoung commented 3 years ago

Hi @elihart

Thanks for reporting the issue. We'll take a look to see if there are any optimizations we can make to mitigate this.

mattdyoung commented 3 years ago

@elihart we'll look into doing some profiling to confirm how much Bugsnag might be contributing to the issue. As you have other libraries hooking in to onActivityResumed it's not necessarily the case that Bugsnag is having the most significant impact, just because that's what is in the stack when we capture the stacktrace in some of these cases.

In the meantime if this is a concern one option to mitigate this would be to disable BreadcrumbType.STATE breadcrumbs in enabledBreadcrumbTypes, as this would prevent Bugsnag hooking in to ActivityBreadcrumbCollector: https://docs.bugsnag.com/platforms/android/configuration-options/#enabledbreadcrumbtypes

elihart commented 3 years ago

Following up on this, we are seeing ANRs from bugsnag breadcrumbs that happen in other places beyond just activity resume. We have a bugsnag error grouping for ANRs that happen on any custom place that we leave a breadcrumb in the app.

They all share this part of the stacktrace:

ANR
 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: 24.  Wait queue head age: 14105.7ms.)

    [vdso]:1248 __kernel_rt_sigreturn
    /data/app/com.airbnb.android-1/oat/arm64/base.odex:139548288 oatexec
    unknown:-2 com.bugsnag.android.ndk.NativeBridge.addBreadcrumb
    NativeBridge:109 com.bugsnag.android.ndk.NativeBridge.update
    Observable.java:161 java.util.Observable.notifyObservers
    BaseObservable:8 com.bugsnag.android.BaseObservable.notifyObservers
    BreadcrumbState:39 com.bugsnag.android.BreadcrumbState.add
    Client:844 com.bugsnag.android.Client.leaveBreadcrumb
    BugsnagWrapperImpl:104 com.airbnb.android.base.debugimpl.BugsnagWrapperImpl.leaveBreadcrumb
    BugsnagWrapper:231 com.airbnb.android.base.debug.BugsnagWrapper.leaveBreadcrumb

Has there been any progress in improving this? Could breadcrumbs be left asynchronously?

mattdyoung commented 3 years ago

Thanks for the additional info.

We've already released a few performance optimizations in recent versions which reduce the amount of work Bugsnag does on the main thread.

We also are working on some more significant changes to how Bugsnag persists data to device storage which should further reduce the likelihood of such ANRs. I'll update this issue once these improvements are released.

elihart commented 3 years ago

Fantastic, thank you!

elihart commented 2 years ago

I assume work is ongoing on the more significant changes to address bugsnag performance, but I thought I'd share some recent ANR stacktraces where the Bugsnag client was caught logging breadcrumbs in onPause

ANR:  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: 52.  Wait queue head age: 5496.2ms.)
        at java.util.Date.<init>(Date.java:165)
        at com.bugsnag.android.Client.leaveBreadcrumb(Client:896)
        at com.bugsnag.android.Client$2.invoke(Client:196)
        at com.bugsnag.android.Client$2.invoke(Client:192)
        at com.bugsnag.android.ActivityBreadcrumbCollector.leaveBreadcrumb(ActivityBreadcrumbCollector:46)
        at com.bugsnag.android.ActivityBreadcrumbCollector.leaveBreadcrumb$default(ActivityBreadcrumbCollector:36)
        at com.bugsnag.android.ActivityBreadcrumbCollector.onActivityPaused(ActivityBreadcrumbCollector:23)
        at android.app.Application.dispatchActivityPaused(Application.java:251)
        at android.app.Activity.onPause(Activity.java:1731)

ANR
 Broadcast of Intent { act=android.intent.action.SCREEN_OFF flg=0x50200010 }

    [vdso]:1672 __kernel_rt_sigreturn
    /system/lib64/libart.so:3828120 art::OatFile::OatMethod::LinkMethod(art::ArtMethod*) const
    /system/lib64/libart.so:1089968 
    /system/lib64/libart.so:1086428 art::ClassLinker::LoadClassMembers(art::Thread*, art::DexFile const&, unsigned char const*, art::Handle<art::mirror::Class>)
    /system/lib64/libart.so:1062680 art::ClassLinker::DefineClass(art::Thread*, char const*, unsigned long, art::Handle<art::mirror::ClassLoader>, art::DexFile const&, art::DexFile::ClassDef const&)
    /system/lib64/libart.so:1061016 art::ClassLinker::FindClassInBaseDexClassLoader(art::ScopedObjectAccessAlreadyRunnable&, art::Thread*, char const*, unsigned long, art::Handle<art::mirror::ClassLoader>, art::ObjPtr<art::mirror::Class>*)
    /system/lib64/libart.so:1065572 art::ClassLinker::FindClass(art::Thread*, char const*, art::Handle<art::mirror::ClassLoader>)
    /system/lib64/libart.so:991352 art::ClassLinker::ResolveType(art::DexFile const&, art::dex::TypeIndex, art::Handle<art::mirror::DexCache>, art::Handle<art::mirror::ClassLoader>)
    /system/lib64/libart.so:1127660 art::ClassLinker::ResolveType(art::DexFile const&, art::dex::TypeIndex, art::ObjPtr<art::mirror::Class>)
    /system/lib64/libart.so:1077612 art::ClassLinker::LoadSuperAndInterfaces(art::Handle<art::mirror::Class>, art::DexFile const&)
    /system/lib64/libart.so:1062764 art::ClassLinker::DefineClass(art::Thread*, char const*, unsigned long, art::Handle<art::mirror::ClassLoader>, art::DexFile const&, art::DexFile::ClassDef const&)
    /system/lib64/libart.so:1061016 art::ClassLinker::FindClassInBaseDexClassLoader(art::ScopedObjectAccessAlreadyRunnable&, art::Thread*, char const*, unsigned long, art::Handle<art::mirror::ClassLoader>, art::ObjPtr<art::mirror::Class>*)
    /system/lib64/libart.so:1065572 art::ClassLinker::FindClass(art::Thread*, char const*, art::Handle<art::mirror::ClassLoader>)
    /system/lib64/libart.so:991352 art::ClassLinker::ResolveType(art::DexFile const&, art::dex::TypeIndex, art::Handle<art::mirror::DexCache>, art::Handle<art::mirror::ClassLoader>)
    /system/lib64/libart.so:742564 
    /system/lib64/libart.so:2473332 
    /system/lib64/libart.so:5049072 MterpNewInstance
    /system/lib64/libart.so:5064468 ExecuteMterpImpl
    /system/lib64/libart.so:2332200 
    /system/lib64/libart.so:2358568 art::interpreter::ArtInterpreterToInterpreterBridge(art::Thread*, art::DexFile::CodeItem const*, art::ShadowFrame*, art::JValue*)
    /system/lib64/libart.so:2459788 bool art::interpreter::DoCall<false, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)
    /system/lib64/libart.so:5045560 MterpInvokeVirtualQuick
    /system/lib64/libart.so:5089944 ExecuteMterpImpl
    /system/lib64/libart.so:2332200 
    /system/lib64/libart.so:2358568 art::interpreter::ArtInterpreterToInterpreterBridge(art::Thread*, art::DexFile::CodeItem const*, art::ShadowFrame*, art::JValue*)
    /system/lib64/libart.so:2459788 bool art::interpreter::DoCall<false, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)
    /system/lib64/libart.so:5037696 MterpInvokeDirect
    /system/lib64/libart.so:5074456 ExecuteMterpImpl
    /system/lib64/libart.so:2332200 
    /system/lib64/libart.so:2358568 art::interpreter::ArtInterpreterToInterpreterBridge(art::Thread*, art::DexFile::CodeItem const*, art::ShadowFrame*, art::JValue*)
    /system/lib64/libart.so:2459788 bool art::interpreter::DoCall<false, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)
    /system/lib64/libart.so:5037696 MterpInvokeDirect
    /system/lib64/libart.so:5074456 ExecuteMterpImpl
    /system/lib64/libart.so:2332200 
    /system/lib64/libart.so:2358568 art::interpreter::ArtInterpreterToInterpreterBridge(art::Thread*, art::DexFile::CodeItem const*, art::ShadowFrame*, art::JValue*)
    /system/lib64/libart.so:2459788 bool art::interpreter::DoCall<false, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)
    /system/lib64/libart.so:5045560 MterpInvokeVirtualQuick
    /system/lib64/libart.so:5089944 ExecuteMterpImpl
    /system/lib64/libart.so:2332200 
    /system/lib64/libart.so:2358568 art::interpreter::ArtInterpreterToInterpreterBridge(art::Thread*, art::DexFile::CodeItem const*, art::ShadowFrame*, art::JValue*)
    /system/lib64/libart.so:2459788 bool art::interpreter::DoCall<false, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)
    /system/lib64/libart.so:5038392 MterpInvokeStatic
    /system/lib64/libart.so:5074584 ExecuteMterpImpl
    /system/lib64/libart.so:2332200 
    /system/lib64/libart.so:2358568 art::interpreter::ArtInterpreterToInterpreterBridge(art::Thread*, art::DexFile::CodeItem const*, art::ShadowFrame*, art::JValue*)
    /system/lib64/libart.so:2459788 bool art::interpreter::DoCall<false, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)
    /system/lib64/libart.so:5037696 MterpInvokeDirect
    /system/lib64/libart.so:5074456 ExecuteMterpImpl
    /system/lib64/libart.so:2332200 
    /system/lib64/libart.so:4983440 artQuickToInterpreterBridge
    /system/lib64/libart.so:5171232 
    /system/framework/arm64/boot-framework.oat:7780552 oatexec
    unknown:-2 com.bugsnag.android.ndk.NativeBridge.addBreadcrumb
    NativeBridge:109 com.bugsnag.android.ndk.NativeBridge.onStateChange
    BaseObservable:37 com.bugsnag.android.BaseObservable.updateState$bugsnag_android_core_release
    BreadcrumbState:104 com.bugsnag.android.BreadcrumbState.add
    Client:896 com.bugsnag.android.Client.leaveBreadcrumb
    Client:196 com.bugsnag.android.Client$2.invoke
    Client:192 com.bugsnag.android.Client$2.invoke
    ActivityBreadcrumbCollector:46 com.bugsnag.android.ActivityBreadcrumbCollector.leaveBreadcrumb
    ActivityBreadcrumbCollector:36 com.bugsnag.android.ActivityBreadcrumbCollector.leaveBreadcrumb$default
    ActivityBreadcrumbCollector:23 com.bugsnag.android.ActivityBreadcrumbCollector.onActivityPaused
    Application.java:236 android.app.Application.dispatchActivityPaused
    Activity.java:1795 android.app.Activity.onPause

yousif-bugsnag commented 2 years ago

We've now released v5.16.0 which includes performance improvements around breadcrumb date formatting that should address this. (#1525).

Thanks again for raising this @elihart!

bugsnag / bugsnag-android

onActivityResumed breadcrumb contributes to ANR #1250

Describe the bug

Environment