DEV Community: Py ⚔

Leak investigation: Rx disposal race in SQLDelight

Py ⚔ — Mon, 17 May 2021 22:10:41 +0000

Header image: The In-Between by Romain Guy.

In this blog we'll look into how an easy mistake when using Observable.create() can lead to subtle leaks.

I recently investigated the following leak, which I couldn't reproduce systematically:

┬───
...
├─ com.example.hockey.PlayerQueries$selectAllQuery instance
│    ↓ Query.listeners
│            ~~~~~~~~~
├─ java.util.concurrent.CopyOnWriteArrayList instance
│    ↓ CopyOnWriteArrayList.array
│                           ~~~~~
├─ java.lang.Object[] array
│    ↓ Object[].[0]
│               ~~~
├─ sqldelight.runtime.rx.QueryListenerAndDisposable instance
│    Retaining 4.3 kB in 56 objects
│    ↓ QueryListenerAndDisposable.emitter
│                                 ~~~~~~~
... RxJava observer chain
├─ com.example.hockey.PlayersView$onAttachedToWindow$1 instance
│    Anonymous class implementing io.reactivex.functions.Function
│    ↓ PlayersView$onAttachedToWindow$1.this$0
│                                       ~~~~~~
╰→ com.example.hockey.view.PlayersView instance
     Leaking: YES (View.mContext references a destroyed activity)

In the above leaktrace, PlayerQueries$selectAllQuery is a generated SQLDelight query. Our PlayersView is listening for updates to that query while the view is attached by leveraging Query.asObservable(). Once the view is detached, the observable chain is disposed and the query is expected to let go of the corresponding listener.

I inspected the heap dump and found that the view was indeed detached, the observable chain was correctly disposed, and yet the QueryListenerAndDisposable listener had not been removed from the query. Let's look at the Query.asObservable() implementation:

fun <T : Any> Query<T>.asObservable(): Observable<Query<T>> {
  return Observable.create(QueryOnSubscribe(this))
}

private class QueryOnSubscribe<T : Any>(
  private val query: Query<T>
) : ObservableOnSubscribe<Query<T>> {
  override fun subscribe(emitter: ObservableEmitter<Query<T>>) {
    val listener = QueryListenerAndDisposable(emitter, query)
    emitter.setDisposable(listener)
    query.addListener(listener)
    emitter.onNext(query)
  }
}

private class QueryListenerAndDisposable<T : Any>(
  private val emitter: ObservableEmitter<Query<T>>,
  private val query: Query<T>
) : AtomicBoolean(), Query.Listener, Disposable {
  override fun queryResultsChanged() {
    emitter.onNext(query)
  }

  override fun isDisposed() = get()

  override fun dispose() {
    if (compareAndSet(false, true)) {
      query.removeListener(this)
    }
  }
}

Let's now look at the implementation example from Observable.create():

val observable = Observable.create<Event> { emitter ->
  val closeable = api.someMethod { event ->
    emitter.onNext(event)
  }
  emitter.setCancellable(closeable::close)
}

We can rewrite the above example code to use a listener instead of a closeable:

val observable = Observable.create<Event> { emitter ->
  // 1. Create a listener
  val listener: (Event) -> Unit = { event ->
    emitter.onNext(event)
  }
  // 2. Set the listener
  api.addListener(listener)
  // 3. Remove the listener on dispose
  emitter.setCancellable {
    api.removeListener(listener)
  }
}

The above implementation is fairly close to the SQLDelight implementation, with one major difference: SQLDelight sets the disposable before adding the listener to the query, i.e. something like this:

val observable = Observable.create<Event> { emitter ->
  // 1. Create a listener
  val listener: (Event) -> Unit = { event ->
    emitter.onNext(event)
  }
  // 2. Remove the listener on dispose
  emitter.setCancellable {
    api.removeListener(listener)
  }
  // 3. Set the listener
  api.addListener(listener)
}

It turns out that's a mistake! If emitter is already disposed when the subscription runs, then we'll add the listener but never remove it:

val observable = Observable.create<Event> { emitter ->
  // 1. Create a listener
  val listener: (Event) -> Unit = { event ->
    emitter.onNext(event)
  }
  // 2. if emitter is currently already disposed,
  // the cancellable callback fires immediately and
  // there's no listener to remove yet.
  emitter.setCancellable {
    api.removeListener(listener)
  }
  // 3. Set the listener, which will never be removed. Leak!
  api.addListener(listener)
}

Can emitter be already disposed when the subscription runs? Yes! This can happen if the subscription runs on a separate thread from the thread that called subscribe():

val subscription = observable.subscribeOn(Schedulers.io())
  .subscribe()

// `dispose()` might execute at the time as the subscription
// callback.
subscription.dispose()

Take aways

When using Observable.create(), check the order in which you set a listener vs set the disposable.
I opened a PR to fix SQLDelight. In the meantime, remove subscribeOn calls for observables that originate from Query.asObservable(). As you saw from the code above, all Query.asObservable() is doing is setting a listener so there's no need to be on any special scheduler here.

Tap Response Time: Jetpack Navigation 🗺

Py ⚔ — Sat, 24 Apr 2021 19:27:34 +0000

Header image: Surf by Romain Guy.

In Android Vitals - Tap Response Time 👉 we established that the naive approach to measuring Tap Response Time isn't accurate and doesn't scale. Today we'll build a better implementation step by step, on top Jetpack Navigation.

🗺 Navigation library

We'll focus on Jetpack Navigation here, however most of the content applies for any navigation library or tap action. In fact, I first implemented this at Square on top of Flow and Workflow.

Advanced Navigation Sample

We'll implement the Tap Response Time measurement inside the Advanced Navigation Sample and focus on the navigation from the Title screen to the About screen.

aboutButton.setOnClickListener {
  findNavController().navigate(R.id.action_title_to_about)
}

From Tap to Render

What happens exactly when we click on the about button?

Main thread tracing

To figure that out, we enable Java method tracing while clicking on the button :

The MotionEvent.ACTION_UP event is dispatched and a click is posted to the main thread.
The posted click runs, the click listener calls NavController.navigate() and a fragment transaction is posted to the main thread.
The fragment transaction runs, the view hierarchy is updated, and a view traversal is scheduled for the next frame on the main thread.
The view traversal runs, the view hierarchy is measured, laid out and drawn.

What happens after step 4?

Systrace

We get a better high level view with systrace:

In step 4, the view traversal draw pass generates a list of drawing commands (known as display lists) and sends that list of drawing commands to the render thread.
Step 5: the render thread optimizes the display lists, adds effects such as ripples, then leverages the GPU to run the drawing commands and draw into a buffer (an OpenGL surface). Once done, the render thread tells the surface flinger (which lives in a separate process) to swap the buffer and put it on the display.
Step 6 (not visible in the systrace screenshot): the surfaces for all visible windows are composited by the surface flinger and hardware composer, and the result is sent to the display.

Tap Response Time

We previously defined the Tap Response Time as the time from when the user is done pressing a button to when the app has visibly reacted to the tap. In other words, we need to measure the total duration of going through steps 1 to 6.

In the next sections I'll explain how we can detect each step. If you'd rather immediately go to the final implementation, here's the PR against NavigationAdvancedSample.

Step 1: Up dispatch

We leverage square/curtains to intercept touch events. We define TapTracker, a touch event interceptor. TapTracker stores the time of the last MotionEvent.ACTION_UP touch event. When the posted click listener triggers, we retrieve the time of the up event that triggered it by calling TapTracker.currentTap:

object TapTracker : TouchEventInterceptor {

  var currentTap: TapResponseTime.Builder? = null
    private set

  private val handler = Handler(Looper.getMainLooper())

  override fun intercept(
    motionEvent: MotionEvent,
    dispatch: (MotionEvent) -> DispatchState
  ): DispatchState {
    val isActionUp = motionEvent.action == MotionEvent.ACTION_UP
    if (isActionUp) {
      val tapUptimeMillis = motionEvent.eventTime
      // Set currentTap right before the click listener fires
      handler.post {
        TapTracker.currentTap = TapResponseTime.Builder(
          tapUptimeMillis = tapUptimeMillis
        )
      }
    }
    // Dispatching posts the click listener.
    val dispatchState = dispatch(motionEvent)

    if (isActionUp) {
      // Clear currentTap right after the click listener fires
      handler.post {
        currentTap = null
      }
    }
    return dispatchState
  }
}

We then add the TapTracker interceptor to each new window:

class ExampleApplication : Application() {

  override fun onCreate() {
    super.onCreate()

    Curtains.onRootViewsChangedListeners +=
      OnRootViewAddedListener { view ->
        view.phoneWindow?.let { window ->
          if (view.windowAttachCount == 0) {
            window.touchEventInterceptors += TapTracker
          }
        }
      }
  }
}

Step 2: Click listener & navigation

Let's define an ActionTracker that will be called when when the posted click listener triggers:

object ActionTracker {
  fun reportTapAction(actionName: String) {
    val currentTap = TapTracker.currentTap
    if (currentTap != null) {
      // to be continued...
    }
  }
}

Here's how we could leverage it:

aboutButton.setOnClickListener {
  findNavController().navigate(R.id.action_title_to_about)
  ActionTracker.reportTapAction("About")
}

However, we don't want to add that code to every click listener. Instead, we can add a destination listener to the NavController:

navController.addOnDestinationChangedListener { _, dest, _ ->
  ActionTracker.reportTapAction(dest.label.toString())
}

The Advanced Navigation Sample has 3 tabs, and each tab contains its own NavHostFragment and NavController. We could add a destination listener for each tab. Or we can leverage lifecycle callbacks to add a destination listener to every new NavHostFragment instance:

class GlobalNavHostDestinationChangedListener
  : ActivityLifecycleCallbacks {

  override fun onActivityCreated(
    activity: Activity,
    savedInstanceState: Bundle?
  ) {
    if (activity is FragmentActivity) {
      registerFragmentCreation(activity)
    }
  }

  private fun registerFragmentCreation(activity: FragmentActivity) {
    val fm = activity.supportFragmentManager
    fm.registerFragmentLifecycleCallbacks(
      object : FragmentLifecycleCallbacks() {
        override fun onFragmentCreated(
          fm: FragmentManager,
          fragment: Fragment,
          savedInstanceState: Bundle?
        ) {
          if (fragment is NavHostFragment) {
            registerDestinationChange(fragment)
          }
        }
      }, true
    )
  }

  private fun registerDestinationChange(fragment: NavHostFragment) {
    val navController = fragment.navController
    navController.addOnDestinationChangedListener { _, dest, _ ->
      val actionName = dest.label.toString()
      ActionTracker.reportTapAction(actionName)
    }
  }
}

