分析AppFreeze（应用无响应）

         用户在使用应用时会出现点击没反应、应用无响应等情况，其超过一定时间限制后即被定义为应用无响应(appfreeze)。系统提供了检测应用无响应的机制，并生成appfreeze日志供应用开发分析。

一、应用无响应检测能力点

        目前应用无响应检测从以下维度检测，应用开发者了解其原理对定位和分析appfreeze故障非常有帮助。

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

        1、THREAD_BLOCK_6S

        该故障出现表示当前应用主线程有卡死或者执行任务过多的情况，影响任务执行的流畅度和体验。

        该事件的检测原理是：应用的watchdog线程定期向主线程插入判活检测，并在自己线程插入超时上报机制。当判活检测超过3s没有被执行，会上报THREAD_BLOCK_3S警告事件；超过6s依然没有被执行，会上报THREAD_BLOCK_6S主线程卡死事件。两个事件匹配生成THREAD_BLOCK的应用无响应日志。

        检测原理如下图：

         

        2、APP_INPUT_BLOCK

        该故障是指用户的点击事件超过一定时间限制未得到响应，严重影响当前用户体验。

        该事件的检测原理是：用户点击应用的按钮时，输入系统会向应用侧发送点击事件，但超时未收到应用侧的响应反馈回执，则上报该故障。

        检测原理如下图：

        

        3、生命周期切换超时

        生命周期切换超时分为Ability生命周期切换超时和PageAbility生命周期切换超时。

        该故障出现在生命周期切换的过程中，影响当前应用内Ability的切换或者不同PageAbility之间的切换。

        该事件的检测原理是：通过获取不同生命周期切换的过程，在生命周期切换开始的位置向watchdog线程插入超时任务，在生命周期切换完成之后移除超时任务，固定时间内未成功移除将上报故障。

        生命周期切换超时由LIFECYCLE_HALF_TIMEOUT和LIFECYCLE_TIMEOUT两个事件组合而成。LIFECYCLE_HALF_TIMEOUT作为LIFECYCLE_TIMEOUT的警告事件，抓取binder等信息。

        

        不同的生命周期，超时的时间不一样：

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

二、应用无响应日志分析

        应用无响应(appfreeze)故障需要结合应用无响应日志和流水hilog日志一起分析。

        当前示例仅提供一个分析方法，请开发者根据具体问题具体分析。

        应用无响应日志主要分以下几个模块信息：    

        1、日志头部信息

字段	说明
Reason	应用无响应原因，与应用无响应检测能力点对应
PID	发生故障时候的pid，可以用于在流水日志中搜索相关进程信息
PACKAGE_NAME	应用进程包名

============================================================
Device info:HarmonyOS 3.2
Build info:HarmonyOS 4.0.5.3
Module name:com.xxx.xxx
Version:1.0.0
Pid:1561
Uid:20010039
Reason:LIFECYCLE_TIMEOUT
sysfreeze: LIFECYCLE_TIMEOUT LIFECYCLE_TIMEOUT at 20230317170653
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
DOMAIN:AAFWK
STRINGID:LIFECYCLE_TIMEOUT
TIMESTAMP:2023/XX/XX/XX-XX:XX:XX:XX
PID:1561
UID:20010039
PACKAGE_NAME:com.xxx.xxx
PROCESS_NAME:com.xxx.xxx
MSG:ablity:EntryAbility background timeout

        2、日志主干通用信息

        以上三种日志都包含以下几部分信息，可以通过搜索“主要信息字段”在日志中找到对应的位置：

主要信息字段	说明
EVENTNAME	应用无响应原因，或者组成卡死检测的不同事件
TIMESTAMP	发生故障时上报时刻的事件，可以根据应用无响应检测能力点中说明的超时时间，在相应流水日志中缩小查看日志的时间范围
PID	发生故障时候的pid，可以与发生时间和超时时间配合用于在流水日志中搜索相关进程信息
PACKAGE_NAME	应用进程包名
MSG	发生故障时dump信息或者说明信息，后面具体说明
BinderCatcher	进程与其他系统进程间通信的调用信息，显示调用等待时间长的情况
PeerBinder Stacktrace	跟当前进程相关的对端进程有卡死，会抓取对端的进程堆栈
cpuusage	跟当前时间段整机CPU使用情况
memory	跟当前时间当前进程的内存使用情况

         MSG字段信息主要包括卡死上报的原因，以及当前应用主线程的队列中任务堆积信息。

        主线程队列中任务堆积信息包括：

