#我的鸿蒙开发手记# 鸿蒙性能优化之应用无响应 原创 精华

一、简介

在《鸿蒙性能优化之卡顿优化》一文中介绍卡顿优化，除了卡顿外，还有应用无响应，用户在使用应用时会出现点击没反应、应用无响应等情况，其超过一定时间限制后即被定义为应用无响应。当发生卡顿，用户还能使用应用；当发生无响应，用户将无法使用应用，系统会杀死应用。本文将介绍应用无响应检测原理、应用无响应的日志获取方式以及日志信息。

二、应用无响应检测原理

当前应用不响应检测主要包括下表中的类型。

故障类型	说明
THREAD_BLOCK_6S	主线程超时卡死
APP_INPUT_BLOCK	用户输入响应超时
LIFECYCLE_TIMEOUT	Ability生命周期切换超时

2、1 THREAD_BLOCK_6S主线程超时卡死检测原理

应用的看门狗线程定期向主线程插入探测消息，并在自己线程插入超时上报机制。当探测消息超过3s没有被执行，会上报THREAD_BLOCK_3S警告事件；超过6s依然没有被执行，会上报THREAD_BLOCK_6S主线程卡死事件。两个事件匹配生成THREAD_BLOCK的应用无响应日志。

2、2 APP_INPUT_BLOCK用户输入响应超时检测原理

用户的点击事件超过一定时间限制未得到响应，严重影响当前用户体验。用户点击应用的按钮时，输入系统会向应用侧发送点击事件，如果超时未收到应用侧的响应反馈回执，则上报该故障。

2、3 LIFECYCLE_TIMEOUT生命周期切换超时检测原理

生命周期切换超时分为Ability生命周期切换超时和PageAbility生命周期切换超时。其原理是：在生命周期开始执行向看门狗线程插入超时任务，在生命周期执行完成后移除超时任务，固定时间内未成功移除超时任务上报改故障。生命周期切换超时由LIFECYCLE_HALF_TIMEOUT和LIFECYCLE_TIMEOUT两个事件组合而成，LIFECYCLE_HALF_TIMEOUT作为LIFECYCLE_TIMEOUT的警告事件。
不同的生命周期，超时时间不一样：

生命周期	超时时间
load	10秒
Terminate	10秒
Connect	3秒
Disconnect	0.5秒
Foreground	5秒
Background	3秒

对应关系如下图

2、4 获取堆栈

当发生不响应。才去获取堆栈，堆栈可能不准确。因为此时可能已经没有不响应了，此时获取的堆栈就是没有发生不响应的堆栈，我们应当提前获取堆栈。

当主线程处理事件时间在150毫秒到450毫秒之间，系统开始执行周期性任务检测，每隔155ms检测主线程是否再次发生超时事件(总共检测两次)，共三种情况：

• 第一次检测发现超时事件，开始执行堆栈采样，每隔155毫秒采样一次，共采样10次堆栈，第11次收集堆栈并上报事件，结束检测。
• 第一次检测未发生超时事件，第二次检测发现超时事件，开始执行堆栈采样，每隔155毫秒采样一次，共采样10次堆栈，第11次收集堆栈并上报事件，结束检测。
• 两次检测均未发现超时事件，结束检测。

三、应用无响应日志获取

可通过以下方式获取日志：

• 通过DevEco Studio获取日志，DevEco Studio会收集设备的故障日志并归档到FaultLog。
• 通过hiappevent获取，hiappevent对外提供订阅系统卡死事件，可以查询卡死事件信息，这是线上监控应用无响应的方式。关于线上性能监控，可以查看《实战鸿蒙，实现一款线上性能监控框架》。
• 通过shell获取日志，应用无响应日志是以appfreeze-开头，生成在设备“/data/log/faultlog/faultlogger/”路径下。该日志文件名格式为“appfreeze-应用包名-应用UID-秒级时间”。

3、1 日志基本信息

1、进程号：在日志中搜索"Pid"。根据进程号可以查找对应进程的栈信息、在流水日志中过滤出对应进程的日志输出等。
  2、故障类型：在日志中搜索"Reason"。根据故障类型可以参考对应类型的检测原理和故障检测时长。
  3、故障上报时间点：在日志中搜索"Fault time"。
  4、前后台信息：在日志中搜索"Foreground"。
  5、检测时长：对于THREAD_BLOCK_6S事件，当应用处于前台时，检测时长为6s；当应用处在后台时，由于不直接与用户交互，其对主线程阻塞判断有所放宽，其故障检测时长为21s。对于LIFECYCLE_TIMEOUT事件，可以从MSG的reason部分获取是哪种生命周期超时，参照表格获取其对应的故障检测时长。

3、2 eventHandler信息

eventHandler记录了各个队列中各个任务的执行时间，日志里面会有两个eventHandler，第一个eventHandler是警告事件，表明快要发生不响应了。第二个eventHandler是阻塞事件，表明已经发生了不响应。

3、2、1 当前任务运行时长

