loading...
Cover image for Android Vitals - When did my app start? ⏱

Android Vitals - When did my app start? ⏱

pyricau profile image Py ⚔ ・5 min read

Header image: Ressence Type 5 Tilt by Romain Guy.

This blog series is focused on stability and performance monitoring of Android apps in production. Last week, I wrote about using process importance to determine why an app was started.

To track cold start time, we need to know when the app started. There are many ways to do that and this blog evaluates different approaches.

As a reminder, I already established in Android Vitals - What time is it? that I would use SystemClock.uptimeMillis() to measure time intervals.

Application.onCreate()

The simplest approach is to capture the time at which Application.onCreate() is called.

class MyApp : Application() {

  var applicationOnCreateMs: Long = 0

  override fun onCreate() {
    super.onCreate()
    applicationOnCreateMs = SystemClock.uptimeMillis()
  }
}

ContentProvider.onCreate()

In How does Firebase initialize on Android? we learn that a safe early initialization hook for library developers is ContentProvider.onCreate():

class StartTimeProvider : ContentProvider() {

  var providerOnCreateMs: Long = 0

  override fun onCreate(): Boolean {
    providerOnCreateMs = SystemClock.uptimeMillis()
    return false
  }
}

ContentProvider.onCreate() also works for app developers and it's called earlier in the app lifecycle than Application.onCreate().

Class load time

Before any class can be used, it has to be loaded. We can rely on static initializers to store the time at which specific classes are loaded.

We could track the time at which the Application class is loaded:

class MyApp : Application() {

  companion object {
    val applicationClassLoadMs = SystemClock.uptimeMillis()
  }
}

In Android Vitals - Diving into cold start waters 🥶, we learnt that on Android P+ the first class loaded is the AppComponentFactory:

@RequiresApi(Build.VERSION_CODES.P)
class StartTimeFactory : androidx.core.app.AppComponentFactory() {

  companion object {
    val factoryClassLoadMs = SystemClock.uptimeMillis()
  }
}
<?xml version="1.0" encoding="utf-8"?>
<manifest 
    xmlns:android="http://schemas.android.com/apk/res/android"
    xmlns:tools="http://schemas.android.com/tools"
    package="com.example">

  <!-- Replace AndroidX appComponentFactory. -->
  <application
      android:appComponentFactory="com.example.StartTimeFactory"
      tools:replace="android:appComponentFactory"
      tools:targetApi="p" />
</manifest>

To track start time before Android P, Library developers can rely on the class load time of providers:

class StartTimeProvider : ContentProvider() {

  companion object {
    val providerClassLoadMs = SystemClock.uptimeMillis()
  }
}

The class loading order will usually be AppComponentFactory > Application > ContentProvider. That may change if your AppComponentFactory loads other classes on class load.

Process fork time

We know that every app process starts by being forked from Zygote. On Linux & Android, there's a file called /proc/[pid]/stat that is readable and contains stats for each process, including the process start time.

Let's check out man proc, under the /proc/[pid]/stat section:

(2) comm  %s
         The filename of the executable, in parentheses.
         This is visible whether or not the executable is
         swapped out.

...

(22) starttime  %llu
    The time the process started after system boot.  In
    kernels before Linux 2.6, this value was expressed
    in jiffies.  Since Linux 2.6, the value is expressed
    in clock ticks (divide by sysconf(_SC_CLK_TCK)).

/proc/[pid]/stat is a file with one line of text, where each stat is separated by a space. However, the second entry is the filename of the executable, which may contain spaces, so we'll have to jump past it by looking for the first ) character. Once we've done that, we can split the remaining string by spaces and pick the 20th entry at index 19.

object Processes {

  fun readProcessForkRealtimeMillis(): Long {
    val myPid = android.os.Process.myPid()
    val ticksAtProcessStart = readProcessStartTicks(myPid)
    // Min API 21, use reflection before API 21.
    // See https://stackoverflow.com/a/42195623/703646
    val ticksPerSecond = Os.sysconf(OsConstants._SC_CLK_TCK)
    return ticksAtProcessStart * 1000 / ticksPerSecond
  }

  // Benchmarked (with Jetpack Benchmark) on Pixel 3 running 
  // Android 10. Median time: 0.13ms
  fun readProcessStartTicks(pid: Int): Long {
    val path = "/proc/$pid/stat"
    val stat = BufferedReader(FileReader(path)).use { reader ->
      reader.readLine()
    }
    val fields = stat.substringAfter(") ")
        .split(' ')
    return fields[19].toLong()
  }
}

This gives us the realtime for when the process was forked. We can convert that to uptime:

val forkRealtime = Processes.readProcessForkRealtimeMillis()
val nowRealtime = SystemClock.elapsedRealtime()
val nowUptime = SystemClock.uptimeMillis()
val elapsedRealtime = nowRealtime - forkRealtime

val forkUptimeMs = nowUptime - elapsedRealtimeMs

This gives us the real process start time. However, in Android Vitals - Diving into cold start waters 🥶, we concluded that app cold start monitoring should start when ActivityThread.handleBindApplication() is called, because app developers have little influence on the time spent before that.

There's another downside: the process can be forked long before the application starts specializing in ActivityThread.handleBindApplication(). I measured the time from fork to Application.onCreate() in a production app: while the median time was 350ms, the max was 4 days, and the interval was greater than 1 minute for 0.5% of app starts.

Bind application time

One of the first things ActivityThread.handleBindApplication() does is call Process.setStartTimes():

public class ActivityThread {

  private void handleBindApplication(AppBindData data) {
    // Note when this process has started.
    Process.setStartTimes(
        SystemClock.elapsedRealtime(), 
        SystemClock.uptimeMillis()
    );
    ...
  } 
}

The corresponding timestamp is available via Process.getStartUptimeMillis():

Return the SystemClock#uptimeMillis() at which this process was started.

Sounds great, right? Well, it was great, until API 28. I measured the time from bind application to Application.onCreate() in a production app. While the median time was 250ms, on API 28+ the max was 14 hours, and the interval was greater than 1 minute for 0.05% of app starts.

I also found similar issues with the time from class loading of AppComponentFactory to Application.onCreate(): greater than 1 minute for 0.1% of app start on API 28+.

This can't be due to the device sleeping, since we only measure time intervals using SystemClock.uptimeMillis(). I haven't been able to figure out exactly what's going on here, it looks like sometimes bind application starts then halts mid way and the actual app start is much later.

Conclusion

Here's how we can most accurately measure the app start time when monitoring cold start:

  • Up to API 24: Use the class load time of a content provider.
  • API 24 - API 28: Use Process.getStartUptimeMillis().
  • API 28 and beyond: Use Process.getStartUptimeMillis() but filter out weird values (e.g. more than 1 min to get to Application.onCreate()) and fallback to the time ContentProvider.onCreate() is called.

Posted on by:

pyricau profile

Py ⚔

@pyricau

Author of LeakCanary 🍷🥖⛷🇫🇷

Discussion

markdown guide
 

Thanks for the series! It's been extremely helpful. Question on the conclusion again. For APIs before 24, if we don't need Context, could we use an earlier time than the class load time of a content provider, e.g. class load of Application?

 

Speaking of measuring time, is there a way to measure all functions that are being called (especially of various libraries the project uses), till some specific function call, and then look at what could be optimized to make the app-boot better?