Meet Microsoft Snippet — an Android Library for Measuring Code Execution Time

Improve the performance of your apps

Photo by Andrik Langfield on Unsplash

While we write Android apps, we have to take care of performance. And pre-requisite to performance improvement is measurement. So I tried to explore the options that we had already. Below were my requirements,

1. A tool that could give the execution duration of a snippet of code that would range from multiple methods to multiple files.
2. A tool that could strip off the boilerplate code that we have to write to do the measurements and log it.
3. Once you add all the code to do the measurements, you can’t check in the code in your repository for obvious reasons. It would make the code base dirty.

I found a couple of solutions:

1. Hugo — This is a small library written by Jake Wharton, that can measure the time taken to execute a method that is annotated by the library. But there was a limitation that, you can only measure methods. What if my use case starts from the middle of a method and ends in a different method may be in the same or different class file. Use case-based measurement was not possible here.
2. Android profiler — This did not represent the actual execution time that the user is going to experience, this slows down the entire app. Moreover, the problem was, it needed a lot of effort and it slowed down the system also when android studio and emulators are already running. It would emit a lot of data that is not required for my use case.
3. TimeLogger class — Android had provided a time logger class that had some kind of functionality that I was looking for but not completely, it was deprecated too. So I dropped the idea.
4. Measuring on my own — A lot of code needs to be added for noting the start time and end time, and then we have to remove the code also. That would make the code base dirty and reviewers angry.

So finally I thought of building something that could:

1. Reduce the boilerplate code that is required to do the measurement, and also log in to the console.
2. Be shipped to production without hampering the code quality.
3. Tag use cases with the measurements and build gates that could detect regressions with the gathered data. [ gates are frameworks that take the historical data into account spread across different commits over time and try to detect regressions. They work best when we have a rooted device with locked clock frequencies.]
4. Deep dive between a start and end markers of a measurement.
5. Someone could extend the functionality and use the gathered data in a way they want, rather than just logging on logcat.

After 3 weeks of brainstorming and coding Snippet was born.

It provides a clean API to solve our problems. You can find it here. It not only measures the execution time but logs it along with all the surrounding execution context, like class, method, line, thread, etc without we doing any thing extra.

GitHub - microsoft/snippet-timekeeper: An android library to measure code execution time. No need…

To add Snippet to your project, add the below code to the app-level build.gradle:

allprojects {
    repositories {
        maven { url 'https://jitpack.io' }
    }
}

and, to your project-level build.gradle add the below code and replace version(v1.0) with the tag for the release that you want. You can find release tags in the release section of the repository.

dependencies {
    implementation 'com.github.microsoft:snippet-timekeeper:v1.0'
}

It is super easy to set up. If you want your library to do the measurements only in the debug builds, install an instance of MeasuredExecutionPath in Snippet.install(executionPath). All other build types(until and unless specified) will use the default ReleaseExecutionPath that is no-op path. It is advised to do this as soon as possible to make sure you can use Snippet in early executions.

With the above setup, none of your library code will run in the release builds. Everything will be in debug and in release builds library becomes a no-op.

Now comes the part, where we do the measurements.

Suppose you have a sequential code that needs to be measured you can directly pass that as a lambda as below

Demo for Snippet.capture(closure)

Just doing that does the measurement captures the context of the call and prints all the details on the logcat.

Suppose I want to measure the launch time of the application till the onStart() callback fires — I’ll have to start the measurement in the Application class and will have to end the measurement in the activity class. It is not possible through the lambda approach that we discussed above. So we have something called LogToken that takes care of that( more on this later).

We can tag the measurement, the tag needs to be unique.

1. Just start the measurement with a tag and,
2. Find that tag from any place in the code base and end the measurement.

Let’s see that in action. We start the measurement on line:12. We will then find the tag and end the measurement.

Start the tag based measurement in Application class

End the tag based measurement in Activity class

Note: If you are thinking what would happen if a measurement Snippet.startCapture(tag) call does not happen in warm launch cases, and when the activity is launched it calls, Snippet.find(tag).endCapture(). Would it crash? Would it show garbage data?

Answer is no.

Snippet understands that in Android, these things could happen, and end() can be called without start() getting called even under correct user scenarios. That is why it internally makes all such calls no-op. It will not do anything.

This tag based API can also be used to tag your business use cases, like sign-in, user data sync, etc and you can extend the MeasuredExecutionPath to log this data to a file or DB and could build performance gates out of it to detect regression. If a new code will be added in that path, you would know that. Please check out the repo and to see how ExecutionPath can be extended.

Log Tokens

When we do the measurements sometimes, the code is not sequential as in when dealing with callback hells, where we have nested callbacks. We cannot pass everything as a lambda.

So, the moment you call Snippet.startCapture() it returns you with a log token representing the measurement. You can call endCapture method on that when you want to end the measurement.

find() API also works on log tokens internally. LogToken is useful because, in multiple threading scenarios, tags will not work as each tag is associated with on log token. If you are starting n parallel operations, you need to track each with a separate log token. That is when you directly need to use log tokens.

The below example is not the perfect one to show, but should suffice in showcasing how the API works.

override fun loadNewsFeed() {
    val token = Snippet.startCapture()
    disposables.add(repository.getNewsFeedSingle()
        .compose(schedulerProvider.ioToMainSingleScheduler())

        .doOnSubscribe { liveNewsFeed.value = NewsFeedActivityViewModel.Response(LOADING,null) }
        .doOnError { liveNewsFeed.value = NewsFeedActivityViewModel.Response(ERROR, null) }

        .map { feedListFromRepo -> mapNewsFeedToUIState(feedListFromRepo) }
        .subscribe { listOfFeeds, throwable ->
            if (listOfFeeds != null) {
                liveNewsFeed.value = NewsFeedActivityViewModel.Response(SUCCESS, listOfFeeds)
                token.endCapture();
            }
            if (throwable != null) {
                Timber.e("Not able to load feeds. Possible Cause: $throwable")
            }
        })
}

ExecutionPath

If you need to do custom work along with what Snippet does, you can extend the functionality. It is demonstrated in detail in the repository readme with a sample.

Splits

Sometimes we also need to deep dive into what is happening between start() and end() capture.

For that snippet has splits that can measure small sections within the captures. Just get a hold of the log token and call addSplit() on that. It will measure the amount of time that passed b/w the time when last time addSplit() was called and now.

Once the calculation is ended using endCapture() it also presents a Split summary to show a birds eye view of the measurements like below.

Split summary.

There are other features also that are there in Snippet, but we will deal with that in some other post.