AppFreeze采样栈定位“循环处理计算任务”,解决鸿蒙主线程超时问题

0 评论 755 浏览 0 收藏 20 分钟

前文我们分享了“锁竞争”、“UI渲染过载”及“主线程同步IO阻塞”引发无响应问题的分析方法。这一篇,我们将介绍另一种无响应故障模式:“主线程执行耗时循环计算”。

本原创文章帖发布在华为开发者联盟社区,欢迎开发者前往访问评论交流,更多与该内容相关讨论,请点击原帖查看:

AppFreeze采样栈定位“循环处理计算任务”,解决鸿蒙主线程超时问题-华为开发者话题 | 华为开发者联盟

 

前文我们分享了“锁竞争”、“UI渲染过载”及“主线程同步IO阻塞”引发无响应问题的分析方法。这一篇,我们将介绍另一种无响应故障模式:“主线程执行耗时循环计算”。在鸿蒙应用开发中,部分开发者由于对业务逻辑梳理不够充分,或对算法复杂度估计不足,习惯性地将大量计算密集型任务(如数学公式计算(三角函数、矩阵运算等)、复杂的排序、遍历、递归搜索、数据转换等)直接放在主线程(UI线程)中执行。这类操作会持续独占CPU资源,导致主线程消息循环(Event Loop)陷入“繁忙”状态,无法及时响应UI事件,导致界面卡顿、掉帧甚至无响应,严重影响用户体验。本文将演示如何利用AppFreeze增强采样栈,定位此类CPU密集型计算导致的无响应根因。

1. 问题现象

      用户正常使用应用时,触发业务逻辑中的循环计算任务,应用界面逐渐由卡顿、掉帧变为无响应,最终被系统强制退出

      此时系统生成了AppFreeze日志,我们需要分析该日志,定位应用无响应根因。

2. 问题分析:从快照到采样栈

第一步:初步诊断(常规快照排查)

      查看AppFreeze日志中的THREAD_BLOCK_3STHREAD_BLOCK_6S主线程堆栈快照。

THREAD_BLOCK_3S快照

Tid:38843Name:xample.dfx_test
state=R, utime=612, stime=19, priority=-54, nice=-10, clk=100
#00 pc 000000000018bd70 /system/lib/ld-musl-aarch64.so.1(__rem_pio2_large+1016)(86bed4865a3ab1368370b92fd7f496bb)
#01 pc 000000000018b8b0 /system/lib/ld-musl-aarch64.so.1(__rem_pio2+788)(86bed4865a3ab1368370b92fd7f496bb)
#02 pc 00000000000b3fd0 /system/lib/ld-musl-aarch64.so.1(sin+192)(86bed4865a3ab1368370b92fd7f496bb)
#03 pc 00000000002ddb94 /data/storage/el1/bundle/libs/arm64/libentry.so(d3470c557518f4f8633b0b935e5d3206e01fbb7c)
#04 pc 00000000002de100 /data/storage/el1/bundle/libs/arm64/libentry.so(TriggerBusinessBusySync(napi_env__*, napi_callback_info__*)+140)(d3470c557518f4f8633b0b935e5d3206e01fbb7c)
#05 pc 00000000000722cc /system/lib64/platformsdk/libace_napi.z.so(panda::JSValueRef ArkNativeFunctionCallBack<true>(panda::JsiRuntimeCallInfo*)+1004)(f1cff79e287c9e8c76fb45a6edf15268)
#06 pc 0000000000e86b98 /system/lib64/module/arkcompiler/stub.an(RTStub_PushCallArgsAndDispatchNative+40)
#07 pc 0000000000d29818 /system/lib64/module/arkcompiler/stub.an(BCStub_HandleCallthis0Imm8V8StwCopy+396)
#08 at TriggerBusinessBusy_sync entry (entry/src/main/ets/pages/page_second/page_third_appfreeze/appfreeze_threadblock.ets:262:12)
#09 at anonymous entry (entry/src/main/ets/pages/page_second/page_third_appfreeze/appfreeze_threadblock.ets:898:19)

THREAD_BLOCK_6S快照

