Learning by Example

TimingLogger: An idiomatic Android approach to measuring execution time

During your career as an Android developer you will eventually encounter some less than optimal performing code. Maybe this is code that you authored or maybe this is code that you inherited, but its origin story does not really matter. The code is now under your stewardship and your team and your users are looking at you, the ever consummate Android rockstar, to solve the performance problems that are plaguing the app.

There are several different approaches that a developer slinging Android code can take to measure the performance of a block of code. Since many Android developers come from a background in Java programming, one of the more common tactics that you will see is to surround the suspicious code with calls to System.nanoTime() as shown below:

// capture the start time
val startTime = System.nanoTime()

// suspiciously long running block of code
var number = 0L
for (x in 0..10_000_000)
    number += x

// capture the end time
val endTime = System.nanoTime()

// dump the execution time out
Log.d("TimingLoggerDemo","${TimeUnit.MILLISECONDS.convert(endTime -
        startTime, TimeUnit.NANOSECONDS)} ms, (1)")

This is fine and it will certainly get the job done, but in most cases the method that you are profiling will have more than one potential call out or block of code in it that may be the source of the execution time sink. A quick look at the following example demonstrates how using System.nanoTime() or one of its variants (e.g. System.elapsedTime()) can quickly become unwieldy:

// capture the start time
var startTime = System.nanoTime()

// suspiciously long running block of code
var number = 0L
for (x in 0..10_000_000)
    number += x

// capture the end time
var endTime = System.nanoTime()

// dump the execution time out
Log.d("TimingLoggerDemo","${TimeUnit.MILLISECONDS.convert(endTime -
        startTime, TimeUnit.NANOSECONDS)} ms, (1)")

// capture the start time
startTime = System.nanoTime()

// another suspiciously long running block of code
callSomeMethod()

// capture the end time
endTime = System.nanoTime()

// dump the execution time out again
Log.d("TimingLoggerDemo","${TimeUnit.MILLISECONDS.convert(endTime -
        startTime…