钉钉Android团队攻克端线程死循环问题探索与实践

原文标题:最佳实践|一文讲解端线程死循环的治理

原文作者:阿里云开发者

冷月清谈:

本文详细介绍了钉钉Android团队采用的死循环线程检测工具ANRCanary的构建与实施过程。钉钉作为一个拥有超过7亿用户的企业级智能办公平台,面临着线程死循环带来的高耗电、界面卡顿等问题。文章通过四个典型案例(包括多线程操作HashMap、Lottie动画未停止、属性动画泄露、定时任务执行异常)展示了线程死循环的复杂性以及解决方案的实施。钉钉团队通过监控工具ANRCanary,结合CPU占用和堆栈比较的方法,成功识别和修复了线程死循环问题,从而显著提高了APP的性能和用户体验。

怜星夜思:

1、使用HashMap在多线程环境中容易产生的问题有哪些?如何避免?
2、在软件开发中,如何设计一个有效的死循环检测机制?
3、为什么说Timer的定时任务容易受系统时间影响?有没有更稳定的替代方案?

原文内容


阿里妹导读


本文旨在介绍钉钉 Android 团队死循环检测工具建设的思路和典型案例的修复历程。希望通过此次分享,对同样面临类似死循环问题的团队能够有所启发。

引言

钉钉作为一个用户数超 7 亿,服务企业与组织数超过了 2500 万的企业级智能办公平台,终端团队一直将打造极致用户体验作为我们的理念。对于 Android 设备来说,线程死循环问题可能会导致高耗电,界面卡顿,耗尽内存等性能问题。与此同时,死循环问题还具有隐蔽性高,黑盒测试无法感知的特点。针对潜在的线程死循环风险我们进行了专项的治理优化。
本文旨在介绍钉钉 Android 团队死循环检测工具建设的思路和典型案例的修复历程。希望通过此次分享,对同样面临类似死循环问题的团队能够有所启发。

术语表

图片


线程死循环检测机制

线程死循环检测是一项复杂的任务。死循环可以在代码的任何地方发生,从简单的逻辑错误到复杂的系统原因,均可能会导致死循环。因此检测并诊断此类问题相当困难。
钉钉自研的 ANRCanary 监控工具,基于死循环线程高 CPU 占用和堆栈相似的两个特点,实现了精准的死循环检测能力。


获取线程 CPU 占用比

通过读取 Android 系统 proc 目录下面的 stat 文件可以获取进程和线程的 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 耗时差值,计算即可得出。
通常可以将 CPU 占用比超过 10% 的线程标记为高耗时线程。


堆栈比较方案

死循环线程还有一个特点就是当出现一个循环点时,线程堆栈的底部是永远相同的。
以查询历史数据过多的数据库而导致死循环的案例堆栈为例:
如上图所示,针对该线程在一定时间间隔内抓的三个堆栈,可以发现堆栈的相似度很高,则可以将其作为死循环的重点怀疑对象。


CPU 占用和堆栈比较相结合

起因

CPU 占用方案:基于 stat 文件可以知道一个线程占了比较高的 CPU ,但是有效信息只有线程名, 对应不上代码,因此很难分析出耗 CPU 的根因。
堆栈比较方案:能够拿到堆栈信息,但是当线程发生阻塞时(比如读 IO 或跨进程通信),堆栈相似度也很高,因此误报率比较高。
因此唯有将两个方案结合起来,才能比较准确地拿到高 CPU 占用线程的堆栈信息,从而大大提高检测结果的可分析性。

结合方案

结合的关键点为:线程名。因为两个方案输出的信息均包含线程名,因此可以用线程名进行关联匹配。
如上图所示,完整版本的死循环线程检测机制详细说明如下:
  • 首先是线程 CPU 占用比获取阶段
    • 先基于 stat 文件获取进程和线程的 CPU 耗时。

    • 等待一段时间后,再次抓取进程和线程 CPU 耗时。

    • 计算所有线程的 CPU 耗时,超过阈值,则认为属于高 CPU 线程。如果没有这类线程,则结束检测流程。

    • 保存所有的高 CPU 线程的相关信息,留给下一个阶段使用。
  • 其次是堆栈比较阶段
    • 获取所有的 Java 线程对象列表,并进行遍历。

    • 先对 Java 线程进行高 CPU 线程名匹配,如果匹配不中,不会进行堆栈比较,直接移除。

    • 在一定时间内,针对剩余线程连续抓几次堆栈进行堆栈比较,堆栈相似度低于阈值的线程会被移除。
  • 最后是输出检测结果通过筛选的线程就是疑似发生死循环的线程。
    • 将 CPU 占用比信息与线程堆栈信息合并之后,输出检测结果。

实际案例分享

钉钉团队将以上解决方案整合进 ANRCanary 组件,完成线程死循环检测能力的建设。下文将通过几个典型案例,介绍钉钉在线程死循环问题治理上取得的收益。


案例 1:多线程操作 HashMap 线程死循环

