Skip to content
This repository has been archived by the owner on Aug 30, 2023. It is now read-only.

App takes much longer to load when App is built with sentry sdk #442

Closed
12 tasks
tiwariashish86 opened this issue May 30, 2020 · 31 comments · Fixed by #445
Closed
12 tasks

App takes much longer to load when App is built with sentry sdk #442

tiwariashish86 opened this issue May 30, 2020 · 31 comments · Fixed by #445
Labels
bug Something isn't working good first issue Good for newcomers

Comments

@tiwariashish86
Copy link

Platform:

  • Android -> On All Android devices we have. e.g. Galaxy S6 Edge (version 6.0.1), Galaxy Tab S3(version 7.0)
  • Java -> JavaVersion.VERSION_1_8
  • NDK -> android-ndk-r20(Did not try with other NDKs), cmake version 3.12.3

IDE:

  • Android Studio -> 3.5 (issue is seen with cmd gradle build as well)

Build system:

  • Gradle -> 5.5

Android Gradle Plugin:

  • Yes -> If yes, which version?
  • No

Sentry Android Gradle Plugin:

  • Yes -> If yes, which version?
  • No

Proguard/R8: both cases

  • [ X] Enabled
  • [ X] Disabled

sentry-android installed with:

  • [ X] JCenter
  • Bintray
  • Maven Central
  • Manually

The version of sentry-android:
2.1.2


I have the following issue:
When android app is built with sentry sdk it takes around 10 seconds to load the app.

from Logcat :

  1. Without sentry sdk => ActivityManager: Displayed com.machinezone.gow/com.mz.jix.MainActivity: +492ms
  2. with Sentry SDK => I/ActivityManager: Displayed com.machinezone.gow/com.mz.jix.MainActivity: +9s696ms

Displayed => This value represents the amount of time elapsed between launching the process and finishing drawing the corresponding activity on the screen

The issue is specially worse with Asset build on Android.

Steps to reproduce:
Just do an Asset build on android with sentry SDK and launch the app. After that observe approx 10 seconds of black screen before Application finally starts. Sentry SDK inclusion in built is causing significant app startup delay

Actual result:
App startup is significantly delayed.

Expected result:
App startup time should be same as app without Sentry SDK

@tiwariashish86
Copy link
Author

Android Profiler is not helpful. is there a verbose debug level we can set to get more diagnostics and see what is going on in sentry sdk during startup? Is there a way to setup trace in sentry sdk?

@bsergean
Copy link

Note that we don't use the native-sdk integration (breakpad etc...).

@marandaneto
Copy link
Contributor

marandaneto commented May 30, 2020

hey @tiwariashish86 thanks for reporting this.

The log level is configured this way:
https://github.com/getsentry/sentry-android/blob/master/sentry-sample/src/main/AndroidManifest.xml#L38

To enable logging, set this flag to true:
https://github.com/getsentry/sentry-android/blob/master/sentry-sample/src/main/AndroidManifest.xml#L35

are you using the artifact sentry-android or sentry-android-core? sentry-android already bundles sentry-native and start automatically, so just trying to isolate the problem here.

If using sentry-android, could you try using only sentry-android-core without NDK support and see if that still happens?

