Android Vitals - When did my app start? ⏱
Tags: android, vitals, performance, monitoring
Published: 2020-08-21 21:01:05

> Header image: *Ressence Type 5 Tilt* [by Romain Guy](https://www.flickr.com/photos/romainguy/48887849497/in/photostream/).

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](https://dev.to/pyricau/android-vitals-why-did-my-process-start-4d0e).

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?](https://dev.to/pyricau/android-vitals-what-time-is-it-2oih) that I would use `SystemClock.uptimeMillis()` to measure time intervals.

# Application.onCreate()

The simplest approach is to capture the time at which [Application.onCreate()](https://developer.android.com/reference/android/app/Application#onCreate()) is called.

```kotlin
class MyApp : Application() {

  var applicationOnCreateMs: Long = 0

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

# ContentProvider.onCreate()

In [How does Firebase initialize on Android?](https://firebase.googleblog.com/2016/12/how-does-firebase-initialize-on-android.html) we learn that a safe early initialization hook for library developers is [ContentProvider.onCreate()](https://cs.android.com/android/platform/superproject/+/master:frameworks/base/core/java/android/content/ContentProvider.java;l=1048;drc=69e700c7922c34583bddbab4b7ce78adadb90730):

```kotlin
class StartTimeProvider : ContentProvider() {

  var providerOnCreateMs: Long = 0

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

[ContentProvider.onCreate()](https://cs.android.com/android/platform/superproject/+/master:frameworks/base/core/java/android/content/ContentProvider.java;l=1048;drc=69e700c7922c34583bddbab4b7ce78adadb90730) also works for app developers and it's called earlier in the app lifecycle than [Application.onCreate()](https://developer.android.com/reference/android/app/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:

```kotlin
class MyApp : Application() {

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

In [Android Vitals - Diving into cold start waters 🥶](https://dev.to/pyricau/android-vitals-diving-into-cold-start-waters-5hi6), we learnt that on Android P+ the first class loaded is the [AppComponentFactory](https://cs.android.com/android/platform/superproject/+/master:frameworks/base/core/java/android/app/AppComponentFactory.java;drc=69e700c7922c34583bddbab4b7ce78adadb90730;bpv=1;bpt=1;l=35):

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

  companion object {
    val factoryClassLoadMs = SystemClock.uptimeMillis()
  }
}
```

```xml
<?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:

```kotlin
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](https://dev.to/pyricau/android-vitals-diving-into-cold-start-waters-5hi6). 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.

```kotlin
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:

```kotlin
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 🥶](https://dev.to/pyricau/android-vitals-diving-into-cold-start-waters-5hi6), we concluded that app cold start monitoring should start when [ActivityThread.handleBindApplication()](https://cs.android.com/android/platform/superproject/+/master:frameworks/base/core/java/android/app/ActivityThread.java;l=6162;drc=69e700c7922c34583bddbab4b7ce78adadb90730) 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()](https://cs.android.com/android/platform/superproject/+/master:frameworks/base/core/java/android/app/ActivityThread.java;l=6162;drc=69e700c7922c34583bddbab4b7ce78adadb90730) does is call [Process.setStartTimes()](https://cs.android.com/android/platform/superproject/+/master:frameworks/base/core/java/android/os/Process.java;l=644;drc=69e700c7922c34583bddbab4b7ce78adadb90730):

```java
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()](https://developer.android.com/reference/android/os/Process.html#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()](https://developer.android.com/reference/android/os/Process.html#getStartUptimeMillis()).
* API 28 and beyond: Use [Process.getStartUptimeMillis()](https://developer.android.com/reference/android/os/Process.html#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.