最佳实践｜一文讲解端线程死循环的治理

653次阅读  |  发布于1月以前

阿里妹导读

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

引言

钉钉作为一个用户数超 7 亿，服务企业与组织数超过了 2500 万的企业级智能办公平台，终端团队一直将打造极致用户体验作为我们的理念。对于 Android 设备来说，线程死循环问题可能会导致高耗电，界面卡顿，耗尽内存等性能问题。与此同时，死循环问题还具有隐蔽性高，黑盒测试无法感知的特点。针对潜在的线程死循环风险我们进行了专项的治理优化。

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

术语表

线程死循环检测机制

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

获取线程 CPU 占用比

通过读取 Android 系统 proc 目录下面的 stat 文件可以获取进程和线程的 CPU 耗时，如下所示：

如果想计算一段时间区域内的各线程 CPU 占用比，只需要根据进程和线程的 CPU 耗时差值，计算即可得出。通常可以将 CPU 占用比超过 10% 的线程标记为高耗时线程。

堆栈比较方案

死循环线程还有一个特点就是当出现一个循环点时，线程堆栈的底部是永远相同的。以查询历史数据过多的数据库而导致死循环的案例堆栈为例：

如上图所示，针对该线程在一定时间间隔内抓的三个堆栈，可以发现堆栈的相似度很高，则可以将其作为死循环的重点怀疑对象。

CPU 占用和堆栈比较相结合

起因

CPU 占用方案：基于 stat 文件可以知道一个线程占了比较高的 CPU ，但是有效信息只有线程名， 对应不上代码，因此很难分析出耗 CPU 的根因。

堆栈比较方案：能够拿到堆栈信息，但是当线程发生阻塞时（比如读 IO 或跨进程通信），堆栈相似度也很高，因此误报率比较高。因此唯有将两个方案结合起来，才能比较准确地拿到高 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)"
    ]
  }
}

案例 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)"
  ]
}

案例 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)"
  ]
}

监控能力增强

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)"
  ]
}

从附加信息来看，泄露的属性动画为：

基于 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)"
  ]
}

监控能力增强

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

能力增强后的 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)"
  ]
}

看来 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 占用和堆栈比较相结合的方案，突破了线程死循环问题感知难，定位难的瓶颈。通过该监控能力，团队持续对潜在风险进行优化治理，线程死循环问题基本得到根治。提升用户体验是一条漫漫长路，唯有从点滴做起，方能逐步做到卓越。

Copyright© 2013-2020

All Rights Reserved 京ICP备2023019179号-8