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

papa/papa/src/main/java/papa/internal/Perfs.kt

Line 354 in 31eebb3

launch.startUptimeMillis > it

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?