鸿蒙NEXT开发【分析AppFreeze（应用无响应）】 实战案例

1. ThreadBlock 类典型案例——未正确使用锁

背景/原理

xxxservice 上报 THREAD_BLOCK_6S 的 appfreeze 问题

错误代码案例

第4行加锁，第6行函数返回失败后，第6行直接返回未解锁，导致其他线程一直等锁

int xxx()

{

    ...

-   mutex_.lock();

    AIContext aiContext;

    if (ConvertRpcHandle2AIContext(inputs[0], aiContext) != aicp::SUCCESS) {

        return FAILED;

    }

    ...

}

影响/报错

后台应用卡死，用户无感知，但是相关功能不可用

定位思路

提取故障日志关键类别信息

appfreeze: com.huawei.hmsapp.xxx THREAD_BLOCK_6S at 20240408082432

DisplayPowerInfo:powerState:AWAKE

从 Foreground 值可看出 该应用为后台应用，可推断出当真正的 3s 事件上报上来时，后台应用已卡 18s 前

Module name:com.xxx.xxx.xxx

Version:1.2.2.202

VersionCode:1002002202

PreInstalled:Yes

Foreground:No --> 后台

Pid:43675

Uid:20020029

Reason:THREAD_BLOCK_6S

THREAD_BLOCK_3S 上报的时间为 08:24:29:612；

THREAD_BLOCK_6S 上报的时间为 08:24:32:638；相隔 3s 符合预期

DOMAIN:AAFWK

STRINGID:THREAD_BLOCK_6S

TIMESTAMP:2024/04/08-08:24:32:638

PID:43675

UID:20020029

PACKAGE_NAME:com.xxx.xxx.xxx

PROCESS_NAME:com.xxx.xxx.xxx

---

start time: 2024/04/08-08:24:29:627

DOMAIN = AAFWK

EVENTNAME = THREAD_BLOCK_3S

TIMESTAMP = 2024/04/08-08:24:29:612

PID = 43675

UID = 20020029

PACKAGE_NAME = com.xxx.xxx.xxx

PROCESS_NAME = com.xxx.xxx.xxx

3s 上报时会去抓取此时的 EventHandler 信息，时间为 08:24:29.413，符合预期

上报的原因为：App main thread is not response! 主线程无响应

当前正在运行的任务开始时间为 08:24:01.514

MSG =

Fault time:2024/04/08-08:24:29

App main thread is not response!

mainHandler dump is:

EventHandler dump begin curTime: 2024-04-08 08:24:29.413

Event runner (Thread name = , Thread ID = 43675) is running

Current Running: start at 2024-04-08 08:24:01.514, Event { send thread = 43675, send time = 2024-04-08 08:24:01.514, handle time = 2024-04-08 08:24:01.514, task name = uvLoopTask }

watchdog 任务位于高优先级队列（High priority event queue），如下图可发现：每隔 3s 就会抛一个任务到主线程去，符合预期；

THREAD_BLOCK_3S、THREAD_BLOCK_6S 的队列一致，6s 较 3s 多了一个 event

最早的一个 event send time 为 08:24:11.388，与 3s 上报上来的时间 08:24:29:612 刚好差 18s，符合预期；

High priority event queue information:

No.1 : Event { send thread = 43679, send time = 2024-04-08 08:24:11.388, handle time = 2024-04-08 08:24:11.388, id = 1, caller = [watchdog.cpp(Timer:139)] }

No.2 : Event { send thread = 43679, send time = 2024-04-08 08:24:14.458, handle time = 2024-04-08 08:24:14.458, id = 1, caller = [watchdog.cpp(Timer:139)] }

No.3 : Event { send thread = 43679, send time = 2024-04-08 08:24:17.383, handle time = 2024-04-08 08:24:17.383, id = 1, caller = [watchdog.cpp(Timer:139)] }

No.4 : Event { send thread = 43679, send time = 2024-04-08 08:24:20.363, handle time = 2024-04-08 08:24:20.363, id = 1, caller = [watchdog.cpp(Timer:139)] }

No.5 : Event { send thread = 43679, send time = 2024-04-08 08:24:23.418, handle time = 2024-04-08 08:24:23.418, id = 1, caller = [watchdog.cpp(Timer:139)] }

No.6 : Event { send thread = 43679, send time = 2024-04-08 08:24:26.369, handle time = 2024-04-08 08:24:26.369, id = 1, caller = [watchdog.cpp(Timer:139)] }

No.7 : Event { send thread = 43679, send time = 2024-04-08 08:24:29.412, handle time = 2024-04-08 08:24:29.412, id = 1, caller = [watchdog.cpp(Timer:139)] }