EventHandler dump begin curTime: 2025-02-16 04:39:06.296
Event runner (Thread name = , Thread ID = 60129) is running
Current Running: start at 2025-02-16 04:39:00.333, Event { send thread = 60129, send time = 2025-02-16 04:39:00.233, handle time = 2025-02-16 04:39:00.333, trigger time = 2025-02-16 04:39:00.333, task name = uv_timer_task, caller = [ohos_loop_handler.cpp(OnTriggered:72)] }

trigger time指的是任务开始运行时间，dump begin curTime指的是发生卡顿，获取日志的时间。
  当前任务已运行时长 = dump begin curTime - trigger time，如示例中当前任务运行达到6秒。若时间差 > 故障检测时长，表示当前正在运行的任务即是导致应用卡死的任务，需排查该任务运行情况。若时间差较小，表示当前任务仅是检测时间区间内主线程运行的任务之一，主要耗时不一定是本任务，需排查近期运行的任务中耗时较长者。

3、2、2 历史任务队列信息

 History event queue information:
 No. 1 : Event { send thread = 60129, send time = 2025-02-16 04:39:00.228, handle time = 2025-02-16 04:39:00.279, trigger time = 2025-02-16 04:39:00.281, completeTime time = 2025-02-16 04:39:00.281, priority = Low, task name = ArkUIIdleTask }
 No. 2 : Event { send thread = 60185, send time = 2025-02-16 04:39:00.293, handle time = 2025-02-16 04:39:00.293, trigger time = 2025-02-16 04:39:00.293, completeTime time = 2025-02-16 04:39:00.293, priority = High, task name = IdleTime:PostTask }
 No. 3 : Event { send thread = 60129, send time = 2025-02-16 04:39:00.233, handle time = 2025-02-16 04:39:00.333, trigger time = 2025-02-16 04:39:00.333, completeTime time = , priority = Low, task name = uv_timer_task }
 No. 4 : Event { send thread = 60185, send time = 2025-02-16 04:38:57.295, handle time = 2025-02-16 04:38:57.295, trigger time = 2025-02-16 04:38:57.295, completeTime time = , priority = Low, task name =  }

可以从历史任务队列中寻找故障发生时间区间内较为耗时的任务。其中completeTime time为空的任务即是当前任务。任务运行耗时 = completeTime time - trigger time。

3、2、2 VIP priority event queue information超高优先级任务队列信息

VIP priority event queue information:
No.1 : Event { send thread = 3205, send time = 2025-02-16 04:11:15.407, handle time = 2024-08-07 04:11:15.407, task name = ArkUIWindowInjectPointerEvent, caller = [task_runner_adapter_impl.cpp(PostTask:33)] }
No.2 : Event { send thread = 3205, send time = 2025-02-16 04:11:15.407, handle time = 2024-08-07 04:11:15.407, task name = ArkUIWindowInjectPointerEvent, caller = [task_runner_adapter_impl.cpp(PostTask:33)] }

用户输入事件传递链中的任务都属于超高优先级任务，为保障第一时间响应用户。

3、2、3 High priority event queue information高优先级任务队列信息

High priority event queue information:
No.1 : Event { send thread = 35862, send time = 2025-02-16 12:17:25.526, handle time = 2024-08-08 12:17:25.526, id = 1, caller = [watchdog.cpp(Timer:156)] }
No.2 : Event { send thread = 35862, send time = 2025-02-16 12:17:28.526, handle time = 2024-08-08 12:17:28.526, id = 1, caller = [watchdog.cpp(Timer:156)] }
No.3 : Event { send thread = 35862, send time = 2025-02-16 12:17:31.526, handle time = 2024-08-08 12:17:31.526, id = 1, caller = [watchdog.cpp(Timer:156)] }

watchdog任务位于高优先级队列中，每隔3秒发送一次。对比警告/阻塞事件：

警告事件

High priority event queue information:
No.1 : Event { send thread = 35862, send time = 2025-02-16 12:17:25.526, handle time = 2024-08-08 12:17:25.526, id = 1, caller = [watchdog.cpp(Timer:156)] }
No.2 : Event { send thread = 35862, send time = 2025-02-16 12:17:28.526, handle time = 2024-08-08 12:17:28.526, id = 1, caller = [watchdog.cpp(Timer:156)] }
No.3 : Event { send thread = 35862, send time = 2025-02-16 12:17:31.526, handle time = 2024-08-08 12:17:31.526, id = 1, caller = [watchdog.cpp(Timer:156)] }
Total size of High events : 3

阻塞事件

