51

What is best method to measure execution time of Android code snippet?

I have a section of code before and after which I want to place timestamps to find out it's execution time (e.g. one in onCreate() and another in onDestroy() method of activity).

I have tried Time.toMillies(false), but it only returns seconds to me (with constant 000 at the end). I also tried two java functions: System.currentTimeMillis() and System.nanoTime(). First one returns milliseconds of epoch time, second doesn't.

What would be the best way to measure execution time and get good precision?

Prophet
  • 32,350
  • 22
  • 54
  • 79
22332112
  • 2,337
  • 5
  • 21
  • 42

7 Answers7

98

What about TimingLogger?

From TimingLogger documentation:

TimingLogger timings = new TimingLogger(YOUR_TAG, "methodA");
// ... do some work A ... 
timings.addSplit("work A");
// ... do some work B ... 
timings.addSplit("work B");
// ... do some work C ... 
timings.addSplit("work C");
timings.dumpToLog();

and the dump will look like:

     D/TAG     (3459): methodA: begin
     D/TAG     (3459): methodA:      9 ms, work A
     D/TAG     (3459): methodA:      1 ms, work B
     D/TAG     (3459): methodA:      6 ms, work C
     D/TAG     (3459): methodA: end, 16 ms

Do not forget to enable your tag by running: adb shell setprop log.tag.YOUR_TAG VERBOSE

Stephen C
  • 698,415
  • 94
  • 811
  • 1,216
MikeL
  • 5,385
  • 42
  • 41
27

What would be the best way to measure execution time

System.nanoTime() is probably a good choice. Jake Wharton is using that with Hugo, for example.

and get good precision

This is not strictly possible, as anything can happen on the device while your method is executing. Those external factors will affect your time measurements, by stealing away CPU time, tying up I/O channels, etc. You need to average your tests across several runs to try to average out those external factors, and accuracy/precision will suffer as a result.

And, as Marcin Orlowski notes, to actually figure out why you are consuming certain amounts of time, use Traceview.

CommonsWare
  • 986,068
  • 189
  • 2,389
  • 2,491
19

Kotlin Developers

To get the elapsed time in MilliSeconds:

val elapsedTime= measureTimeMillis {
            // call you method from here or add any other statements
} 

To get the time in NanoSeconds:

val elapsedTime= measureNanoTime {
            // call you method from here or add any other statements
}
Suraj Vaishnav
  • 7,777
  • 4
  • 43
  • 46
11

I usually use System.nanoTime() for quick Measurement.

A simple Setup like this

   val startTime =   System.nanoTime()

    //DO SOMETHING

   Log.e("Measure", TASK took : " +  ((System.nanoTime()-startTime)/1000000)+ "mS\n")
Hitesh Sahu
  • 41,955
  • 17
  • 205
  • 154
8

What you ask about is called profiling, and there're tools to help you with that on Android as well. See article Profiling with Traceview and dmtracedump on official developer site.

Marcin Orlowski
  • 72,056
  • 11
  • 123
  • 141
  • 1
    totally agree, although when in profiling mode the app is slower, the information about thread, methods and percentage of time spent on them is worth it. Otherwise, I'd say System.currentTimeMillis() is what he wants. – shalafi May 28 '14 at 14:07
0

Posting answer for folks developing android applications with Kotlin; also this is the only answer that comes up in search as first main result for code performance of Kotlin in android.

A simple Kotlin answer is already present on this thread for measuring perf in ms and nanosec - but my solution will help folks who want to log and execute function inline same time after execution completes, also is a cleaner approach when there is multiple performance measurement involved of different functions

Create functions as such:

//the inline performance measurement method
private inline fun <T> measurePerformanceInMS(
        logger: (Long) -> Unit,
        function: () -> T)
: T {
    val startTime = System.currentTimeMillis()
    val result: T = function.invoke()
    val endTime = System.currentTimeMillis()
    logger.invoke( endTime - startTime)
    return result
}

//the logger function
fun logPerf(time: Long){
    Log.d("TAG","PERFORMANCE IN MS: $time ms ")
}

//the function whose performance needs to be checked
fun longRunningFunction() : Int{
    var x = 0
    for (i in 1..20000) x++
    return x
}

This way you can keep logging, performance computation and function execution under a single function call and no code replication needed.

If you require nano second measurement then use System.nanoTime()

USAGE :

val endResult = measurePerformanceInMS({time -> logPerf(time)}){
            longRunningFunction()
        }

NOTE : here the 'endResult' will carry the result of function whose performance was being measured.

MDT
  • 1,535
  • 3
  • 16
  • 29
0

Adding to the above answers there is a library called Snippet that could be used to measure the execution times. It also takes care of logging and putting all the relevant execution on the logs. It also takes care of measuring non contiguous spans of code, that could span across multiple methods and even files. Below is how it deals with contiguous code. We can add splits within a measurement too.

@Override  
protected void onCreate(@Nullable Bundle savedInstanceState) {  
    // The capture API can be used to measure the code that can be passed as a lambda.  
    // Adding this lambda captures the class, line, thread etc automatically into the logcat.
    // This cannot be use for code that returns a value as the lambda declared for closure is 
    // is a non returning lambda. For the case that could return a value and are a little complex // use the log-token based API demonstrated below.  
    
    // Captures the code as a lambda.  
    Snippet.capture(()-> super.onCreate(savedInstanceState)); 
}

The code will also become no-op in the release builds.

To configure it, just add the below code in the application onCreate() as early as possible.

if(BuildConfig.DEBUG) {             
        Snippet.install(new Snippet.MeasuredExecutionPath());      
        Snippet.newFilter("SampleFilter");      
        Snippet.addFlag(Snippet.FLAG_METADATA_LINE | Snippet.FLAG_METADATA_THREAD_INFO);      
} 

https://github.com/microsoft/snippet-timekeeper

vishal_ratna
  • 116
  • 1
  • 5