Step 3: Fragment transaction

Calling NavController.navigate() does not immediately update the view hierarchy. Instead, a fragment transaction is posted to the main thread. The view for the destination fragment will be created and attached when the fragment transaction executes. Since all pending fragment transactions are executed at once, we add our own custom transaction to leverage the runOnCommit() callback. Let's first build a utility, OnTxCommitFragmentViewUpdateRunner.runOnViewsUpdated():

class OnTxCommitFragmentViewUpdateRunner(
  private val fragment: Fragment
) {
  fun runOnViewsUpdated(block: (View) -> Unit) {
    val fm = fragment.parentFragmentManager
    val transaction = fm.beginTransaction()
    transaction.runOnCommit {
      block(fragment.view!!)
    }.commit()
  }
}

We then pass an instance to ActionTracker.reportTapAction():

class GlobalNavHostDestinationChangedListener
 ...
     val navController = fragment.navController
     navController.addOnDestinationChangedListener { _, dest, _ ->
       val actionName = dest.label.toString()
-      ActionTracker.reportTapAction(actionName)
+      ActionTracker.reportTapAction(
+        actionName,
+        OnTxCommitFragmentViewUpdateRunner(fragment)
+      )
     }
   }
 }

 object ActionTracker {
-  fun reportTapAction(actionName: String) {
+  fun reportTapAction(
+      actionName: String,
+      viewUpdateRunner: OnTxCommitFragmentViewUpdateRunner
+  ) {
     val currentTap = TapTracker.currentTap
     if (currentTap != null) {
-      // to be continued...
+      viewUpdateRunner.runOnViewsUpdated { view ->
+        // to be continued...
+      }
     }
   }
 }

Step 4: Frame & view hierarchy traversal

When the fragment transaction executes, a view traversal is scheduled for the next frame, which we hook into with Choreographer.postFrameCallback():

 object ActionTracker {
+
+  // Debounce multiple calls until the next frame
+  private var actionInFlight: Boolean = false
+
   fun reportTapAction(
       actionName: String,
       viewUpdateRunner: OnTxCommitFragmentViewUpdateRunner
   ) {
     val currentTap = TapTracker.currentTap
-    if (currentTap != null) {
+    if (!actionInFlight & currentTap != null) {
+      actionInFlight = true
       viewUpdateRunner.runOnViewsUpdated { view ->
-        // to be continued...
+        val choreographer = Choreographer.getInstance()
+        choreographer.postFrameCallback { frameTimeNanos ->
+          actionInFlight = false
+          // to be continued...
+        }
       }
     }
   }
 }

Step 5: RenderThread

Once the view traversal is done, the main thread sends the display lists to the render thread. The render thread does additional work and then tells the surface flinger to swap the buffer and put it on the display. We register a OnFrameMetricsAvailableListener to get the total frame duration (including time spent on the render thread):

 object ActionTracker {
 ...
         val choreographer = Choreographer.getInstance()
         choreographer.postFrameCallback { frameTimeNanos ->
           actionInFlight = false
-          // to be continued...
+          val callback: (FrameMetrics) -> Unit = { frameMetrics ->
+            logTapResponseTime(currentTap, frameMetrics)
+          }
+          view.phoneWindow!!.addOnFrameMetricsAvailableListener(
+            CurrentFrameMetricsListener(frameTimeNanos, callback),
+            frameMetricsHandler
+          )
         }
       }
     }
   }
+
+  private fun logTapResponseTime(
+    currentTap: TapResponseTime.Builder,
+    fM: FrameMetrics
+  ) {
+    // to be continued...
+  }

Once we have the frame metrics we can determine when the frame buffer was swapped, and therefore the Tap Response Time, i.e. the time from MotionEvent.ACTION_UP to buffer swap:

 object ActionTracker {
 ...
     currentTap: TapResponseTime.Builder,
     fM: FrameMetrics
   ) {
-    // to be continued...
+    val tap = currentTap.tapUptimeMillis
+    val intendedVsync = fM.getMetric(INTENDED_VSYNC_TIMESTAMP)
+    // TOTAL_DURATION is the duration from the intended vsync
+    // time, not the actual vsync time.
+    val frameDuration = fM.getMetric(TOTAL_DURATION)
+    val bufferSwap = (intendedVsync + frameDuration) / 1_000_000
+    Log.d("TapResponseTime", "${bufferSwap-tap} ms")
   }
 }

Step 6: SurfaceFlinger

There's no Java API to determine when the composited frames end up being sent to the display by SurfaceFlinger, so I didn't include that part. Romain Guy mentioned this can be done with a native call to EGL_ANDROID_get_frame_timestamps.

Result

When we click on the About button, we now see a nice log in Logcat:

D/TapResponseTime: 105 ms

I ran systrace at the same time. As you can see in the screenshot, the time from tap to buffer swap is also 105ms:

Conclusion

You can see the final result in this PR. Feel free to leave comments on the PR! I added a few more things that I didn't cover in this blog, such as back key support and logging tab navigation.

I intend to eventually create a Square Open Source library for this. Until then, you have everything you need to get started.

My hope is that you can leverage this code to start measuring tap response time in your production apps, which will help you improve the experience of your customers 👏.

⚖️ This work is licensed under a Creative Commons Attribution 4.0 International License

Android Vitals - Tap Response Time 👉

Py ⚔ — Thu, 15 Apr 2021 14:10:20 +0000

Header image: Alone Together by Romain Guy.

Android users expect apps to respond to their actions within a short time window.

💡 Did you know?

UX research teaches us that a response time shorter than 100ms feels immediate, and a response time beyond 1s makes users lose focus. When the response time gets closer to 10 seconds, users simply abandon their task (source).

👉📱

Measuring user action response times is critical to ensure a good user experience. Taps are the most common action apps must respond to. Can we measure Tap Response Time?

🎓 Tap Response Time

The Tap Response Time is the time from when the user is done pressing a button to when the app has visibly reacted to the tap.
More precisely, it's the time from when the finger leaves the touch screen to when the display has rendered a frame with a visible reaction to that tap (e.g. the start of a navigation animation). The Tap Response Time does not include any animation time.

Naive Tap Response Time

I opened the Navigation Advanced Sample project and added a call to measureTimeMillis() to measure the Tap Response Time when tapping on the about button.

aboutButton.setOnClickListener {
  val tapResponseTimeMs = measureTimeMillis {
    findNavController().navigate(R.id.action_title_to_about)
  }
  PerfAnalytics.logTapResponseTime(tapResponseTimeMs)
}

Simple enough! However this approach presents several drawbacks:

⌛️ It can return a negative time.
📈 It doesn't scale with the codebase size.
👉 It doesn't account for the time from when the finger leaves the touch screen to when the click listener is called.
📱 It doesn't account for the time from when we're done calling NavController.navigate() to when the display has rendered a frame with the new screen visible.

⌛️ Negative time

measureTimeMillis() calls System.currentTimeMillis() whihch can be set by the user or the phone network, so the time may jump backwards or forwards unpredictably. Elapsed time measurements should not use System.currentTimeMillis() (learn more: Android Vitals - What time is it?
).

📈 Large codebases

Adding measuring code to every single meaningful click listener is a daunting task. We need a solution that scales with the codebase size, which means we need central hooks to detect when meaningful actions are triggered by taps.

👉 Touch pipeline

When a finger leaves the touch screen, the following happens:

The system_server process receives the information from the touch screen and determines which window should receive a MotionEvent.UP touch event.

💡 Did you know?

Every window is associated with an input event socket pair: the first socket is owned by system_server to send input events. That first socket is paired with a second socket owned by the app that created the window, to receive input events.

The system_server process sends the touch event to the input event socket for the targeted window.
The app receives the touch event on its listening socket, stores it in a queue (ViewRootImpl.QueuedInputEvent) and schedules a Choreographer frame to consume input events.

💡 Did you know?

The system_server process detects when an input event stays in the queue for more than 5 seconds, and that's when it knows it should show an Application Not Responding (ANR) dialog.

When the Choreographer frame triggers, the touch event is dispatched to the root view of a window, which then dispatches it through its view hierarchy.
The tapped view receives the MotionEvent.UP touch event and posts a click listener callback (source). This lets other visual state of the view update before click actions start.
Then finally when the main thread runs that posted callback the view click listener is called.

As you can see, quite a lot happens from when the finger leaves the touch screen to when the click listener is called. Every motion event includes the time at which the event occurred (MotionEvent.getEventTime()). If we could get access to that MotionEvent.UP event leading to a click we could measure the true start of the Tap Response Time.

📱 Traversal and rendering

What does this do?

findNavController().navigate(R.id.action_title_to_about)

In most apps, the above code starts a fragment transaction. That transaction may be immediate (commitNow()) or posted (commit()).
When the transaction execute, the view hierarchy is updated and a layout traversal is scheduled.
When the layout traversal executes, a new frame is drawn into a surface.
It is then composited with frames from other windows and sent to the display. To learn more, watch this talk from Romain Guy and Chet Haase: Drawn out: How Android renders.

Ideally we'd like to know exactly when a change to the view hierarchy becomes actually visible on the display. Unfortunately, as far as I know there's no Java API for that, so we'll have to get creative.

🤔 What now?

We've seen that the naive approach to measuring Tap Response Time isn't accurate and doesn't scale. We need to build something better!

The good news is, I've implemented exactly that, on top of Jetpack Navigation. ~~The bad news is, you'll have to wait for me to publish Part 2!~~. The even better news is, you can read about it in Part 2: Tap Response Time: Jetpack Navigation 🗺.

⚖️ This work is licensed under a Creative Commons Attribution 4.0 International License.

Waldo, where's my UI?

Py ⚔ — Wed, 27 Jan 2021 19:41:44 +0000

Today, Waldo.io, a no-code platform for automated mobile tests, announced general availability of their Android support.

// Detect dark theme var iframe = document.getElementById('tweet-1354481799611736075-839'); if (document.body.className.includes('dark-theme')) { iframe.src = "https://platform.twitter.com/embed/Tweet.html?id=1354481799611736075&theme=dark" }

I was recently talking with the CEO of Waldo, Amine Bellakrid. I told him that the llama logo was super cute and the UI gorgeous... but I had doubts a no-code platform was a good fit for automated mobile tests.