Do you use the auto-init mode or you call SentryAndroid.init(...) by yourself and if so, where (which App's lifecycle)?

Those numbers are running on debug or release mode?

If you uninstall the APK completely and install it again (fresh install), can you reproduce the same delay?

Do you have the release health feature enabled? it's disabled by default and enabled like this:
https://github.com/getsentry/sentry-android/blob/master/sentry-sample/src/main/AndroidManifest.xml#L59
If it's enabled, try to disable it and see if it helps.

Did you experience this using older versions? 2.x or only after upgrading to 2.1.2?

Could you disable the automatic breadcrumbs and see if this helps somehow? some integrations depend on context.getSystemService which is not the fastest Android API.
You can do that by options.enableAllAutoBreadcrumbs(false) on SDK init.

Almost 10 seconds is... a lot, we haven't done benchmarking yet, but it's doubtful to be that much (this could cause an ANR on every single run).

We need to do some IO on the main thread due to the nature of such SDK, like to create the caching folders, but this would slow down a few milliseconds only in the very 1st run and not in next ones.

When running our sample, which is a very light App. of course, the full startup with all the integrations enabled takes less than a sec.
The sample is https://github.com/getsentry/sentry-android/tree/master/sentry-sample
or https://github.com/getsentry/examples/tree/master/android

I'm not sure what's causing this, but please take the time to answer all those questions and then we are gonna do a deep investigation, thanks again for reporting this and let's keep in the loop.

cc @bruno-garcia

@marandaneto marandaneto added good first issue Good for newcomers NDK sentry-android-ndk and sentry-native for Android question Further information is requested labels May 30, 2020
@bsergean
Copy link

Hey @marandaneto thanks a lot for the quick answer.

We know it's a tough bug as we don't have too much info on what's going but wanted to get the ball rolling. I can answer some questions for Ashish (Ashish please double check all my answers) as I did the integration of the sdk.

  1. We are using sentry-android-core
  2. We are using release health feature, but Ashish tried to turn it off and it didn't help. We noticed one net request that took like 200s.
  3. We use the automatic sdk initialization. Maybe we could switch to the manual one, and do it in a background thread ? Would things still work ?
  4. I was even thinking about trying the 'raw' sentry-java sdk to isolate the problem further (I did that at some point when we ran into the Android 4.4. permission problem).
  5. This happen with release and debug builds.

For context what we call an asset build is our final production build, where we package tons of files (like 20,000 ?) in the apk. I believe this could be the problem, where some api perform poorly because of that (like trying to scan the apk directory content repeatedly, not sure).

One thing I wonder is how hard it would be for us to build the sdk locally, so that we can run the Android profiler locally.

@marandaneto
Copy link
Contributor

hey @bsergean thanks for a prompt reply.

  1. 200s for a network request is quite a bit, I've not noticed taking so long, our transport layer happens on a background thread though, otherwise, you'd get NetworkOnMainThreadException, so I don't think this is related to slow startup but good to know anyway.
    Btw give it a try to the latest version 2.1.4, gzip is the default encoding now, this helps a little bit.

Do you use sentry.io or on-premise?

  1. The problem of doing this on a background thread is: if a Crash happens on App. init. before the SDK has the chance to initialize, those crashes won't be captured by Sentry, I won't recommend that for now but finding the root cause and fixing it.
    Answering your question, it'd be possible with this side effect.

  2. you could try using sentry-core instead of sentry-android-core and initing the SDK manually Sentry.init(...) but only for isolating the issue as all the top Android integrations live in sentry-android-core mainly.

  3. have you tried to debug and see where it stuck? because sources are also published, so technically you could debug the whole thing.

You just need to add a breakpoint here:
https://github.com/getsentry/sentry-android/blob/master/sentry-android-core/src/main/java/io/sentry/android/core/SentryInitProvider.java#L18
This is the main point of the automatic init mode.

We do need to list the assets folder, but this also happens on a background thread:
https://github.com/getsentry/sentry-android/blob/master/sentry-android-core/src/main/java/io/sentry/android/core/DefaultAndroidEventProcessor.java#L882

A trick thing here is if you init. the SDK and right after you capture an event using Sentry, the background thread above is gonna await till its job is done, so if you do any sort of Sentry.captureSomething on App. init, try to comment this out and see if it helps, this could be a bottleneck if you have 20k files on assets folder and use Sentry on App. init.

Yes, I believe it's rather simple to build the SDK locally if you fork this repo and press play on the sample project, it runs immediately, so adding this repo as a dependency of your project instead of the maven packages would work seamlessly I believe, but again, sources are also published so I believe you don't even need that to be able to debug things.

Yes, it's a tough one but we'll figure this out, thanks for the feedback so far.

@marandaneto marandaneto removed the NDK sentry-android-ndk and sentry-native for Android label May 31, 2020
@tiwariashish86
Copy link
Author

@marandaneto I am using release build. Issue is reproducible 100% with sentry sdk in all cases(fresh vs old install)

@tiwariashish86
Copy link
Author

tiwariashish86 commented Jun 1, 2020

So when I disable auto-init in manifest using following (note that I have not called init anywhere yet), app loads fine.

<meta-data android:name="io.sentry.auto-init" android:value="false" />

With Above configuration ('io.sentry:sentry-android-core:2.1.2')
I/ActivityManager: Displayed com.machinezone.gow/com.mz.jix.MainActivity: +615ms

@marandaneto
Copy link
Contributor

@tiwariashish86 yep but in this case, it disables (by removing it) the SDK completely.

Could you take the time and try the things I've mentioned in my previous messages?
Also answering the questions I've made, so I'll have a better understanding of the problem.
The most important part is to find the root cause of such slowness, thanks a lot :)

@tiwariashish86
Copy link
Author

