1、卡顿
Android的卡顿通常是由主线程中的耗时操作造成的,而主线程的工作原理是通过Looper的无限循环进行消息处理,我们可以通过监听每条消息的执行时间来判断是否出现卡顿(Looper设置MessageLogging监听),如果消息的处理时间达到2s,则会触发统计,上报包括线程栈信息、当前Activity等一系列信息。
2、ANR
ANR的统计与卡顿类似,但是时间不是Android系统定义ANR的时间,我们设置的阀值为5s,即消息的处理时间达到了5s就触发上报。上报内容除了线程的栈等信息外,还会有「自定义栈信息」,该栈信息包含每个方法的执行时间,便于我们精准定为ANR的根本原因。
3、慢函数统计
慢函数统计是由卡顿和ANR衍生出来的一个统计,我们会对主线程的每条Msg进行「自定义栈信息」收集,如果单条Msg执行时间达到700ms,则会触发慢函数统计。为什么时700ms,这个来自于Android官网的定义:冻结的帧 | Android 开发者 | Android Developers。以敏感程度来看,慢函数统计 > 卡顿 > ANR。
1、实现思路
监听主线程每一次Msg的执行时间,并借助函数插桩实现对App中每个方法的执行时间统计,出现卡顿/ANR时上报「系统栈信息」+「当前Msg执行的函数耗时」
2、实现对主线程消息监听
观察到 Looper 中有以下设置监听的方法:
该监听方法在Looper.loop()方法中被调用,用于观察msg分发的开始与结束:
我们通过给主线程Looper设置自定义的 Printer 监听,以观察其中Msg的执行时间。在SDK中我们将上述逻辑封装为单例 LooperMonitor,并暴露出设置listener的方法,在每条消息分发开始与结束时刻进行回调:
// 回调Msg分发开始&结束的接口
abstract class LooperDispatchListener {
var isHasDispatchStart = false
open fun isValid() = false
open fun dispatchStart() {} // 开始分发消息
open fun dispatchEnd() {} // 结束分发消息
}
|
注意「dispatchStart」与「dispatchEnd」方法,下面会经常提到
3、实现卡顿统计
实现对主线程 Looper 中的消息监听后,我们便可以实现对卡顿的监听:
(1)注册 LooperDispatchListener;
(2)在「dispatchStart」时记录时间,同时在工作线程中 post 一个延迟 2s 的 Runnable;
(3)在「dispatchEnd」中 remove 掉(1)中的 Runnable。这样如果Msg分发时间超过了 2s,则会触发(1)中 post 的 Runnable,即触发卡顿统计。
对于卡顿(Lag)我们统计的信息有:
(1)当前展示的Activity名称(通过给Application注册ActivityLifecycleCallbacks实现获取);
(2)主线程栈信息(通过 Looper.getMainLooper().thread.stackTrace 获取);
(3)时间、App名称、App版本、用户编号等基础信息。
// 一次卡顿信息统计
{
"foreground" : true , // 是否前台
"event_desc" : "com.gmlive.soulmatch.TestActivity" , // 场景
"stack_file" : "http://***TYyNzM3MjYzODgyOCMyODEjdHh0.txt" , // 栈信息保存在文件中
"stack_hash" : "90560ACE023A944674AB12EF080CE939" ,
"appName" : "SweetWords" ,
"appVersion" : "5.2.00" ,
"system" : "29" ,
"platform" : "1" ,
"machine" : "Xiaomi Mi 10" ,
"appFirstStartTime" : "2021-07-27 15:56:52" , // APP启动时间
"reportType" : "LAG" , // 上报类型
"time" : "2021-07-27 15:57:15" ,
"userId" : 842894
} // 主线程的栈信息(这里很明显看出来是调用了sleep造成的卡顿)
java.lang.Thread.sleep(Thread.java: 356 )
android.os.SystemClock.sleep(SystemClock.java: 131 )
com.inke.apm.trace.TracePlugin$Companion.L(TracePlugin.kt: 233 )
com.inke.apm.trace.TracePlugin$Companion.A(TracePlugin.kt: 180 )
com.inke.apm.trace.TracePlugin$Companion.testANR(TracePlugin.kt: 174 )
com.gmlive.soulmatch.TestActivity$onCreate$ 3 .onClick(TestActivity.kt: 25 )
com.meelive.ingkee.autotrack.monitor.biz.TrackTouchDelegate$TrackClickListener.onClick(TrackTouchDelegate.java: 171 )
android.view.View.performClick(View.java: 7188 )
android.view.View.performClickInternal(View.java: 7165 )
android.view.View.access$ 3500 (View.java: 822 )
android.view.View$PerformClick.run(View.java: 27701 )
android.os.Handler.handleCallback(Handler.java: 914 )
android.os.Handler.dispatchMessage(Handler.java: 100 )
android.os.Looper.loop(Looper.java: 227 )
android.app.ActivityThread.main(ActivityThread.java: 7582 )
java.lang.reflect.Method.invoke(Native Method)
|
我们注意到,普通的栈信息可以让我们大致定位到卡顿原因,但是有时候无法精准定位,比如多个耗时操作集合为一个卡顿。
所以对于ANR,我们还会统计「自定义栈信息」,该栈信息包含了方法的执行时间,有助于我们精确定位。
4、实现自定义栈信息收集&分析
整体实现思路:
(1)给所有方法定义自增的「方法ID」,记录在文件中,在打包时输出;同时在每个方法的开始位置与结束位置进行插桩,在应用运行期间,插桩的方法会将当前的「方法ID」与「时间戳」整合保存在数组中,对数组进行循环覆盖插入数据。
(2)在开始统计栈信息时,记录此时插入数组的 Index。
(3)结束统计时,对数组进行复制,范围从开始的 Index 到当前的 Index。至此,我们可以获得一系列「方法ID」+「时间戳」的数据。
(4)将复制出来的部分整合计算,可以得到包含执行时间的栈信息。
(5)分析「自定义栈信息」
下面是具体过程
(1)对所有方法进行插桩
我门使用「Gradle Transform + ASM字节码工具」完成对APP中所有代码进行插桩,主要分为两步:
第一步
通过 Transform 遍历所有的 Input class(通过ASM解析class,过滤掉R.java等无用文件),收集所有方法信息到一个「方法Map」中,方法信息包括「方法ID」「类名」「方法名」「方法描述」,其中方法ID为自定义属性,ID值从0开始递增,同时输出 methodMapping.txt 文件,其中记录了所有方法的信息:
// 以下为methodMapping文件的内容,一行信息内容依次为:方法ID,accessFlag,类名 方法名称 方法描述
1 , 9 ,com.google.zxing.EncodeHintType values ()[Lcom.google.zxing.EncodeHintType;
2 , 1 ,com.facebook.binaryresource.ByteArrayBinaryResource <init> ([B)V
3 , 1 ,com.gmlive.common.appupdate.UpdateManager$ 1 onParseResult (Lcom.gmlive.common.appupdate.entity.UpdateEntity;)V
4 , 1 ,com.facebook.binaryresource.ByteArrayBinaryResource openStream ()Ljava.io.InputStream;
5 , 9 ,com.google.zxing.EncodeHintType valueOf (Ljava.lang.String;)Lcom.google.zxing.EncodeHintType;
......
129515 , 1 ,com.zego.ve.VClk$EventHandler doFrame (J)V
129516 , 1 ,com.zego.ve.ThreadUtils$ 4 run ()V
1048574 , 1 ,android.os.Handler dispatchMessage (Landroid.os.Message;)V // 注意
|
注意:最后一个方法固定为 Handler 的 dispatchMessage,因为系统方法无法插桩,但是在消息分发开始时我们需要做一个标记,以便我们分析,所以手动补充这个方法信息到mathodMapping中,其ID为方法ID的最大值。
同时,在App运行时,我们会在「dispatchBegin」与「dispatchEnd」方法中手动调用「i」「o」方法,记录 Handler 的 dispatchMessage的栈信息:
举个例子,首先我们定义一个普通的 Flutter 控件,按照正常的控件进行实现就可以。
// i方法,dispatchBegin中调用,入参为dispatchMessage方法的ID,即1048574
AppMethodBeat.i(AppMethodBeat.METHOD_ID_DISPATCH)
// o方法,dispatchEnd中调用
AppMethodBeat.o(AppMethodBeat.METHOD_ID_DISPATCH)
|
第二步
再次遍历所有 Input class,在「方法Map」中含有的方法的开始位置插入静态方法「i」,结束位置插入静态方法「o」,用于在代码执行时记录栈信息,「i」「o」方法的代码如下:
// 供插入的数组(方法ID、时间戳会整合为一个long数据插入)
private static long [] sBuffer = new long [Constants.BUFFER_SIZE];
// 当前插入的下标
private static int sIndex = 0 ;
// 上次插入的下标
private static int sLastIndex = - 1 ;
// 防止重复执行i操作
private static boolean assertIn = false ;
// 方法ID的最大值
private static final int METHOD_ID_MAX = 0xFFFFF ;
// 该方法为 Handler 的 dispatchMessage,是手动插入的方法,最后一个方法ID
public static final int METHOD_ID_DISPATCH = METHOD_ID_MAX - 1 ; /**
* hook method when it's called in.
*/
public static void i( int methodId) {
if (methodId >= METHOD_ID_MAX) {
return ;
}
// 判断当前是否为主线程
if (Thread.currentThread().getId() == sMainThreadId) {
if (assertIn) {
Log.e(TAG, "ERROR!!! AppMethodBeat.i Recursive calls!!!" );
return ;
}
assertIn = true ;
// 数组下标循环循环
if (sIndex >= Constants.BUFFER_SIZE) {
sIndex = 0 ;
}
// 整合数据为一个long,插入sBuffer中,最后一个参数true代表方法开始,false为方法结束
mergeData(methodId, sIndex, true );
++sIndex;
assertIn = false ;
}
} /**
* hook method when it's called out.
*/
public static void o( int methodId) {
if (methodId >= METHOD_ID_MAX) {
return ;
}
if (Thread.currentThread().getId() == sMainThreadId) {
if (sIndex >= Constants.BUFFER_SIZE) {
sIndex = 0 ;
}
mergeData(methodId, sIndex, false );
++sIndex;
}
}
|
这里要注意的是,我们Transform的范围是「SCOPE_FULL_PROJECT」,会包括项目中引入的SDK(会被插入「i」&「o」方法)(不包括Android系统的方法,插桩只能插apk包内的代码)
上面的「mergeData」方法会整合数据到一个长整型中,并插入sBuffer数组,数据格式如下:
第一位代表的是执行的「i」还是「o」;
接下来20位为方法ID,最大值为0xFFFFF(1048575);
最前面的43位为时间戳(从App启动开始的时间毫秒值,最大为0x7FFFFFFFFFF,将近300年);
完成插桩后,代码运行时就会持续对sBuffer进行循环插入,我们需要栈信息时,就可以从sBuffer中copy出指定范围的内容。
比如有a\b\c三个方法,a方法被调用,同时a调用b,b调用c,则会向sBUffer中插入6个long数据:
上图中,c方法执行了250ms(「o」的时间戳300ms减去「i」的时间戳50ms)。
这里sBuffer的长度会设置的比较长,BUFFER_SIZE 为 500_000(预计会消耗3.8M的内存)
(2)记录开始的 Index
为了维护sBuffer的全局下标「sIndex」属性的私有性,我们使用自定义内部类 IndexRecord 记录当前 Index;因为可能记录多个开始点,且插入/删除频繁,所以我们以链表的形式维护。
以ANR为例,在统计开始时,即dispatchStart时(消息开始分发),我们会创建一个IndexRecord,以记录开始点的Index。
// maskIndex 会创建一个 IndexRecord 插入记录的链表,入参为当前场景,仅供参考
anrTask.beginRecord = AppMethodBeat.getInstance().maskIndex( "AnrTracer#dispatchBegin" )
|
(3)结束统计,复制数组
在触发ANR统计时(延迟post出的Runnable开始执行),我们会使用当前的 Index 与记录的 IndexRecord 来作为范围,复制 sBuffer 的内容。
// 复制方法进出的信息
val data = AppMethodBeat.getInstance().copyData(beginRecord)
// 从链表中移除IndexRecord
beginRecord?.release()
|
// 复制方法
public long [] copyData(IndexRecord startRecord) {
// 创建一个临时的 IndexRecord 作为结尾位置,进行数组copy;方法中使用 System.arraycopy 进行复制。
return copyData(startRecord, new IndexRecord(sIndex - 1 ));
}
|
(4)整合方法信息
复制出来的数组内容为一系列的进出方法信息,我们可以根据这些信息计算出各个方法的「深度」「连续执行次数」「执行时间」。
再看(1)中的例子整合出的栈信息:
其中时间由「i」记录的时间戳(方法开始时间)减去「o」记录的时间戳(方法结束时间)。
需要注意的是,实际情况我们会以 Handler 的 dispatchMessage 方法为起点进行统计。
同时我们会计算关键栈,即最具参考价值的那一行栈信息,规则是:执行时间大于整个栈执行时间的30%,且栈深度为最深的方法为 StackKey。
(5)分析栈信息
举个例子,这是真实环境获取的栈信息,下面重现下分析过程:
// 方法深度,方法ID,连续执行次数,执行时间
0 , 1048574 , 1 , 5003 // Handler 的 dispatchMessage 方法,标记开始
1 , 22988 , 1 , 5003
2 , 19414 , 1 , 5003
3 , 23020 , 1 , 5003 // 深度为3,执行时间为5秒,耗时方法在这个方法内
4 , 87779 , 1 , 0 // 深度为4,执行时间为0,说明耗时方法与这个方法无关,在这个方法的同级方法中,继续找深度为4的方法
4 , 87786 , 1 , 0
5 , 87812 , 1 , 0
4 , 85465 , 1 , 0
4 , 85436 , 1 , 0
4 , 22989 , 1 , 0
5 , 23727 , 1 , 0
4 , 4009 , 1 , 5003 // 找到同级的耗时方法,继续找下一深度(5)的耗时方法
5 , 4017 , 1 , 5003 // 继续找下一深度(6)的耗时方法
6 , 8307 , 1 , 0
6 , 62395 , 1 , 0
7 , 62414 , 1 , 0
7 , 62396 , 1 , 0
8 , 62588 , 1 , 0
9 , 62594 , 1 , 0
10 , 62753 , 1 , 0
10 , 62597 , 1 , 0
11 , 22895 , 1 , 0
12 , 22903 , 1 , 0
13 , 62449 , 1 , 0
14 , 22917 , 1 , 0
6 , 4556 , 1 , 5003 // 时间为5s,深度为6,继续深入
7 , 19441 , 1 , 5003
8 , 18803 , 1 , 5003
9 , 18801 , 1 , 5003
10 , 52899 , 1 , 5003 <-- stackKey 找到这里,深度最深,根本原因就是这个方法了
|
我们根据输出的 methodMapping 解析一下这里面耗时5秒的栈:
// 对于耗时5s的方法进行一下解析,找到对应 methodId 的方法信息
4 , 4009 , 1 , 5003
4009 --> com.gmlive.soulmatch.IMMessageListActivity$initTitleLayout$ 2 onChanged (Ljava.lang.Object;)V
5 , 4017 , 1 , 5003
4017 --> com.gmlive.soulmatch.IMMessageListActivity$initTitleLayout$ 2 onChanged (Lcom.gmlive.soulmatch.repository.user.UserIntimacyWrapper;)V
6 , 4556 , 1 , 5003
4556 --> com.gmlive.soulmatch.view.VideoLinkTipView showOrNot (I)V
7 , 19441 , 1 , 5003
19441 --> com.gmlive.soulmatch.repository.user.glue.UserModelRepositoryGlue getUser ()Lcom.gmlive.soulmatch.repository.entity.UserModelEntity;
8 , 18803 , 1 , 5003
18803 --> com.gmlive.soulmatch.repository.user.UserModelRepository get (ILjava.lang.String;)Lcom.gmlive.soulmatch.objectbox.impl.ObjectBoxEntityImpl;
9 , 18801 , 1 , 5003
18801 --> com.gmlive.soulmatch.repository.user.UserModelRepository get (ILjava.lang.String;)Lcom.gmlive.soulmatch.repository.entity.UserModelEntity;
10 , 52899 , 1 , 5003
52899 --> com.gmlive.soulmatch.objectbox.impl.ObjectboxState query (Ljava.lang.String;)Ljava.util.List;
|
上面方法深度逐个递增,最终定位是ObjectBox数据库的查询耗时,正是我们计算出的StackKey。
5、实现ANR统计
ANR的统计与卡顿的统计相似,在「dispatchStart」时post一个延迟的Runnable,在「dispatchEnd」时remove。
卡顿的时间阀值我们定义为2s,ANR我们定义为5s,同时ANR会多收集上面一点讲到的「自定义栈信息」。
6、实现慢函数统计
慢函数统计会计算「dispatchStart」与「dispatchEnd」的时间差,即主线程Msg分发的时间,在「dispatchEnd」进行判断,如果时间大于700ms,则在工作线程开始收集「自定义栈信息」并整合上报。
慢函数统计与ANR的触发原理有点差异,但是收集的信息与ANR基本一致。
ANR陷阱是卡顿统计的痛点之一,简单来说就是我们获取的卡顿数据比真实卡顿发生要延后,或者在多个卡顿之中我们并没有命中到关键的一次,比如连续的多个耗时消息、系统高负载导致的卡顿等都可能统计不到关键信息。所以,我们应该将统计数据从「只获取当前一次Msg的信息」拉长到「获取最近多个耗时Msg的信息」,同时也要结合其他手段进行多角度分析,最终完善我们的统计方案。
卡顿统计是APM系统工程中不可或缺的一环,它直接展示了App使用的流畅程度,面对真实生产使用,上述方案仍有不足,我们将继续完善APM系统工程。
参考链接
冻结的帧 | Android 开发者 | Android Developers
https://developer.android.com/topic/performance/vitals/frozen
Looper | Android Developers
https://developer.android.com/reference/android/os/Looper.html#setMessageLogging(android.util.Printer)
Tencent/matrix
https://github.com/Tencent/matrix