应用做完后,有时候会发现应用比较卡或是反应比较慢,这时候就得去排查是什么原因导致的响应慢,我们的第一反应就是哪个函数执行是比较耗时的,那该怎么去排查耗时函数呢,在可能耗时的函数里答应执行时间么,那这个工作量就有点大了,也不利于维护,这里所以分享的就是如何去查找耗时函数,该如何去查找呢?这里先来看下代码实现,后面再来说说实现的原理:
代码实现
public class MethodMonitor implements Runnable {
private Handler mLogHandler;
private static final String TAG="tangedegushi";
//分发和处理消息开始前的log
private static final String START = ">>>>> Dispatching";
//分发和处理消息结束后的log
private static final String END = "<<<<< Finished";
//记录方法执行时间
private long time;
//记录是否是耗时方法
private boolean isLargerTime;
//记录当前的耗时方法(方法所在的栈)
private String stackMessage;
//默认执行时间大于多少是耗时函数
private static final long MAX_TIME = 100;
private static MethodMonitor sInstance = new MethodMonitor();
private MethodMonitor() {
HandlerThread t = new HandlerThread("monitorMethod");
t.start();
mLogHandler = new Handler(t.getLooper());
}
public static void monitorTakeUpTime(){
Looper.getMainLooper().setMessageLogging(new Printer() {
@Override
public void println(String x) {
if (x.startsWith(START)) {
sInstance.addMonitor();
}
if (x.startsWith(END)) {
sInstance.removeMonitor();
}
}
});
}
private void addMonitor() {
isLargerTime = false;
time = System.currentTimeMillis();
mLogHandler.postDelayed(this, MAX_TIME);
}
private void removeMonitor() {
mLogHandler.removeCallbacks(this);
if (isLargerTime) {
Log.e(TAG, "卡顿时间 = "+(System.currentTimeMillis() - time)+" 卡顿函数 = "+stackMessage);
}
}
@Override
public void run() {
StackTraceElement[] stackTrace = Looper.getMainLooper().getThread().getStackTrace();
for (StackTraceElement st : stackTrace) {
// 过滤出自己应用的
if (st.toString().contains("com.ubtechinc.cruzr.")) {
isLargerTime = true;
stackMessage = st.toString();
}
}
}
}
使用很简单,在启动应用的时候调用MethodMonitor.monitorTakeUpTime(),这样就可以看到耗时函数的输出,以及函数执行所耗费的时间,看完实现后,再来说说这里实现的的原理,这里利用的主要是Android的Looper,Looper里面有对外提供打印日志的方法setMessageLogging(),只需往里面设置即可,设置完后,会在Looper的loop()方法里面使用到,这里就来看看loop这个方法:
原理讲解
public static void loop() {
final Looper me = myLooper();
if (me == null) {
throw new RuntimeException("No Looper; Looper.prepare() wasn't called on this thread.");
}
final MessageQueue queue = me.mQueue;
// Make sure the identity of this thread is that of the local process,
// and keep track of what that identity token actually is.
Binder.clearCallingIdentity();
final long ident = Binder.clearCallingIdentity();
// Allow overriding a threshold with a system prop. e.g.
// adb shell 'setprop log.looper.1000.main.slow 1 && stop && start'
final int thresholdOverride =
SystemProperties.getInt("log.looper."
+ Process.myUid() + "."
+ Thread.currentThread().getName()
+ ".slow", 0);
boolean slowDeliveryDetected = false;
for (;;) {
Message msg = queue.next(); // might block
if (msg == null) {
// No message indicates that the message queue is quitting.
return;
}
// This must be in a local variable, in case a UI event sets the logger
final Printer logging = me.mLogging;
if (logging != null) {
logging.println(">>>>> Dispatching to " + msg.target + " " +
msg.callback + ": " + msg.what);
}
final long traceTag = me.mTraceTag;
long slowDispatchThresholdMs = me.mSlowDispatchThresholdMs;
long slowDeliveryThresholdMs = me.mSlowDeliveryThresholdMs;
if (thresholdOverride > 0) {
slowDispatchThresholdMs = thresholdOverride;
slowDeliveryThresholdMs = thresholdOverride;
}
final boolean logSlowDelivery = (slowDeliveryThresholdMs > 0) && (msg.when > 0);
final boolean logSlowDispatch = (slowDispatchThresholdMs > 0);
final boolean needStartTime = logSlowDelivery || logSlowDispatch;
final boolean needEndTime = logSlowDispatch;
if (traceTag != 0 && Trace.isTagEnabled(traceTag)) {
Trace.traceBegin(traceTag, msg.target.getTraceName(msg));
}
final long dispatchStart = needStartTime ? SystemClock.uptimeMillis() : 0;
final long dispatchEnd;
try {
msg.target.dispatchMessage(msg);
dispatchEnd = needEndTime ? SystemClock.uptimeMillis() : 0;
} finally {
if (traceTag != 0) {
Trace.traceEnd(traceTag);
}
}
if (logSlowDelivery) {
if (slowDeliveryDetected) {
if ((dispatchStart - msg.when) <= 10) {
Slog.w(TAG, "Drained");
slowDeliveryDetected = false;
}
} else {
if (showSlowLog(slowDeliveryThresholdMs, msg.when, dispatchStart, "delivery",
msg)) {
// Once we write a slow delivery log, suppress until the queue drains.
slowDeliveryDetected = true;
}
}
}
if (logSlowDispatch) {
showSlowLog(slowDispatchThresholdMs, dispatchStart, dispatchEnd, "dispatch", msg);
}
if (logging != null) {
logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
}
// Make sure that during the course of dispatching the
// identity of the thread wasn't corrupted.
final long newIdent = Binder.clearCallingIdentity();
if (ident != newIdent) {
Log.wtf(TAG, "Thread identity changed from 0x"
+ Long.toHexString(ident) + " to 0x"
+ Long.toHexString(newIdent) + " while dispatching to "
+ msg.target.getClass().getName() + " "
+ msg.callback + " what=" + msg.what);
}
msg.recycleUnchecked();
}
}
在这个方法中找到logging这个变量,这个变量就是我们通过setMessageLogging()设置进来的,可以看到logging在输出的字符串中有">>>>> Dispatching"和"<<<<< Finished",在这两个输出之间就是方法的执行时间,所以在这里是可以打印出所有方法的执行时间的,要找出耗时函数,这里就需要过滤一下,上面代码中所取的耗时时间大于100ms,这个可以自己定义,loop()方法中消息的分发主要是在msg.target.dispatchMessage(msg);中执行的,简单实用的一个工具类。