阿里妹导读
引言
术语表
线程死循环检测机制
获取线程 CPU 占用比
进程的 stat 信息
进程 ID 为:11162
进程用户态 CPU 耗时 101, 内核态 CPU 耗时 51 。
对于死循环来说,CPU 的占用主要体现在用户态,所以我们只关注用户态的 CPU 占用比就好。
主线程的 stat 信息
主线程的线程 ID 为 11162, 与进程 ID 相同。 主线程用户态 CPU 耗时 12, 内核态 CPU 耗时 8 。则主线程用户态 CPU 占用比为:12 / 101 = 12%
子线程 Jit thread pool 的 stat 信息
子线程的线程 ID 为:11168,与进程 ID 不相同。
子线程用户态和内核态 CPU 耗时均为 0 ,则该子线程用户态 CPU 占用比为:0% 。
堆栈比较方案
CPU 占用和堆栈比较相结合
起因
结合方案
首先是线程 CPU 占用比获取阶段 先基于 stat 文件获取进程和线程的 CPU 耗时。
等待一段时间后,再次抓取进程和线程 CPU 耗时。
计算所有线程的 CPU 耗时,超过阈值,则认为属于高 CPU 线程。如果没有这类线程,则结束检测流程。
保存所有的高 CPU 线程的相关信息,留给下一个阶段使用。 其次是堆栈比较阶段 获取所有的 Java 线程对象列表,并进行遍历。
先对 Java 线程进行高 CPU 线程名匹配,如果匹配不中,不会进行堆栈比较,直接移除。
在一定时间内,针对剩余线程连续抓几次堆栈进行堆栈比较,堆栈相似度低于阈值的线程会被移除。 最后是输出检测结果通过筛选的线程就是疑似发生死循环的线程。 将 CPU 占用比信息与线程堆栈信息合并之后,输出检测结果。
实际案例分享
案例 1:多线程操作 HashMap 线程死循环
{
"case:1420548922":{
"name":"DThread-2",
"threadCPURate":0.*,
"threadStackList":[
"java.util.HashMap.put(HashMap.java:425)",
"fde.f(SourceFile:299)",
"iwx$1.doAfter(SourceFile:57)",
"prw.parseData(SourceFile:23)",
"prv.a(SourceFile:18)",
"pru$1.run(SourceFile:56)",
"com.***.threadpool.TaskRunner.call(SourceFile:750)",
"java.lang.Thread.run(Thread.java:762)"
]
},
"case:1961205280":{
"name":"DThread-19",
"threadCPURate":0.*,
"threadStackList":[
"java.util.HashMap.put(HashMap.java:425)",
"fde.f(SourceFile:299)",
"iwx$1.doAfter(SourceFile:57)",
"prw.parseData(SourceFile:23)",
"psc.a(SourceFile:342)",
"com.***.im.cl.a(SourceFile:100)",
"prz.query(SourceFile:2628)",
"psh$12.onExecuteRpc(SourceFile:244)",
"pri$1.run(SourceFile:143)",
"com.***.threadpool.TaskRunner.call(SourceFile:750)",
"java.lang.Thread.run(Thread.java:762)"
]
}
}
从死循环信息来看: 两个线程堆栈均为高 CPU 线程,且最后都是在操作 HashMap。很明显是踩到了 HashMap 多线程不安全的这个坑。
将对应 HashMap 的使用改为 ConcurrentHashMap 之后,该问题得到解决。
案例 2:Lottie 动画后台未停止导致高 CPU 消耗
"case:-1056518995":{
"name":"main",
"threadCPURate":0.*,
"threadStackList":[
"com.airbnb.lottie.LottieAnimationView.invalidateDrawable(SourceFile:189)",
"com.airbnb.lottie.LottieDrawable.invalidateSelf(SourceFile:261)",
"lb.onValueChanged(SourceFile:100)",
"com.airbnb.lottie.animation.keyframe.BaseKeyframeAnimation.b(SourceFile:60)",
"nj.a(SourceFile:427)",
"com.airbnb.lottie.LottieDrawable$1.onAnimationUpdate(SourceFile:103)",
"pb.c(SourceFile:88)",
"pd.doFrame(SourceFile:96)",
"android.view.Choreographer$CallbackRecord.run(Choreographer.java:785)",
"android.view.Choreographer.doFrame(Choreographer.java:568)",
"android.os.Handler.dispatchMessage(Handler.java:95)",
"android.os.Looper.loop(Looper.java:136)",
"android.app.ActivityThread.main(ActivityThread.java:5336)",
"com.android.internal.os.ZygoteInit.main(ZygoteInit.java:689)"
]
}
从死循环信息来看: 发生死循环的是主线程。
主线程相对于整个 APP 进程,CPU 占用量很高。
从堆栈看是因为 Lottie 动画导致的。
经过本地验证发现确实存在切换到后台 Lottie 依然在执行动画的问题。
原因是因为钉钉使用的 Lottie 版本太低导致,升级 Lottie 版本之后该问题得到解决。
案例 3:属性动画泄露导致高 CPU 消耗
初步分析
"case:-647468375":{
"name":"main",
"threadCPURate":0.*,
"threadStackList":[
"android.graphics.drawable.LayerDrawable.setAlpha(LayerDrawable.java:1364)",
"android.animation.ObjectAnimator.animateValue(ObjectAnimator.java:990)",
"android.animation.ValueAnimator.animateBasedOnTime(ValueAnimator.java:1349)",
"android.animation.ValueAnimator.doAnimationFrame(ValueAnimator.java:1481)",
"android.animation.AnimationHandler.doAnimationFrame(AnimationHandler.java:146)",
"android.animation.AnimationHandler$1.doFrame(AnimationHandler.java:54)",
"android.view.Choreographer.doCallbacks(Choreographer.java:1047)",
"android.view.Choreographer.doFrame(Choreographer.java:914)",
"android.os.Handler.dispatchMessage(Handler.java:100)",
"android.os.Looper.loop(Looper.java:214)",
"android.app.ActivityThread.main(ActivityThread.java:7659)",
"com.android.internal.os.ZygoteInit.main(ZygoteInit.java:938)"
]
}
从死循环信息来看: 死循环发生在主线程。
主线程相对于整个进程,CPU 占用率非常高,大量抢占了子线程的 CPU 时间片。
堆栈里没有业务堆栈,因此暂时无法定位到问题代码。只能看出是发生了属性动画泄露,需要增加监控能力。
监控能力增强
从系统 AnimationHandler 类入手,获取到当前运行中的属性动画实例列表。
从属性动画实例中提取关键信息,并附加到 ANRCanary 日志中上报。
"case:-647468375":{
"attachInfo":{
"animatorList":[
{
"duration":1200,
"propertyList":[
{
"clazz":"IntPropertyValuesHolder",
"message":"alpha: 25 255 "
}
],
"repeatCount":-1,
"target":"android.graphics.drawable.LayerDrawable",
"viewPath":"TextView:recording|RelativeLayout:0|RelativeLayout:0"
},
...
},
"name":"main",
"threadCPURate":0.*,
"threadStackList":[
"android.graphics.drawable.LayerDrawable.setAlpha(LayerDrawable.java:1364)",
"android.animation.ObjectAnimator.animateValue(ObjectAnimator.java:990)",
"android.animation.ValueAnimator.animateBasedOnTime(ValueAnimator.java:1349)",
"android.animation.ValueAnimator.doAnimationFrame(ValueAnimator.java:1481)",
"android.animation.AnimationHandler.doAnimationFrame(AnimationHandler.java:146)",
"android.animation.AnimationHandler$1.doFrame(AnimationHandler.java:54)",
"android.view.Choreographer.doCallbacks(Choreographer.java:1047)",
"android.view.Choreographer.doFrame(Choreographer.java:914)",
"android.os.Handler.dispatchMessage(Handler.java:100)",
"android.os.Looper.loop(Looper.java:214)",
"android.app.ActivityThread.main(ActivityThread.java:7659)",
"com.android.internal.os.ZygoteInit.main(ZygoteInit.java:938)"
]
}
duration:该动画时长为 1200 毫秒。
propertyList:
clazz:属性值的类型为 int 。
message:属性名为 alpha,属性变化值为从 25 到 255。
repeatCount:循环次数为 -1 ,即无限循环永远不停止,难怪会发生泄露。
target:alpha 属性所属的对象类型为:LayerDrawable 。
viewPath:
LayerDrawable 所属的 View 类型为 TextView。
该 TextView 的 viewId 为 recording 。
该 TextView 的父辈节点均为 RelativeLayout 类型。
案例 4:定时任务执行异常导致死循环
初步分析
"case:-2147483648":{
"name":"Timer-0",
"threadCPURate":0.*,
"threadStackList":[
"android.os.MessageQueue.enqueueMessage(MessageQueue.java:577)",
"android.os.Handler.enqueueMessage(Handler.java:662)",
"android.os.Handler.sendMessageAtTime(Handler.java:631)",
"android.os.Handler.sendMessageDelayed(Handler.java:601)",
"android.os.Handler.postDelayed(Handler.java:429)",
"de.executor(SourceFile:31)",
"tm.query(SourceFile:268)",
"mk.start(SourceFile:166)",
"mk$1.run(SourceFile:93)",
"java.util.TimerThread.mainLoop(Timer.java:555)",
"java.util.TimerThread.run(Timer.java:505)"
]
}
从死循环信息来看:
发生死循环的线程名为:Timer-0 。
该线程相对于整个进程,CPU 占用率也很高。
死循环的原因看起来是某个消息队列被打满导致。
因为 Handler 的消息队列被打满之后,每次 postDelayed 调用都要执行一次插入排序遍历整个队列。
监控能力增强
获取当前进程全部的线程对象,逐个遍历。
如果线程为 HandlerThread 类及其子类,则包含有消息队列,可以尝试获取其消息队列长度。
如果消息队列长度超过一定阈值,则可以判定为消息队列被打满。
对消息队列中的消息进行遍历聚合,分析出 Top 级消息内容。
允许存在多个线程的消息队列被打满的情况。
"case:-2147483648":{
"attachInfo":{
"messageQueueList":[
{
"repeatRate":1,
"repeatSignature":"android.os.Handler|jlh",
"threadName":"TaskHandlerThread",
"totalCount":****
}
]
},
"name":"Timer-0",
"threadCPURate":0.*,
"runTime":***,
"threadStackList":[
"android.os.MessageQueue.enqueueMessage(MessageQueue.java:577)",
"android.os.Handler.enqueueMessage(Handler.java:662)",
"android.os.Handler.sendMessageAtTime(Handler.java:631)",
"android.os.Handler.sendMessageDelayed(Handler.java:601)",
"android.os.Handler.postDelayed(Handler.java:429)",
"de.executor(SourceFile:31)",
"tm.query(SourceFile:268)",
"mk.start(SourceFile:166)",
"mk$1.run(SourceFile:93)",
"java.util.TimerThread.mainLoop(Timer.java:555)",
"java.util.TimerThread.run(Timer.java:505)"
]
}
从附加信息来看: repeatRate:消息队列重复率为 100%,说明均为同一类消息。
repeatSignature:重复消息的 Runnable 类型混淆后为:jlh,确实为监控模块的周期性任务。
threadName:消息队列所属的线程名为:TaskHandlerThread
totalCount:消息队列长度远远超出正常消息队列的长度,确实被打满。
runTime:进程存活时长并不大。正常消息队列应该只有几条消息,而不应该被打满。
最终定位
private void mainLoop() {
while (true) {
TimerTask task;
boolean taskFired;
long currentTime, executionTime;
// 1.从运行队列中获取头部的周期性任务
task = queue.getMin();
// 2.获取系统时间(关键点!!!)
currentTime = System.currentTimeMillis();
// 3.获取周期性任务期望执行时间
executionTime = task.nextExecutionTime;
taskFired = executionTime <= currentTime;
// 4.用两个时间的比较结果,决定是否执行周期性任务
if (taskFired) {
task.run();
}
}
}
如果往前修改系统时间,周期性任务将停止执行。
如果往后修改系统时间,间隔时间会失效,周期性任务开始连续不停地执行。
总结