Knojj Space
MTK稳定性问题分析
Knojj
  2024-01-02 20:47:57   2024-01-03 10:11:54

系统稳定性问题类型：

KE hang_detect NE JE EE WATCHDOG HWT HW_reboot等等以及应用ANR

Framwork/APP同学稳定性接触最多的主要是SWT/ANR类

SWT介绍:Sytem Server watchdog

63694739488889511363800088636174177227117933659298165System Server

为什么需要SWT机制?

在核心服务和核心线程卡住的时候，让系统有自动复位的机会。于是，google引入了Sytem Server watchdog机制。这个机制来监控核心服务和核心线程是否卡住。

SWT的原理

原理图：

6369473965402116959309633056368246868264969061877272616总框图

最开始设计只是在main looper 里面执行register 的monitor 对象 的monitor 方法. 后续Google 改进，通过HandlerChecker 来达成，在HandlerChecker 中审查注入的montior 对象是否能快速执行。即在foreground thread 来执行register 的monitor 对象，而对于其他的线程，则是审查规定时间内是否可以达到idle，不是一直卡死在某个message执行上。需要注意的是,__ SystemServer Watchdog启动是在SystemServer init 的后期, 如果SystemServer 在init 的过程中卡死了，那么就意味着watchdog 不会有任何的作用.__

源码启动区域：

在system_server的startBootstrapServices（）方法中初始化启动，老版本android在startOtherService（）方法中启动。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
private void startBootstrapServices(@NonNull TimingsTraceAndSlog t) {
            ...
            traceBeginAndSlog("InitWatchdog");

            final Watchdog watchdog = Watchdog.getInstance();

            watchdog.init(context, mActivityManagerService);

            traceEnd();

            ...

            traceBeginAndSlog("StartWatchdog");

            Watchdog.getInstance().start();

            traceEnd();

}

Watchdog的运行逻辑

  1. Watchdog运行后，便开始无限循环，依次调用每一个HandlerChecker的scheduleCheckLocked()方法2、调度完HandlerChecker之后，便开始定期检查是否超时，每一次检查的间隔时间由CHECK_INTERVAL常量设定，为30秒3、每一次检查都会调用evaluateCheckerCompletionLocked()方法来评估一下HandlerChecker的完成状态：      a、COMPLETED表示已经完成      b、WAITING和WAITED_HALF表示还在等待，但未超时      c、OVERDUE表示已经超时。默认情况下，timeout是1分钟，但监测对象可以通过传参自行设定，譬如PKMS的Handler Checker的超时是10分钟4、如果超时时间到了，还有HandlerChecker处于未完成的状态(OVERDUE)，则通过getBlockedCheckersLocked()方法，获取阻塞的HandlerChecker，生成一些描述信息5、保存日志，包括一些运行时的堆栈信息，这些日志是我们解决Watchdog问题的重要依据。如果判断需要杀掉system_server进程，则给当前进程(system_server)发送signal 9

06-28 17:29:39.002 1000 560 586 W Watchdog: *** GOODBYE!

06-28 17:29:39.002 1000 560 586 I Process : Sending signal. PID: 560 SIG: 9

ANR

首先理解什么是ANR?

ANR(Application Not responding)，是指应用程序未响应，Android系统对于一些事件需要在一定的时间范围内完成，如果超过预定时间能未能得到有效响应或者响应时间过长（即Android 应用的__UI线程__处于阻塞状态的时间过长），就会造成ANR。

如果应用位于前台，系统会向用户显示一个对话框，如图所示。

IMG_256

ANR 对话框会为用户提供强行退出应用的选项。

ANR的意义是什么？

负责更新界面的应用主线程无法处理用户输入事件或绘制操作，会引起用户的不满，故产生此机制，让应用或者开发者关注并避免此种情况。

ANR的三个条件

__主线程__：只有应用程序进程的主线程响应超时才会产生ANR；

__超时时间__：产生ANR的上下文不同，超时时间也会不同，但只要在这个时间上限内没有响应就会ANR；

__输入事件/特定操作__：输入事件是指按键、触屏等设备输入事件，特定操作是指BroadcastReceiver和Service的生命周期中的各个函数，产生ANR的上下文不同，导致ANR的原因也会不同

