search

urbanairship / android-library

Urban Airship Android SDK
Other
111 stars 122 forks source link

Rapid rise of anr, Android urbanairship-fcm:12.2.0 #152

Closed ZhangShuFly closed 4 years ago

ZhangShuFly commented 4 years ago

❗For how-to inquiries involving Airship functionality or use cases, please contact (support)[https://support.airship.com/].

Preliminary Info

What Airship dependencies are you using?

ℹ com.urbanairship.android:urbanairship-fcm:12.2.0

What are the versions of any relevant development tools you are using?

ℹ Android Studio

Report

What unexpected behavior are you seeing?

ℹ Upgrade to urbanairship- fcm:12.2.0 After that, from the Google play console, we can see that the rate of ANR is rising rapidly, which is mainly caused by locationreceive.

What is the expected behavior?

ℹLow ANR

What are the steps to reproduce the unexpected behavior?

Do you have logging for the issue?

ℹ Broadcast of Intent { act=com.urbanairship.location.ACTION_LOCATION_UPDATE flg=0x10 cmp=com.jason.android/com.urbanairship.location.LocationReceiver (has extras) }

marc-scig commented 4 years ago

Hi @ZhangShuFly,

We're going to need more information than this. Most important will be a full crashlog/ANR trace, but also it would help to know what version of the library you upgraded from, how you're using Airship location services in your app, whether there are specific android OS versions and devices seeing the crash, etc.

ZhangShuFly commented 4 years ago

@marc-scig Thank you for your reply. ℹ I upgraded from 10.0.1 to 12.2.0. ℹ In my code, the only things about location are:

UAirship.shared (). locationManager.isLocationUpdatesEnabled = true
UAirship.shared (). locationManager.isBackgroundLocationAllowed = true

I'm sure there's no code for location other than that. ℹ From Android 5.0 to 10.0. Including Samsung, LG, moto and other devices ℹ Report: Today, 11:07 AM on app version 11000247 LGE LG Premier Pro (cv3), 2048MB RAM, Android 8.1 Report 1

COLLAPSE ALL "main" tid=1 Native "main" prio=5 tid=1 Native | group="main" sCount=1 dsCount=0 flags=1 obj=0x73acd4b8 self=0xad0af000 | sysTid=13781 nice=0 cgrp=default sched=0/0 handle=0xb187c4a4 | state=S schedstat=( 0 0 0 ) utm=43 stm=13 core=1 HZ=100 | stack=0xbe142000-0xbe144000 stackSize=8MB | held mutexes=

00 pc 000000000004aa8c /system/lib/libc.so (__epoll_pwait+20)

01 pc 000000000001b671 /system/lib/libc.so (epoll_pwait+60)

02 pc 000000000001b6a1 /system/lib/libc.so (epoll_wait+12)

03 pc 0000000000010035 /system/lib/libutils.so (android::Looper::pollInner(int)+120)

04 pc 000000000000ff25 /system/lib/libutils.so (android::Looper::pollOnce(int, int, int, void**)+32)

05 pc 00000000000b6189 /system/lib/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv, _jobject, int)+24)

06 pc 0000000000192d9d /system/framework/arm/boot-framework.oat (Java_android_os_MessageQueue_nativePollOnce__JI+92)

at android.os.MessageQueue.nativePollOnce (Native method) at android.os.MessageQueue.next (MessageQueue.java:325) at android.os.Looper.loop (Looper.java:151) at android.app.ActivityThread.main (ActivityThread.java:6724) 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) "Jit thread pool worker thread 0" tid=2 Native "Jit thread pool worker thread 0" daemon prio=5 tid=2 Native | group="main" sCount=1 dsCount=0 flags=1 obj=0x14fc0198 self=0xad0afc00 | sysTid=13787 nice=9 cgrp=default sched=0/0 handle=0xa5807970 | state=S schedstat=( 0 0 0 ) utm=0 stm=0 core=1 HZ=100 | stack=0xa5709000-0xa570b000 stackSize=1022KB | held mutexes=

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

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

02 pc 000000000038e7b5 /system/lib/libart.so (art::ThreadPool::GetTask(art::Thread*)+172)

03 pc 000000000038e12b /system/lib/libart.so (art::ThreadPoolWorker::Run()+62)

04 pc 000000000038dd49 /system/lib/libart.so (art::ThreadPoolWorker::Callback(void*)+92)

05 pc 0000000000049517 /system/lib/libc.so (__pthread_start(void*)+22)

06 pc 000000000001b261 /system/lib/libc.so (__start_thread+32)

"ReferenceQueueDaemon" tid=4 Waiting "ReferenceQueueDaemon" daemon prio=5 tid=4 Waiting | group="system" sCount=1 dsCount=0 flags=1 obj=0x14fc02a8 self=0xad0b0800 | sysTid=13789 nice=4 cgrp=default sched=0/0 handle=0x93340970 | state=S schedstat=( 0 0 0 ) utm=0 stm=0 core=3 HZ=100 | stack=0x9323e000-0x93240000 stackSize=1038KB | held mutexes= at java.lang.Object.wait (Native method)

