三方相机问题分析八:【返帧异常导致性能卡顿】Snapchat后置使用特效预览出现卡顿
【关注我,后续持续新增专题博文,谢谢!!!】
上一篇我们讲了:
这一篇我们开始讲: 三方相机问题分析八:【返帧异常导致性能卡顿】Snapchat后置使用特效预览出现卡顿9089927
目录
一、问题背景
二、:问题分析过程
2.1:基于原理分析
2.2 :分析camx hal进程返帧情况
2.3 :分析丢帧原因
2.4 :分析node回调慢原因。
2.5 :解决方式
2.6 :屏蔽node方式
2.7 :解决方案
一、问题背景
【前提条件】【Prerequistes】下载安装Snapchat
【操作步骤】【Operation steps】在首页调用相机后置使用TUNG SAHUR AR特效,点击右边动作按钮后预览
【实际结果】【Actual results】会越来越卡直到定屏
【期望结果】【Expected results】预览拍照流畅
二、:问题分析过程
2.1:基于原理分析
性能分析一般使用systrace分析卡顿原因,通过systrace分析发现camx hal进程返帧帧率很低,疑似返帧失败,需要进一步分析日志查看返帧情况。(本文不讨论systrace分析过程,后续可专题讲解性能)
2.2 :分析camx hal进程返帧情况
相机Camera日志分析之三十一:高通Camx HAL十种流程基础分析关键字汇总(后续持续更新中)
分析返帧情况的关键字查看:process_capture_result,我们搜索看看:
行 161718: 04-22 09:51:54.018 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb40000702f50b438, status: 00000000, stream: 0xb4000070bce2a648行 162018: 04-22 09:51:54.103 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb40000702f50b3b8, status: 00000000, stream: 0xb4000070bce2a648行 162323: 04-22 09:51:54.177 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb4000070287152d8, status: 00000000, stream: 0xb4000070bce2a648行 162625: 04-22 09:51:54.251 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb4000070251e7fb8, status: 00000000, stream: 0xb4000070bce2a648行 162981: 04-22 09:51:54.419 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb4000070251e7f58, status: 00000000, stream: 0xb4000070bce2a648行 163297: 04-22 09:51:54.609 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb40000702f50b358, status: 00000000, stream: 0xb4000070bce2a648行 163565: 04-22 09:51:54.698 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb4000070251e7bb8, status: 00000000, stream: 0xb4000070bce2a648行 163929: 04-22 09:51:54.991 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb40000702f50b2b8, status: 00000000, stream: 0xb4000070bce2a648行 164186: 04-22 09:51:55.069 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb40000702f50bb38, status: 00000000, stream: 0xb4000070bce2a648行 164553: 04-22 09:51:55.234 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb4000070bce5ba98, status: 00000000, stream: 0xb4000070bce2a648行 164879: 04-22 09:51:55.603 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb4000070251e7eb8, status: 00000000, stream: 0xb4000070bce2a648行 165137: 04-22 09:51:55.679 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb40000702f50b438, status: 00000000, stream: 0xb4000070bce2a648行 166243: 04-22 09:51:56.082 1559 1946 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb40000702f50b3b8, status: 00000000, stream: 0xb4000070bce2a648行 166292: 04-22 09:51:56.093 1559 1946 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb4000070287152d8, status: 00000000, stream: 0xb4000070bce2a648行 166715: 04-22 09:51:56.161 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb4000070251e7fb8, status: 00000000, stream: 0xb4000070bce2a648行 167202: 04-22 09:51:56.325 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb4000070251e7f58, status: 00000000, stream: 0xb4000070bce2a648行 167497: 04-22 09:51:56.369 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb40000702f50b358, status: 00000000, stream: 0xb4000070bce2a648行 168193: 04-22 09:51:56.542 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb4000070251e7bb8, status: 00000000, stream: 0xb4000070bce2a648行 168459: 04-22 09:51:56.566 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb40000702f50b2b8, status: 00000000, stream: 0xb4000070bce2a648行 168745: 04-22 09:51:56.601 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb40000702f50bb38, status: 00000000, stream: 0xb4000070bce2a648行 169091: 04-22 09:51:56.660 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb4000070bce5ba98, status: 00000000, stream: 0xb4000070bce2a648行 169498: 04-22 09:51:56.692 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb4000070251e7eb8, status: 00000000, stream: 0xb4000070bce2a648行 170087: 04-22 09:51:56.770 1559 1941 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb40000702f50b438, status: 00000000, stream: 0xb4000070bce2a648行 170455: 04-22 09:51:56.810 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb40000702f50b3b8, status: 00000000, stream: 0xb4000070bce2a648行 170777: 04-22 09:51:56.851 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb4000070287152d8, status: 00000000, stream: 0xb4000070bce2a648行 171150: 04-22 09:51:56.899 1559 1940 I CamX : [CONFIG][HAL ] camxhal3.cpp:2163 process_capture_result() output_buffers[0] : 0xb40000702f0e7d80, buffer: 0xb4000070251e7fb8, status: 00000000, stream: 0xb4000070bce2a648行 171575: 04-22 09:51:56.962
我们可以发现04-22 09:51:55只有4帧返回,04-22 09:51:54只有8帧,04-22 09:51:56有15帧。而且前面时间段有20多帧。因此我们需要分析只有4帧返回的异常丢帧情况。
2.3 :分析丢帧原因
我们挑选1帧正常帧率的日志和1帧异常帧率的日志进行过程,使用之前总结的关键字process_capture_request和CSLFenceCallback进行对比:
- 1帧正常帧率的日志:
行 30: 04-22 09:51:31.365 1559 2011 I CamX : [CORE_CFG][HAL ] camxhal3.cpp:1836 process_capture_request() frame_number 2418, settings 0x0, logicalCameraId: 0, cameraId: 0 num_output_buffers 1, num_input_buffers 0行 31: 04-22 09:51:31.365 1559 2011 I CamX : [CONFIG][HAL ] camxhal3.cpp:1862 process_capture_request() output_buffers[0] : 0xb40000708c1e23c0, buffer: 0x71407b90d0, status: 00000000, stream: 0xb4000070bce2a648行 181: 04-22 09:51:31.375 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_TFE0_cam0 : Type 65544 portId=10 Fence 29 signaled with success in node fence handler FOR 923 :NodeOutputPortFence_RealTimeFeatureZSLPreviewRaw_TFE0_cam0_PortId_10行 200: 04-22 09:51:31.376 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_com.qti.node.gme0_cam0 : Type 255 portId=0 Fence 27 signaled with success in node fence handler FOR 922 :DelayedBufferFence_RealTimeFeatureZSLPreviewRaw_com.qti.node.gme0_cam0行 205: 04-22 09:51:31.376 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_com.qti.node.gme0_cam0 : Type 255 portId=0 Fence 26 signaled with success in node fence handler FOR 922 :NodeOutputPortFence_RealTimeFeatureZSLPreviewRaw_com.qti.node.gme0_cam0_PortId_0行 317: 04-22 09:51:31.386 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_TFE0_cam0 : Type 65544 portId=4 Fence 19 signaled with success in node fence handler FOR 923 :NodeOutputPortFence_RealTimeFeatureZSLPreviewRaw_TFE0_cam0_PortId_4行 318: 04-22 09:51:31.386 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_TFE0_cam0 : Type 65544 portId=5 Fence 30 signaled with success in node fence handler FOR 923 :NodeOutputPortFence_RealTimeFeatureZSLPreviewRaw_TFE0_cam0_PortId_5行 326: 04-22 09:51:31.386 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_TFE0_cam0 : Type 65544 portId=15 Fence 31 signaled with success in node fence handler FOR 923 :NodeOutputPortFence_RealTimeFeatureZSLPreviewRaw_TFE0_cam0_PortId_15行 330: 04-22 09:51:31.386 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_TFE0_cam0 : Type 65544 portId=1 Fence 2 signaled with success in node fence handler FOR 923 :NodeOutputPortFence_RealTimeFeatureZSLPreviewRaw_TFE0_cam0_PortId_1行 332: 04-22 09:51:31.386 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_TFE0_cam0 : Type 65544 portId=7 Fence 24 signaled with success in node fence handler FOR 923 :NodeOutputPortFence_RealTimeFeatureZSLPreviewRaw_TFE0_cam0_PortId_7行 337: 04-22 09:51:31.387 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_com.qti.node.memcpy5_cam0 : Type 255 portId=0 Fence 43 signaled with success in node fence handler FOR 923 :NodeOutputPortFence_RealTimeFeatureZSLPreviewRaw_com.qti.node.memcpy5_cam0_PortId_0行 401: 04-22 09:51:31.392 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_IPE0_cam0 : Type 65538 portId=8 Fence 28 signaled with success in node fence handler FOR 922 :NodeOutputPortFence_RealTimeFeatureZSLPreviewRaw_IPE0_cam0_PortId_8
- 1帧异常帧率的日志:
行 22: 04-22 09:51:54.105 1559 1562 I CamX : [CORE_CFG][HAL ] camxhal3.cpp:1836 process_capture_request() frame_number 2881, settings 0x0, logicalCameraId: 0, cameraId: 0 num_output_buffers 1, num_input_buffers 0行 23: 04-22 09:51:54.105 1559 1562 I CamX : [CONFIG][HAL ] camxhal3.cpp:1862 process_capture_request() output_buffers[0] : 0xb400007028715180, buffer: 0x71407b90d0, status: 00000000, stream: 0xb4000070bce2a648行 176: 04-22 09:51:54.126 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_TFE0_cam0 : Type 65544 portId=10 Fence 16 signaled with success in node fence handler FOR 1388 :NodeOutputPortFence_RealTimeFeatureZSLPreviewRaw_TFE0_cam0_PortId_10行 180: 04-22 09:51:54.136 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_TFE0_cam0 : Type 65544 portId=4 Fence 8 signaled with success in node fence handler FOR 1388 :NodeOutputPortFence_RealTimeFeatureZSLPreviewRaw_TFE0_cam0_PortId_4行 181: 04-22 09:51:54.137 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_TFE0_cam0 : Type 65544 portId=5 Fence 18 signaled with success in node fence handler FOR 1388 :NodeOutputPortFence_RealTimeFeatureZSLPreviewRaw_TFE0_cam0_PortId_5行 183: 04-22 09:51:54.137 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_TFE0_cam0 : Type 65544 portId=15 Fence 30 signaled with success in node fence handler FOR 1388 :NodeOutputPortFence_RealTimeFeatureZSLPreviewRaw_TFE0_cam0_PortId_15行 186: 04-22 09:51:54.137 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_TFE0_cam0 : Type 65544 portId=1 Fence 5 signaled with success in node fence handler FOR 1388 :NodeOutputPortFence_RealTimeFeatureZSLPreviewRaw_TFE0_cam0_PortId_1行 188: 04-22 09:51:54.137 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_TFE0_cam0 : Type 65544 portId=7 Fence 14 signaled with success in node fence handler FOR 1388 :NodeOutputPortFence_RealTimeFeatureZSLPreviewRaw_TFE0_cam0_PortId_7行 203: 04-22 09:51:54.138 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_com.qti.node.memcpy5_cam0 : Type 255 portId=0 Fence 38 signaled with success in node fence handler FOR 1388 :NodeOutputPortFence_RealTimeFeatureZSLPreviewRaw_com.qti.node.memcpy5_cam0_PortId_0行 225: 04-22 09:51:54.155 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_com.qti.node.gme0_cam0 : Type 255 portId=0 Fence 34 signaled with success in node fence handler FOR 1385 :DelayedBufferFence_RealTimeFeatureZSLPreviewRaw_com.qti.node.gme0_cam0行 227: 04-22 09:51:54.155 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_com.qti.node.gme0_cam0 : Type 255 portId=0 Fence 33 signaled with success in node fence handler FOR 1385 :NodeOutputPortFence_RealTimeFeatureZSLPreviewRaw_com.qti.node.gme0_cam0_PortId_0行 291: 04-22 09:51:54.175 1559 1649 I CamX : [ INFO][CORE ] camxnode.cpp:6827 CSLFenceCallback() Node::RealTimeFeatureZSLPreviewRaw_IPE0_cam0 : Type 65538 portId=8 Fence 45 signaled with success in node fence handler FOR 1385 :NodeOutputPortFence_RealTimeFeatureZSLPreviewRaw_IPE0_cam0_PortId_8
对比发现:
- 正常日志:com.qti.node.gme0 node 10ms就回调了。
- 异常日志:com.qti.node.gme0 node 50ms才回调了,导致IPE node也返帧慢,最终导致帧率太低。本身帧率33ms 1帧,这个node太慢了。然而CSLFenceCallback最终是KMD kernel执行完触发回调的。
2.4 :分析node回调慢原因。
我们搜索异常帧的error和warn日志:
1559 1940 W IS_ALGO : IS1028: V3: is_valid_frame_times(2999): Frame drop was detected. (# of missing frames, current frame SOF, previous frame SOF): 1, 51954154078, 51954087165 1559 1940 W IS_ALGO : IS1028: V3: is_valid_frame_times(2999): Frame drop was detected. (# of missing frames, current frame SOF, previous frame SOF): 1, 51954154078, 51954087165 1559 1940 W IS_ALGO : IS1028: V3: is_valid_frame_times(2999): Frame drop was detected. (# of missing frames, current frame SOF, previous frame SOF): 1, 51954154078, 51954087165 1559 1940 E IS_ALGO : IS0518: V3: is_valid_frequency(1533): acc: frame_id 1407: estimated_frequency = 801.7Hz is different between frames! (might indicate on missing samples / false time stamps) average estimated freq = 416.0Hz 1559 1940 W IS_ALGO : IS1028: V3: is_valid_frame_times(2999): Frame drop was detected. (# of missing frames, current frame SOF, previous frame SOF): 1, 51954154078, 51954087165 1559 1940 E IS_ALGO : IS0519: V3: is_valid_frequency(1546): Gyro: frame_id 1408: Average estimated frequency = 801.8Hz is different from requested frequency = 416.0Hz 1559 1940 E IS_ALGO : IS0518: V3: is_valid_frequency(1533): acc: frame_id 1408: estimated_frequency = 801.7Hz is different between frames! (might indicate on missing samples / false time stamps) average estimated freq = 416.0Hz 1559 1940 E IS_ALGO : IS0518: V3: is_valid_frequency(1533): acc: frame_id 1409: estimated_frequency = 801.9Hz is different between frames! (might indicate on missing samples / false time stamps) average estimated freq = 416.0Hz 1559 1940 W IS_ALGO : IS1028: V3: is_valid_frame_times(2999): Frame drop was detected. (# of missing frames, current frame SOF, previous frame SOF): 1, 51954287903, 51954220991 1559 1940 W IS_ALGO : IS1028: V3: is_valid_frame_times(2999): Frame drop was detected. (# of missing frames, current frame SOF, previous frame SOF): 1, 51954287903, 51954220991 1559 1941 W IS_ALGO : IS1028: V3: is_valid_frame_times(2999): Frame drop was detected. (# of missing frames, current frame SOF, previous frame SOF): 1, 51954287903, 51954220991
我们发现频繁打印频率,gyro采样率不够导致的Frame drop was detected,从而frame SOF丢帧。
2.5 :解决方式
1:联系BSP模块分析gyro采样率问题,但周期比较长。
2:由于是三方APP,无需执行com.qti.node.gme0 node,我们可以对此三方过滤该node。
2.6 :屏蔽node方式
我们分析代码,可以知道可以由此变量控制是否执行gme node。
camx/src/swl/eis/gme/camxchinodegme.h
1976 BOOL m_bIsDefaultGridTransformEnabled; ///< Flag to check if default grid and
1977 ///< transform enable
2.7 :解决方案
我们在ChiGMENode::Initialize中通过三方包名判断设置m_isNeedSkip3rdGme =TRUE,即可在OverrideProcessRequest过程中将m_bIsDefaultGridTransformEnabled设置为true。
8552 VOID ChiGMENode::OverrideProcessRequest(
8553 CHINODEPROCESSREQUESTINFO* pProcessRequestInfo,
8554 UINT32 currentCameraIdIndex,
8555 INT32& sequenceNumber)
8556 {
8557 if (m_skipGMEforLongshot && m_longshotTag)
8558 {
8559 VOID* pData = NULL;
8560 pData = ChiNodeUtils::GetMetaData(pProcessRequestInfo->frameNum, m_longshotTag | InputMetadataSectionMask,
8561 ChiMetadataDynamic, &g_ChiNodeInterface, m_hChiSession);
8562
8563 if (pData)
8564 {
8565 BOOL isLongShot = *static_cast<BOOL*>(pData);
8566 if (isLongShot)
8567 {
8568 m_bIsDefaultGridTransformEnabled = TRUE;
8569 }
8570 else
8571 {
8572 m_bIsDefaultGridTransformEnabled = m_bIsDefaultGridEnable;
8573 }
8574 }
8575 else
8576 {
8577 m_bIsDefaultGridTransformEnabled = m_bIsDefaultGridEnable;
8578 }
8579 }
8580 //这里来过滤node
8581 if (m_isNeedSkip3rdGme ==TRUE)
8582 {
8583 m_bIsDefaultGridTransformEnabled = TRUE;
8584 }
8585 }
【关注我,后续持续新增专题博文,谢谢!!!】
下一篇讲解: