Learning by Example

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, TimeUnit.NANOSECONDS)} ms, (2)")

...and on and on for each possible culprit

Thankfully Android has a simpler, more concise, and more idiomatic class available in its utility package for profiling a questionable method such as the one above. Introducing (or perhaps reintroducing since it has been available since API Level 1), the TimingLogger class!

Crowd Reacts Upon Hearing of the TimingLogger Class

Let’s rewrite the sample above, but this time we will leverage the TimingLogger class to capture the execution time measurement. Shall we? Yes, yes we shall:

// instantiate a timing logger

val timingLogger = TimingLogger("TimingLoggerDemo", "")



// suspiciously long running block of code

var number = 0L

for (x in 0..10_000_000)

number += x

timingLogger.addSplit("(1)")



// another suspiciously long running block of code

callSomeMethod()

timingLogger.addSplit("(2)")



// dump all of the execution times out

timingLogger.dumpToLog()

And the output of running the code above is as follows:

TimingLogger Output

So basically you just instantiate a TimingLogger object and then call out to the addSplit(split-label) method for each piece of code that you want to measure. Once you’ve got all of your banana splits in place you call dumpToLog() to write the measurements out to logcat.

🔔 One common pitfall of the TimingLogger class is that, by default, it will not produce any output. To see the output you must set the logging level of the tag specified during class instantiation to VERBOSE. In our sample code we specified a tag of “TimingLoggerDemo” and so the following command must be executed through a terminal in order to see the output from our sample.