The problem with no-code tests

No-code platforms typically provide a recorder tool that lets you navigate through the app, recording everywhere you tapped. Then later on you can replay the test automatically, and get notified when it fails.

Automated tests are expected to fail when a change breaks the correct behavior of the app. Unfortunately, no-code platforms tend to generate brittle tests that also fail on small changes that didn't introduce incorrect behavior.

This creates a lot of noise, so teams tend to stop updating and running these tests and they just rot in a corner.

Note: similar problems can happen with code based tests, but we've introduced patterns to work around them (e.g. Testing Robots)

Apparently Waldo is different

When I shared my doubts, Amine smiled and said I should try Waldo. So I created a new example project with 3 tabs:

I recorded a simple test on Waldo.io, tapping on the second tab (Dashboard) and then the 3rd tab (Notifications).

Messing with Waldo

Tab swap

I started by swapping out the second and the third navigation tab:

The result is interesting: Waldo clicked on the correct tab (Dashboard) even though it changed place, and the test passed.

Changing strings

Next, I renamed the Dashboard tab to Summary . Still ✅ .

Changing everything else

Ok, time to make this really hard. I also changed the tab menu id and its icon. No way this can still work.

... the test still passes and finds the right tabs to tap on, in the right order.

One thing that's really cool in the screenshot above:

Screen similarity should be at least 70%.
Current similarity: 93%

I don't know how the similarity is calculated, but it seems more advanced than a simple matching on view ids, bitmap content or string content. That explains why Waldo is totally fine with me changing the UI.

Ok but I really want to break it

I decided to just be mean and remove the tab. Take that Waldo!

This time the test is failing 😏.

Let's see what happens when I click Update test:

The recorder is on the right, the new scenario at the top left and the old scenario at the bottom left. Now that I have only two tabs, I click on the Notifications tab and the scenario is immediately updated. Nice!

Conclusion

I changed my mind: no-code test platforms don't have to be brittle!

I don't know all the details of how Waldo does it, so I hope they can share more about it some day and bring the community forward. In the meantime, I would definitely give Waldo a shot.

Full disclosure: Amine is my friend and I've been advising the Waldo team every now and then on some cool Android tech problems. I wrote this blog on my own though.

Android Vitals - How adb measures App Startup 🔎

Py ⚔ — Tue, 01 Dec 2020 17:05:55 +0000

Last week, Chet Haase published a great blog post: Testing App Startup Performance. It leverages the output of ActivityTaskManager to obtain the app startup duration.

Whenever an activity starts, you’ll see something like this in the logcat output:

ActivityTaskManager: Displayed
com.android.samples.mytest/.MainActivity: +1s380ms

This duration (1,380ms in this example) represents the time that it took from launching the app to the time when the system consider it “launched,” which includes drawing the first frame (hence “Displayed”).

This article is a deep dive to explore the question:

What does `ActivityTaskManager` measure exactly?

I know you're impatient, let's jump to the conclusion: ActivityTaskManager measures the time (uptime on API < 30, realtime on API 30+) from when system_process receives an Intent to start an activity to when the window of that activity is done drawing.

Key takeways:

This measure includes a few hundred milliseconds prior to app code and resources loading, i.e. time that an app developer cannot affect.
You can measure this without the extra time from within the app, I'll share how at the end.

And now, let's dive into AOSP code!

`ActivityTaskManager` log

ActivityTaskManager: Displayed
com.android.samples.mytest/.MainActivity: +1s380ms

We know what the log looks like so we can search for it on cs.android.com:

This leads us to ActivityTaskManager.logAppDisplayed():

private void logAppDisplayed(TransitionInfoSnapshot info) {
  StringBuilder sb = mStringBuilder;
  sb.setLength(0);
  sb.append("Displayed ");
  sb.append(info.launchedActivityShortComponentName);
  sb.append(": ");
  TimeUtils.formatDuration(info.windowsDrawnDelayMs, sb);
  Log.i(TAG, sb.toString());
}

The startup duration is TransitionInfoSnapshot.windowsDrawnDelayMs. It's calculated in TransitionInfoSnapshot.notifyWindowsDrawn():

TransitionInfoSnapshot notifyWindowsDrawn(
  ActivityRecord r, 
  long timestampNs
) {  
  TransitionInfo info = getActiveTransitionInfo(r);
  info.mWindowsDrawnDelayMs = info.calculateDelay(timestampNs);
  return new TransitionInfoSnapshot(info);
}

private static final class TransitionInfo {
 int calculateDelay(long timestampNs) {
   long delayNanos = timestampNs - mTransitionStartTimeNs;
   return (int) TimeUnit.NANOSECONDS.toMillis(delayNanos);
 }
}

Let's find where timestampNs and mTransitionStartTimeNs are captured.

ActivityMetricsLogger.notifyActivityLaunching() captures the start of the activity transition:

private LaunchingState notifyActivityLaunching(
  Intent intent,
  ActivityRecord caller,
  int callingUid
) {
  long transitionStartNs = SystemClock.elapsedRealtimeNanos();
  LaunchingState launchingState = new LaunchingState();
  launchingState.mCurrentTransitionStartTimeNs = transitionStartNs;
  return launchingState;
}

TransitionInfoSnapshot.notifyWindowsDrawn() is called by ActivityRecord.onWindowsDrawn() which is called by ActivityRecord.updateReportedVisibilityLocked():

void updateReportedVisibilityLocked() {
  // ...
  if (nowDrawn != reportedDrawn) {
    onWindowsDrawn(nowDrawn, SystemClock.elapsedRealtimeNanos());
    reportedDrawn = nowDrawn;
  }
  // ...
}

We now know where the start and end timestamps are captured, but unfortunately ActivityMetricsLogger.notifyActivityLaunching() and ActivityRecord.updateReportedVisibilityLocked() have many call sites, so it's hard to dig further within the AOSP source.

Debugging `system_process`

I was telling a friend I hit a dead end looking at the Android sources, and he asked me:

Why don't you put a breakpoint?

Duh. I have never tried to debug system_process, but there's no reason we can't. Thanks Vincent for the idea! Lucky for us, Android Studio is set up to find sources for the Android version the app is compiled against:

I can put a breakpoint like I would in my app:

Side note: this screenshot shows SystemClock.uptimeMillis() while the code I shared aboved showed SystemClock.elapsedRealtimeNanos(). I'm using an API 29 device, and it turns out that API 29 measured startup time with SystemClock.uptimeMillis(), and API 30 measures it with SystemClock.elapsedRealtimeNanos().

Using a rooted device, I can connect a debugger to system_process:

When I start my app, I hit a breakpoint for ActivityMetricsLogger.notifyActivityLaunching():

and another breakpoint for TransitionInfoSnapshot.notifyWindowsDrawn():

Reading the stacktraces

The first stacktrace shows that the start timestamp is captured when system_process receives an Intent to start an activity.
The second stacktrace shows that the end timestamp is captured when the window of that activity is done drawing. The corresponding frame should be visible on the display within 16 ms.

App startup time

In Android Vitals - Diving into cold start waters 🥶, I explored what happens on app startup and concluded:

The user experience of launching an activity starts when the user touches the screen, however app developers have little influence on the time spent before ActivityThread.handleBindApplication(), so that's where app cold start monitoring should start.

ActivityThread.handleBindApplication() loads the APK and the app components (AppComponentFactory, ContentProvider, Application). Unfortunately, ActivityTaskManager uses ActivityTaskManagerService.startActivity() as start time, which happens some time before ActivityThread.handleBindApplication().

How much time is `ActivityTaskManager` adding?

In Android Vitals - When did my app start? ⏱, I showed that we can use Process.getStartUptimeMillis() to get the timestamp at which ActivityThread.handleBindApplication() was called. I also shared a code snippet to read the process fork time (see Processes.readProcessForkRealtimeMillis()). We can logs these 2 values to logcat:

val forkRealtime = Processes.readProcessForkRealtimeMillis()
val nowRealtimeMs = SystemClock.elapsedRealtime()
val nowUptimeMs = SystemClock.uptimeMillis()
val elapsedRealtimeMs = nowRealtimeMs - forkRealtime
val forkUptimeMs = nowUptimeMs - elapsedRealtimeMs
Log.d("AppStart", "$forkUptimeMs fork timestamp")

val processStart = Process.getStartUptimeMillis()
Log.d("AppStart", "$processStart bindApplication() timestamp")

We also need to log ActivityMetricsLogger.mCurrentTransitionStartTime. We can make our previous system_process breakpoint non-suspending and have it log the value. The output of Evaluate and log goes to the debugger console. We want all logs in logcat so we're invoking Log.d() from there:

Results

D/AppStart: 27464211 Intent received
D/AppStart: 27464340 fork timestamp
D/AppStart: 27464533 bindApplication() timestamp
...
I/ActivityTaskManager: Displayed
com.example.logstartup/.MainActivity: +1s185ms

That's 129 ms from receiving the intent to forking the zygote process, and 193 ms from forking to ActivityThread.handleBindApplication(), i.e. 322 ms before the app starts loading its code and resources. In this example, that's ~30% of the app startup time reported by ActivityTaskManager.

The real number is lower than that, since system_process was running with a debugger connected. Still, it's significant enough that you should have this extra penalty in mind when measuring app startup with ActivityTaskManager.

Measuring app startup time from within the app

In Android Vitals - First draw time 👩‍🎨 I showed how to determine the first draw time. I compared that timestamp with the timestamp passed to TransitionInfoSnapshot.notifyWindowsDrawn(), and the two values are only a few milliseconds apart.

We can put together what we've learnt to measure the app startup duration from within the app:

class MyApp : Application() {

  override fun onCreate() {
    super.onCreate()

    var firstDraw = false
    val handler = Handler()

    registerActivityLifecycleCallbacks(
      object : ActivityLifecycleCallbacks {
      override fun onActivityCreated(
        activity: Activity,
        savedInstanceState: Bundle?
      ) {
        if (firstDraw) return
        val name = activity::class.java.simpleName
        val window = activity.window
        window.onDecorViewReady {
          window.decorView.onNextDraw {
            if (firstDraw) return@onNextDraw
            firstDraw = true
            handler.postAtFrontOfQueue {
              val start = Process.getStartUptimeMillis()
              val now = SystemClock.uptimeMillis()
              val startDurationMs = now - start
              Log.d(
                "AppStart", 
                "Displayed $name in $startDurationMs ms"
              )
            }
          }
        }
      }
    })
  }
}

D/AppStart: Displayed MainActivity in 863 ms

