写给面试的·StackTrace衍生篇

前言

面试中经常会被问到这样一个问题或者它的类似问题。

你如何用程序的方式检测导致UI卡顿的问题,并且定位

思考

我个人觉得这其实是一个还不错的综合体,考察点也还算多,也可以衍生出一些题目。

先来拆解一下关键词,程序的方式检测UI卡顿定位

  • 程序的方式检测:不是通过图形工具、不是通过交互来检测,而是通过编写工具类在应用运行时来检测
  • UI卡顿:UI线程做了一些耗时的操作
  • 定位:通过日志打印出耗时超过阈值的方法

技术补完

StackTrace&StackTraceElement

先来堆栈追踪部分的知识点,因为这块 api 用的多,但了解少。

StackTrace

StackTrace(堆栈跟踪),用栈的形式保存方法的调用信息。

这个其实我们一点也不陌生,在处理异常的时候,经常会这么写一句:e.printStackTrace(),即打印调用异常的堆栈信息,方便我们在异常发生的时候能定位到具体的问题。

StackTraceElement

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
/**
* An element in a stack trace, as returned by {@link
* Throwable#getStackTrace()}. Each element represents a single stack frame.
* All stack frames except for the one at the top of the stack represent
* a method invocation. The frame at the top of the stack represents the
* execution point at which the stack trace was generated. Typically,
* this is the point at which the throwable corresponding to the stack trace
* was created.
*
* @since 1.4
* @author Josh Bloch
*/
public final class StackTraceElement implements java.io.Serializable {
// 省略 N行
}

获取StackTraceElement的方法有2种,返回值为StackTraceElement[]

  • Thread#getStackTrace(),常见代码Thread.currentThread().getStackTrace()
  • Throwable#getStackTrace()

StackTraceElement[]包含了StackTrace的内容,遍历它可以得到方法见的调用过程,即可以得到当前方法以及其调用者的方法名、调用行数等信息。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32

// main 函数入口
fun main() {
funA()
}

// 方法A
fun funA() {
println("--->>> enter funA")
funB()
}

// 方法B
fun funB() {
println("--->>> enter funB")

val elements = Thread.currentThread().stackTrace

elements.forEachIndexed { index, e ->
val className = e.className
val funcName = e.methodName
val fileName = e.fileName
val lineNum = e.lineNumber
println(
"--->>> StackTraceElement index=>$index," +
" fileName=>$fileName, " +
"className=>$className, " +
"funcName=>$funcName, " +
"lineNum=>$lineNum"
)
}
}

输出,如图:

StackTraceElement使用

Looper

主线程里有个Looper,在loop方法中会不断取出Message,调用其绑定的 Handler 在主线程执行。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
loop(){
final Looper me = myLooper();
final MessageQueue queue = me.mQueue;

// 省略 N行
for (;;) {

// might block
Message msg = queue.next();

// 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);
}

// 看这里
msg.target.dispatchMessage(msg);

if (logging != null) {
logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
}

// 省略 N行
}
}

关键点,我们只要有办法检测:msg.target.dispatchMessage(msg)的执行时间,判断执行时间是否大于我们设置的某个阈值就可以判断UI线程是否有耗时操作了。此代码执行前后,如果设置了logging,会分别打印出:>>>>> Dispatching to<<<<< Finished to 这样的日志。

实操

BlockCanary

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22

private const val START = ">>>>> Dispatching"

private const val END = "<<<<< Finished"

class BlockCanary private constructor() {

companion object {

fun start() {
Looper.getMainLooper()
.setMessageLogging { str: String ->
when (str) {
START ->
LoggerMonitor.INSTANCE.start()
END ->
LoggerMonitor.INSTANCE.stop()
}
}
}
}
}

LoggerMonitor

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39

private const val THRESHOLD = 1 * 1000L

class LoggerMonitor private constructor() {

private val loggerThread: HandlerThread = HandlerThread("logger")

private val ioHandler: Handler

private val runnable = Runnable {
val log = buildString {
val stackTrace = Looper.getMainLooper().thread.stackTrace
stackTrace.forEach { e: StackTraceElement ->
append("$e\n")
}
}
Log.e("TAG", log)
}

val isMonitor: Boolean
get() = ioHandler.hasCallbacks(runnable)

init {
loggerThread.start()
ioHandler = Handler(loggerThread.looper)
}

companion object {
val INSTANCE by lazy { LoggerMonitor() }
}

fun start() {
ioHandler.postDelayed(runnable, THRESHOLD)
}

fun stop() {
ioHandler.removeCallbacks(runnable)
}
}