High priority event queue information:
No.1 : Event { send thread = 35862, send time = 2025-02-16 12:17:25.526, handle time = 2024-08-08 12:17:25.526, id = 1, caller = [watchdog.cpp(Timer:156)] }
No.2 : Event { send thread = 35862, send time = 2025-02-16 12:17:28.526, handle time = 2024-08-08 12:17:28.526, id = 1, caller = [watchdog.cpp(Timer:156)] }
No.3 : Event { send thread = 35862, send time = 2025-02-16 12:17:31.526, handle time = 2024-08-08 12:17:31.526, id = 1, caller = [watchdog.cpp(Timer:156)] }
No.4 : Event { send thread = 35862, send time = 2025-02-16 12:17:34.530, handle time = 2024-08-08 12:17:34.530, id = 1, caller = [watchdog.cpp(Timer:156)] }
Total size of High events : 4

阻塞队列相比于警告队列长，而对应的第一个任务没有发生变化，可能存在两种情况：

• 当前正在运行的任务卡死阻塞，导致其他任务一直未被调度执行。
• 更高优先级队列中任务堆积，导致watchdog任务未被调度执行。

3、3 堆栈信息

日志中最重要的就是堆栈信息了，一般来说，堆栈会直接定位到问题代码，但是有时堆栈也无法直接定位到问题代码。日志中会有两个堆栈，第一个是警告堆栈，第二个阻塞堆栈。比如主线程卡死，第一个堆栈就是3秒卡死的堆栈，第二个堆栈就是6秒卡死的堆栈。

3、3、1 警告堆栈和阻塞堆栈一致

大部分情况下，警告堆栈和阻塞堆栈一致，这种情况下，堆栈一般可以直接定位到问题代码。

警告堆栈和阻塞堆栈一致，在等锁的情况下卡死了，通过反编译获取对应代码行，排查其他线程栈和代码上下文锁的使用。

# 01 pc 00000000000c3e40 /system/lib64/libc++.so(std::__h::mutex::lock()+8)(9cbc937082b3d7412696099dd58f4f78242f9512)

警告堆栈和阻塞堆栈一致，binder卡死，也就是跨进程调用卡死了。通过跨进程栈帧下面的业务栈帧，识别应用是通过什么接口进行跨进程请求，识别对端是什么进程。需要结合binder调用链，确定对端阻塞没有返回的原因。

# 01 pc 0000000000006508 /system/lib64/chipset-pub-sdk/libipc_common.z.so(OHOS::BinderConnector::WriteBinder(unsigned long, void*)+100)(1edec25445c569dd1093635c1da3bc0a) --> binder 卡死

警告堆栈和阻塞堆栈一致，卡在某业务栈帧。

#01 at anonymous (entry/src/main/ets/pages/Index.ets:93:11)

3、3、2 瞬时栈

瞬时栈指的是警告堆栈和阻塞堆栈不一致，表示两个时刻是在线程的运行过程中抓取的栈信息，此时进程未卡死，属于线程繁忙场景。这种情况需结合trace和hilog判断应用具体运行场景，针对场景进行优化。

3、4 hilog信息

当堆栈无法直接定位问题，就需要结合hilog信息。搜索关键词“catcher cmd: hilog”

catcher cmd: hilog -z 1000 -P 
02-16 16:35:02.367 60129 60129 E A03D00/com.shijing.zijin/JSAPP: accessSync failed with error message: No such file or directory, error code: 13900002
02-16 16:35:02.370 60129 60129 E A03D00/com.shijing.zijin/JSAPP: accessSync failed with error message: No such file or directory, error code: 13900002
02-16 16:35:02.371 60129 60129 I A03D00/com.shijing.zijin/JSAPP: Callee constructor is OK string
02-16 16:35:02.371 60129 60129 I A03D00/com.shijing.zijin/JSAPP: Ability::constructor callee is object [object Object]
02-16 16:35:02.384 60129 60129 I A00000/com.shijing.zijin/testTag: Ability onWindowStageCreate
02-16 16:35:02.392 60129 60129 I A00000/com.shijing.zijin/testTag: Ability onForeground

一般分析步骤：

1、搜索关键词 “NotifyAppFault” 确定故障上报时间点

2、推断故障检测区间

3、判断该时间区间内应用主线程运行状态

3、5 trace信息

当主线程处理时长大于450毫秒，系统就会抓Trace。调用录制函数后，每隔150毫秒检测主线程是否再次发生超时事件(检测次数 = 20)，其中，只要在20个间隔检测时，有一次主线程事件超时150ms，3s检测结束后落盘trace。
  trace大小为1-5M，对于trace文件的解析可以使用smpartperf在线工具进行解读。
  导入trace文件后页面解读：从上往下主要展示时间轴、cpu使用率、cpu使用情况、进程间通讯数据的方法调用情况、进程、线程和方法调用情况，由此可以在事件维度上对这些数据进行直观展示。
  更多对trace文件使用的介绍可以参考：web端加载trace说明。

注意

启动主线程超时检测抓取trace的功能的前提：开发者使用nolog版本，开发者模式处于关闭状态；
  log和nolog版本：在手机中，点击设置——搜索关键字“关于本机”——软件版本进行查看。log版本会以log结尾；
  关闭开发者模式后， 可能无法使用DevEco Studio。因此，可以提前安装应用，再关闭开发者模式。