search

square / papa

PAPA: Performance of Android Production Applications
Apache License 2.0
357 stars 15 forks source link

Multi warm start logs #23

Open pyricau opened 2 years ago

pyricau commented 2 years ago

Quotes from someone reaching out:

So, I tried to use tart library 0.4.1 in our code, it seems that when i install it and launch Coldstart, it marks it as "warm_start". It considers the app in PreLaunchState.NO_ACTIVITY_NO_SAVED_STATE -> "warm start" Also, when the app starts up in Coldstart, there are multiple calls to the listeners and it prints multiple warm start values. I am not sure but our app actually calls multiple activities during login.

bash-3.2$ cat temp.log | grep "launch:"
11-14 01:31:08.776 16717 16717 I System.out: cold start launch: 26161 ms
11-14 01:31:08.873 16717 16717 I System.out: warm start launch: 402 ms
11-14 01:31:17.739 16717 16717 I System.out: warm start launch: 4835 ms
11-14 01:31:17.981 16717 16717 I System.out: warm start launch: 3930 ms

So, when I do an app coldstart, it does properly do the "cold start launch: 26161 ms" logging. However, during startup for login screen, we create multiple activites and the screen does go back and forth, I am assuming that is the reason, we are see multiple warm starts. However, this happens only for login. I will need to test it for our regular flow.

bash-3.2$ cat temp4.log | grep "launch:"
11-14 15:09:25.133 28592 28592 I System.out: cold start launch: 25984 ms AppLaunch(preLaunchState=NO_PROCESS_FIRST_LAUNCH_AFTER_INSTALL, start=CpuDuration(unit=MILLISECONDS, uptime=51343916, realtime=51343916), end=CpuDuration(unit=NANOSECONDS, uptime=51369900643380, realtime=51369900636193), duration=CpuDuration(unit=NANOSECONDS, uptime=25984643380, realtime=25984636193), isSlowLaunch=true)
11-14 15:09:25.176 28592 28592 I System.out: warm start launch: 451 ms AppLaunch(preLaunchState=NO_ACTIVITY_NO_SAVED_STATE, start=CpuDuration(unit=NANOSECONDS, uptime=51370052020166, realtime=51370052022718), end=CpuDuration(unit=NANOSECONDS, uptime=51370503960940, realtime=51370503959638), duration=CpuDuration(unit=NANOSECONDS, uptime=451940774, realtime=451936920), isSlowLaunch=false)
11-14 15:09:34.478 28592 28592 I System.out: warm start launch: 4987 ms AppLaunch(preLaunchState=NO_ACTIVITY_NO_SAVED_STATE, start=CpuDuration(unit=NANOSECONDS, uptime=51373486448008, realtime=51373486450925), end=CpuDuration(unit=NANOSECONDS, uptime=51378473692463, realtime=51378473690119), duration=CpuDuration(unit=NANOSECONDS, uptime=4987244455, realtime=4987239194), isSlowLaunch=true)
11-14 15:09:34.700 28592 28592 I System.out: warm start launch: 3900 ms AppLaunch(preLaunchState=NO_ACTIVITY_NO_SAVED_STATE, start=CpuDuration(unit=NANOSECONDS, uptime=51375758783495, realtime=51375758786776), end=CpuDuration(unit=NANOSECONDS, uptime=51379659350550, realtime=51379659348675), duration=CpuDuration(unit=NANOSECONDS, uptime=3900567055, realtime=3900561899), isSlowLaunch=true)

when you tap the app icon, that launches an activity, which then .. finishes itself and launches another activity?

yes, but the activity is then paused and it launches another activity

pyricau commented 2 years ago

The scenario to reproduce this is likely to have a first activity that finishes itself from onResume() instead of from onCreate() as apps should do. As a result, we get back to 0 resumed activity and when the next one comes in we count this as a warm start.

I don't if this means a frame will be displayed in the meantime. That might be happening

Should play around with Android to see if there's a way to detect this use case. Activities finishing themselves and starting another one is async by nature (IPC to system_server), it's only sync when done in onCreate() I think.