Android小技巧——利用TimingLogger打印程序的执行时间

  在移动设备上运行的程序，我们一般都比较关注它所耗的性能，所以，在写Android程序的时候，有时候我们会看某个操作用了多长时间。一般的做法是，在这个操作之前获取一下系统的时间，然后在这个操作之后在获取一下系统时间，然后取差值。这么做并没有什么错，其实，Android的开发者已经给我们封装好了一个类，那就是TimingLogger类，使用它可以很方便地打印某个操作的耗时。

  它的用法很简单，下面的源码注释中有：

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

  所以呢，使用它分3步：

new一个TimiLogger对象；

在需要打印时间的地方调用addSplit(String splitLabel)方法;

调用dumpToLog()打印日志。

  还是举个栗子吧，看看1000000次空循环会用多长时间：

TimingLogger timing = new TimingLogger("timing","loop");
for (int i=0;i<1000000;) {
i++;
}
timing.addSplit("end loop");
timing.dumpToLog();

  打印出来的日志是这个格式的：



  用了1ms，还挺快。但是，使用的时候会发现，貌似打印不出log，没关系，在命令行输入这条命令：

adb shell setprop log.tag.timing VERBOSE

  这条命令的意思是，把TAG为timing的这条log级别设置为VERBOSE，在v以上的Log都能打印出来。

  为什么要这么设置呢？看下面的源码，在TimingLogger的构造方法中，调用了reset(tag, label)方法，然后reset(tag, label)又调用了reset()方法，有这样一条语句：

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

这个mDisable的值表示mTag为VERBOSE级别时是否不能打印，如果用Log打印一下，会发现它的值为true，就是说不能打印级别为VERBOSE的mTag的日志。因为默认情况下只可以打印INFO以上的日志，所以就有了上面的那条命令，使其可以打印级别在VERBOSE以上时都可以打印。

  虽然看起来很简洁，用起来还是不太简单啊。

  最后看一下TimingLogger的源码，非常简单，加上注释总共150行不到。

/*
* Copyright (C) 2007 The Android Open Source Project
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
*      http://www.apache.org/licenses/LICENSE-2.0 *
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/

package android.util;

import java.util.ArrayList;

import android.os.SystemClock;

/**
* A utility class to help log timings splits throughout a method call.
* Typical usage is:
*
* <pre>
*     TimingLogger timings = new TimingLogger(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();
* </pre>
*
* <p>The dumpToLog call would add the following to the log:</p>
*
* <pre>
*     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
* </pre>
*/
public class TimingLogger {

/**
* The Log tag to use for checking Log.isLoggable and for
* logging the timings.
*/
private String mTag;

/** A label to be included in every log. */
private String mLabel;

/** Used to track whether Log.isLoggable was enabled at reset time. */
private boolean mDisabled;

/** Stores the time of each split. */
ArrayList<Long> mSplits;

/** Stores the labels for each split. */
ArrayList<String> mSplitLabels;

/**
* Create and initialize a TimingLogger object that will log using
* the specific tag. 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.
* @param tag the log tag to use while logging the timings
* @param label a string to be displayed with each log
*/
public TimingLogger(String tag, String label) {
reset(tag, label);
}

/**
* Clear and initialize a TimingLogger object that will log using
* the specific tag. 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.
* @param tag the log tag to use while logging the timings
* @param label a string to be displayed with each log
*/
public void reset(String tag, String label) {
mTag = tag;
mLabel = label;
reset();
}

/**
* Clear and initialize a TimingLogger object that will log using
* the tag and label that was specified previously, either via
* the constructor or a call to reset(tag, label). 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.
*/
public void reset() {
mDisabled = !Log.isLoggable(mTag, Log.VERBOSE);
if (mDisabled) return;
if (mSplits == null) {
mSplits = new ArrayList<Long>();
mSplitLabels = new ArrayList<String>();
} else {
mSplits.clear();
mSplitLabels.clear();
}
addSplit(null);
}

/**
* Add a split for the current time, labeled with splitLabel. If
* Log.isLoggable was not enabled to at least the Log.VERBOSE for
* the specified tag at construction or reset() time then this
* call does nothing.
* @param splitLabel a label to associate with this split.
*/
public void addSplit(String splitLabel) {
if (mDisabled) return;
long now = SystemClock.elapsedRealtime();
mSplits.add(now);
mSplitLabels.add(splitLabel);
}

/**
* Dumps the timings to the log using Log.d(). If Log.isLoggable was
* not enabled to at least the Log.VERBOSE for the specified tag at
* construction or reset() time then this call does nothing.
*/
public void dumpToLog() {
if (mDisabled) return;
Log.d(mTag, mLabel + ": begin");
final long first = mSplits.get(0);
long now = first;
for (int i = 1; i < mSplits.size(); i++) {
now = mSplits.get(i);
final String splitLabel = mSplitLabels.get(i);
final long prev = mSplits.get(i - 1);

Log.d(mTag, mLabel + ":      " + (now - prev) + " ms, " + splitLabel);
}
Log.d(mTag, mLabel + ": end, " + (now - first) + " ms");
}
}