如何计算主线程中的方法耗时？
看一下Looper的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();
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;
if (traceTag != 0 && Trace.isTagEnabled(traceTag)) {
Trace.traceBegin(traceTag, msg.target.getTraceName(msg));
}
try {
msg.target.dispatchMessage(msg);
} finally {
if (traceTag != 0) {
Trace.traceEnd(traceTag);
}
}
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();
}
}
耗时的处理会发生在dispatchMessage中 可以替换掉mLogging 并记录开始和结束的时间
记录开始的位置：
if (logging != null) {
logging.println(">>>>> Dispatching to " + msg.target + " " +
msg.callback + ": " + msg.what);
}
记录结束的位置：
if (logging != null) {
logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
}
重写Printer的println方法：
@Override
public void println(String x) {
if (mStopWhenDebugging && Debug.isDebuggerConnected()) {
return;
}
if (!mPrintingStarted) {
mStartTimestamp = System.currentTimeMillis(); //开始时间
mStartThreadTimestamp = SystemClock.currentThreadTimeMillis();
mPrintingStarted = true;
startDump(); //开始收集堆栈信息
} else {
final long endTime = System.currentTimeMillis(); //结束时间
mPrintingStarted = false;
if (isBlock(endTime)) { //卡顿
notifyBlockEvent(endTime);
}
stopDump(); //停止收集堆栈信息
}
}
private boolean isBlock(long endTime) { //是否卡顿
return endTime - mStartTimestamp > mBlockThresholdMillis;
}
/**
* Start monitoring.
*/
public void start() {
if (!mMonitorStarted) {
mMonitorStarted = true;
Looper.getMainLooper().setMessageLogging(mBlockCanaryCore.monitor); //设置自定义的Printer
}
}
private void startDump() { //方法堆栈的信息收集
if (null != BlockCanaryInternals.getInstance().stackSampler) { //采集堆栈信息 stackSampler继承自AbstractSampler
BlockCanaryInternals.getInstance().stackSampler.start();
}
if (null != BlockCanaryInternals.getInstance().cpuSampler) { //采集CPU信息
BlockCanaryInternals.getInstance().cpuSampler.start();
}
}
AbstractSampler的start方法：
public void start() {
if (mShouldSample.get()) {
return;
}
mShouldSample.set(true);
HandlerThreadFactory.getTimerThreadHandler().removeCallbacks(mRunnable);
HandlerThreadFactory.getTimerThreadHandler().postDelayed(mRunnable, //启动mRunnable
BlockCanaryInternals.getInstance().getSampleDelay());
}
private Runnable mRunnable = new Runnable() {
@Override
public void run() {
doSample();
if (mShouldSample.get()) {
HandlerThreadFactory.getTimerThreadHandler()
.postDelayed(mRunnable, mSampleInterval); //轮询
}
}
};
堆栈采样：
@Override
protected void doSample() { //堆栈采样
StringBuilder stringBuilder = new StringBuilder();
for (StackTraceElement stackTraceElement : mCurrentThread.getStackTrace()) {
stringBuilder
.append(stackTraceElement.toString())
.append(BlockInfo.SEPARATOR);
}
synchronized (sStackMap) {
if (sStackMap.size() == mMaxEntryCount && mMaxEntryCount > 0) {
sStackMap.remove(sStackMap.keySet().iterator().next());
}
sStackMap.put(System.currentTimeMillis(), stringBuilder.toString());
}
}
private void notifyBlockEvent(final long endTime) {
final long startTime = mStartTimestamp;
final long startThreadTime = mStartThreadTimestamp;
final long endThreadTime = SystemClock.currentThreadTimeMillis();
HandlerThreadFactory.getWriteLogThreadHandler().post(new Runnable() {
@Override
public void run() {
mBlockListener.onBlockEvent(startTime, endTime, startThreadTime, endThreadTime);
}
});
}
CPU采样：
Linux中CPU的活动保存在/proc/stat文件中 从系统开启时累计到当前时刻
~$ cat /proc/stat
cpu 38082 627 27594 893908 12256 581 895 0 0 //CPU总的使用情况
cpu0 22880 472 16855 430287 10617 576 661 0 0
cpu1 15202 154 10739 463620 1639 4 234 0 0
intr 120053 222 2686 0 1 1 0 5 0 3 0 0 0 47302 0 0 34194 29775 0 5019 845 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
ctxt 1434984
btime 1252028243
processes 8113
procs_running 1
procs_blocked 0
第二行的数据解析：
user (38082) 处于用户态的运行时间
不包含 nice值为负进程
nice (627) nice值为负的进程所占用的CPU时间
system (27594) 处于核心态的运行时间
idle (893908) 除IO等待时间以外的其它等待时间iowait (12256) 从系统启动开始累计到当前时刻 IO等待时间
irq (581) 硬中断时间
irq (581) 软中断时间
stealstolen(0) 一个其他的操作系统运行在虚拟环境下所花费的时间
guest(0) 这是在Linux内核控制下为客户操作系统运行虚拟CPU所花费的时间
总的CPU时间=以上所有指标的和
某一进程的所有信息保存在/proc/pid/stat中 从系统开始时累计到当前时刻
CPU采样：
@Override
protected void doSample() {
BufferedReader cpuReader = null;
BufferedReader pidReader = null;
try {
cpuReader = new BufferedReader(new InputStreamReader( //总CPU采样
new FileInputStream("/proc/stat")), BUFFER_SIZE);
String cpuRate = cpuReader.readLine();
if (cpuRate == null) {
cpuRate = "";
}
if (mPid == 0) {
mPid = android.os.Process.myPid();
}
pidReader = new BufferedReader(new InputStreamReader(
new FileInputStream("/proc/" + mPid + "/stat")), BUFFER_SIZE); //某一进程CPU采样
String pidCpuRate = pidReader.readLine();
if (pidCpuRate == null) {
pidCpuRate = "";
}
parse(cpuRate, pidCpuRate);
} catch (Throwable throwable) {
Log.e(TAG, "doSample: ", throwable);
} finally {
try {
if (cpuReader != null) {
cpuReader.close();
}
if (pidReader != null) {
pidReader.close();
}
} catch (IOException exception) {
Log.e(TAG, "doSample: ", exception);
}
}
}
private void parse(String cpuRate, String pidCpuRate) {
String[] cpuInfoArray = cpuRate.split(" ");
if (cpuInfoArray.length < 9) {
return;
}
long user = Long.parseLong(cpuInfoArray[2]);
long nice = Long.parseLong(cpuInfoArray[3]);
long system = Long.parseLong(cpuInfoArray[4]);
long idle = Long.parseLong(cpuInfoArray[5]);
long ioWait = Long.parseLong(cpuInfoArray[6]);
long total = user + nice + system + idle + ioWait
+ Long.parseLong(cpuInfoArray[7])
+ Long.parseLong(cpuInfoArray[8]);
String[] pidCpuInfoList = pidCpuRate.split(" ");
if (pidCpuInfoList.length < 17) {
return;
}
long appCpuTime = Long.parseLong(pidCpuInfoList[13])
+ Long.parseLong(pidCpuInfoList[14])
+ Long.parseLong(pidCpuInfoList[15])
+ Long.parseLong(pidCpuInfoList[16]);
if (mTotalLast != 0) {
StringBuilder stringBuilder = new StringBuilder();
long idleTime = idle - mIdleLast;
long totalTime = total - mTotalLast;
stringBuilder
.append("cpu:")
.append((totalTime - idleTime) * 100L / totalTime)
.append("% ")
.append("app:")
.append((appCpuTime - mAppCpuTimeLast) * 100L / totalTime)
.append("% ")
.append("[")
.append("user:").append((user - mUserLast) * 100L / totalTime)
.append("% ")
.append("system:").append((system - mSystemLast) * 100L / totalTime)
.append("% ")
.append("ioWait:").append((ioWait - mIoWaitLast) * 100L / totalTime)
.append("% ]");
synchronized (mCpuInfoEntries) {
mCpuInfoEntries.put(System.currentTimeMillis(), stringBuilder.toString());
if (mCpuInfoEntries.size() > MAX_ENTRY_COUNT) {
for (Map.Entry<Long, String> entry : mCpuInfoEntries.entrySet()) {
Long key = entry.getKey();
mCpuInfoEntries.remove(key);
break;
}
}
}
}
mUserLast = user;
mSystemLast = system;
mIdleLast = idle;
mIoWaitLast = ioWait;
mTotalLast = total;
mAppCpuTimeLast = appCpuTime;
}
总结
- 通过hook
Looper中的Printer计算方法的耗时 -
Thread#getStackTrace获取堆栈信息 - cat
/proc/stat和/proc/pid/stat文件读取CPU信息
