Android Vitals - When did my app start? ⏱

pyricau

Py ⚔

Posted on August 21, 2020

Android Vitals - When did my app start? ⏱

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()
  }
}
Enter fullscreen mode Exit fullscreen mode

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
  }
}
Enter fullscreen mode Exit fullscreen mode

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()
  }
}
Enter fullscreen mode Exit fullscreen mode

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()
  }
}
Enter fullscreen mode Exit fullscreen mode
<?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>
Enter fullscreen mode Exit fullscreen mode

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()
  }
}
Enter fullscreen mode Exit fullscreen mode

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)).
Enter fullscreen mode Exit fullscreen mode

/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()
  }
}
Enter fullscreen mode Exit fullscreen mode

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
Enter fullscreen mode Exit fullscreen mode

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.

Pre forking

There's another downside to relying on fork time: 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. This might be due to some systems keeping a pool of pre forked zygotes to accelerate app start.

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()
    );
    ...
  } 
}
Enter fullscreen mode Exit fullscreen mode

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.
💖 💪 🙅 🚩
pyricau
Py ⚔

Posted on August 21, 2020

Join Our Newsletter. No Spam, Only the good stuff.

Sign up to receive the latest update from our blog.

Related