ℹ Because I can't reproduce this issue, there's no more information for you.

rlepinski commented 4 years ago

@ZhangShuFly This is a background ANR probably due to the broadcast receiver not finishing in time. Broadcasts start the entire app, not just our SDK, so anything that changed that starts in Application.onCreate could also be the cause of the ANR. The Airship LocationReceiver does most its work on a background thread but still has to finish the intent on time. How are you calling takeOff? What work are you doing in the onAirshipReady callback?

ZhangShuFly commented 4 years ago

@rlepinski ℹI call UAirship.takeOff in Application.onCreate(). ℹ onAirshipReady callback code:

  `
fun configAirship()
{
    UAirship.takeOff(application) { airship ->
        if(airship == null) return@takeOff

        airship.pushManager.setNotificationFactory(CustomNotificationFactory(application))
        airship.pushManager.addRegistrationListener(SampleRegistrationListener())

        UAirship.shared().locationManager.isLocationUpdatesEnabled = true
        UAirship.shared().locationManager.isBackgroundLocationAllowed = true

        enablePushNotification(true)
    }
}

fun enablePushNotification(enabled: Boolean)
{
    UAirship.shared().pushManager.apply {
        isSoundEnabled = enabled
        isVibrateEnabled = enabled
        isPushEnabled = enabled
        userNotificationsEnabled = enabled
    }

    UAirship.shared().locationManager.isLocationUpdatesEnabled = enabled

    if (enabled)
    {
        sendTagsToServer()
    }
}

fun sendTagsToServer()
{
    val allTags = LinkedHashSet<String>()
                ...
    UAirship.shared().pushManager.tags = allTags
}
    `

ℹ Application.onCreate and onairshipready callback are unchanged from the previous version .But Google play console shows a lot of new ANRS related to LocationReceiver. The only thing I can think of is that I upgraded 10.0.1 to 12.2.0.

image

rlepinski commented 4 years ago

Could you expand the sendTagsToServer method?

ZhangShuFly commented 4 years ago

I'm sure there are no time-consuming tasks in sendtagstoserver. `

/**
 * Set tags to Airship
 */
@Synchronized
fun sendTagsToServer()
{
    val allTags = LinkedHashSet<String>()
    allTags.add("N_ALL")

    var tagUser = "U_ANONYMOUS"
    if (isLogin())
    {
        allTags.add("U_LOGGEDIN")
        tagUser = "U_MVPD"
    }
    allTags.add(tagUser)

    val carrier = Build.BRAND
    if (!TextUtils.isEmpty(carrier))
    {
        allTags.add("U_CARRIER_" + carrier.toUpperCase())
    }

    val  region = getDefaultRegionName()
    allTags.add(String.format("U_REGION_%s", region.trim().toUpperCase().replace(" ", "_")))
    UAirship.shared().pushManager.tags = allTags
}

/**
 * from SharedPreferences
 */
fun isLogin(): Boolean
{
    return ShareDataManager.NLShareData.getPreferenceBoolean(Constants.PROVIDER_LOGIN_STATE, false)
}

/**
 *  ‘configs’ is a global variable object
 */
fun getDefaultRegionName(): String {
    return Config.configs?.getRegionName() ?: "East"
}

`

rlepinski commented 4 years ago

The only location code that changed from 10.x to 12.x was androidx migration. I am almost certain it has to do with the amount of work your application is doing during onCreate, making it take too long to process the intent. We had similar issues with apps taking too long to process notifications causing background ANRs. We can deploy the same solution where we finish the broadcast in 10 seconds even if the work is not done yet, making it possible for the OS to suspend the process before we fully process the location.

ZhangShuFly commented 4 years ago

ℹ Thanks. Besides to do a lot of work in Application.onCreate, do you think there are any other possible reasons? Has anyone else reported an issue similar to mine? Usually the onCteate method will be executed soon, I haven't thought when it will be blocked.

ℹ I reappeared this ANR when the app started today. Please help me to have a look. The app has been started normally, the ANR prompt appears on the MainActivity page. Attach trace and log: anr_2020-06-16-10-59-54-312.txt logcat.txt

ℹI checked the 10. x and 12. x codes. Version 10.x uses LocationService, and version 12.x changes to LocationReceiver. LocationReceiver.onReceive using goAsync, but UAirship.waitForTakeOff uses synchronized . If more than one broadcast in a short time, is it possible for ANR to occur?

rlepinski commented 4 years ago

It will only wait once, after its initialized then it will return early every time. There should be no reason for it take more than 100 ms in normal circumstances, so again I think it either has to be something in your application or doing some blocking in onAirshipReady. We did have it waiting up to 9 seconds, so if your process takes that long to initialize then we would only have 1 second to process the request.

I would recommend looking at your application startup time and trying to see how long it takes in various network conditions.

We released SDK 13.2 that will finish the broadcast early even if the update is not fully processed. This will prevent the background ANR but its possible the location update could get dropped if the OS suspends the process.