Time code execution in Android

Question

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 here. 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 is supposed to dump the times in in LogCat. But I can't see nothing.. 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..

Answer 1

Try doing:

adb shell logcat

Answer 2

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

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

Answer 3

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

private long startnow;
private long endnow;

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