• 当前正在运行的任务以及任务启动的时间：如果跟当前日志上报的时间相差很大，则当前运行的任务就是卡死的主要任务事件。

• 历史任务时间：可判断是否由于历史任务过多且每一个任务执行都占一定时间，导致当前的新任务运行时无法及时响应。

• 堆积中还没有执行的任务。

         3、日志主干特异性信息(应用主线程卡死超时)

        Reason是THREAD_BLOCK_6S的日志。根据前面的应用主线程卡死超时的原理可知，THREAD_BLOCK由THREAD_BLOCK_3S和THREAD_BLOCK_6S两部分组成。将两部分日志对比分析，可更准确的判断是卡死还是执行任务过多造成无法响应的情况。

        THREAD_BLOCK_3S在日志的前部分，THREAD_BLOCK_6S在THREAD_BLOCK_3S后面写入。可以通过EVENTNAME字段搜索两个事件在日志中的位置。

        两个事件中都包含MSG字段，该字段在应用主线程卡死超时故障中写入了当前主线程处理队列的信息，可查看在两个时间点中主线程事件处理队列排队情况。

        示例日志显示了在Low priority的队列中05:06:18.145的事件一直在处理，THREAD_BLOCK_3S和THREAD_BLOCK_6S的队列都显示其存在。这说明主线程卡死不是任务过多情况。

        由于THREAD_BLOCK_6S是主线程卡死，进程堆栈信息只需要关注主线程的堆栈(主线程线程号跟进程号相同)。当前示例日志主线程堆栈显示通过ArkUI控件到JS运行，说明卡死在Js代 码中。3S和6S都是这个位置的堆栈，说明JS有卡死，但原因排除任务过多导致。

        THREAD_BLOCK_3S：

