冷启动首帧完成时延问题分析
应用启动可以分为冷启动和热启动:
- 冷启动:当应用启动时,后台没有该应用的进程,这时系统会重新创建一个新的进程分配给该应用, 这种启动方式就叫做冷启动。
- 热启动:当应用程序已经在后台运行,此时用户再次打开应用程序时,应用程序仍然在内存中,可以直接从内存中加载并继续之前的状态,而不需要重新初始化和加载资源,这种称为热启动。
冷启动首帧完成时延:指的是应用冷启动时,从点击离手开始到应用进程首帧送显上屏显示的这一段时间,称为冷启动首帧完成时延。
冷启动首帧完成时延的参考值为680ms,在定位冷启动时延相关问题时可以将此作为性能是否达标的一个参考。
性能参考起止点介绍
冷启动首帧完成时延的性能衡量的起点为用户点击应用图标离手点时间,止点为应用首帧送显的时间。
注意:如果应用启动时存在广告,需要减去广告时间,即冷启动首帧完成时延计算要去除广告时间。
问题定位思路
冷启动首帧完成时延问题的通用定位思路为先确认时延起止点,然后看起止点时延是否超参考值680ms,未超过则说明达标,超过则根据关键Trace信息将时延区间分为七个阶段:
1. input阶段(参考值:8ms)。
2. TP事件分发(参考值:15ms)。
3. 触发应用启动(参考值:20ms)。
4. 进程创建(参考值:15ms)。
5. 应用加载(参考值:15ms)。
6. Ability资源加载界面布局(参考值:500ms)。
7. 首帧渲染显示(参考值:20ms)。
分析时,优先看第6阶段Ability资源加载界面布局是否超过参考值500ms(应用进程耗时),如果超过则根据应用进程Trace信息分析耗时原因,并和应用侧对齐处理。如果是其他阶段耗时超过参考值,则根据实际情况找到耗时Trace并和对应领域对齐是否存在问题(通常情况下都是应用侧耗时导致超标,其他阶段可视情况是否需要分析),处理流程如下图:
确认起止点
冷启动首帧完成时延起点确认:冷启动首帧完成时延的起点是多模子系统收到硬件传递过来的离屏信号的Trace开始点。
起点Trace查找顺序:H:DispatchTouchEvent type=1(大桌面ohos.sceneboard) -> CPU Running Trace(多模子系统mmi_service)-> H:service report(多模子系统mmi_service)。
- 在大桌面泳道(ohos.sceneboard)搜索H:DispatchTouchEvent并且type=1(0,1,2分别代表按下,抬起,移动)的Trace点,该Trace点代表大桌面收到点击离手事件的Trace;
- 然后找到多模子系统泳道(mmi_service),找到H:DispatchTouchEvent前的一个CPU Running Trace,该Trace下有一个H:service report touchId:{id}, type: up [id: 0, x:{X}, y:{Y}]的Trace点,该Trace点的X,Y坐标和H:DispatchTouchEvent是对应的,且类型也是up,代表的是多模子系统收到点击离手事件的时间,H:service report这个Trace开始位置就是起点。
冷启动首帧完成时延止点确认:冷启动首帧完成时延的终点是应用进程启动后的第一帧。
在应用进程中找到首个H:ReceiveVsync Trace点代表应用进程启动后收到的首个垂直同步信号,这里就会开始绘制应用的首帧。
止点Trace查找顺序:H:ReceiveVsync(应用进程) -> H:FlushMessages(大桌面ohos.sceneboard)-> H:SendCommands(大桌面ohos.sceneboard)-> H:MarshRSTransactionData(大桌面ohos.sceneboard) -> H:RSMainThread::ProcessCommandUni(RS服务render_service)-> H:RSUniRender:FlushFrame(RS服务render_service)-> H:RSHardwareThread(RS送显线程RSHardwareThrea)。
- 从应用进程收到的首个H:ReceiveVsync Trace点开始,该Trace下可以找到H:FlushMessages -> H:SendCommands -> H:MarshRSTransactionData的Trace,这3个Trace点代表应用进程首次通知RS服务进行图形渲染。
- 从H:MarshRSTransactionData Trace点可以跳转到render_service(RS渲染服务进程)泳道的H:RSMainThread::ProcessCommandUni Trace点,代表render_service收到应用进程首帧渲染通知的点,从这个点往右下找可以看到H:RSUniRender:FlushFrame的Trace,代表将渲染的图像数据刷新到缓冲区。
- 找到RS服务送显线程泳道RSHardwareThrea,在这个泳道上找到H:RSUniRender:FlushFrame后的第一个H:RSHardwareThread::CommitAndReleaseLayersTrace点,这里代表RS服务将应用首帧提交上屏,该Trace的结束点也就是冷启动首帧完成时延的止点。
找问题点
根据应用进程启动过程中的关键Trace点,我们可以将应用启动划分为:
1.input阶段 -> 2.TP事件分发 -> 3.触发应用启动 -> 4.进程创建 -> 5.应用加载 -> 6.Ability资源加载界面布局 -> 7.首帧渲染显示等七个部分,每个部分所属领域及参考耗时见下表:
序号 | 阶段(子系统) | 起点Trace(泳道) | 终点Trace(泳道) | 参考耗时 |
1 | input阶段(多模) | H:service report开始(mmi_service) | H:DispatchTouchEvent开始(render_service) | 8ms |
2 | TP事件分发(大桌面) | H:DispatchTouchEvent开始(render_service) | AppExecFwk::BundleMgrProxy::QueryAbilityInfo结束(OS_SceneSession) | 15ms |
3 | 触发应用启动(元能力) | AppExecFwk::BundleMgrProxy::QueryAbilityInfo结束(OS_SceneSession) | AppExecFwk::AppSpawnClient::StartProcess开始(OS_FFRT) | 20ms |
4 | 进程创建(Appspawn) | AppExecFwk::AppSpawnClient::StartProcess开始(OS_FFRT) | AppExecFwk::AppSpawnClient::StartProcess结束(OS_FFRT) | 15ms |
5 | 应用加载(元能力) | AppExecFwk::AppSpawnClient::StartProcess结束(OS_FFRT) | AppExecFwk::MainThread::HandleLaunchApplication结束(应用进程) | 15ms |
6 | Ability资源加载界面布局(应用) | AppExecFwk::MainThread::HandleLaunchApplication结束(应用进程) | 首帧H:FlushMessages结束(应用进程) | 500ms |
7 | 首帧渲染显示(图形) | 应用首个H:ReceiveVsync开始(应用进程) | H:RSHardwareThread::CommitAndReleaseLayers结束点(RSHardwareThrea) | 20ms |
注:这里耗时均为参考值,仅供定界参考。
分析应用侧耗时
从上表中可以看出第6阶段Ability资源加载界面布局(应用侧)是参考耗时最长的部分,所以我们优先分析第6阶段应用侧耗时是否超标,应用侧Trace区间如下图:
可以看到第6阶段耗时589ms,明显超出参考值500ms,所以可以判定为应用侧时延超标。通过观察应用进程这段Trace信息发现是H:PageRouterManager::RunPage这一个Trace耗时较长,大约413ms,进一步往下看发现是H:SourceTextModule::Instantiate和H:SourceTextModule::Evaluate这两部分耗时较长,至此基本确定了问题Trace点。
常见问题
1. 应用首页加载耗时较长导致应用冷启动首帧完成时延不达标
问题根因分析
正常H:PageRouterManager::RunPage Trace的时长在40ms左右。
问题Trace,H:PageRouterManager::RunPage耗时414ms,明显高于正常值。
查看Trace信息发现耗时主要集中在H:SourceTextModule::Instantiate和H:SourceTextModule::Evaluate两个Trace:
a. H:SourceTextModule::Instantiate异常点分析。
圈中该Trace范围,在下方详情中可以看到方法调用栈及耗时,可以看到AbilityRuntime::JsModuleReader::operator执行了很多次每次2.5ms左右,实际上里面调用的是AppExecFwk::BundleMgrProxy::GetBundleInfoForSelf方法,然后切到Slice List页签,这里可以看到函数的调用次数和耗时统计,发现GetBundleInfoForSelf调用了41次,总耗时109.3ms,到这里基本可以判断耗时长的原因是因为重复调用GetBundleInfoForSelf。
b. H:H:SourceTextModule::Evaluate异常点分析。
中间存在一段空白区域,耗时84ms,这里执行的是应用侧代码逻辑,需联系应用侧结合具体代码分析耗时原因。
优化方案
a. GetBundleInfoForSelf 调用41次,原因是import hsp包时会获取hsp的路径信息,从而调用了GetBundleInfoForSelf。单hap场景下,模块推荐使用多har,不推荐使用hsp,hsp是采用动态加载,会增加编译耗时、响应时延会出现多次调用。
b. 应用侧问题由应用侧分析修改。
1. 应用Ability的onCreate回调耗时较长导致应用冷启动首帧完成时延不达标
Trace点H:virtual void OHOS::AbilityRuntime::JsUIAbility::OnStart(const OHOS::AbilityRuntime::Want &, sptrAAFwk::SessionInfo)对应的Ability生命周期函数onCreate的回调函数,其中H:napi_value OHOS::AbilityRuntime::JsUIAbility::CallObjectMethod耗时376ms, 这个是在执行应用侧JS代码。
优化方案
应用侧排查Ability生命周期函数onCreate是否存在耗时操作,是否可优化。
1. 首页so加载耗时较长导致应用冷启动首帧完成时延不达标
问题根因分析
H:PageRouterManager::LoadPage下的H:JSPandaFileExecutor::ExecuteFromFile代表加载首页时的so加载,这里看到导入耗时208ms,通过分析应用首页代码发现是因为引入了photobrowser大图组件,多引入了90+so文件导致so加载时间变长。
去除photobrowser大图组件后,so加载耗时降低到92ms。
优化方案
首页尽量不要引入过多无用组件或非必要组件,对于非常用页面及引入耗时长so的页面可以采用动态加载的方式进行优化。
冷启动Trace抓取方法
Step1:打开DevEco Studio的Profiler -> 选择设备进程 -> Frame模式 -> Create Session -> 启动录制。
注意:第二步选择进程时不要选择要录制的进程,因为要录制的进程需要处于未启动状态,这里是通过录制其他进程间接录制目标进程的启动Trace信息。
Step2: 启动录制后,在设备上点击应用图标启动要录制的目标应用(点击到离手时间稍微长点,否则可能录制不到点击事件的Trace),等到应用首页加载后,点击停止结束录制。
Step3:录制完成后会工具会分析展示Trace数据。
冷启动首帧完成时延Trace点解读
冷启动首帧完成时延之后的关键Trace区间主要体现在应用进程启动阶段,关键Trace为H:static void OHOS::AppExecFwk::MainThread::Start(),这是进程启动的Trace打点,该Trace点下主要包含如下Trace:
序号 | 所属泳道 | Trace点 | Trace点描述 |
1 | 应用进程 | H:void OHOS::AppExecFwk::MainThread::HandleLaunchApplication | 应用对象创建及相关资源依赖模块加载 |
2 | 应用进程 | H:void OHOS::AppExecFwk::MainThread::HandleLaunchAbility | Ability对象创建及相关资源依赖模块加载 |
3 | 应用进程 | H:void OHOS::AbilityRuntime::UIAbilityThread::HandleAbilityTransaction | 该阶段主要是AbilityStage/Ability的启动生命周期,执行相应的生命周期回调 |
4 | 应用进程 | H:Napi complete, name:getRawFileContent | 加载本地资源 |
5 | 应用进程 | H:Napi complete, name:JsWindowStage::OnLoadContent | 加载首页内容 |
6 | 应用进程 | H:PageRouterManager::RunPage | 页面路由预处理及页面绘制(这里是出问题频率比较高的地方) |