假设我们的阈值设置为 1000ms,当str匹配到>>> Dispatching时,调用LoggerMonitor.INSTANCE.start(),在 1000ms后执行一个任务,打印出UI线程的堆栈信息(这次在子线程中执行)。正常情况,我们的msg.target.dispatchMessage(msg)执行耗时小于 1000ms,所以str匹配到<<<<< Finished,就会调用LoggerMonitor.INSTANCE.remove()移除任务。

这里还用到了 HandlerThread,也利用了 Looper,只不过这个 Looper 在子线程中。

测试环节

Application#onCreate

1
2
3
4
5
6
class DemoApplication : Application() {
override fun onCreate() {
super.onCreate()
BlockCanary.start()
}
}

耗时模拟

1
2
3
4
5
6
7
btn_test.setOnClickListener {
try {
Thread.sleep(2000L)
} catch (e: Throwable) {
e.printStackTrace()
}
}

点击按钮,打印出 log:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
2020-03-10 01:40:10.509 4740-4765/info.hellovass.build_example E/TAG: java.lang.Thread.sleep(Native Method)
java.lang.Thread.sleep(Thread.java:373)
java.lang.Thread.sleep(Thread.java:314)
info.hellovass.build_example.MainActivity$onCreate$1.onClick(MainActivity.kt:15)
android.view.View.performClick(View.java:6597)
android.view.View.performClickInternal(View.java:6574)
android.view.View.access$3100(View.java:778)
android.view.View$PerformClick.run(View.java:25885)
android.os.Handler.handleCallback(Handler.java:873)
android.os.Handler.dispatchMessage(Handler.java:99)
android.os.Looper.loop(Looper.java:193)
android.app.ActivityThread.main(ActivityThread.java:6669)
java.lang.reflect.Method.invoke(Native Method)
com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:493)
com.android.internal.os.ZygoteInit.main(ZygoteInit.java:858)

会打印出耗时相关的代码信息,然后可以通过日志定位到耗时的方法。

Choreographer???

2020-03-10 01:40:11.516 4740-4740/info.hellovass.build_example I/Choreographer: Skipped 119 frames! The application may be doing too much work on its main thread.

这个日志似乎怎么感觉那么熟悉呢?其实日常开发中,如果我们操作不当(UI线程里执行耗时的操作)就能看到。而这个Choreographer,好像和啥 Android16ms绘制一帧等关键词有着说不清的关系。

没错,正是在下。

Android 系统每隔 16ms 发出 VSYNC 信号,触发对 UI 的渲染。Android SDK 包含了一个相关类,以及相应的回调。理论上来说,两次回调的时间周期应该在 16ms以内,超过了,我们则认为是一次造成卡顿的耗时操作,于是:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
class BlockCanary2 private constructor() {

companion object {
fun start() {
Choreographer.getInstance()
.postFrameCallback(object : Choreographer.FrameCallback {
override fun doFrame(frameTimeNanos: Long) {
if (LoggerMonitor.INSTANCE.isMonitor){
LoggerMonitor.INSTANCE.stop()
}
LoggerMonitor.INSTANCE.start()
Choreographer.getInstance()
.postFrameCallback(this)
}
})
}
}
}

第一次的时候开始检测,如果超过阈值则输出相关堆栈信息;否则移除。

衍生

这就完了嘛?兄dei,想多了,如果生产环境的性能检测工具这么写,那真的就是面向离职编程了2333。

实际要考虑的问题简直不要太多!

  • Handler#hasCallbacks 方法仅支持 Android Q 及以上
  • 阈值为1000ms,第一个方法耗时980ms,第二个方法耗时20ms,这时候打印的堆栈是20ms的方法的堆栈
  • 阈值还是为1000ms,第一个方法耗时500ms,第二个方法耗时500ms,这时候只打印了第二个方法的堆栈
  • 怎么把这些堆栈信息同步到远端

写在最后

突然想起好久之前看到过@markzhai发布过一个检测UI卡顿的工具,但当时年轻不懂其中的奥秘,连随手star都忘了。

这次一定!

参考