Tid:38843Name:xample.dfx_test
state=R, utime=875, stime=19, priority=10, nice=-10, clk=100
#00 pc 00000000000b381c /system/lib/ld-musl-aarch64.so.1(log+0)(86bed4865a3ab1368370b92fd7f496bb)
#01 pc 00000000002de064 /data/storage/el1/bundle/libs/arm64/libentry.so(d3470c557518f4f8633b0b935e5d3206e01fbb7c)
#02 pc 00000000002de14c /data/storage/el1/bundle/libs/arm64/libentry.so(TriggerBusinessBusySync(napi_env__*, napi_callback_info__*)+216)(d3470c557518f4f8633b0b935e5d3206e01fbb7c)
#03 pc 00000000000722cc /system/lib64/platformsdk/libace_napi.z.so(panda::JSValueRef ArkNativeFunctionCallBack<true>(panda::JsiRuntimeCallInfo*)+1004)(f1cff79e287c9e8c76fb45a6edf15268)
#04 pc 0000000000e86b98 /system/lib64/module/arkcompiler/stub.an(RTStub_PushCallArgsAndDispatchNative+40)
#05 pc 0000000000d29818 /system/lib64/module/arkcompiler/stub.an(BCStub_HandleCallthis0Imm8V8StwCopy+396)
#06 at TriggerBusinessBusy_sync entry (entry/src/main/ets/pages/page_second/page_third_appfreeze/appfreeze_threadblock.ets:262:12)
#07 at anonymous entry (entry/src/main/ets/pages/page_second/page_third_appfreeze/appfreeze_threadblock.ets:898:19)

初步分析两次快照

时间点

线程状态

关键调用栈 (Top Frames)

行为分析

THREAD_BLOCK_3S

R (Running)

rem_pio2 -> sin -> TriggerBusinessBusySync ->TriggerBusinessBusy_sync

主线程在执行业务逻辑(进行公式计算),处于运行态

THREAD_BLOCK_6S

R (Running)

log -> TriggerBusinessBusySync ->TriggerBusinessBusy_sync

主线程在执行业务逻辑(日志打印),处于运行态

      两次快照,状态均为R(Runing),且两次堆栈不一致,说明应用主线程没有完全卡住不动,是在执行繁忙任务,单仅凭两次快照无法判断具体哪个环节耗时过长,需要引入增强日志中的多帧采样统计来寻找”热点”。

