Firebase Performance Monitoring: The App start trace _app_start seems missing, but other traces work!

[kurosaki-tisak]

[READ] Step 1: Are you in the right place?

Issues filed here should be about bugs in the code in this repository.
If you have a general question, need help debugging, or fall into some
other category use one of these other channels:

• For general technical questions, post a question on StackOverflow
  with the firebase tag.
• For general Firebase discussion, use the firebase-talk
  google group.
• For help troubleshooting your application that does not fall under one
  of the above categories, reach out to the personalized
  Firebase support channel.

[REQUIRED] Step 2: Describe your environment

• Android Studio version: Android Studio Hedgehog | 2023.1.1 Patch 2
• Firebase Component: Firebase Performance
• Component version: com.google.firebase.firebase-perf:1.4.2

[REQUIRED] Step 3: Describe the problem

Steps to reproduce:

As the screenshot below, I found the app start trace was missing from both the Logcat and Performance dashboards, but other automatic traces and custom traces work!

I have done everything like the documents said, but the _app_start is still missing!

[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.

[lehcar09]

Hi @kurosaki-tisak, thank you for reaching out and reporting the issue. When trying to reproduce the issue, I noticed that instead of "_app_start", an "_as" event has been logged in the Logcat.

Upon checking the Firebase Console Dashboard, the "_app_start" event is visible under the Custom traces tab.

Could you check if you can see the _as event being logged?

[kurosaki-tisak]

Hello @lehcar09 and thank you for your support!

As you can see in the screenshot below, _as trace seems missing while both _fs (_app_in_foreground) and _bs (_app_in_background) work as usual!

Also, on the Firebase Performance Dashboard, as shown in the screenshot below, the _app_startup (showing only 1 sample) used to appear long ago. Now, as I've mentioned, it's missing without any clue, so please help!

Thank you!

[lehcar09]

Is there any chance you share an MCVE to help us investigate the issue? If you're unable to provide one, can you try our quickstart app and see if you can reproduce the issue?

[VishalRajora]

I am also facing the same issue.
After changing BOM version from '31.1.1' to above, _as is not logged in the logcat and FirebasePerformance consol.

But the twist is, I have created one sample app and tried the same, So _as is logging in logcat and consol

[VishalRajoraTiket]

I have fixed this.

[argzdev]

Hi @VishalRajora, thanks for confirming that this is resolved on your end. I'm guessing there might've been a configuration issue. I'll go ahead and close this for now. Thanks!

[PhilGlass]

@argzdev we're seeing the same thing others have described above - no app start traces, but custom traces and all the other automatic traces are fine.

Looking at our data in Firebase this seems to have started when we upgraded the Firebase BOM from 31.1.1 to 32.2.0.

There are no Firebase-tagged errors in logcat that I can see, we just aren't getting any app start traces. How would you suggest I further debug this?

[PhilGlass]

I think I figured this out. It's because we initialize Firebase manually, and there was a change between those BOM versions that explicitly disables app start traces if you aren't using FirebaseInitProvider.

firebase-android-sdk/firebase-common/src/main/java/com/google/firebase/FirebaseApp.java

Lines 433 to 437 in bb0823f

	// Don't provide StartupTime in direct boot mode or if Firebase was manually started
	if (UserManagerCompat.isUserUnlocked(applicationContext)
	&& FirebaseInitProvider.isCurrentlyInitializing()) {
	builder.addComponent(Component.of(startupTime, StartupTime.class));
	}

firebase-android-sdk/firebase-perf/src/main/java/com/google/firebase/perf/FirebasePerfEarly.java

Lines 48 to 52 in bb0823f

	if (startupTime != null) {
	AppStartTrace appStartTrace = AppStartTrace.getInstance();
	appStartTrace.registerActivityLifecycleCallbacks(context);
	uiExecutor.execute(new AppStartTrace.StartFromBackgroundRunnable(appStartTrace));
	}

[PhilGlass]

That turns out to only be the first issue - it still doesn't work after switching to FirebaseInitProvider.

When I attach a debugger and start the app from the launcher icon I'm seeing that this:

firebase-android-sdk/firebase-perf/src/main/java/com/google/firebase/perf/metrics/AppStartTrace.java

Lines 568 to 572 in bb0823f

	// if no activity has ever been created.
	if (trace.onCreateTime == null) {
	trace.isStartedFromBackground = true;
	}
	}