ANR的发生场景和常见类型

主线程被阻塞5秒钟以上，就会抛出ANR对话框。不同的组件发生ANR的时间不一样，Activity是5秒，BroadCastReceiver是10秒，Service是20秒（均为前台）。

常见类型：

1.点击事件(按键和触摸事件)5s内没被处理: Input event dispatching timed out；

2.service 前台20s后台200s未完成启动：Timeout executing service；

Service Timeout是位于”ActivityManager”线程中的AMS.MainHandler收到SERVICE_TIMEOUT_MSG消息时触发。

对于Service有两类:

对于前台服务，则超时为SERVICE_TIMEOUT = 20s；

对于后台服务，则超时为SERVICE_BACKGROUND_TIMEOUT = 200s

3.BroadcastReceiver的事件(onRecieve方法)在规定时间内没处理完(前台广播为10s，后台广播为60s)：Timeout of broadcast BroadcastRecord

以BroadcastReviever为例，在onRecieve()方法执行10秒内没发生第一种ANR(也就是在这个过程中没有输入事件或输入事件还没到5s)才会发生Receiver timeout，否则将先发生事件无响应ANR，所以onRecieve()是有可能执行不到10s就发生ANR的，所以不要在onRecieve()方法里面干活

4.ContentProvider的publish在10s内没进行完：timeout publishing content providers

ANR原理

  1. 在进行相关操作调用hander.sendMessage发送一个ANR的消息，延时时间为ANR发生的时间(如activity是当前时间5s之后)。

2.进行相关的操作

3.操作结束后remove掉该条message。如果相关的操作在规定时间没有执行完成，该条message将被handler取出并执行，就发生了ANR。

代码流程解释（service ANR超时监控）：

bumpServiceExecutingLocked__函数会调用__scheduleServiceTimeoutLocked(r.app);

从而发送消息mAm.mHandler.sendMessageDelayed(msg, proc.mServices.shouldExecServicesFg()? SERVICE_TIMEOUT : SERVICE_BACKGROUND_TIMEOUT);

到此，system_server在创建service，并发送了超时消息。

如何处理这个消息？

在ActivityThread.java中的handleCreateService方法调用serviceDoneExecuting函数并调用至__serviceDoneExecutingLocked方法__

进而调用mAm.mHandler.removeMessages(ActivityManagerService.SERVICE_TIMEOUT_MSG, r.app);

以上方法的主要工作是当service启动完成，则移除服务超时消息SERVICE_TIMEOUT_MSG。

但是当没有成功移除此消息时，会发生ANR，这个消息的接收在ActivityManagerService.java ::MainHandler中。

1
2
3
4
5
6
7
8
9
10
11
case SERVICE\_TIMEOUT\_MSG: \{

                  /// M: ANR Debug Mechanism @\{

                  if (mAnrManager.delayMessage(mHandler, msg, SERVICE_TIMEOUT_MSG,ActiveServices.SERVIC_TIMEOU))

                  return; }

                  mServices.serviceTimeout((ProcessRecord) msg.obj);

\}

进一步在函数中调用