第二步:深入挖掘(增强采样栈分析)

      开启增强日志后,查看采样频率最高的热点函数,在日志文件中可以看到增强日志。

      增强日志中最多可抓到10次采样栈,分析采样栈,提取热点函数

      [Hotspot #1] – Frequency: 40% (4/10)

#00 pc 000000000018c4fc /system/lib/ld-musl-aarch64.so.1(86bed4865a3ab1368370b92fd7f496bb)
#01 pc 000000000018b8b0 /system/lib/ld-musl-aarch64.so.1(86bed4865a3ab1368370b92fd7f496bb)
#02 pc 00000000000b3fd0 /system/lib/ld-musl-aarch64.so.1(sin+192)(86bed4865a3ab1368370b92fd7f496bb)
#03 pc 00000000002ddb94 /data/storage/el1/bundle/libs/arm64/libentry.so(d3470c557518f4f8633b0b935e5d3206e01fbb7c)
#04 pc 00000000002de100 /data/storage/el1/bundle/libs/arm64/libentry.so(TriggerBusinessBusySync(napi_env__*, napi_callback_info__*)+140)(d3470c557518f4f8633b0b935e5d3206e01fbb7c)
#05 pc 00000000000722cc /system/lib64/platformsdk/libace_napi.z.so(panda::JSValueRef ArkNativeFunctionCallBack<true>(panda::JsiRuntimeCallInfo*)+1004)(f1cff79e287c9e8c76fb45a6edf15268)
#06 pc 0000000000e86b98 /system/lib64/module/arkcompiler/stub.an(RTStub_PushCallArgsAndDispatchNative+40)
#07 pc 0000000000d29818 /system/lib64/module/arkcompiler/stub.an(BCStub_HandleCallthis0Imm8V8StwCopy+396)
#08 at TriggerBusinessBusy_sync (entry|entry|1.0.0|src/main/ets/pages/page_second/page_third_appfreeze/appfreeze_threadblock.ts:228:14)
#09 at anonymous (entry|entry|1.0.0|src/main/ets/pages/page_second/page_third_appfreeze/appfreeze_threadblock.ts:1808:25)

      [Hotspot #2] – Frequency: 40% (4/10)

#00 pc 00000000000b3374 /system/lib/ld-musl-aarch64.so.1(cos+172)(86bed4865a3ab1368370b92fd7f496bb)
#01 pc 00000000002de038 /data/storage/el1/bundle/libs/arm64/libentry.so(d3470c557518f4f8633b0b935e5d3206e01fbb7c)
#02 pc 00000000002de13c /data/storage/el1/bundle/libs/arm64/libentry.so(TriggerBusinessBusySync(napi_env__*, napi_callback_info__*)+200)(d3470c557518f4f8633b0b935e5d3206e01fbb7c)
#03 pc 00000000000722cc /system/lib64/platformsdk/libace_napi.z.so(panda::JSValueRef ArkNativeFunctionCallBack<true>(panda::JsiRuntimeCallInfo*)+1004)(f1cff79e287c9e8c76fb45a6edf15268)
#04 pc 0000000000e86b98 /system/lib64/module/arkcompiler/stub.an(RTStub_PushCallArgsAndDispatchNative+40)
#05 pc 0000000000d29818 /system/lib64/module/arkcompiler/stub.an(BCStub_HandleCallthis0Imm8V8StwCopy+396)
#06 at TriggerBusinessBusy_sync (entry|entry|1.0.0|src/main/ets/pages/page_second/page_third_appfreeze/appfreeze_threadblock.ts:228:14)
#07 at anonymous (entry|entry|1.0.0|src/main/ets/pages/page_second/page_third_appfreeze/appfreeze_threadblock.ts:1808:25)

关键线索提取

1. 分析栈顶特征:栈顶高频出现cos和sin,表明主线程在做公式计算;

2. 业务层定位:明确指向libentry.so中的TriggerBusinessBusySync方法,这是问题的入口函数;

3. 根因类型:属于“循环处理计算任务”故障模式。

第三步:锁定根因(代码审查)

      根据日志定位到具体入口函数,查看源码问题代码片段如下:

      ArkTs侧调用

function TriggerBusinessBusy_sync() {
  console.log('TriggerBusinessBusy_sync start');
  testNapi.TriggerBusinessBusySync();
  console.log('TriggerBusinessBusy_sync run');
}

      c++侧实现

napi_value TriggerBusinessBusySync(napi_env env, napi_callback_info info) {
    OH_LOG_INFO(LOG_APP"[%s@%d] TriggerBusinessBusySync start - simulate business busy operation blocking main thread for 7 seconds", __func__, __LINE__);
    double result = 0;
    for (int i = 0; i < 100000000; i++) {
        result += sqrt(i) * sin(i);
        for (int j = 0; j < 10; j++) {
            result += cos(j) * log(j + 1);
        }
    }
    for (int k = 0; k < 50000000; k++) {
        result += tan(k) * atan(k);
        for (int l = 0; l < 5; l++) {
            result += exp(l) * log(l + 2);
        }
    }
    OH_LOG_INFO(LOG_APP"[%s@%d] TriggerBusinessBusySync end", __func__, __LINE__);
    napi_value jsResult;
    napi_create_double(env, result, &jsResult);
    return jsResult;
}

根因总结

1. 高频计算密集型操作:连续循环执行sqrt/sin/cos/log/tan/atan/exp等数学函数,无IO等待,持续占用CPU资源。

2. 同步阻塞设计:在主线程同步调用承担耗时计算任务的接口,主线程一直在等待计算结果返回,导致用户UI交互得不到及时响应。

3. 解决方案与最佳实践

优化策略

      优化方案一:异步化改造,使用async_work将同步计算移至后台线程,主线程快速返回。

      优化方案二:使用FFRT提交异步任务,利用系统线程池管理长时任务。

      下面具体展开说明优化方案一。

优化方案一:使用async_work将同步计算移至后台线程

ArkTs侧调用

async function TriggerBusinessBusy_sync() {
  try {
    console.log('TriggerBusinessBusy_sync start');
    await testNapi.TriggerBusinessBusySync();
    console.log('TriggerBusinessBusy_sync run');
  } catch (error) {
    console.error(`Failed to TriggerBusinessBusy_sync. Message: ${error.message}`);
  }
}

c++侧实现

// 异步工作上下文结构
typedef struct {
  napi_env env;
  napi_deferred deferred;
  double result;
} AsyncWorkContext;

// 执行阶段:在子线程中运行
static void ExecuteBusyWork(napi_env env, void* data) {
    AsyncWorkContext* context = (AsyncWorkContext*)data;
    OH_LOG_INFO(LOG_APP"[%s@%d] TriggerBusinessBusySync start - running in worker thread", __func__, __LINE__);
    double result = 0;
    for (int i = 0; i < 100000000; i++) {
        result += sqrt(i) * sin(i);
        for (int j = 0; j < 10; j++) {
            result += cos(j) * log(j + 1);
        }
}
for (int k = 0; k < 50000000; k++) {
        result += tan(k) * atan(k);
        for (int l = 0; l < 5; l++) {
            result += exp(l) * log(l + 2);
        }
}
context->result = result;
OH_LOG_INFO(LOG_APP"[%s@%d] TriggerBusinessBusySync end - worker thread completed", __func__, __LINE__);
}

// 完成阶段:在主线程中运行,返回结果
static void CompleteBusyWork(napi_env env, napi_status status, void* data) {
    AsyncWorkContext* context = (AsyncWorkContext*)data;
    napi_value jsResult;
    // 创建返回结果
    napi_create_double(env, context->result, &jsResult);   
    // 通过 Promise resolve 返回结果
    napi_resolve_deferred(env, context->deferred, jsResult);
    // 释放上下文内存
    free(context);
}

// 主入口函数
napi_value TriggerBusinessBusySync(napi_env env, napi_callback_info info) {
    // 分配异步工作上下文
    AsyncWorkContext* context = (AsyncWorkContext*)malloc(sizeof(AsyncWorkContext));
    if (context == NULL) {
        OH_LOG_ERROR(LOG_APP"[%s@%d] Failed to allocate memory for context", __func__, __LINE__);
        napi_value error;
        napi_value msg = nullptr;
        napi_create_string_utf8(env, "Memory allocation failed"NAPI_AUTO_LENGTH, &msg);
        napi_create_error(env, nullptr, msg, &error);
        return error;
    }
context->env = env;
context->deferred = NULL;
context->result = 0;
// 创建 Promise
napi_value promise;
napi_status status = napi_create_promise(env, &context->deferred, &promise);

// 创建异步工作
napi_async_work asyncWork;
status = napi_create_async_work(env,
NULL,// asyncResource
promise,// resourceHint (用于调试)
ExecuteBusyWork,// execute callback
CompleteBusyWork,// complete callback
context,// data
  &asyncWork);

// 队列化异步工作
status = napi_queue_async_work(env, asyncWork);

// 返回 Promise
return promise;
}

4. 总结与启示

      通过这个案例,本文展示了如何利用AppFreeze增强采样栈定位并解决“循环处理计算任务”类型无响应问题:

1. 快照看状态:通过对比不同时间点的快照,判断线程是”阻塞”还是”繁忙”。

2. 采样看热点:通过分析增强日志中“热点”函数,快速定位问题入口函数。

3. 代码看逻辑:通过阅读业务源码,发现主线程 “循环处理计算任务”的设计缺陷。

4. 架构做优化:引入异步任务,从根本上解决主线程CPU负载过高的问题。

—————————————————————————————————–

🔗 官网开发者学堂视频:https://developer.huawei.com/consumer/cn/training/result?type2List=201783644516849879&orderBy=1&courseType=5

🔗 社区DFX专题文章:  https://developer.huawei.com/consumer/cn/forum/subject/2101218731402391001

【扫码加入 HarmonyOS DFX 技术交流群】

本文由 @华为开发者联盟 授权发布于人人都是产品经理。未经作者许可,禁止转载

题图来自Unsplash,基于CC0协议

该文观点仅代表作者本人,人人都是产品经理平台仅提供信息存储空间服务

更多精彩内容,请关注人人都是产品经理微信公众号或下载App
海报
评论
评论请登录
  1. 目前还没评论,等你发挥!