is executed before onActivityCreated is able to set onCreateTime:

firebase-android-sdk/firebase-perf/src/main/java/com/google/firebase/perf/metrics/AppStartTrace.java

Line 328 in bb0823f

onCreateTime = clock.getTime();

So Firebase considers this a background process start and does not send an app start trace.

[PhilGlass]

The ordering assumptions described here seem to be wrong:

firebase-android-sdk/firebase-perf/src/main/java/com/google/firebase/perf/metrics/AppStartTrace.java

Lines 552 to 559 in bb0823f

	/**
	* We use StartFromBackgroundRunnable to detect if app is started from background or foreground.
	* If app is started from background, we do not generate AppStart trace. This runnable is posted
	* to main UI thread from FirebasePerfEarly. If app is started from background, this runnable will
	* be executed before any activity's onCreate() method. If app is started from foreground,
	* activity's onCreate() method is executed before this runnable.
	*/
	public static class StartFromBackgroundRunnable implements Runnable {

Here's a simple demonstration that mimics what Firebase Performance is doing. Copy-paste this provider into a new sample project, register it in the manifest and launch the default activity:

class SampleProvider : ContentProvider() {
    private var activityCreated = false
    private var mainThreadRunnableRun = false

    override fun onCreate(): Boolean {
        (context!!.applicationContext as Application).registerActivityLifecycleCallbacks(object :
            ActivityLifecycleCallbacks {
            override fun onActivityCreated(activity: Activity, savedInstanceState: Bundle?) {
                Log.d(
                    "FirebasePerf",
                    "onActivityCreated: mainThreadRunnableRun = $mainThreadRunnableRun"
                )
                activityCreated = true
            }

            override fun onActivityStarted(activity: Activity) {}
            override fun onActivityResumed(activity: Activity) {}
            override fun onActivityPaused(activity: Activity) {}
            override fun onActivityStopped(activity: Activity) {}
            override fun onActivitySaveInstanceState(activity: Activity, outState: Bundle) {}
            override fun onActivityDestroyed(activity: Activity) {}
        })

        Handler(Looper.getMainLooper()).post {
            Log.d("FirebasePerf", "mainThreadRunnable.run(): activityCreated = $activityCreated")
            mainThreadRunnableRun = true
        }

        return true
    }

    override fun query(
        uri: Uri,
        projection: Array<out String>?,
        selection: String?,
        selectionArgs: Array<out String>?,
        sortOrder: String?
    ): Cursor? {
        TODO("Not yet implemented")
    }

    override fun getType(uri: Uri): String? {
        TODO("Not yet implemented")
    }

    override fun insert(uri: Uri, values: ContentValues?): Uri? {
        TODO("Not yet implemented")
    }

    override fun delete(uri: Uri, selection: String?, selectionArgs: Array<out String>?): Int {
        TODO("Not yet implemented")
    }

    override fun update(
        uri: Uri,
        values: ContentValues?,
        selection: String?,
        selectionArgs: Array<out String>?
    ): Int {
        TODO("Not yet implemented")
    }
}

You'll see this in logcat:

15:13:17.036 FirebasePerf              D  mainThreadRunnable.run(): activityCreated = false
15:13:17.352 FirebasePerf              D  onActivityCreated: mainThreadRunnableRun = true

[PhilGlass]

One more update: It appears that the ordering assumptions hold sometimes. Weirdly things seem to behave differently on emulators and physical devices.

Using the sample code in #5764 (comment):

API 24 emulator (they hold):

15:36:22.413 FirebasePerf              D  onActivityCreated: mainThreadRunnableRun = false
15:36:22.423 FirebasePerf              D  mainThreadRunnable.run(): activityCreated = true

API 34 physical device (they do not hold, so there are no app start traces sent):

12:36:31.532 FirebasePerf              D  mainThreadRunnable.run(): activityCreated = false
12:36:31.567 FirebasePerf              D  onActivityCreated: mainThreadRunnableRun = true

API 34 emulator (they hold):

12:27:08.056 FirebasePerf              D  onActivityCreated: mainThreadRunnableRun = false
12:27:08.075 FirebasePerf              D  mainThreadRunnable.run(): activityCreated = true

I don't have any other physical devices to test on at the moment.