Conclusion

The output from ActivityTaskManager is convenient, and totally worth using if you're trying to compare startup time for different versions of your app. Just be aware that there's a non-trivial portion of that time that app developers cannot affect.
You can measure app startup time from within the app. I intend to eventually publish that code as an open source library, in the meantime the details are in Android Vitals - First draw time 👩‍🎨.

Header image: Deep Dive by Romain Guy.

Android Vitals - Profiling App Startup 🔬

Py ⚔ — Mon, 23 Nov 2020 23:03:19 +0000

Header image: The In-Between by Romain Guy.

My previous articles focused on measuring Android app start in production. Once we've established a metric and scenarios that trigger a slow app start, the next step is to improve performance.

To understand what makes the app start slow, we need to profile it. Android Studio provides several types of profiler recording configurations:

Trace System Calls (aka systrace, perfetto): Low impact on runtime, great for understanding how the app interacts with the system and CPUs, but not the Java method calls that happen inside the app VM.
Sample C/C++ Functions (aka Simpleperf): Not interesting to me, the apps I deal with run much more bytecode than native code. On Q+ this is supposed to now also sample Java stacks in a low overhead way, but I haven't managed to get that working.
Trace Java Methods: This captures all VM method calls which introduces so much overhead that the results don't mean much.
Sample Java Methods: Less overhead than tracing but shows the Java method calls that happen inside the VM. This is my preferred option when profiling app startup.

Start recording on app startup

The Android Studio profiler has UI to start a trace by connecting to an already running process, but no obvious way to start recording on app startup.

The option exist but is hidden away in the run configuration for your app: check Start this recording on startup in the profiling tab.

Then deploy the app via Run > Profile app.

Profiling release builds

Android developers typically use a debug build type for their everyday work, and debug builds often include a debug drawer, extra libraries such as LeakCanary, etc. Developers should profile release builds rather than debug builds to make sure they're fixing the actual issues that their customers are facing.

Unfortunately, release builds are non debuggable so the Android profiler can't record traces on release builds.

Here are a few options to work around that issue.

1. Create a debuggable release build

We could temporarily make our release build debuggable, or create a new release build type just for profiling.

android {
  buildTypes {
    release {
      debuggable true
      // ...
    }
  }
}