以上可总结：应用主线程从 08:24:01.514 开始运行本次任务，第一次 3s 检测开始时间为 08:24:11.388，真正开始卡住的时间在 08:24:11 左右；

查看主线程栈：从 xxx_request_client.so -> libsamgr_proxy.z.so -> libipc_core.z.so(OHOS::BinderConnector::WriteBinder)

可知：此时主线程发起了一个 ipc 请求，对端进程未返回导致卡死，如下堆栈所示。

Tid:43675, Name:xxx

00 pc 0000000000168c44 /system/lib/ld-musl-aarch64.so.1(ioctl+176)(91b804d2409a13f27463debe9e19fb5d)

01 pc 0000000000049268 /system/lib64/platformsdk/libipc_core.z.so(OHOS::BinderConnector::WriteBinder(unsigned long, void*)+112)(e59500a4ea66775388332f6e3cc12fe3)

02 pc 0000000000054fd4 /system/lib64/platformsdk/libipc_core.z.so(OHOS::BinderInvoker::TransactWithDriver(bool)+296)(e59500a4ea66775388332f6e3cc12fe3)

03 pc 00000000000544c8 /system/lib64/platformsdk/libipc_core.z.so(OHOS::BinderInvoker::WaitForCompletion(OHOS::MessageParcel*, int*)+304)(e59500a4ea66775388332f6e3cc12fe3)

04 pc 0000000000053c84 /system/lib64/platformsdk/libipc_core.z.so(OHOS::BinderInvoker::SendRequest(int, unsigned int, OHOS::MessageParcel&, OHOS::MessageParcel&, OHOS::MessageOption&)+312)(e59500a4ea66775388332f6e3cc12fe3)

05 pc 000000000002d6d8 /system/lib64/platformsdk/libipc_core.z.so(OHOS::IPCObjectProxy::SendRequestInner(bool, unsigned int, OHOS::MessageParcel&, OHOS::MessageParcel&, OHOS::MessageOption&)+128)(e59500a4ea66775388332f6e3cc12fe3)

06 pc 0000000000030e00 /system/lib64/platformsdk/libipc_core.z.so(OHOS::IPCObjectProxy::GetProtoInfo()+396)(e59500a4ea66775388332f6e3cc12fe3)

07 pc 000000000002e990 /system/lib64/platformsdk/libipc_core.z.so(OHOS::IPCObjectProxy::WaitForInit()+292)(e59500a4ea66775388332f6e3cc12fe3)

08 pc 0000000000036cd0 /system/lib64/platformsdk/libipc_core.z.so(OHOS::IPCProcessSkeleton::FindOrNewObject(int)+116)(e59500a4ea66775388332f6e3cc12fe3)

09 pc 00000000000571cc /system/lib64/platformsdk/libipc_core.z.so(OHOS::BinderInvoker::UnflattenObject(OHOS::Parcel&)+272)(e59500a4ea66775388332f6e3cc12fe3)

10 pc 00000000000463a4 /system/lib64/platformsdk/libipc_core.z.so(OHOS::MessageParcel::ReadRemoteObject()+116)(e59500a4ea66775388332f6e3cc12fe3)

11 pc 000000000001250c /system/lib64/chipset-pub-sdk/libsamgr_proxy.z.so(OHOS::SystemAbilityManagerProxy::CheckSystemAbility(int, bool&)+952)(6f113f37ac6ac882cfa16077ad5b406a)

12 pc 0000000000010e7c /system/lib64/chipset-pub-sdk/libsamgr_proxy.z.so(OHOS::SystemAbilityManagerProxy::GetSystemAbilityWrapper(int, std::__h::basic_string<char, std::__h::char_traits, std::__h::allocator> const&)+232)(6f113f37ac6ac882cfa16077ad5b406a)

13 pc 00000000000118b8 /system/lib64/chipset-pub-sdk/libsamgr_proxy.z.so(OHOS::SystemAbilityManagerProxy::Recompute(int, int)+132)(6f113f37ac6ac882cfa16077ad5b406a)

14 pc 0000000000011170 /system/lib64/chipset-pub-sdk/libsamgr_proxy.z.so(OHOS::DynamicCache<int, OHOS::sptrOHOS::IRemoteObject>::QueryResult(int, int)+316)(6f113f37ac6ac882cfa16077ad5b406a)

15 pc 0000000000007e0c xxx_request_client.so(xxx::RPCRequestClient::GetService()+540)(557450139184527807025a632613fd76)