tiwariashish86 commented Jun 3, 2020

Couple of questions @bsergean has already answered. Here is what I tried after that and findings:

a. Disabled AutoBreadCrums as you mentioned. It made no difference.
b. Commented out All calls to captureEvent, addBreadcrum and had only init(manual init in Application's onCreate)enabled. That made no difference either and issue was still there.
c. Init(manual init, disabled auto init) itself runs pretty fast, so it does not seem like init is the bottleneck here so that is weird because if I disable the init(app works fine since sentry sdk is disabled completely) but if I enable it call to init executes pretty fast but there is certainly a good amount of delay between Application's onCreate(Sentry init is manually called here) and Main Activity's onCreate.
d. Ran the proxy for network requests, first network request appears in the proxy after app has successfully loaded after 20 seconds so that does not seem to be causing any issue as well. plus that call seems Async.
e. Disabling Health feature did not make any difference as well.
f. tried some older versions of sentry sdk and went as far as to 2.0 but still see the issue.
g. I see some people have complained about similar delay here getsentry/sentry-java#708 . not sure if this one is related but seems to be fixed in 1.7.
h. I ran appTrace with perfetto but did not see any troublesome issue there. Android Studio's CPU profiler is not giving any useful information as well. May be that is probably I did not build sentry sdk locally so that is what I am going to do next.
i. surprisingly Android Q performs alot better than Android P and previous. Issue is practically non-existent on Android Q. So may be build settings (TargetSDK, minSDK and gradle version) differences causing the issue. Our app supports till API 19 and built with gradle 5.5 though that may not be the case.
J. is there any call to AssetManager in sentry sdk since we are seeing the issue only when app is built with assets?

@bsergean
Copy link

bsergean commented Jun 3, 2020 via email

@tiwariashish86
Copy link
Author

Adding to previous, also I tried to make init asynchronous, that did not make any difference either. I saw the same delay. So seems like something else is going on after init behind the scenes. Enabling sentry logging was not useful as well.

@bsergean
Copy link

bsergean commented Jun 3, 2020 via email

@tiwariashish86
Copy link
Author

@bsergean yeah I have seen that but the thing is that call is asynchronous so should not have blocked the main thread. contextData = executorService.submit(() -> loadContextData());

@marandaneto
Copy link
Contributor

marandaneto commented Jun 3, 2020

@bsergean yeah I have seen that but the thing is that call is asynchronous so should not have blocked the main thread. contextData = executorService.submit(() -> loadContextData());

maybe there's some concurrency (using context.getAssets()) when we are trying to look up the proguard Id and your App. also tries to load its assets, would it be possible to debug this and confirm this is the bottleneck? as I said, sources are published, you just need a breakpoint on the SDK init.

edit:
this is a background thread, but if somebody does a Sentry.captureSomethign() right away, this background gets awaited as we need this to be finished in order to demangle stack traces.

@marandaneto
Copy link
Contributor

marandaneto commented Jun 3, 2020

Manoel maybe one way to reproduce the problem would be to add say 20,000 assets to an apk, and see if init gets slower.

yeah I'll try to figure this out, how the files look like? what are their extension and average size?

@marandaneto
Copy link
Contributor

Adding to previous, also I tried to make init asynchronous, that did not make any difference either. I saw the same delay. So seems like something else is going on after init behind the scenes. Enabling sentry logging was not useful as well.

could you enable the Sentry logging and filter the logcat using Sentry and copypasta to us? this is very helpful, be sure to run the App. on debug mode or we won't see the logcat at all.

@marandaneto
Copy link
Contributor

I see one call here: sentry-android-core/src/main/java/io/sentry/android/core/DefaultAndroidEventProcessor.java 12:import android.content.res.AssetManager; 898: AssetManager assets = context.getAssets(); Code is this. Ashish can you try to make this function a no-op ?

this class is package-private, so you can remove the DefaultAndroidEventProcessor for testing.

Init. the SDK manually like this:

    SentryAndroid.init(
      this,
      options -> {
        options.getEventProcessors().remove(1);
      });

If the App. loads fast and normally, we can isolate the problem to this class DefaultAndroidEventProcessor
mind doing it @tiwariashish86 ? thanks

@marandaneto
Copy link
Contributor

I've taken a shot here #445

I guess this is the root cause of the issue, if you confirm that the test above solves the problem, I'll get this into the next version right away.

thanks for the collaboration so far, we are aiming to make it better day by day and opening issues and helping us to find and fix them is all we ask and need ❤️

@bsergean
Copy link

bsergean commented Jun 3, 2020 via email

@tiwariashish86
Copy link
Author

tiwariashish86 commented Jun 3, 2020

Above experiment did not solve the issue. Looking more closely on sentry logs. Here are the sentry logs :
2020-06-03 09:54:16.441 14061-14061/? D/Sentry: Auto-init: false
2020-06-03 09:54:16.442 14061-14061/? I/Sentry: Retrieving auto-init from AndroidManifest.xml
2020-06-03 09:54:16.462 14061-14061/? D/Sentry: debug read: true
2020-06-03 09:54:16.462 14061-14061/? I/Sentry: Retrieving configuration from AndroidManifest.xml
2020-06-03 09:54:16.505 14061-14061/? I/Sentry: Initializing SDK with DSN:
2020-06-03 09:54:16.505 14061-14061/? I/Sentry: GlobalHubMode: 'true'
2020-06-03 09:54:40.538 14061-14107 I/Sentry: Proguard UUIDs file not found.

So if you see the last two line the time difference is 24 seconds and this is the time that last line(Proguard) takes to show up on screen. So this tells me that probably looking for Proguard UUIDs file is taking time(may be some lock contention). Is there a way to disable that completely without recompiling the sdk? otherwise would recompile locally and check it out.

Also, @marandaneto Can we please release new sdk with your fix?

@bsergean
Copy link

bsergean commented Jun 3, 2020 via email

@tiwariashish86
Copy link
Author

tiwariashish86 commented Jun 3, 2020

So I managed to run Perfetto on Android Q. Though the issue is less worse on Android Q, it does show lock contention in AssetManager and that overlaps with App startup time. Also shows around 5 seconds of delay on Android Q(much worse before that). I am attaching screenshots for the app.
Screen Shot 2020-06-03 at 11 06 26 AM
Screen Shot 2020-06-03 at 11 06 44 AM

@marandaneto
Copy link
Contributor

hey @tiwariashish86 thanks for that.
so our guess was right, let me make the release then.

@marandaneto
Copy link
Contributor

hey @tiwariashish86 https://github.com/getsentry/sentry-android/releases/tag/2.1.5
could you try this out? let us know how it goes, thanks.

@tiwariashish86
Copy link
Author

tiwariashish86 commented Jun 3, 2020

that actually crashed with following error in Application's onCreate:

Caused by: java.lang.RuntimeException: AssetManager has been destroyed at android.content.res.AssetManager.ensureValidLocked(AssetManager.java:472) at android.content.res.AssetManager.getResourceValue(AssetManager.java:505) at android.content.res.AssetManager.getResourceText(AssetManager.java:534) at android.content.res.Resources.getText(Resources.java:362) at android.content.res.Resources.getString(Resources.java:460)

@marandaneto
Copy link
Contributor

@tiwariashish86 that's odd, I've 4 devices here and it runs just fine, let me look into it.

@tiwariashish86
Copy link
Author

tiwariashish86 commented Jun 3, 2020

Ok With break point, I see it is hitting catch (FileNotFoundException e) { logger.log(SentryLevel.INFO, "sentry-debug-meta.properties file was not found."); and then when continuing it dies with above error mentioned. And also see some event submission failures in next run

Sentry: Event submission failed: e71b5afcaf464cb4b5bebaa6d9712507 java.lang.IllegalStateException: Sending the event failed. at io.sentry.core.transport.AsyncConnection$EventSender.flush(AsyncConnection.java:308) at io.sentry.core.transport.AsyncConnection$EventSender.run(AsyncConnection.java:258) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:462)

@marandaneto
Copy link
Contributor

@tiwariashish86 yep, the AssetManager seems to be a single instance per App. and can't be closed, but this has different behaviors in different versions, that's my guess.
Can you please try 2.1.6? it's already published, didn't create the tag yet.

@marandaneto marandaneto added bug Something isn't working and removed question Further information is requested labels Jun 3, 2020
@bsergean
Copy link

bsergean commented Jun 3, 2020

I'm stealing the thunder from Ashish but it looks like 2.1.6 is the winner !!!! no more crash and lag gone.

Thanks so much @marandaneto

@marandaneto
Copy link
Contributor

hey, @bsergean and @tiwariashish86 thanks for the collaboration, yeah lesson learned.
let us know if you find any more issues.

@tiwariashish86
Copy link
Author

Thanks @marandaneto for your help!!

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bug Something isn't working good first issue Good for newcomers
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants