Time code execution in Android

What is the easiest to time execution in Android?

I have looked around a bit and I found TimingLogger on the Android SDK, and instructions h开发者_JS百科ere. It looks very convenient. But I can't get it work. This is my code:

TimingLogger timings = new TimingLogger("TopicLogTag", "Parsing html");
   My code to time here...
timings.dumpToLog();

It's supposed to dump the times in LogCat. But I can't see anything.. I What am I doing wrong? Eclipse doesn't show any varnings. I guess it has something with verbose ouput, but I have set LogCat to show Verbose. Thank you..

I gave it a test run and I am experiencing the same thing. It all boils down to this little bit of the description in the Javadoc for TimingLogger:

If the Log.isLoggable is not enabled to at least the Log.VERBOSE level for that tag at creation time then the addSplit and dumpToLog call will do nothing.

I did a test locally:

TimingLogger timings = new TimingLogger("MyTag", "Initialization");
Log.d("MyTag", "Is Loggable? " + Log.isLoggable("MyTag", Log.VERBOSE));
timings.dumpToLog();

And oddly, I get an output to the log:

06-28 08:35:18.693: DEBUG/MyTag(24366): Is Loggable? false

But that's it. And since it's false, I doubt TimingLogger is doing anything, based on the TimingLogger code:

  90     /**
  91      * Clear and initialize a TimingLogger object that will log using
  92      * the tag and label that was specified previously, either via
  93      * the constructor or a call to reset(tag, label). If the
  94      * Log.isLoggable is not enabled to at least the Log.VERBOSE
  95      * level for that tag at creation time then the addSplit and
  96      * dumpToLog call will do nothing.
  97      */
  98     public void reset() {
  99         mDisabled = !Log.isLoggable(mTag, Log.VERBOSE);
 100         if (mDisabled) return;
 101         if (mSplits == null) {
 102             mSplits = new ArrayList<Long>();
 103             mSplitLabels = new ArrayList<String>();
 104         } else {
 105             mSplits.clear();
 106             mSplitLabels.clear();
 107         }
 108         addSplit(null);
 109     }

I'm not sure why Log.isLoggable is returning false when it's obviously logging at above VERBOSE, since my Log.d obviously logged.

You can enable logging for that tag manually from the [Log class Javadoc][3]:

You can change the default level by setting a system property: 'setprop log.tag. ' Where level is either VERBOSE, DEBUG, INFO, WARN, ERROR, ASSERT, or SUPPRESS. SUPPRESS will turn off all logging for your tag. You can also create a local.prop file that with the following in it: 'log.tag.=' and place that in /data/local.prop.

Which I did through adb shell:

$ adb shell
# setprop
usage: setprop <key> <value>
# setprop log.tag.MyTag VERBOSE
# 

Results in:

06-28 08:53:42.447: DEBUG/MyTag(24739): Is Loggable? true
06-28 08:53:44.744: DEBUG/MyTag(24739): Initialization: begin
06-28 08:53:44.744: DEBUG/MyTag(24739): Initialization: end, 0 ms

See droidgren's comment on this answer - apparently a call to addSplit is also necessary.

[3]: http://developer.android.com/reference/android/util/Log.html#isLoggable(java.lang.String, int)

I found another more simple solution which measures the exact same time as TimingLogger, which doesn't require setprop.

private long startnow;
private long endnow;

startnow = android.os.SystemClock.uptimeMillis();
*Your time consuming code here*
endnow = android.os.SystemClock.uptimeMillis();
Log.d("MYTAG", "Execution time: " + (endnow - startnow) + " ms");

If you guys take a look at its source code, actually the implementation for the TimingLogger class is quite simple.

So what I did, which perfectly fits for my use case, was to make my own version of the class but changing the reset() method to

public void reset() {
    mDisabled = false; // <- This is what has changed.
    if (mDisabled) return;
    if (mSplits == null) {
        mSplits = new ArrayList<Long>();
        mSplitLabels = new ArrayList<String>();
    } else {
        mSplits.clear();
        mSplitLabels.clear();
    }
    addSplit(null);
}

The catch here is changing from

mDisabled = !Log.isLoggable(mTag, Log.VERBOSE);

to

mDisabled = false;

This way we don't have to mess with adb.

If you simply looking for logs as explained in developer.android.com, you will not be able to see logs. So use below command:

1. adb shell setprop log.tag.MyTag VERBOSE

Note: MyTag is the first parameter you passed when creating new TimingLogger as below:

TimingLogger timings = new TimingLogger("MyTag", "MyMethodName");

For your questions's answer, you should execute below command: adb shell setprop log.tag.TopicLogTag VERBOSE

And there you are. Happy coding !!!

Sometimes we don't need to know the exact time that took us an operation but we want to know, why that operation took so long. Thus, for speeding up code, we only need to know some kind of relational order of parts of that operation where the one taking up the most time seems to be the one you should optimize. Therefore, android brings method tracing:

Debug.startMethodTracing("YOUR_TRACE_FILE_NAME");

// Do your operations

Debug.stopMethodTracing();

Then, the os writes the trace file containing all call infos to filesystem. Simply drag'n'drop that file onto traceview.bat and start inspecting what calls took how long.

Benefits:

• You can inspect all called functions and methods that have been called while tracing.
• No need to synchronize data for multithreaded apps.
• Trace is written to file automatically - no log cat magic or whatever is necessary. All data is encapsulated together, ready to be inspected.
• As soon as you start adding time measuring and especially logging, you wreck your timing anyways.

Link: http://developer.android.com/tools/debugging/debugging-tracing.html

Try doing:

adb shell logcat