start time:2017/08/08-17:06:24:380
DOMAIN = AAFWK EVENTNAME THREAD_BLOCK_3S
TIMESTAMP = 2017/08/08-17:06:24:363
PID = 1561
UID = 20010039
TID = 1566
PACKAGE_NAME com.ohos.huawei.myapplication
PROCESS_NAME com.ohos.huawei.myapplication
eventLog_action pb:1 eventLog_interval 10
MSG = App main thread is not response!EventHandler dump begin curTime:2017-08-08 05:06:24.362
  Event runner (Thread name =Thread ID 1561)is running
  Current Running:start at 2017-08-08 05:06:18.145,Event send thread 1561,send time =2017-08-08 05:06:18.145,handle time =2017-08-08 05:
  Immediate priority event queue information:
  Total size of Immediate events 0
  High priority event queue information:
  No.1 Event send thread 1561,send time 2017-08-08 05:06:18.039,handle time 2017-08-08 05:06:21.539,task name [anr_handler.cpp(Send Total size of High events 1
  Low priority event queue information:
  No.1:Event{send thread=1566,send time=2017-08-0805:06:21.062,handle time=2017-08-0805:06:21.062,id=1}
  Total size of Low events 1
  Idle priority event queue information:
  Total size of Idle events 0
  Total event size :2

 Timestamp: 2017-08-0817:06:24.4142447784
 Pid: 1561
 Uid: 20010039
 Process name: com.ohos.huawei.myapplication
 Tid:1561 Name:i.myapplication
   at anonymous (D:/project/HarmonyOSOS/MyApplication_test/entry/build/default/intermediates/loader_out/default/ets,pages/Index_.js:0:1)
   #00 pc 0017909c /system/lib/libark_jsruntime.so
   #01 pc 00177ebb /system/lib/libark_jsruntime.so
   #02 pc 0024b4bb /system/lib/libark_jsruntime.so(panda:FunctionRef:Call(panda:ecmascript:EcmaVM const*,panda:Local<panda:JSValueRef>,panda
   #03 pc 00fbed23 /system/lib/libace.z.so
   #04 pc 00d8208f /system/lib/libace.z.so
   ...

        THREAD_BLOCK_6S：

start time: 2017/08/08-17:06:27:299
DOMAIN = AAFWK
EVENTNAME THREAD_BLOCK_6S
TIMESTAMP = 2017/08/08-17:06:27:292
PID = 1561
UID = 20010039
TID = 1566
PACKAGE_NAME com.ohos.huawei.myapplication
PROCESS NAME com.ohos.huawei.myapplication eventLog_action cmd:c,cmd:m,tr,k:SysRqFile
eventLog_interval 10
MSG = App main thread is not response!EventHandler dump begin curTime:2017-08-08 05:06:27.291
  Event runner (Thread name =Thread ID =1561)is running
  Current Running:start at 2017-08-08 05:06:18.144, Event {send thread 1561,send time =2017-08-08 05:06:18.145,handle time =2017-08-08 05:
  Immediate priority event queue information:
  Total size of Immediate events 0
  High priority event queue information:
  No.1 Event send thread 1561,send time 2017-08-08 05:06:18.039,handle time 2017-08-08 05:06:21.539,task name [arr_handler.cpp(Se Total size of High events 1
  Low priority event queue information:
  No.1:Event{send thread=1566,send time=2017-08-0805:06:21.062,handle time=2017-08-0805:06:21.062,id=1}
  No.2 Event send thread 1566,send time 2017-08-08 05:06:24.369,handle time 2017-08-08 05:06:24.369,id =1
  Total size of Low events 2
  Idle priority event queue information:
  Total size of Idle events 0
  Total event size 3

Timestamp:2017-08-0817:0k:27,4142447784
Pid:1561
Uid:20010039
Process name:com.ohos.huawei.myapplication
Tid:1561 Name:i.myapplication
  at anonymous (D:/project/HarmonyOS0S/MyApplication_test/entry/build/default/intermediates/loader_out/default/ets/pages/Index_.js:0:1)
  #00 pc 00178dcc /system/lib/libark_jsruntime.so
  #01 pc 00177ebb /system/lib/libark_jsruntime.so
  #02 pc 0024b4bb /system/lib/libark_jsruntime.so(panda:FunctionRef:Call(panda:ecmascript:EcmaVM const*,panda:Local<panda:JSValueRef>,par
  #03 pc 00fbed23 /system/lib/libace.z.so
  #04 pc 00d8208f /system/lib/libace.z.so
  #05 pc 00d7af1b /system/lib/libace.z.so

        4、日志主干特异性信息(用户输入响应超时)

        Reason是APP_INPUT_BLOCK，表明用户点击事件超过5s没有得到反馈。

        MSG信息是这个事件的说明：用户的输入没有得到响应。

        APP_INPUT_BLOCK的日志信息可以参考通用日志信息进行分析。需特别说明的是，一般情况下用户输入无响应大概率主线程也会卡死。可以结合两个日志的三个堆栈、两个BinderCatcher信息，进行对比查看。如果没有主线程卡死的日志，说明有可能在输入事件之前有大量的细碎的其他事件，细碎的事件不足以卡死主线程，但是数量比较多导致用户的输入事件响应不过来。

         5、日志主干特异性信息(生命周期切换超时)

        Reason是LIFECYCLE_TIMEOUT的日志与上文THREAD_BLOCK_6S和THREAD_BLOCK_3S一样都是有两个事件。分别是LIFECYCLE_HALF_TIMEOUT和LIFECYCLE_TIMEOUT

        MSG说明当前是什么生命周期的超时。

        示例可以看出，LIFECYCLE_TIMEOUT的可以看出Ability在切换后台的时候超时，可以按照上面生命周期切换超时的超时时间来找流水日志等信息。

        LIFECYCLE_TIMEOUT：

DOMAIN:AAFWK
STRINGID:LIFECYCLE
TIMEOUT TIMESTAMP:2023/03/10-17:06:53:65
PID:1561
UID:20010039
PACKAGE_NAME:com.ohos.huawei.myapplication
PROCESS_NAME:com.ohos.huawei.myapplication
MSG:ability:EntryAbility background timeout

三、应用退出

        当应用发生以下故障时，为了保证可恢复，会杀死应用。

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