Libraries and Android Framework code often have a different behavior if the APK is debuggable. ART disables a lot of optimizations to enable connecting a debugger, which affects performance significantly and unpredictably (see this talk. So this solution is not ideal.

2. Profile on a rooted device

Rooted devices allow the Android Studio profiler to record traces on non debuggable builds.

Profiling on an emulator is generally not recommended - the performance of every system component will be different (cpu speed, cache sizes, disk perf), so an 'optimization' can actually make things slower by shifting the work to something that's slower on a phone. If you don't have a rooted physical device available, you can create an emulator without Play Services and then run adb root.

3. Use simpleperf on Android Q

There's a tool called simpleperf which supposedly enables profiling release builds on non rooted Q+ devices, if they have a special manifest flag. The doc calls it profileableFromShell, the XML example has a profileable tag with an android:shell attribute, and the official manifest documentation shows nothing.

<manifest ...>
    <application ...>
      <profileable android:shell="true" />
    </application>
</manifest>

I looked at the manifest parsing code on cs.android.com:

if (tagName.equals("profileable")) {
  sa = res.obtainAttributes(
    parser,
    R.styleable.AndroidManifestProfileable
  );
  if (sa.getBoolean(
    R.styleable.AndroidManifestProfileable_shell,
    false
  )) {
    ai.privateFlags |= ApplicationInfo.PRIVATE_FLAG_PROFILEABLE_BY_SHELL;
  }
}

It looks like you can trigger profiling from command line if the manifest has <profileable android:shell="true" /> (I haven't tried). As far as I understand the Android Studio team is still working on integrating with this new capability.

Profiling a downloaded APK

At Square our releases are built in CI. As we saw earlier, profiling app startup from Android Studio requires checking an option in a run configuration. How can we do this with a downloaded APK?

Turns out, it's possible but hidden under File > Profile or Debug APK. This opens up a new window with the unzipped APK, and from that you can set up the run configuration and start profiling.

Android Studio profiler slows everything down

Unfortunately, when I tested these methods on a production app, profiling from Android Studio slowed down app startup a lot (~10x slower), even on recent Android versions. I'm not sure why, maybe it's the "advanced profiling", which doesn't seem like it can be disabled. We need to find another way!

Profiling from code

Instead of profiling from Android Studio, we can start the trace directly from code:

val tracesDirPath = TODO("path for trace directory")
val fileNameFormat = SimpleDateFormat(
  "yyyy-MM-dd_HH-mm-ss_SSS'.trace'",
  Locale.US
)
val fileName = fileNameFormat.format(Date())
val traceFilePath = tracesDirPath + fileName
// Save up to 50Mb data.
val maxBufferSize = 50 * 1000 * 1000
// Sample every 1000 microsecond (1ms)
val samplingIntervalUs = 1000
Debug.startMethodTracingSampling(
  traceFilePath, 
  maxBufferSize,
  samplingIntervalUs
)

// ...

Debug.stopMethodTracing()

We can then pull the trace file from the device and load it in Android Studio.

When to start recording

We should start recording the trace as early as possible in the app lifecycle. As I explained in Android Vitals - Diving into cold start waters 🥶, the earliest code that can run on app startup before Android P is a ContentProvider and on Android P+ it's the AppComponentFactory.

Before Android P / API < 28

class AppStartListener : ContentProvider() {
  override fun onCreate(): Boolean {
    Debug.startMethodTracingSampling(...)
    return false
  }
  // ...
}

<?xml version="1.0" encoding="utf-8"?>
<manifest
  xmlns:android="http://schemas.android.com/apk/res/android"
  xmlns:tools="http://schemas.android.com/tools">

  <application>
    <provider
        android:name=".AppStartListener"
        android:authorities="com.example.appstartlistener"
        android:exported="false" />
  </application>

</manifest>

~~Unfortunately we cannot control the order in which ContentProvider instances are created, so we may be missing some of the early startup code.~~

Edit: @anjalsaneen pointed out in the comments that when defining a provider we can set a initOrder tag, and the highest number gets initialized first.

Android P+ / API 28+

@RequiresApi(28)
class MyAppComponentFactory() :
  androidx.core.app.AppComponentFactory() {

  @RequiresApi(29)
  override fun instantiateClassLoader(
    cl: ClassLoader,
    aInfo: ApplicationInfo
  ): ClassLoader {
    if  (Build.VERSION.SDK_INT >= 29) {
      Debug.startMethodTracingSampling(...)
    }
    return super.instantiateClassLoader(cl, aInfo)
  }

  override fun instantiateApplicationCompat(
    cl: ClassLoader,
    className: String
  ): Application {
    if  (Build.VERSION.SDK_INT < 29) {
      Debug.startMethodTracingSampling(...)
    }
    return super.instantiateApplicationCompat(cl, className)
  }
}

<?xml version="1.0" encoding="utf-8"?>
<manifest
  xmlns:android="http://schemas.android.com/apk/res/android"
  xmlns:tools="http://schemas.android.com/tools">

  <application
    android:appComponentFactory=".MyAppComponentFactory"
    tools:replace="android:appComponentFactory"
    tools:targetApi="p">
  </application>

</manifest>

Where to store traces

val tracesDirPath = TODO("path for trace directory")

API < 28: The broadcast receiver has access to a context on which we can call Context.getDataDir() to store the trace in the app directory.
API 28: AppComponentFactory.instantiateApplication() is in charge of creating a new application instance so there's no context available yet. We can hard code the path to /sdcard/ directly, though that requires the WRITE_EXTERNAL_STORAGE permission.
API 29+: When targeting API 29, hardcoding /sdcard/ stops working. We can add the requestLegacyExternalStorage flag but it's not supported on API 30 anyway. Edit: Yacine Rezgui suggested trying out MANAGE_EXTERNAL_STORAGE on API 30+. Either way, AppComponentFactory.instantiateClassLoader() passes an ApplicationInfo so we can use ApplicationInfo.dataDir to store the trace in the app directory.

When to stop recording

In Android Vitals - First draw time 👩‍🎨, we learnt that cold start ends when the app's first frame completely loads. We can leverage the code from that article to know when to stop method tracing:

class MyApp : Application() {

  override fun onCreate() {
    super.onCreate()

    var firstDraw = false
    val handler = Handler()

    registerActivityLifecycleCallbacks(
      object : ActivityLifecycleCallbacks {
      override fun onActivityCreated(
        activity: Activity,
        savedInstanceState: Bundle?
      ) {
        if (firstDraw) return
        val window = activity.window
        window.onDecorViewReady {
          window.decorView.onNextDraw {
            if (firstDraw) return
            firstDraw = true
            handler.postAtFrontOfQueue {
              Debug.stopMethodTracing()
            }
          }
        }
      }
    })
  }
}

We could also record for a fixed amount of time greater than the app start, e.g. 5 seconds:

Handler(Looper.getMainLooper()).postDelayed({
  Debug.stopMethodTracing()
}, 5000)

Profiling with Nanoscope

Another option for profiling app startup is uber/nanoscope. It's an Android image with built-in low overhead tracing. It's great but has a few limitations:

It only traces the main thread.
A large app will overfill the in-memory trace buffer.

// Detect dark theme var iframe = document.getElementById('tweet-1330929229341442048-553'); if (document.body.className.includes('dark-theme')) { iframe.src = "https://platform.twitter.com/embed/Tweet.html?id=1330929229341442048&theme=dark" }

App Startup steps

Once we have a startup trace, we can start investigating what's taking time. You should expect 3 main sections:

ActivityThread.handlingBindApplication() contains the startup work before activity creation. If that's slow then we probably need to optimize Application.onCreate().
TransactionExecutor.execute() is in charge of creating and resuming the activity, which includes inflating the view hierarchy.
ViewRootImpl.performTraversals() is where the framework performs the first measure, layout and draw. If this is slow then it could be the view hierarchy being too complex, or views with custom drawing that need to be optimized.

If you notice that a service is being started before the first view traversal, it might be worth delaying the start of that service so that it happens after the view traversal.

Conclusion

A few take aways:

Profile release builds to focus on the actual issues.
The state of profiling app start on Android is far from ideal. There's basically no good out of the box solution, but the Jetpack Benchmark team is working on this.
Start the recording from code to prevent Android Studio from slowing everything down.

Many thanks to the many folks who helped me out on Slack and Twitter: Kurt Nelson, Justin Wong, Leland Takamine, Yacine Rezgui, Raditya Gumay, Chris Craik, Mike Nakhimovich, Artem Chubaryan, Rahul Ravikumar, Yacine Rezgui, Eugen Pechanec, Louis CAD, Max Kovalev.

Leak detection: Android Studio vs LeakCanary ⚔️

Py ⚔ — Fri, 30 Oct 2020 00:13:40 +0000

I recently came across this comment in a post:

The thing really annoying about LeakCanary or Android Studio, most of the time leaks identified by LeakCanary do not appear in Profiler/Memory/memory leaks, I wonder if LeakCanary is showing false positives or Android Studio is missing positives.

That's a good question, let's dig into code and figure this out!

False positive leaks in Android Studio

Before answering the question, we need to talk about where the idea of false positive leaks comes from: Android Studio.

That warning was originally a longer description:

Activity and Fragment instances that might be causing memory leaks. For Activities, these are instances that have been destroyed but are still being referenced. For Fragments, these are instances that do not have a valid FragmentManager but are still being referenced. Note, these instance might include Fragments that were created but are not yet being utilized.

The documentation provides more insights on false positive leaks:

In certain situations, such as the following, the filter might yield false positives:

A Fragment is created but has not yet been used.

A Fragment is being cached but not as part of a FragmentTransaction.

The phrasing is vague but it looks like false positive leaks only applies to Fragments.

Android Studio leak filtering

Android Studio dumps and analyzes the heap when you press the Dump Heap icon.

Leaking instances are displayed by enabling the "Activity/Fragment Leaks" filter, which updates the bottom panel to only show leaking instances. The filtering is performed by ActivityFragmentLeakInstanceFilter:

const val FRAGFMENT_MANAGER_FIELD_NAME = "mFragmentManager"

/**
 * A Fragment instance is determined to be potentially leaked if
 * its mFragmentManager field is null. This indicates that the
 * instance is in its initial state. Note that this can mean that
 * the instance has been destroyed, or just starting to be
 * initialized but before being attached to an activity. The
 * latter gives us false positives, but it should not uncommon
 * as long as users don't create fragments way ahead of the time
 * of adding them to a FragmentManager.
 */
private fun isPotentialFragmentLeak(
  instance: InstanceObject
): Boolean {
  return isValidDepthWithAnyField(
    instance,
    { FRAGFMENT_MANAGER_FIELD_NAME == it },
    { it == null }
  )
}

/**
 * Check if the instance has a valid depth and any field
 * satisfying predicates on its name and value
 */
private fun isValidDepthWithAnyField(
  inst: InstanceObject,
  onName: (String) -> Boolean,
  onVal: (Any?) -> Boolean
): Boolean {
  val depth = inst.depth
  return depth != 0 && depth != Int.MAX_VALUE &&
         inst.fields.any {
           onName(it.fieldName) && onVal(it.value)
         }
}

(yes, Fragfment manager)

So, a fragment is considered leaking if its mFragmentManager field is null and the fragment is reachable via strong references (that's what valid depth means in the above code). If you create a fragment instance but don't add it, it would be reported as a leak, hence the warning about false positive leaks.

How LeakCanary finds fragment leaks

Unlike Android Studio, LeakCanary does not look at the mFragmentManager field for all fragment instances in memory. LeakCanary hooks into the Android lifecycle to automatically detect when fragments are destroyed and should be garbage collected. These destroyed objects are passed to an ObjectWatcher, which holds weak references to them.

if (activity is FragmentActivity) {
  val supportFragmentManager = activity.supportFragmentManager
  supportFragmentManager.registerFragmentLifecycleCallbacks(
    object : FragmentManager.FragmentLifecycleCallbacks() {

      override fun onFragmentDestroyed(
        fm: FragmentManager,
        fragment: Fragment
      ) {
        objectWatcher.watch(
          fragment,
          "Received Fragment#onDestroy() callback"
        )
      }
    },
    true
  ) 
}

If the weak reference held by ObjectWatcher isn't cleared after waiting 5 seconds and running garbage collection, the watched object is considered retained, and potentially leaking. LeakCanary dumps the Java heap into a .hprof file (a heap dump)

Then LeakCanary parses the .hprof file using Shark and locates the retained objects in that heap dump.

And this is where LeakCanary differs from Android Studio: it looks for the custom weak references that it created (KeyedWeakReference) and checks their referent field in KeyedWeakReferenceFinder:

/**
 * Finds all objects tracked by a KeyedWeakReference, i.e. al
 * objects that were passed to ObjectWatcher.watch().
 */
object KeyedWeakReferenceFinder : LeakingObjectFinder {

  override fun findLeakingObjectIds(graph: HeapGraph): Set<Long> {
    return graph.findClassByName("leakcanary.KeyedWeakReference")
      .instances
      .map { weakRef ->
        weakRef["java.lang.ref.Reference", "referent"]!!
          .value
          .asObjectId
      }
      .filter { objectId ->
        objectId != ValueHolder.NULL_REFERENCE
      }
      .toSet()
  }
}

That means LeakCanary only surfaces fragments that are actually leaking.

Why LeakCanary reports more leaks

Now that we've established that LeakCanary does not have the same false positive leaks as Android Studio, let's go back to the main observation:

most of the time leaks identified by LeakCanary do not appear in Profiler/Memory/memory leaks

The explanation is in the LeakCanary documentation:

LeakCanary automatically detects leaks for the following objects:

destroyed Activity instances

destroyed Fragment instances

destroyed fragment View instances

cleared ViewModel instances

Android Studio does not detect leaks for destroyed fragment View instances or cleared ViewModel instances. The former is actually a common cause of leak:

Adding a Fragment instance to the backstack without clearing that Fragment’s view fields in Fragment.onDestroyView() (more details in this StackOverflow answer).

Conclusion

If LeakCanary reports a leak trace, then there is definitely a leak. LeakCanary is always right! Unfortunately, we can't blame false positive leaks on the little yellow bird as an excuse for not fixing leaks.

The real size of Android objects 📏

Py ⚔ — Tue, 22 Sep 2020 22:31:08 +0000

Header image: Deep Dive by Romain Guy.

I'm currently reimplementing how LeakCanary computes the retained heap size of objects. As a quick reminder:

Shallow heap size of an object: The object size in the memory.

Retained heap size of an object: The shallow size of that object plus the shallow size of all the objects that are transitively held in memory by only that object. In other words, it's the amount of memory that will be freed when that object is garbage collected.

One cannot trust a shallow size

As part of that work, I compared the shallow size of objects as reported in LeakCanary versus other heap dump tools such as YourKit, Eclipse Memory Analyzer Tool (MAT) and Android Studio Memory Analyzer. That's when I realized something was wrong: every tool provides a different answer.

I asked Jesse Wilson about it and he pointed me to this article by Aleksey Shipilёv: What Heap Dumps Are Lying To You About. Some take aways:

Every Java VM lays out its memory in a slightly different way and performs various optimizations, such as changing field order, aligning bits, etc.
The heap dump format (.hprof) is a standard. A class dump record contains the list of fields and their types as well as the instance size of the class. Aleksey Shipilёv asked about having the instance size be the actual size of an instance in memory but the answer was nope: the sizes in the HPROF dump are VM and padding independent, to avoid breaking expectations from consuming tools.
There's a tool called JOL that instruments the JVM runtime to report the actual size of an object. Aleksey used that to compare the size reported in hprof based tools with the actual size and found that they were all wrong in a different way.

In Exploring Java's Hidden Costs, Jake Wharton showed how to use JOL. Unfortunately, JOL only runs on JVMs, and not the Dalvik or ART runtimes. To quote Jake:

In this case, because the classes are exactly the same and the JVM 64 bit, and Android's now 64 bit, the number should be translatable. If that bothers you, treat them as an approximation and allow for some 20% variance. It's certainly a lot easier than figuring out how to get the object sizes on Android itself. Which is not impossible, it's just a lot easier this way.

Damn it, in LeakCanary all we have is the heap dump. Sounds like we need to go the not easy way!

I asked Romain Guy about this and he suggested looking at JVM TI, an agent interface that is implemented on Android 8+ as ART TI. JVM TI exposes a GetObjectSize API.

Read the Source, Luke

Learn to Read the Source, Luke - Coding Horror

Android is Open Source, so we can always find answers to our questions... as long as we know where to search!

JVM TI

Here's the implementation of JVM TI GetObjectSize():



jvmtiError ObjectUtil::GetObjectSize(env* env ATTRIBUTE_UNUSED,
                                     jobject jobject,
                                     jlong* size_ptr) {
  art::ObjPtr<art::mirror::Object> object = 
      soa.Decode<art::mirror::Object>(jobject);

  *size_ptr = object->SizeOf();
  return ERR(NONE);
}

The interesting code lives in Object::SizeOf():



template<VerifyObjectFlags kVFlags>
inline size_t Object::SizeOf() {
  size_t result;
  constexpr VerifyObjectFlags kNewFlags = RemoveThisFlags(kVFlags);
  if (IsArrayInstance<kVFlags>()) {
    result = AsArray<kNewFlags>()->template SizeOf<kNewFlags>();
  } else if (IsClass<kNewFlags>()) {
    result = AsClass<kNewFlags>()->template SizeOf<kNewFlags>();
  } else if (IsString<kNewFlags>()) {
    result = AsString<kNewFlags>()->template SizeOf<kNewFlags>();
  } else {
    result = GetClass<kNewFlags, kWithoutReadBarrier>()
        ->template GetObjectSize<kNewFlags>();
  }
  return result;
}

Instance size

Let's focus on instance size, which is the last else in that conditional. If the object is an instance, then its size is retrieved from GetClass()->GetObjectSize() which returns the value from object_size_ in class.h:



// Total object size; used when allocating storage on gc heap.
// (For interfaces and abstract classes this will be zero.)
// See also class_size_.
uint32_t object_size_;

Instance allocation

Let's double check that this is the actual size of instances in memory by looking at usages. We find that object_size_ is used by Class::Alloc() in class-alloc-inl.h



template<bool kIsInstrumented, Class::AddFinalizer kAddFinalizer, 
    bool kCheckAddFinalizer>
inline ObjPtr<Object> Class::Alloc(Thread* self, 
    gc::AllocatorType allocator_type) {
  gc::Heap* heap = Runtime::Current()->GetHeap();
  return heap->AllocObjectWithAllocator<kIsInstrumented, false>(
      self, this, this->object_size_, allocator_type,
      VoidFunctor()
  );
}

So the actual memory allocated for an object is indeed defined by object_size_ in class.h.

Note: the memory allocated by Heap::AllocObjectWithAllocator() in heap-inl.h might be rounded up to a multiple of 8 when using a Thread-local bump allocator (TLAB, see Trash Talk by Chet Haase and Romain Guy). However the default CMS GC does not use that allocator.

Class linking

Looked at more usages for object_size_ we find that it's set by ClassLinker::LinkFields() in class_linker.cc when linking classes:



bool ClassLinker::LinkFields(Thread* self,
                             Handle<mirror::Class> klass,
                             bool is_static,
                             size_t* class_size) {
  MemberOffset field_offset(0);

  ObjPtr<mirror::Class> super_class = klass->GetSuperClass();
  if (super_class != nullptr) {
    field_offset = MemberOffset(super_class->GetObjectSize());
  }

  // ... code that increases field_offset as fields are added

  size_t size = field_offset.Uint32Value();
  klass->SetObjectSize(size);

  return true;
}

Back to heap dumps

Now that we know how to get the actual size of instances, let's compare that with the instance size reported in Android heap dumps.

When we trigger a heap dump via Debug.dumpHprofData(), the VM calls DumpHeap() in hprof.cc. Let's look at Hprof::DumpHeapClass(), more specifically the part where the instance size of a class is added:



// Instance size.
if (klass->IsClassClass()) {
  // As mentioned above, we will emit instance fields as
  // synthetic static fields. So the base object is "empty."
  __ AddU4(0);
} else if (klass->IsStringClass()) {
  // Strings are variable length with character data at the end 
  // like arrays. This outputs the size of an empty string.
  __ AddU4(sizeof(mirror::String));
} else if (klass->IsArrayClass() || klass->IsPrimitive()) {
  __ AddU4(0);
} else {
  __ AddU4(klass->GetObjectSize());  // instance size
}

The last else in that conditional is the instance size for most instances, and once again points to object_size_ in class.h.

So, unlike Open JDK heap dumps, Android heap dumps contain the actual size of instances in memory.

Exploring heap dump records

In Exploring Java's Hidden Costs, Jake showed the output from JOL for android.util.SparseArray:



android.util.SparseArray object internals:
SIZE     TYPE DESCRIPTION 
4        (object header)
4        (object header)
4        (object header)
4        int SparseArray.mSize
1        boolean SparseArray.mGarbage
3        (alignment/padding gap)
4        int[] SparseArray.mKeys
4        Object[] SparseArray.mValues
4        (loss due to the next object alignment)

Instance size: 32 bytes

Let's use the LeakCanary heap dump parser (Shark) to see what Android heap dumps report:



val hprofFile = "heap_dump_android_o.hprof".classpathFile()
val sparseArraySize = hprofFile.openHeapGraph().use { graph ->
  graph.findClassByName("android.util.SparseArray")!!.instanceByteSize
}
println("Instance size: $sparseArraySize bytes")

Result:



Instance size: 21 bytes

Nice, that's way less than the 32 bytes reported by JOL!

Let's look at the details of the reported fields:



val description = hprofFile.openHeapGraph().use { graph ->
  graph.findClassByName("android.util.SparseArray")!!
      .classHierarchy
      .flatMap { clazz ->
        clazz.readRecord().fields.map { field ->
          val fieldSize = if (field.type == REFERENCE_HPROF_TYPE)
            graph.identifierByteSize
          else
            byteSizeByHprofType.getValue(field.type)
          val typeName =
            if (field.type == REFERENCE_HPROF_TYPE)
              "REF"
            else
              primitiveTypeByHprofType.getValue(field.type).name
          val className = clazz.name
          val fieldName = clazz.instanceFieldName(field)
          "$fieldSize $typeName $className#$fieldName"
        }.asSequence()
      }.joinToString("\n")
}
println(description)

Result:



1 BOOLEAN android.util.SparseArray#mGarbage
4 REF android.util.SparseArray#mKeys
4 INT android.util.SparseArray#mSize
4 REF android.util.SparseArray#mValues
4 REF java.lang.Object#shadow$_klass_
4 INT java.lang.Object#shadow$_monitor_

So every SparseArray instance has a shallow size of 21 bytes, which includes 8 bytes from the Object class and 13 bytes for its own fields... and 0 bytes wasted!

Gaps and alignment

ClassLinker::LinkFields() in class_linker.cc determines the position of every field in memory, with the following rules:

The first N bytes are used to store the field values of the parent class, based on the parent Class::GetObjectSize(). N could be anything, even an odd number. If the parent class has gaps (unused bytes), these won't be touched.
Then fields are inserted, aligned on their size: longs are 8 byte aligned, ints are 4 byte aligned, etc.
The insertion order is references first, then primitive fields with largest field first. E.g. reference then long then int then char then boolean.
Because fields must be aligned on their own size, there may be gaps. Here's an example on a 32 bit ART VM:



open class Parent {
  val myChar = 'a'
  val myBool1 = true
  val myBool2 = false
}

class Child : Parent() {
  val ref1 = Any()
  val ref2 = Any()
  val myLong = 0L
}



# java.lang.Object is 8 bytes
4 REF     java.lang.Object#shadow$_klass_
4 INT     java.lang.Object#shadow$_monitor_
# com.example.Parent is 8 + 3 = 11 bytes
2 CHAR    com.example.Parent#myChar
1 BOOLEAN com.example.Parent#myBool1
1 BOOLEAN com.example.Parent#myBool2
# com.example.Child is 11 + 21 = 32 bytes
1 GAP for 4 byte alignment for refs
4 REF     com.example.Child#ref1
4 REF     com.example.Child#ref2
4 GAP for 8 byte alignment for long
8 LONG    com.example.Child#myLong

Here com.example.Child is 32 bytes which includes 5 bytes wasted for field alignment.

If a field can fit in an existing gap, that field gets moved forward:



open class Parent {
  val myChar = 0
  val myBool1 = true
  val myBool2 = false
}

class Child : Parent() {
  val ref1 = Any()
  val ref2 = Any()
  val myLong = 0L
  // Added myInt and myBool3
  val myInt = 0
  val myBool3 = true
}



# java.lang.Object is 8 bytes
4 REF     java.lang.Object#shadow$_klass_
4 INT     java.lang.Object#shadow$_monitor_
# com.example.Parent is 8 + 3 = 11 bytes
2 CHAR    com.example.Parent#myChar
1 BOOLEAN com.example.Parent#myBool1
1 BOOLEAN com.example.Parent#myBool2
# com.example.Child is 11 + 21 = still 32 bytes!
1 BOOLEAN com.example.Parent#myBool3 (1 byte gap)
4 REF     com.example.Child#ref1
4 REF     com.example.Child#ref2
4 INT     com.example.Child#myInt (4 byte gap)
8 LONG    com.example.Child#myLong

In this example we added an int and a boolean to Child and the instance size hasn't changed.

Conclusion

Unlike Open JDK heap dumps, Android heap dumps contain the actual size of instances in memory.
We only looked into instance size, on the latest Art implementation. It'd be interesting to do a similar investigation for class size and array size, and also see if the same results can be observed on Dalvik.
Reading the Android sources is fun! Even when, like me, you have no idea how C++ works. Comments, symbol names and git history usually provide enough details to figure it out.

Many thanks to Romain Guy, Jesse Wilson and Artem Chubaryan who sent me so many pointers and entertained my stupid ideas.

Android Vitals - First draw time 👩‍🎨

Py ⚔ — Sat, 29 Aug 2020 11:51:28 +0000

Header image: Light Field by Romain Guy.

This blog series is focused on stability and performance monitoring of Android apps in production. Last week, I wrote about how to best determine the app start time.

Today, we focus on determining the time at which cold start ends.

According to the Play Console documentation:

Startup times are tracked when the app's first frame completely loads.

We learn a bit more from the App startup cold time documentation:

Once the app process has completed the first draw, the system process swaps out the currently displayed background window, replacing it with the main activity. At this point, the user can start using the app.

In Android Vitals - Rising to the first drawn surface 🤽‍♂️, we learnt that:

ActivityThread.handleResumeActivity() schedules the first frame.
On the first frame Choreographer.doFrame() calls ViewRootImpl.doTraversal() which performs a measure pass, a layout pass, and finally the first draw pass on the view hierarchy.

First frame

Since API level 16, Android provides a simple API to schedule a callback when the next frame happens: Choreographer.postFrameCallback().

class MyApp : Application() {

  var firstFrameDoneMs: Long = 0

  override fun onCreate() {
    super.onCreate()
    Choreographer.getInstance().postFrameCallback {
      firstFrameDoneMs = SystemClock.uptimeMillis()
    }
  }
}

Unfortunately, calling Choreographer.postFrameCallback() has the side effect of scheduling a frame that runs before the first traversal is scheduled. So the time reported here is before the time of the frame that runs the first draw. I was able to reproduce this on API 25 but also noticed it doesn't happen in API 30, so this bug was probably fixed.

First draw

ViewTreeObserver

On Android, each view hierarchy has a ViewTreeObserver which can hold callbacks for global events such as layout or draw.

ViewTreeObserver.addOnDrawListener()

We can call ViewTreeObserver.addOnDrawListener() to register a draw listener:

view.viewTreeObserver.addOnDrawListener { 
  // report first draw
}

ViewTreeObserver.removeOnDrawListener()

We only care about the first draw, so we need to remove the OnDrawListener as soon as we've received a callback. Unfortunately, ViewTreeObserver.removeOnDrawListener() cannot be called from the onDraw() callback:

public final class ViewTreeObserver {
  public void removeOnDrawListener(OnDrawListener victim) {
    checkIsAlive();
    if (mInDispatchOnDraw) {
      throw new IllegalStateException(
          "Cannot call removeOnDrawListener inside of onDraw");
    }
    mOnDrawListeners.remove(victim);
  }
}

So we have to do the removal in a post:

class NextDrawListener(
  val view: View,
  val onDrawCallback: () -> Unit
) : OnDrawListener {

  val handler = Handler(Looper.getMainLooper())
  var invoked = false

  override fun onDraw() {
    if (invoked) return
    invoked = true
    onDrawCallback()
    handler.post {
      if (view.viewTreeObserver.isAlive) {
        viewTreeObserver.removeOnDrawListener(this)
      }
    }
  }

  companion object {
    fun View.onNextDraw(onDrawCallback: () -> Unit) {
      viewTreeObserver.addOnDrawListener(
        NextDrawListener(this, onDrawCallback)
      )
    }
  }
}

Notice the nice extension function:

view.onNextDraw { 
  // report first draw
}

FloatingTreeObserver

If we call View.getViewTreeObserver() before the view hierarchy is attached, there is no real ViewTreeObserver already available so the view will create a fake one to store the callbacks:

public class View {
  public ViewTreeObserver getViewTreeObserver() {
    if (mAttachInfo != null) {
      return mAttachInfo.mTreeObserver;
    }
    if (mFloatingTreeObserver == null) {
      mFloatingTreeObserver = new ViewTreeObserver(mContext);
    }
    return mFloatingTreeObserver;
  }
}

Then when the view is attached the callbacks are merged back into the real ViewTreeObserver.

That's nice, except there was a bug fixed in API 26: the draw listeners were not merged back into the real view tree observer.

We work around that by waiting until the view is attached before registering our draw listeners:

class NextDrawListener(
  val view: View,
  val onDrawCallback: () -> Unit
) : OnDrawListener {

  val handler = Handler(Looper.getMainLooper())
  var invoked = false

  override fun onDraw() {
    if (invoked) return
    invoked = true
    onDrawCallback()
    handler.post {
      if (view.viewTreeObserver.isAlive) {
        viewTreeObserver.removeOnDrawListener(this)
      }
    }
  }

  companion object {
    fun View.onNextDraw(onDrawCallback: () -> Unit) {
      if (viewTreeObserver.isAlive && isAttachedToWindow) {
        addNextDrawListener(onDrawCallback)
      } else {
        // Wait until attached
        addOnAttachStateChangeListener(
            object : OnAttachStateChangeListener {
          override fun onViewAttachedToWindow(v: View) {
            addNextDrawListener(onDrawCallback)
            removeOnAttachStateChangeListener(this)
          }

          override fun onViewDetachedFromWindow(v: View) = Unit
        })
      }
    }

    private fun View.addNextDrawListener(callback: () -> Unit) {
      viewTreeObserver.addOnDrawListener(
        NextDrawListener(this, callback)
      )
    }
  }
}

DecorView

Now that we have a nice utility to listen to the next draw, we can use it when an activity is created. Note that the first created activity may not draw: it's fairly common for apps to have a trampoline activity as launcher activity which immediately starts another activity and finishes itself. We register our draw listener on the activity window DecorView.

class MyApp : Application() {

  override fun onCreate() {
    super.onCreate()

    var firstDraw = false

    registerActivityLifecycleCallbacks(
      object : ActivityLifecycleCallbacks {
      override fun onActivityCreated(
        activity: Activity,
        savedInstanceState: Bundle?
      ) {
        if (firstDraw) return
        activity.window.decorView.onNextDraw {
          if (firstDraw) return
          firstDraw = true
          // report first draw
        }
      }
    })
  }
}

Locking window characteristics

According to the documentation for Window.getDecorView():

Note that calling this function for the first time "locks in" various window characteristics as described in setContentView().

Unfortunately, we're calling Window.getDecorView() from ActivityLifecycleCallbacks.onActivityCreated() which is called by Activity.onCreate(). In a typical activity, setContentView() is called after super.onCreate() so we're calling Window.getDecorView() before setContentView() is called, which has unexpected side effects.

We need to wait for setContentView() to be called before we retrieve the decor view.

Window.Callback.onContentChanged()

We can use Window.peekDecorView() to determine if we already have a decor view. If not, we can register a callback on our window, which provides the hook we need, Window.Callback.onContentChanged():

This hook is called whenever the content view of the screen changes (due to a call to Window#setContentView() or Window#addContentView()).

However, a window can only have one callback, and the activity already sets itself as the window callback. So we'll need to replace that callback and delegate to it.

Here's a utility class which does that and adds a Window.onDecorViewReady() extension function:

class WindowDelegateCallback constructor(
  private val delegate: Window.Callback
) : Window.Callback by delegate {

  val onContentChangedCallbacks = mutableListOf<() -> Boolean>()

  override fun onContentChanged() {
    onContentChangedCallbacks.removeAll { callback ->
      !callback()
    }
    delegate.onContentChanged()
  }

  companion object {
    fun Window.onDecorViewReady(callback: () -> Unit) {
      if (peekDecorView() == null) {
        onContentChanged {
          callback()
          return@onContentChanged false
        }
      } else {
        callback()
      }
    }

    fun Window.onContentChanged(block: () -> Boolean) {
      val callback = wrapCallback()
      callback.onContentChangedCallbacks += block
    }

    private fun Window.wrapCallback(): WindowDelegateCallback {
      val currentCallback = callback
      return if (currentCallback is WindowDelegateCallback) {
        currentCallback
      } else {
        val newCallback = WindowDelegateCallback(currentCallback)
        callback = newCallback
        newCallback
      }
    }
  }
}

Leveraging `Window.onDecorViewReady()`

Let's put it all together:

class MyApp : Application() {

  override fun onCreate() {
    super.onCreate()

    var firstDraw = false

    registerActivityLifecycleCallbacks(
      object : ActivityLifecycleCallbacks {
      override fun onActivityCreated(
        activity: Activity,
        savedInstanceState: Bundle?
      ) {
        if (firstDraw) return
        val window = activity.window
        window.onDecorViewReady {
          window.decorView.onNextDraw {
            if (firstDraw) return
            firstDraw = true
            // report first draw
          }
        }
      }
    })
  }
}

Not quite there yet

Let's look at the OnDrawListener.onDraw() documentation:

Callback method to be invoked when the view tree is about to be drawn.

Drawing can still take a while. We want to know when the drawing is done, not when it starts. Unfortunately, there is no ViewTreeObserver.OnPostDrawListener API.

In Android Vitals - Rising to the first drawn surface 🤽‍♂️, we learnt that the first frame and traversal all happen in just one MSG_DO_FRAME message. If we could determine when that message ends, we would know when we're done drawing.

Handler.postAtFrontOfQueue()

Instead of determining when the MSG_DO_FRAME message ends, we can detect when the next message starts by posting to the front of the message queue with Handler.postAtFrontOfQueue():

class MyApp : Application() {

  var firstDrawMs: Long = 0

  override fun onCreate() {
    super.onCreate()

    var firstDraw = false
    val handler = Handler()

    registerActivityLifecycleCallbacks(
      object : ActivityLifecycleCallbacks {
      override fun onActivityCreated(
        activity: Activity,
        savedInstanceState: Bundle?
      ) {
        if (firstDraw) return
        val window = activity.window
        window.onDecorViewReady {
          window.decorView.onNextDraw {
            if (firstDraw) return
            firstDraw = true
            handler.postAtFrontOfQueue {
              firstDrawMs = SystemClock.uptimeMillis()
            }
          }
        }
      }
    })
  }
}

Edit: I measured the time difference between the first onNextDraw() and the following postAtFrontOfQueue() in production on a large number of devices, here are the results:

10th percentile: 25ms
25th percentile: 37ms
50th percentile: 61ms
75th percentile: 109ms
90th percentile: 194ms

That interval is significant enough to not be left out.

Conclusion

We now have everything we need to monitor cold start times in production:

In Why did my process start? 🌄 we learnt how to detect a cold start.
In When did my app start? ⏱ we learnt how to determine the app start time.
In this blog we learnt how to determine the first draw time.

I hope you enjoyed these deep dives, stay tuned for more!

// Detect dark theme var iframe = document.getElementById('tweet-1291126907426099200-671'); if (document.body.className.includes('dark-theme')) { iframe.src = "https://platform.twitter.com/embed/Tweet.html?id=1291126907426099200&theme=dark" }

Android Vitals - When did my app start? ⏱

Py ⚔ — Fri, 21 Aug 2020 21:01:05 +0000

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.

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()
    );
    ...
  } 
}

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.

Android Vitals - Why did my process start? 🌄

Py ⚔ — Sat, 15 Aug 2020 14:06:06 +0000

Header image: Windmill Sunrise by Romain Guy.

This blog series is focused on stability and performance monitoring of Android apps in production. Last week, I wrote about how to determine if an app start is a cold start:

If we post a message and no activity was created when that message runs, then we know this isn't a cold start, even if an activity is eventually launched 20 seconds later.

class MyApp : Application() {

  override fun onCreate() {
    super.onCreate()

    var firstActivityCreated = false

    registerActivityLifecycleCallbacks(object :
        ActivityLifecycleCallbacks {

      override fun onActivityCreated(
          activity: Activity,
          savedInstanceState: Bundle?
      ) {
        if (firstActivityCreated) {
          return
        }
        firstActivityCreated = true
      }
    })
    Handler().post {
      if (firstActivityCreated) {
        // TODO Report cold start
      }
    }
  }
}

With this approach, we must wait for an activity to be launched or that message to run before we know if an app start is a cold start. Sometimes it would be useful to know that from within Application.onCreate(). For example, we might want to preload resources asynchronously to optimize cold start:

class MyApp : Application() {

  override fun onCreate() {
    super.onCreate()

    if (isColdStart()) {
      preloadDataForUiAsync()
    }
  }
}

Process importance

While there is no Android API to know why a process was started, there is one to know why a process is still running: RunningAppProcessInfo.importance, which we can read from ActivityManager.getMyMemoryState(). According to the Processes and Application Lifecycle documentation:

To determine which processes should be killed when low on memory, Android places each process into an "importance hierarchy" based on the components running in them and the state of those components. [...] When deciding how to classify a process, the system will base its decision on the most important level found among all the components currently active in the process.

Right when the process starts, we could check its importance. If the importance is IMPORTANCE_FOREGROUND, it must be a cold start:

class MyApp : Application() {

  override fun onCreate() {
    super.onCreate()

    if (isForegroundProcess()) {
      preloadDataForUiAsync()
    }
  }

  private fun isForegroundProcess(): Boolean {
    val processInfo = ActivityManager.RunningAppProcessInfo()
    ActivityManager.getMyMemoryState(processInfo)
    return processInfo.importance == IMPORTANCE_FOREGROUND
  }
}

Confirming with data

I implemented cold start detection with both approaches in a sample app and got identical results either way. I then added the detection code to a production app with enough installs to provide meaningful results. Here are the (anonymized) results:

This pie chart includes only app startups where an activity was created before the first post.

97.4% had an importance of 100, i.e. IMPORTANCE_FOREGROUND.
2.4% had an importance of 400, i.e. IMPORTANCE_CACHED (previously named IMPORTANCE_BACKGROUND).
0.2% map to other importances.

Let's look at that data from another angle: given a specific importance, how often was an activity created before the first post?

When startup importance is 100 there's always an activity created before first post. And when an activity is created before first post, 97.4% of the time the importance is 100.
When startup importance is 400 there's almost never an activity created before first post. Almost never is not never, there are still enough cases that when an activity is created before first post, 2.4% of the time the importance is 400.

The most likely explanation for the 2.4% with importance 400 is that those were not cold starts, however the system received a query to start an activity almost immediately after the process started, right when running Application.onCreate() but before we had a chance to add our first post.

Edit: I logged the importance after first post and compared that to the importance on app start. My data showed that 74% of app starts where an activity was created before first post and the start process importance was not 100 had that process importance changed to 100 after first post. This seem to confirm the theory that the system decided to start the activity after the app had already began to start.

Conclusion

We can combine our findings from the previous post to determine cold start accurately. A cold start:

Has a process importance of IMPORTANCE_FOREGROUND on app startup.
Has the first activity created before the first post is dequeued.
Has the first activity created with a null bundle.

Here's the updated code:

class MyApp : Application() {

  override fun onCreate() {
    super.onCreate()

    if (isForegroundProcess()) {
      var firstPostEnqueued = true
      Handler().post {
        firstPostEnqueued = false
      }
      registerActivityLifecycleCallbacks(object :
          ActivityLifecycleCallbacks {

        override fun onActivityCreated(
            activity: Activity,
            savedInstanceState: Bundle?
        ) {
          unregisterActivityLifecycleCallbacks(this)
          if (firstPostEnqueued && savedInstanceState == null) {
            // TODO Report cold start
          }
        }
      })
    }
  }

  private fun isForegroundProcess(): Boolean {
    val processInfo = ActivityManager.RunningAppProcessInfo()
    ActivityManager.getMyMemoryState(processInfo)
    return processInfo.importance == IMPORTANCE_FOREGROUND
  }
}

I hope you're enjoying these investigations!

Py ⚔

@piwai

Android Vitals, a thread!

I'm writing a blog series focused on stability and performance monitoring of Android apps in production.

I'll update this thread with links to new articles as I publish them.

Check in every week for new content!

🧵⬇️⬇️⬇️⬇️⬇️⬇️🧵

21:40 PM - 05 Aug 2020

0 2

Android Vitals - Is this a cold start? 🦋

Py ⚔ — Wed, 05 Aug 2020 22:00:07 +0000

Header image: Follow the Light by Romain Guy.

This blog series is focused on stability and performance monitoring of Android apps in production. In the last 2 posts, I wrote about what happens from when the user taps a launcher icon to when the first activity is drawn.

A cold start is an activity launch where the app process starts from scratch in response to an intent to start an activity. According to the App startup time documentation:

This type of start presents the greatest challenge in terms of minimizing startup time, because the system and app have more work to do than in the other launch states.
We recommend that you always optimize based on an assumption of a cold start. Doing so can improve the performance of warm and hot starts, as well.

To optimize cold start, we need to measure it, which means we need to monitor cold start times in production.

Unfortunately, there is no Activity.isThisAColdStart() API on Android. This is by design: the Activity lifecycle APIs indicate when to save and restore state and abstract away the death and rebirth of processes. The engineers who designed the Android APIs didn't want us to write overly complex code with special cases for all the various ways an activity can be started. So there's no API.

How are we supposed to monitor cold start if we can't tell a cold start from any other process start?

This post leverages what we learnt from our previous deep dives on cold start to start building out our own version of the missing Activity.isThisAColdStart() API.

Traditional approach

Most apps and libraries report a cold start if the first activity was created within a minute of the app start. It looks something like this:

class MyApp : Application() {

  override fun onCreate() {
    super.onCreate()

    val appCreateMs = SystemClock.uptimeMillis()

    var firstActivityCreated = false

    registerActivityLifecycleCallbacks(object :
        ActivityLifecycleCallbacks {
      override fun onActivityCreated(
          activity: Activity,
          savedInstanceState: Bundle?
      ) {
        if (firstActivityCreated) {
          return
        }
        firstActivityCreated = true
        val activityCreateMs = SystemClock.uptimeMillis()
        if (activityCreateMs - appCreateMs < 60_000) {
          // TODO Report cold start
        }
      }
    })
  }
}

Unfortunately, this approach also includes cases where the app process was started to respond to a broadcast receiver, a content provider query or to start a service, and then an activity was launched sometimes later within the first minute. We should exclude these cases from our cold start monitoring to avoid skewing our results.

Leveraging our research

In the previous blog post, we learnt that:

When the app process starts, it calls ActivityThread.main() which makes a blocking IPC call to ActivityManagerService.attachApplication() in the system_server process.
The system_server process makes an IPC call to ActivityThread.bindApplication() in the app process which enqueues a BIND_APPLICATION message to the main thread message queue.
Then, for each activity that needs to launch, the system_server process makes an IPC call to ActivityThread.scheduleTransaction() in the app process which enqueues an EXECUTE_TRANSACTION message to the main thread message queue.
When the IPC call to ActivityManagerService.attachApplication() is done, ActivityThread.main() then calls Looper.loop() which loops forever, processing messages posted to its MessageQueue.
The first message processed is BIND_APPLICATION, which calls ActivityThread.handleBindApplication() which calls Application.onCreate().
The next message processed is EXECUTE_TRANSACTION which calls TransactionExecutor.execute() which launches the activity.

This means that in Application.onCreate(), the main thread message queue already has the EXECUTE_TRANSACTION message enqueued. If we post a new message from Application.onCreate(), it will execute after EXECUTE_TRANSACTION and therefore after the activity has been created. If we post a message and no activity was created when it executes, then we know this isn't a cold start, even if an activity is eventually launched 20 seconds later.

Here's how we can detect a cold start:

class MyApp : Application() {

  override fun onCreate() {
    super.onCreate()

    var firstActivityCreated = false

    registerActivityLifecycleCallbacks(object :
        ActivityLifecycleCallbacks {

      override fun onActivityCreated(
          activity: Activity,
          savedInstanceState: Bundle?
      ) {
        if (firstActivityCreated) {
          return
        }
        firstActivityCreated = true
      }
    })
    Handler().post {
      if (firstActivityCreated) {
        // TODO Report cold start
      }
    }
  }
}

Lukewarm start

According to the App startup time documentation:

There are many potential states that could be considered warm starts. For instance:

The user backs out of your app, but then re-launches it. The process may have continued to run, but the app must recreate the activity from scratch via a call to onCreate().

The system evicts your app from memory, and then the user re-launches it. The process and the activity need to be restarted, but the task can benefit somewhat from the saved instance state bundle passed into onCreate().

So if the activity is created with a saved instance state bundle, then that shouldn't be considered a cold start. However, since the process needs to be restarted, there's still a lot more work to do than just creating an activity. Let's call this a lukewarm start.

We can update our code to take this into account:

class MyApp : Application() {

  override fun onCreate() {
    super.onCreate()

    var firstActivityCreated = false
    var hasSavedState = false

    registerActivityLifecycleCallbacks(object :
        ActivityLifecycleCallbacks {

      override fun onActivityCreated(
          activity: Activity,
          savedInstanceState: Bundle?
      ) {
        if (firstActivityCreated) {
          return
        }
        firstActivityCreated = true
        hasSavedState = savedInstanceState != null
      }
    })
    Handler().post {
      if (firstActivityCreated) {
        if (hasSavedState) {
          // TODO Report lukewarm start
        } else {
          // TODO Report cold start
        }
      }
    }
  }
}

Conclusion

The Android framework team doesn't want us to think too hard about process start and activity launch, yet the Android app performance team insists that we optimize cold start. Challenge accepted! We're starting to shape our own version of the missing Activity.isThisAColdStart() API, but we're far from done. Stay tuned for more!

// Detect dark theme var iframe = document.getElementById('tweet-1291126907426099200-759'); if (document.body.className.includes('dark-theme')) { iframe.src = "https://platform.twitter.com/embed/Tweet.html?id=1291126907426099200&theme=dark" }

DEV Community: Py ⚔

Leak investigation: Rx disposal race in SQLDelight

Take aways

Tap Response Time: Jetpack Navigation 🗺

🗺 Navigation library

Advanced Navigation Sample

From Tap to Render

Main thread tracing

Systrace

Tap Response Time

Step 1: Up dispatch

Step 2: Click listener & navigation

Step 3: Fragment transaction

Step 4: Frame & view hierarchy traversal

Step 5: RenderThread

Step 6: SurfaceFlinger

Result

Conclusion

Android Vitals - Tap Response Time 👉

💡 Did you know?

👉📱

🎓 Tap Response Time

Naive Tap Response Time

⌛️ Negative time

📈 Large codebases

👉 Touch pipeline

💡 Did you know?

💡 Did you know?

📱 Traversal and rendering

🤔 What now?

Waldo, where's my UI?

The problem with no-code tests

Apparently Waldo is different

Messing with Waldo

Tab swap

Changing strings

Changing everything else

Ok but I really want to break it

Conclusion

Android Vitals - How adb measures App Startup 🔎

What does ActivityTaskManager measure exactly?

ActivityTaskManager log

Debugging system_process

Reading the stacktraces

App startup time

How much time is ActivityTaskManager adding?

Results

Measuring app startup time from within the app

Conclusion

Android Vitals - Profiling App Startup 🔬

Start recording on app startup

Profiling release builds

1. Create a debuggable release build

2. Profile on a rooted device

3. Use simpleperf on Android Q

Profiling a downloaded APK

Android Studio profiler slows everything down

Profiling from code

When to start recording

Before Android P / API < 28

Android P+ / API 28+

Where to store traces

When to stop recording

Profiling with Nanoscope

App Startup steps

Conclusion

Leak detection: Android Studio vs LeakCanary ⚔️

False positive leaks in Android Studio

Android Studio leak filtering

How LeakCanary finds fragment leaks

Why LeakCanary reports more leaks

Conclusion

The real size of Android objects 📏

One cannot trust a shallow size

Read the Source, Luke

JVM TI

Instance size

Instance allocation

Class linking

Back to heap dumps

What does `ActivityTaskManager` measure exactly?

`ActivityTaskManager` log

Debugging `system_process`

How much time is `ActivityTaskManager` adding?

Leveraging `Window.onDecorViewReady()`