Firebase performance - _app_start metric outliers, metric reports few minutes

[adamszeremeta]

Description

Hello, we are using Firebase Performance SDK in our few apps. Sometimes _app_start metric reports outstanding app start duration in comparision with normal results (under 1s). This seems like a bug / situation we can't ourself understand.

Normal _app_start session metric looks like this:

where _app_start took 550ms and our custom metric to first view controller (App_Start_until_home_screen) took under 2s.

However we can also see sessions (few of them) which look like this:

In this case first gray trace is our custom metric (9 seconds) and _app_start has shown duration of 1032s.

Any idea what situation is this? How can we eliminate it? Seems to me like some kind of SDK bug.

Edit: Seems like this can be reported if app starts due to background fetch. I guess we have to disable then firebase performance? (but there is no really a good way to do this now). When app launches in background "didBecomeActive" is never called so metric is waiting for user app launch (if still alive) and reports that then.

Reproducing the issue

No response

Firebase SDK Version

FirebasePerformance (10.0.0)

Xcode Version

14

Installation Method

CocoaPods

Firebase Product(s)

Analytics, Crashlytics, In-App Messaging, Performance, Remote Config

Targeted Platforms

iOS

Relevant Log Output

No response

If using Swift Package Manager, the project's Package.resolved

Expand Package.resolved snippet

```json Replace this line with the contents of your Package.resolved. ```

If using CocoaPods, the project's Podfile.lock

Expand Podfile.lock snippet

```yml - FirebasePerformance (10.0.0): - FirebaseCore (~> 10.0) - FirebaseInstallations (~> 10.0) - FirebaseRemoteConfig (~> 10.0) - GoogleDataTransport (~> 9.2) - GoogleUtilities/Environment (~> 7.8) - GoogleUtilities/ISASwizzler (~> 7.8) - GoogleUtilities/MethodSwizzler (~> 7.8) - nanopb (< 2.30910.0, >= 2.30908.0) ```

[google-oss-bot]

I couldn't figure out how to label this issue, so I've labeled it for a human to triage. Hang tight.

[rizafran]

Thanks for reaching out, @adamszeremeta. Before I proceed with reproducing the issue, could you provide your Podfile.lock/Podfile?

[adamszeremeta]

I can't give you directly Podfile as this is multi layer project. I can give you lock file, but I've redacted our internal private libraries.

Podfile_lock.txt

[rizafran]

Hi @adamszeremeta, could you confirm if the issue is happening to any iOS versions?

[adamszeremeta]

Yes, I saw it on multiple iOS 15 and 16 versions, for example: 16.1, 16.2, 16.3 15.5 15.6, 15.7, 14.8

[visumickey]

Firebase Performance currently eliminates app start traces that are involved in the context of app backgrounding Reference. So, ideally this situation should not occur. The duration of 1032s definitely sounds suspicious.

Do you what percentile of the app start traces are at a higher duration? Is is quite common or some rare app start duration measurements? Secondly, can you shed some light around the custom trace you created to measure the app start duration (Specifically - when did you start and end the trace metric)?

[google-oss-bot]

Hey @adamszeremeta. We need more information to resolve this issue but there hasn't been an update in 5 weekdays. I'm marking the issue as stale and if there are no new updates in the next 5 days I will close it automatically.

If you have more information that will help us get to the bottom of this, just add a comment!

[adamszeremeta]

@visumickey Hey, sorry for the delayed response.

As for percentile, we saw this in one app on 90%, and on other in lowest 5% of users populations (so 95% percentile). We have spotlight search and thats why we have also background fetch in those apps.

As for our custom trace - we start it in "didFinishLaunching" and and when we fetch the data on out custom splash controller and move to main app controller. Our trace is also cancelled if app goes to background ("didEnterBackground") before app moves to our main controller. Recently we also added cancellation to our custom trace in "performFetchWithCompletionHandler".

[AlexApriamashvili]

Hi folks!

I believe we also experience similar issues with our performance metrics on iOS and the _app_start metric in particular. Here's an example of one odd session that was captured, but some numbers go as high as 10 minutes for just the _app_start which is certainly unrealistic.

Here's an example of such a trace

As you can see, after the first 7-8 seconds since launch, the application goes completely inactive (no events, no network calls, nothing). In about 190s the applicationDidBecomeActive(_:) method is called. While we do not specifically trace for when the application resigns active state, I'm quite confident in saying that the app could've gone inactive for the time being. The user could've received a phone call, answered an SMS or just accidentally locked the screen while launching the app.

From my initial investigation, I did not spot any relevant observations for the willResignActiveNotification notification in the Firebase SDK code. Experimenting with this on my device has produced the FPRTraceStateForegroundOnly value for the trace.backgroundTraceState, which could be the reason why those traces were being reported in the first place.

I'm also curious if there was a way to deduct the time the app was in the background from the overall trace duration. This is currently the biggest problem for some of our performance traces when it comes to high (P95, P99) quantiles. Right now the time is reported as just a difference between the start and the end date of the trace multiplied by USEC_PER_SEC.

While we can introduce logic on our end to submit this as a custom metric, I'm also curious if there's a direct way to get support for this.

Thank you.

[Vyazovoy]

Hi! I'm experiencing the same issue. When percentile set to 90% I see app start time like 10-17 minutes but when I set percentile to 85% the metric drops to reasonable 0.5-1.3 seconds. Firebase version: 10.23.0 Package manager: SPM

[anthonybusto]

Hey firebase team! We are also seeing this same issue where 90% and 95% percentile are showing numbers up to 20+ minutes for startup time. We believe it's a bug inside the Firebase SDK and these are not real numbers.

We are using v10.23.0 with SPM package manager as well.