API 34 calls first post before activity is created

[carlonzo]

Running Papa sample app I have noticed that on API 34 preLaunchState was always warm (preLaunchState=NO_ACTIVITY_NO_SAVED_STATE(WARM)). Adding some debugging log I notice that the recording of the first post on main thread is called before the recordActivityCreated is called.

This makes the calculation in computePreLaunchState never detect a cold state. Here are the logs I captured force-closing the application.

API 31

papa: recordActivityCreated com.example.papa.MainActivity
Papa First post
AppLaunch(preLaunchState=NO_PROCESS(COLD), duration=269 ms, isSlowLaunch=false, trampolined=false, backgroundDuration=5496 ms, startUptimeMillis=7484542)
AppStartData(processStartRealtimeMillis=7484340, processStartUptimeMillis=7484340, handleBindApplicationElapsedUptimeMillis=202, firstAppClassLoadElapsedUptimeMillis=280, perfsInitElapsedUptimeMillis=292, importance=100, importanceAfterFirstPost=100, importanceReasonCode=0, importanceReasonPid=0, startImportanceReasonComponent=null, lastAppVisibilityState=INVISIBLE, lastVisibilityChangeElapsedTimeMillis=5585, lastAppAliveElapsedTimeMillis=3293, appTasks=[AppTask(topActivity={com.example.papa/com.example.papa.MainActivity}, elapsedSinceLastActiveRealtimeMillis=308, numActivities=1, baseIntent=Intent { act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10000000 pkg=com.example.papa cmp=com.example.papa/.MainActivity })], classLoaderInstantiatedElapsedUptimeMillis=281, applicationInstantiatedElapsedUptimeMillis=291, firstIdleElapsedUptimeMillis=476, appUpdateData=RealAppUpdateData(status=NORMAL_START, firstInstallTimeMillis=1697521926122, lastUpdateTimeMillis=1697521926122, allInstalledVersionNames=[null], allInstalledVersionCodes=[0], updatedOsSinceLastStart=false, rebootedSinceLastStart=false, crashedInLastProcess=false, elapsedRealtimeSinceCrash=null), firstPostElapsedUptimeMillis=405, firstPostAtFrontElapsedUptimeMillis=320, firstComponentInstantiated=papa.AndroidComponentEvent@f3400f, firstActivityOnCreate=papa.ActivityOnCreateEvent@fb1089c, firstActivityOnStart=papa.AndroidComponentEvent@3a862a5, firstActivityOnResume=papa.AndroidComponentEvent@d5e767a, firstGlobalLayout=papa.AndroidComponentEvent@5adce2b, firstPreDraw=papa.AndroidComponentEvent@141288, firstDraw=papa.AndroidComponentEvent@3618421, firstIdleAfterFirstDraw=papa.AndroidComponentEvent@94d8046, firstPostAfterFirstDraw=papa.AndroidComponentEvent@f392207, firstTouchEvent=null, firstFrameAfterFullyDrawnElapsedUptimeMillis=null, customFirstEvents={})

API 34

Papa First post
papa: recordActivityCreated com.example.papa.MainActivity
AppLaunch(preLaunchState=NO_ACTIVITY_NO_SAVED_STATE(WARM), duration=62 ms, isSlowLaunch=false, trampolined=false, backgroundDuration=39160 ms, startUptimeMillis=101300601)
AppStartData(processStartRealtimeMillis=154339820, processStartUptimeMillis=101300428, handleBindApplicationElapsedUptimeMillis=49, firstAppClassLoadElapsedUptimeMillis=110, perfsInitElapsedUptimeMillis=122, importance=100, importanceAfterFirstPost=100, importanceReasonCode=0, importanceReasonPid=0, startImportanceReasonComponent=null, lastAppVisibilityState=INVISIBLE, lastVisibilityChangeElapsedTimeMillis=39109, lastAppAliveElapsedTimeMillis=37840, appTasks=[AppTask(topActivity={com.example.papa/com.example.papa.MainActivity}, elapsedSinceLastActiveRealtimeMillis=140, numActivities=1, baseIntent=Intent { act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10000000 pkg=com.example.papa cmp=com.example.papa/.MainActivity })], classLoaderInstantiatedElapsedUptimeMillis=111, applicationInstantiatedElapsedUptimeMillis=121, firstIdleElapsedUptimeMillis=238, appUpdateData=RealAppUpdateData(status=NORMAL_START, firstInstallTimeMillis=1697027361683, lastUpdateTimeMillis=1697529874253, allInstalledVersionNames=[null], allInstalledVersionCodes=[0], updatedOsSinceLastStart=false, rebootedSinceLastStart=false, crashedInLastProcess=false, elapsedRealtimeSinceCrash=null), firstPostElapsedUptimeMillis=154, firstPostAtFrontElapsedUptimeMillis=151, firstComponentInstantiated=papa.AndroidComponentEvent@d43ab9d, firstActivityOnCreate=papa.ActivityOnCreateEvent@c881812, firstActivityOnStart=papa.AndroidComponentEvent@d33ebe3, firstActivityOnResume=papa.AndroidComponentEvent@58cc9e0, firstGlobalLayout=papa.AndroidComponentEvent@5b46499, firstPreDraw=papa.AndroidComponentEvent@bcba35e, firstDraw=papa.AndroidComponentEvent@a2f633f, firstIdleAfterFirstDraw=papa.AndroidComponentEvent@824a40c, firstPostAfterFirstDraw=papa.AndroidComponentEvent@eddb155, firstTouchEvent=null, firstFrameAfterFullyDrawnElapsedUptimeMillis=null, customFirstEvents={})

is this a known issue or I am reading this wrong?

[carlonzo]

one note I want to mention here: in my internal tests with few devices I used firstIdle time instead of firstPost time to calculate the preLaunchState in https://github.com/square/papa/blob/31eebb3d70908bcb1209d82f066ec4d4377183ee/papa/src/main/java/papa/internal/Perfs.kt#L354

this looks like is working fine apart that pre 34 chained activity launches are all called before the firstIdle, when from 34 idle is called after the first activity launched.

[pyricau]

Thanks, this is definitely worth looking into. I wonder what changed.

[guuilp]

One thing I've noticed on my Pixel 7 Pro (API 34): after I manually kill the app, android starts the process again in background.

Here's the logcat:

---------------------------- PROCESS STARTED (15052) for package br.com.brainweb.ifood.debug ----------------------------
2024-04-09 17:23:07.003 15052-15052 GLP                     br.com.brainweb.ifood.debug          D  Pre-launch state: NO_ACTIVITY_NO_SAVED_STATE(WARM) 
                                                                                                    Is slow launch: false 
                                                                                                    Trampolined: false 
                                                                                                    Invisible Duration: 842629 
                                                                                                    Startup millis: 6225223 
                                                                                                    Duration: 510
---------------------------- PROCESS ENDED (15052) for package br.com.brainweb.ifood.debug ----------------------------
---------------------------- PROCESS STARTED (15605) for package br.com.brainweb.ifood.debug ----------------------------

[rcmkt]

Thanks, this is definitely worth looking into. I wonder what changed.

Hi, could you tell please, did you make some investigation of it?