1
2
3
4
5
void serviceTimeout(ProcessRecord proc) {
......
 if (anrMessage != null) {
mAm.mAnrHelper.appNotResponding(proc,anrMessage);
}

总的来说是在启动activity或者服务时通过发送一个超时消息，当时间到了之后，没有将此条timeout消息移除，则就会触发timeout流程，回调mAm.appNotResponding(proc, null, null, false, anrMessage);

关于appNotResponding函数：（见链接）

http://aosp\.opersys\.com/xref/android\-12\.0\.0\_r2/xref/frameworks/base/services/core/java/com/android/server/am/ProcessErrorStateRecord\.java\#219

在这里会打印出当前发生ANR的必要信息以及通过调用mService.addErrorToDropBox（）函数往dropbox中去写入ANR trace， 至此也就是为什么研发工程师从dropbox取ANR的trace来分析anr。

常见SWT/ANR原因：

1. 等锁

线程状态为“Blocked”，通过关键字“held by”进一步确认哪个线程拿住了锁，如有死锁检查code逻辑进行解锁；

线程状态为“Waiting”，表示当前线程需要另外一个线程来notify()，需要根据callstack结合code来做分析，以找到是另外的某个线程拿住了锁。

2. SurfaceFlinger卡住

SF hang Time > 40s（Service.sf.status值），sf hang，

直接在”SYS_ANDROID_LOG”搜索”I watchdog”，看是否有“surfaceflinger hang”关键字。如果有，请进一步确认main_log里有”SF-WD”相关log打印；

SystemServer或其它进程的thread block在android.view.SurfaceControl.XXXX，这通常是该进程binder到SurfaceFlinger，等surfaceflinger返回；这时候不一定是main thread卡住了，mainlog中不一定有“SF-WD”

这种情况一般都需要首先排查SurfaceFlinger。

3.Native方法执行时间过长

线程状态为”Native”，根据native方法找到对应模块的owner，进一步确认该native方法为何执行时间过长，例如是否等待硬件返回或者硬件本身存在问题等,binder:transact

4. Binder Server卡住

线程状态为“Native”，且含有如下callstack：

IPCThreadState::waitForResponse-->IPCThreadState::talkWithDriver，这种问题重点是找对端，找对端是在执行什么操作，是被卡住还是执行时间太长无返回。

5. Zygote fork进程时卡住

线程状态为”Native”，确认callstack中有”Process.zygoteSendArgsAndGetResult”，

对于Zygote fork进程时卡住的问题，一般是由于底层memory问题引起的

6.Dump时间过长

发生Anr系统在dump信息过多时引发，一般为系统loading过重引发

onReachLimit(){

dumpbinderInfo();

}

7.性能问题

这种问题需要check系统状态

关于SWT/ANR问题的分析方法与一般步骤

SWT相关：

如何确认重启/异常类型？通过解析db，db_history文件查看

  1. DB:在mtk平台我们统一通过db文件来确认系统发生了何种异常；是通过Aee机制实现的，db路径生成在设备内data/aee_exp或data/vendor/aee_exp；由于安全策略的限制，默认系统不会抓取Normal DB（如普通app的Anr情况），只会抓取fatal db，如需要抓取normal exception db，可修改rc通过设置属性ro.vendor.aee.enforcing为no，可以去设置抓取Normal exception的db文件。
  2. 如何解析DB：使用GAT解析db，解析后会生成db中的各类信息，如_exp_main.txt,SYS_BINDER_INFO，SWT_JBT_TRACES等...

关于db信息的提取：

  1. 查看重启类型，查看_exp_main.txt中的BackTrace信息；
  2. 如根据_exp_main.txt已经足够提取到有效信息，则关注具体发生问题的原因；如无法提取到足够信息，则进一步提取db抓取到的其他信息
  3. 根据提取到的结论，确认是客制化修改还是原生逻辑或其他原因，制定不同策略处理。

ANR相关：

ANR问题主要有两种原因:应用自身的问题和系统异常导致的问题。在分析 ANR 问题的时候，最主要的就是要确定是哪个原因导致的(当然也有一些中间地带，比如代码写的不好，在正常情况下不会暴露，在系统出问题的时候很快就暴露出来)

ANR问题一般的分析步骤如下:

1、分析trace.txt:查看是否有明显的异常，比如死锁、SystemServer异常持锁等

1.死锁堆栈:观察Trace堆栈，确认是否有明显问题，如主线程是否与其他线程发生死锁，如果是进程内部发生了死锁，只需找到与当前线程死锁的线程，问题即可解决

2.业务堆栈:观察通过Trace堆栈，发现当前主线程堆栈正在执行业务逻辑，这时候需要分析对应的代码，查看是否真的有问题

1.重要:如果业务方觉得这里没有问题，需要进一步分析，因为Trace堆栈可能并不是真正耗时的地方，需要结合其他信息一起分析

3.IPC Block堆栈:观察通过Trace堆栈，发现主线程堆栈是在跨进程(Binder]通信，这时候可以根据其他Log、BinderInfo等信息，来分析IPC信息

1.大部分IPC都是在跟SystemServer，如果没有Binderlnfo，可以搜索对应的接口关键字，在SystemServer进程查找是否有相关的堆栈

4.系统堆栈:通过观察Trace，发现当前堆栈只是简单的系统堆栈，比如NativePollOnce，想要搞清楚是否发生严重耗时，以及进一步的分析定位

重要:大部分比较难分析的ANR基本上应用主线程堆栈都是NativePollOnce这个状态，之所以出现这种状态，可能有下面几个原因：

1.确实没有消息在处理，可能进程被冻结，或者No Focused Window这种 ANR

2.刚好处理完某一个耗时消息，系统抓堆栈的时候，已经晚了，耗时的状态没有抓到；

3.线程调度的原因，主线程没有机会执行。

2、分析 EventLog:

看具体的ANR时间(搜索am_anr)，看看是否跟ANRlog能够对上，以确定ANRLog是否有效，如果ANRLog有效,分析ANRLog，提取有用信息:pid、tid、死锁等，遇到ANR问题，摆在我们面前的trace是不是第一案发现场，如果ANR发生的输出的信息很多，当时的CPU和1/0资源比较紧张，那么这段日志输出的时间点可能会延迟10秒到20秒都有可能，所以我们有时候需要提高警惕。不过正常情况下，EventLog中的am_anr的输出时间是最早的，也是最接近 ANR时间的(提取有效信息到单独文件中)

3.分析AndroidLog:看MainLoq(AndroidLog)或者SystemLog查看ANR详细信息(搜索ANR

in),提取有效的信息(提取有效信息到单独文件中)

1.发生ANR的时间

2.打印ANR日志的进程

3.发生ANR的进程

4.发生 ANR 的原因

5.CPU负载

6.Memory 负载

7.CPU使用统计时间段

8.各进程的CPU使用率

1.总的 CPU 使用率

2.缺页次数fault

1.xxxminor表示高速缓存中的缺页次数，可以理解为进程在做内存访问

2.xxxmajor表示内存的缺页次数，可以理解为进程在做10操作

9.CPU使用汇总

4.配合Main Log[AndroidLog]和EventLog把CPU开始和结束的时间点内的所有有用信息提取出来到一个文件中，搜索的主要关键字:pid，进程名，WindowManager、ActivityManager等

1.收集关键操作场景，比如解锁、安装应用、亮灭屏、应用启动等

2.收集异常和系统关键Log：

1.系统变慢:比如Slowoperation，Slow dispatch、Slow delivery、dvm lock sample

2.进程变化:am_kill、am_proc_died.lowmemorykiller、ANR、应用启动关系等

3系统信息:cpuinfo、meminfo、binderinfo(是否满了 IpcState:waiting thread to free)、iowait[是否过高]

4.消息监控:ANR前的ANRMessage打印，Block Message 信息，应用自己代码执行逻辑推断出的Message耗时等

3.收集ANR进程的所有关键线程的运行情况线程优先级等

4.根据第四步提取出来的关键信息文件，进一步理出系统当时的情况、状态((推荐

vscode或者notepad++，有线索就全局搜索))，比如：

1.是处于低内存频繁杀进程?

2重启第一次解锁系统繁忙

3.还是短时间内多个应用启动系统繁忙

4.还是应用自己的逻辑等待?

5.针对不同的ANR类型，提取不同的信息，不行就加Log复现

案例分析：SWT问题（分析anr类trace也可参考此过程，上述的__原因__134均在此案例中有所体现）____

  1. 确认原因：

首先仅从，db携带的文件后缀即可以初步看出是什么类型的异常，此份异常为SWT(SyetemServerWatchDog),并非抓取到db一定是重启，也可能是Hang屏，死机，子系统重启等问题，并不一定会带来设备的重启；如果是重启机器，初步可以通过bugreport提取boot.reason信息，查看上次设备重启类型：如[persist.vendor.aeev.last.boot.reason]: [reboot,shell]；有的机型在适配bootreason的selinux权限时没做好，可能会出现bugreport无法查询到重启原因的关键字属性，此时可以在Mtklog的mobilelog中提取properties中的信息，properties记录的信息为上次重启前的系统属性文件。

  1. 分析_aee_exp.txt

提取头部信息，看到异常原因为SWT system_server_watchdog，system_server进程被block

Exception Class: SWT

Exception Type: system_server_watchdog

__Current Executing Process: __

system_server

Trigger time:[2022-04-13 10:37:13.419704] pid:1557

__Backtrace: __

Process: system_server

Subject: Blocked in handler on foreground thread (android.fg), Blocked in handler on main thread (main), Blocked in handler on display thread (android.display), Blocked in handler on animation thread (android.anim), Blocked in handler on ActivityManager (ActivityManager)

ErrorId: 8727de2e-d778-44cb-9583-8069abe8049c

观察主线程信息：

主线程处于Blocked状态，说明主线程在等锁过程中被block,继续跟进锁的信息，根据Held by thread 31，继续去查询tid=31的线程在执行什么逻辑，可以搜索关键字tid=31或者直接搜索锁的地址0x01e74e68，查询后发现持锁未释放原因是tid=31线程在等另外一个锁

当在文件中继续查询tid=208或者锁0x017e2bf8时，发现无法继续搜到相关线程信息，线索断了....

这种情况很常见，_exp_main.txt中的trace信息和系统dump出anr trace差不多，在有些时候很难将所有信息抓全，或者dump的时机提前或延后，很容易造成无效trace，在抓了db的情况下，在这种情况可以进一步去看db文件夹中的SWT_JBT_TRACES文件，会存留一些信息作为对_exp_main.txt的补充。在此文件搜索锁信息或tid信息，可以看到这里是最后一把锁的位置

找到__最终的锁__信息后的四步走：1.确认锁 2.线程状态 3.是否在做binder通信 4.大概是在做什么？

针对本例：2__确认此线程处于Native状态，说明函数的执行已经在Native方法里了，不存在线程block了， 3__binder通信的关键字IPCThreadState::talkWithDriver说明了在和对端做binder通信 __4__在binder通信时大概是执行什么方法到了对端？一般情况下，比如此例中的__BpSurfaceComposerClient::createSurface__基本可以猜到这个binder通信的对象是__SurfaceFlinger__了。本着可能无法确认对端的情况，顺便明确下如何通过__binder client__端查询对端__binder server__，按照标准路径继续下一步查对端的信息，这种情况还需要借助SWT_JBT_TRACES来查，或者是通过SYS_BINDER_INFO来查。

在SWT_JBT_TRACES可能无法查询到binder信息，直接在SYS_BINDER_INFO搜索，查询关键字：

outgoing transaction

搜索__outgoing transaction__时，会过滤出大量的信息，__如何提取自己需要查询的binder信息？**四个数字__A:B to C:D(cpid:ctid to spid:stid)**

解释： A:client端进程的PID，B:client端进程的SYSTID；

   C:server端进程的PID，D:server端进程的SYSTID;

此例：client端信息：Binder线程1557_13,1557为system_server的client pid，systid=3103,

所以我们查询binder信息时，过滤此关键信息，得到：

outgoing transaction 158952757: 0000000000000000 from 1557:3103 to 895:931 code 1 flags 10 pri 0:110 r1 start 60872.334366 android 2022-04-13 10:35:48.743

说明此案例的server对端为pid为895，systid为931的线程；

最终我们定位的结论即为：当surfaceflinger执行android::Client::createSurface方法内斥锁迟迟没有释放，执行时间太长，没有返回，故卡在了对端，client端被blocked。

查看代码：

这个问题我们看到了最终的锁，但是目前以自己对surfaceflinger的理解不足以让我们独立解决这个问题，在aosp上找到了问题的patch，至此一个完整的问题闭环。虽然我们看到了我们在具体模块上的不足，甚至最终并不是我们提交的patch；

但是大部分情况下我们只需要拥有定位问题和将问题指向具体模块的能力就够了，经过详细精准的分析流转到具体的模块不代表我们只会转bug，而是具体的事需要专业的owner做，每个模块的owner都有每个模块特有的法宝和方法来处理各自模块的问题。我们力求做到分析定位精准以推进问题的解决。

一种系统常见类型：NE__

 Native属于linux再上一层，可以直接运行于linux的那一层，用于区别java层。native层是由各种lib/binary组成。同样这一层也会出现这种异常，我们称为NE。NE的全称是native exception。

常见于系统重要组件，如SurfaceFlinger，AudioServer,SensorService....

NE问题出现怎么处理？如何还原执行函数

举一较为简单的例子，只介绍方法，不代表所有的NE都这么好分析：-_-

SF NE问题，空指针问题，堆栈最终停留在SetFrameRate方法

空指针好解，但是函数调用在哪呢？

借助什么解析？addr2line

工具如何获取？源码

路径：prebuilts/gcc/linux-x86/aarch64/aarch64-linux-android-4.9/bin/

（此为64位，32位的路径在：prebuilts/gcc/linux-x86/arm/***/bin）具体路径自己翻翻代码

命令：__aarch64-linux-android-addr2line -Cipfe $symbols中对应的so库 $堆栈地址__

如：./aarch64-linux-android-addr2line -Cipfe /symbols/system/lib64/libsurfaceflinger.so 00000000000e9c2c

针对这个堆栈解析：

？？？

1：#00 pc 00000000000e9c2c

:2：#01 pc 0000000000146044

定位到调用逻辑：

services/surfaceflinger/SurfaceFlinger.cpp:6836

最终解决方案：

其他类型常见问题：

常见的mtk平台的硬件类稳定性问题，此类问题，转底层和硬件分析确认

1.OCP电源过流保护

2.HW_reboot

硬件重启，超出WDT超时机制范围

3.HWT

硬件WDT超时机制

4.2sec_reboot VSYS 供电不稳定；2sec_reboot问题属于PMIC突然掉电，软件侧的dump保存流程根本不可能来得及跑。属于硬件问题

  1. KE kernel panic
MTK稳定性问题分析
2024/01/02/MTK稳定性问题分析/
Author
Knojj
Published
2024-01-02 20:47
License
  1. 系统稳定性问题类型：
  2. SWT介绍:Sytem Server watchdog
    1. 为什么需要SWT机制?
      1. SWT的原理
      2. 源码启动区域：
      3. Watchdog的运行逻辑
  3. ANR
    1. 首先理解什么是ANR?
    2. ANR的意义是什么？
    3. ANR的三个条件
      1. ANR的发生场景和常见类型
    4. 常见类型：
    5. ANR原理
    6. 常见SWT/ANR原因：
      1. 1. 等锁
      2. 2. SurfaceFlinger卡住
      3. 3.Native方法执行时间过长
      4. 4. Binder Server卡住
      5. 5. Zygote fork进程时卡住
      6. 6.Dump时间过长
      7. 7.性能问题
  4. 关于SWT/ANR问题的分析方法与一般步骤
    1. SWT相关：
      1. 如何确认重启/异常类型？通过解析db，db_history文件查看
      2. 关于db信息的提取：
    2. ANR相关：
      1. ANR问题一般的分析步骤如下:
    3. 案例分析：SWT问题（分析anr类trace也可参考此过程，上述的__原因__134均在此案例中有所体现）____
  5. 一种系统常见类型：NE__
    1. NE问题出现怎么处理？如何还原执行函数
      1. 借助什么解析？addr2line
  6. 其他类型常见问题：
  1. 系统稳定性问题类型：
  2. SWT介绍:Sytem Server watchdog
    1. 为什么需要SWT机制?
      1. SWT的原理
      2. 源码启动区域：
      3. Watchdog的运行逻辑
  3. ANR
    1. 首先理解什么是ANR?
    2. ANR的意义是什么？
    3. ANR的三个条件
      1. ANR的发生场景和常见类型
    4. 常见类型：
    5. ANR原理
    6. 常见SWT/ANR原因：
      1. 1. 等锁
      2. 2. SurfaceFlinger卡住
      3. 3.Native方法执行时间过长
      4. 4. Binder Server卡住
      5. 5. Zygote fork进程时卡住
      6. 6.Dump时间过长
      7. 7.性能问题
  4. 关于SWT/ANR问题的分析方法与一般步骤
    1. SWT相关：
      1. 如何确认重启/异常类型？通过解析db，db_history文件查看
      2. 关于db信息的提取：
    2. ANR相关：
      1. ANR问题一般的分析步骤如下:
    3. 案例分析：SWT问题（分析anr类trace也可参考此过程，上述的__原因__134均在此案例中有所体现）____
  5. 一种系统常见类型：NE__
    1. NE问题出现怎么处理？如何还原执行函数
      1. 借助什么解析？addr2line
  6. 其他类型常见问题：