本案例涉及 Java 中一个经典的死循环问题,即在多线程环境中操作 HashMap 有可能触发无限循环的情况。
 ANRCanary 抓到的上报信息如下:
{
"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 消耗

 ANRCanary 抓到的上报信息如下:
"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 消耗

初步分析

 ANRCanary 抓到的上报信息如下:
"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 时间片。

    • 堆栈里没有业务堆栈,因此暂时无法定位到问题代码。只能看出是发生了属性动画泄露,需要增加监控能力。

监控能力增强

 ANRCanary 在感知到发生属性动画泄露以后,需要将发生泄露的属性动画揪出来。大致方案为:
  • 从系统 AnimationHandler 类入手,获取到当前运行中的属性动画实例列表。

  • 从属性动画实例中提取关键信息,并附加到 ANRCanary 日志中上报。
能力增强后的 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 类型。

基于 viewId 、动画时长、属性变化值等信息,快速定位到问题代码,确认了导致泄露的原因并修复。


案例 4:定时任务执行异常导致死循环

本案例为一个隐蔽且复杂的死循环问题,解决过程极具挑战性,耗时甚长。

初步分析

 ANRCanary 抓到的上报信息如下:
"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 调用都要执行一次插入排序遍历整个队列。

监控能力增强

经过翻阅代码,确认代码中有一个周期性任务。周期性任务的实现方式采用的是 Java 提供的 Timer 类。正常情况下应该不会导致消息队列被打满才对。
 ANRCanary 在感知到消息队列疑似被打满以后,需要收集更多信息来进行确认情况。大致方案为:
  • 获取当前进程全部的线程对象,逐个遍历。

  • 如果线程为 HandlerThread 类及其子类,则包含有消息队列,可以尝试获取其消息队列长度。

  • 如果消息队列长度超过一定阈值,则可以判定为消息队列被打满。

  • 对消息队列中的消息进行遍历聚合,分析出 Top 级消息内容。

  • 允许存在多个线程的消息队列被打满的情况。
能力增强后的 ANRCanary 抓到的上报信息如下:
"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:进程存活时长并不大。正常消息队列应该只有几条消息,而不应该被打满。
看来 Timer 的间隔能力确实失效了,死循环问题是真实存在的。

最终定位

对于 Timer 的运行机制进行深入分析以后发现问题:
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();
}
}
}
如以上代码片段第 9 行所示,Timer 的间隔时间是基于系统时间戳的。也就是说,修改手机系统时间会影响 Timer 周期性任务的执行。
写一个简单的 Demo 验证以后得出结论:
  • 如果往前修改系统时间,周期性任务将停止执行。

  • 如果往后修改系统时间,间隔时间会失效,周期性任务开始连续不停地执行。
至此终于定位到该死循环的根因。修改方案就是把 Timer 替换为 ScheduleExecutorService 来实现周期性任务,将不受系统时间变更的影响。

总结

长久以来,线程死循环问题经常是偶现的,比较隐蔽难以发现,钉钉自研的 ANRCanary 通过将高 CPU 占用和堆栈比较相结合的方案,突破了线程死循环问题感知难,定位难的瓶颈。通过该监控能力,团队持续对潜在风险进行优化治理,线程死循环问题基本得到根治。
提升用户体验是一条漫漫长路,唯有从点滴做起,方能逐步做到卓越。


有效的死循环检测机制应该包括CPU占用监控和堆栈跟踪两个方面。可以通过捕捉高CPU占用的线程,并分析它的堆栈变化情况,查看是否有重复执行的模式。

HashMap处理多线程的时候,可能会出现resize时的循环链表问题,导致CPU使用率爆高。除了ConcurrentHashMap,也可以通过工具类Collections的synchronizedMap方法来包装HashMap。

除了死循环,HashMap还可能会出现线程看到的数据不一致现象,即所谓的脏读。使用线程安全的替代品如ConcurrentHashMap是一种解决策略,它内部采用分段锁技术,有效提高并发访问率。

设计时还需要考虑误报和漏报问题。例如,一些密集计算任务自然CPU占用高,和死循环不同。需要对业务逻辑有足够理解,按场景区别对待。

结合实时监控与定期检查,使用工具自动化跟踪线程状态,如Java中可以通过JVisualVM等工具来辅助检测。另外,还应该添加合适的日志记录,协助问题追踪和分析。

Timer定时任务是基于系统的实时时钟进行调度的,如果系统时间被修改,会直接影响到Timer的调度准确性,因此在系统时间被调整的情况下会出现执行异常。更稳定的替代方案是ScheduledExecutorService,它允许使用相对时间而非系统时间进行任务调度,从而避免了系统时间变动带来的影响。

Timer的问题在于它依赖的是绝对时间,这对于需要精准控制执行时间的应用场景是个大问题。而ScheduledExecutorService使用的是相对时间,更适合多任务并发处理,确保长时间运行的稳定性和准确性。

HashMap在多线程环境下会因为没有进行同步操作而可能导致死循环或数据不一致的问题。一个常见的办法是使用ConcurrentHashMap,它支持完全并发的检索和高预期并发更新。

使用Timer时,如果系统时间突然向前或向后跳跃,Timer计划的执行时间点会被打乱,导致计划任务执行的不可预期。ScheduledExecutorService是基于时间延迟来执行任务的,相对来说更加可靠。