问题现象

视频内容卡死,进度条在走,声音在播放。

http://jira.it.chehejia.com/browse/XHMI-99697

Feishu20240425-185841.mp4

问题分析

android-log.zip

从 log 分析 buffer queue 的操作流程,注释中说明了当前 dequeue、acquire 和 free slot 状态。为了方便查看,删除了一部分内容。

% Set dequeue timeout 0
17:06:51.306  8362 29197 I Producer: setDequeueTimeout: 0
% Set max dequeue count 8
17:06:51.306  8362 29197 I Producer: setMaxDequeuedBufferCount: maxDequeuedBuffers = 8
% Dequeue request detach slot 0
17:06:51.308  8362 29197 I Producer: dequeueBuffer: returning slot=0/0 buf=0xb4000078194889d0 flags=0x1
17:06:51.308  8362 29197 I Producer: requestBuffer: slot 0
17:06:51.308  8362 29197 I Producer: detachBuffer: slot 0
% Dequeue slot 0...8
17:06:51.318  8362  8612 I Producer: dequeueBuffer: returning slot=0/0 buf=0xb4000078194a0190 flags=0x1
17:06:51.323  8362  8612 I Producer: dequeueBuffer: returning slot=1/0 buf=0xb400007819428f40 flags=0x1
17:06:51.325  8362  8612 I Producer: dequeueBuffer: returning slot=2/0 buf=0xb40000781943e420 flags=0x1
17:06:51.327  8362  8612 I Producer: dequeueBuffer: returning slot=3/0 buf=0xb400007819484ad0 flags=0x1
17:06:51.328  8362  8612 I Producer: dequeueBuffer: returning slot=4/0 buf=0xb40000781949b240 flags=0x1
17:06:51.330  8362  8612 I Producer: dequeueBuffer: returning slot=5/0 buf=0xb40000781943a760 flags=0x1
17:06:51.332  8362  8612 I Producer: dequeueBuffer: returning slot=6/0 buf=0xb4000078194a46c0 flags=0x1
17:06:51.333  8362  8612 I Producer: dequeueBuffer: returning slot=7/0 buf=0xb400007819490ce0 flags=0x1
17:06:51.336  8362  8612 I Producer: dequeueBuffer: returning slot=8/0 buf=0xb40000781943d610 flags=0x1
% No free slot, not queued, TIMED_OUT error
17:06:51.337  8362  8612 E Producer: dequeueBuffer: BufferQueue TIMED_OUT
% Queue 0, acquire. Now dequeued 1 2 3 4 5 6 7 8, acquired 0
17:06:51.341  8362 29197 I Producer: queueBuffer: slot=0/1 time=3333669461399 dataSpace=260 validHdrMetadataTypes=0x0 crop=[0,0,720,1280] transform=0 scale=SCALE_TO_WINDOW
17:06:51.341  8362 29197 I Consumer: acquireBuffer: acquiring { slot=0/1 buffer=0xb4000078194a0190 }
% No free slot, dequeue count = max count, INVALID_OPERATION error
17:06:51.348  8362  8612 E Producer: dequeueBuffer: BufferQueue INVALID_OPERATION
17:06:51.358  8362  8612 E Producer: dequeueBuffer: BufferQueue INVALID_OPERATION
% Queue 5, acquire 5. Now dequeued 1 2 3 6 7 8, acquired 0 5
17:06:51.396  8362 29197 I Producer: queueBuffer: slot=5/2 time=3333730357519 dataSpace=260 validHdrMetadataTypes=0x0 crop=[0,0,720,1280] transform=0 scale=SCALE_TO_WINDOW
17:06:51.396  8362 29197 I Consumer: acquireBuffer: acquiring { slot=5/2 buffer=0xb40000781943a760 }
% Queue 4, acquire 4. Now dequeued 1 2 3 6 7 8, acquired 0 4 5
17:06:51.397  8362 29197 I Producer: queueBuffer: slot=4/3 time=3333763690849 dataSpace=260 validHdrMetadataTypes=0x0 crop=[0,0,720,1280] transform=0 scale=SCALE_TO_WINDOW
17:06:51.397  8362 29197 I Consumer: acquireBuffer: acquiring { slot=4/3 buffer=0xb40000781949b240 }
% Release 0. Now dequeued 1 2 3 5 6 7 8, acquired 4 5, free 0
17:06:51.404  8362 11816 I Consumer: releaseBuffer: releasing slot 0
% Queue 6, acquire 6. Now dequeued 1 2 3 7 8, acquired 4 5 6
17:06:51.426  8362 29197 I Producer: queueBuffer: slot=6/4 time=3333797024179 dataSpace=260 validHdrMetadataTypes=0x0 crop=[0,0,720,1280] transform=0 scale=SCALE_TO_WINDOW
17:06:51.426  8362 29197 I Consumer: acquireBuffer: acquiring { slot=6/4 buffer=0xb4000078194a46c0 }
% Dequeue 0. Now dequeued 0 1 2 3 7 8, acquired 4 5 6
17:06:51.437  8362  8612 I Producer: dequeueBuffer: returning slot=0/1 buf=0xb4000078194a0190 flags=0
% No free slot, dequeue count < max count, TIMED_OUT error
17:06:51.438  8362  8612 E Producer: dequeueBuffer: BufferQueue TIMED_OUT
% Release 4 5. Now dequeued 0 1 2 3 7 8, acquired 6, free 4 5
17:06:51.438  8362 11816 I Consumer: releaseBuffer: releasing slot 5
17:06:51.471  8362 11816 I Consumer: releaseBuffer: releasing slot 4
% Queue 3, acquire 3. Now dequeued 0 1 2 7 8, acquired 3 6, free 4 5
17:06:51.477  8362 29197 I Producer: queueBuffer: slot=3/5 time=3333847024174 dataSpace=260 validHdrMetadataTypes=0x0 crop=[0,0,720,1280] transform=0 scale=SCALE_TO_WINDOW
17:06:51.477  8362 29197 I Consumer: acquireBuffer: acquiring { slot=3/5 buffer=0xb400007819484ad0 }
% Dequeue 5 4. Now dequeued 0 1 2 4 5 7 8, acquired 3 6
17:06:51.516  8362  8612 I Producer: dequeueBuffer: returning slot=5/2 buf=0xb40000781943a760 flags=0
17:06:51.518  8362  8612 I Producer: dequeueBuffer: returning slot=4/3 buf=0xb40000781949b240 flags=0
% No free slot, dequeue count < max count, TIMED_OUT error
17:06:51.519  8362  8612 E Producer: dequeueBuffer: BufferQueue TIMED_OUT
% Release 6. Now dequeued 0 1 2 4 5 7 8, acquired 3, free 6
17:06:51.521  8362 11816 I Consumer: releaseBuffer: releasing slot 6
% Queue 8, acquire 8. Now dequeued 0 1 2 4 5 7, acquired 3 8, free 6
17:06:51.528  8362 29197 I Producer: queueBuffer: slot=8/6 time=3333880357504 dataSpace=260 validHdrMetadataTypes=0x0 crop=[0,0,720,1280] transform=0 scale=SCALE_TO_WINDOW
17:06:51.528  8362 29197 I Consumer: acquireBuffer: acquiring { slot=8/6 buffer=0xb40000781943d610 }
% Dequeue 6. Now dequeued 0 1 2 4 5 6 7, acquired 3
17:06:51.530  8362  8612 I Producer: dequeueBuffer: returning slot=6/4 buf=0xb4000078194a46c0 flags=0
% No free slot, dequeue count < max count, TIMED_OUT error
17:06:51.532  8362  8612 E Producer: dequeueBuffer: BufferQueue TIMED_OUT
% Queue 7, acquire 7. Now dequeued 0 1 2 4 5 6, acquired 3 7
17:06:51.538  8362 29197 I Producer: queueBuffer: slot=7/7 time=3333913690834 dataSpace=260 validHdrMetadataTypes=0x0 crop=[0,0,720,1280] transform=0 scale=SCALE_TO_WINDOW
17:06:51.539  8362 29197 I Consumer: acquireBuffer: acquiring { slot=7/7 buffer=0xb400007819490ce0 }
% No free slot, dequeue count < max count, TIMED_OUT error
17:06:51.543  8362  8612 E Producer: dequeueBuffer: BufferQueue TIMED_OUT
% Release 3. Now dequeued 0 1 2 4 5 6, acquired 7, free 3
17:06:51.553  8362 11816 I Consumer: releaseBuffer: releasing slot 3
% Queue 5, acquire 5. Now dequeued 0 1 2 4 6, acquired 5 7, free 3
17:06:51.578  8362 29197 I Producer: queueBuffer: slot=5/8 time=3333947024164 dataSpace=260 validHdrMetadataTypes=0x0 crop=[0,0,720,1280] transform=0 scale=SCALE_TO_WINDOW
17:06:51.578  8362 29197 I Consumer: acquireBuffer: acquiring { slot=5/8 buffer=0xb40000781943a760 }
% Release 8 7. Now dequeued 0 1 2 4 6, acquired 5, free 3 7 8
17:06:51.588  8362 11816 I Consumer: releaseBuffer: releasing slot 8
17:06:51.620  8362 11816 I Consumer: releaseBuffer: releasing slot 7
% Dequeue 3 8 7. Now dequeued 0 1 2 3 4 6 7 8, acquired 5
17:06:51.621  8362  8612 I Producer: dequeueBuffer: returning slot=3/5 buf=0xb400007819484ad0 flags=0
17:06:51.622  8362  8612 I Producer: dequeueBuffer: returning slot=8/6 buf=0xb40000781943d610 flags=0
17:06:51.624  8362  8612 I Producer: dequeueBuffer: returning slot=7/7 buf=0xb400007819490ce0 flags=0
% No free slot, dequeue count = max count, INVALID_OPERATION error
17:06:51.624  8362  8612 E Producer: dequeueBuffer: BufferQueue INVALID_OPERATION
% Queue 2, acquire 2. Now dequeued 0 1 3 4 6 7 8, acquired 2 5
17:06:51.628  8362 29197 I Producer: queueBuffer: slot=2/9 time=3333997024159 dataSpace=260 validHdrMetadataTypes=0x0 crop=[0,0,720,1280] transform=0 scale=SCALE_TO_WINDOW
17:06:51.628  8362 29197 I Consumer: acquireBuffer: acquiring { slot=2/9 buffer=0xb40000781943e420 }
% No free slot, dequeue count < max count, TIMED_OUT error
17:06:51.635  8362  8612 E Producer: dequeueBuffer: BufferQueue TIMED_OUT
% Queue 3, acquire 3. Now dequeued 0 1 4 6 7 8, acquired 2 3 5
17:06:51.658  8362 29197 I Producer: queueBuffer: slot=3/10 time=3334030357489 dataSpace=260 validHdrMetadataTypes=0x0 crop=[0,0,720,1280] transform=0 scale=SCALE_TO_WINDOW
17:06:51.658  8362 29197 I Consumer: acquireBuffer: acquiring { slot=3/10 buffer=0xb400007819484ad0 }
% Release 5. Now dequeued 0 1 4 6 7 8, acquired 2 3, free 5
17:06:51.671  8362 11816 I Consumer: releaseBuffer: releasing slot 5
# Queue 6, acquire 6. Now dequeued 0 1 4 7 8, acquired 2 3 6
17:06:51.688  8362 29197 I Producer: queueBuffer: slot=6/11 time=3334063690819 dataSpace=260 validHdrMetadataTypes=0x0 crop=[0,0,720,1280] transform=0 scale=SCALE_TO_WINDOW
17:06:51.688  8362 29197 I Consumer: acquireBuffer: acquiring { slot=6/11 buffer=0xb4000078194a46c0 }
% Release 2. Now dequeued 0 1 4 7 8, acquired 3 6, free 2
17:06:51.704  8362 11816 I Consumer: releaseBuffer: releasing slot 2
# Dequeue 5 2. Now dequeued 0 1 2 4 5 7 8, acquired 3 6
17:06:51.713  8362  8612 I Producer: dequeueBuffer: returning slot=5/8 buf=0xb40000781943a760 flags=0
17:06:51.714  8362  8612 I Producer: dequeueBuffer: returning slot=2/9 buf=0xb40000781943e420 flags=0
% No free slot, dequeue count < max count, TIMED_OUT error
17:06:51.715  8362  8612 E Producer: dequeueBuffer: BufferQueue TIMED_OUT
17:06:51.725  8362  8612 E Producer: dequeueBuffer: BufferQueue TIMED_OUT
% Queue 8, acquire 8. Now dequeued 0 1 2 4 5 7, acquired 3 6 8
17:06:51.728  8362 29197 I Producer: queueBuffer: slot=8/12 time=3334097024149 dataSpace=260 validHdrMetadataTypes=0x0 crop=[0,0,720,1280] transform=0 scale=SCALE_TO_WINDOW
17:06:51.728  8362 29197 I Consumer: acquireBuffer: acquiring { slot=8/12 buffer=0xb40000781943d610 }
% Release 3 6. Now dequeued 0 1 2 4 5 7, acquired 8, free 3 6
17:06:51.737  8362 11816 I Consumer: releaseBuffer: releasing slot 3
17:06:51.772  8362 12718 I Consumer: releaseBuffer: releasing slot 6
% Dequeue 3 6. Now dequeued 0 1 2 3 4 5 6 7, acquired 8
17:06:51.804  8362  8612 I Producer: dequeueBuffer: returning slot=3/10 buf=0xb400007819484ad0 flags=0
17:06:51.805  8362  8612 I Producer: dequeueBuffer: returning slot=6/11 buf=0xb4000078194a46c0 flags=0
% No free slot, dequeue count = max count, INVALID_OPERATION error
17:06:51.806  8362  8612 E Producer: dequeueBuffer: BufferQueue INVALID_OPERATION
% Queue 4, acquire 4. Now dequeued 0 1 2 3 5 6 7, acquired 4 8
17:06:51.809  8362 29197 I Producer: queueBuffer: slot=4/13 time=3334147024144 dataSpace=260 validHdrMetadataTypes=0x0 crop=[0,0,720,1280] transform=0 scale=SCALE_TO_WINDOW
17:06:51.809  8362 29197 I Consumer: acquireBuffer: acquiring { slot=4/13 buffer=0xb40000781949b240 }
% Queue 5, acquire 5. Now dequeued 0 1 2 3 6 7, acquired 4 5 8
17:06:51.810  8362 29197 I Producer: queueBuffer: slot=5/14 time=3334180357474 dataSpace=260 validHdrMetadataTypes=0x0 crop=[0,0,720,1280] transform=0 scale=SCALE_TO_WINDOW
17:06:51.810  8362 29197 I Consumer: acquireBuffer: acquiring { slot=5/14 buffer=0xb40000781943a760 }
% No free slot, dequeue count < max count, TIMED_OUT error
17:06:51.816  8362  8612 E Producer: dequeueBuffer: BufferQueue TIMED_OUT
% Release 8 4. Now dequeued 0 1 2 3 6 7, acquired 5, free 4 8
17:06:51.820  8362 12718 I Consumer: releaseBuffer: releasing slot 8
17:06:51.854  8362 12718 I Consumer: releaseBuffer: releasing slot 4
% Dequeue 8 4. Now dequeued 0 1 2 3 4 6 7 8, acquired 5
17:06:51.895  8362  8612 I Producer: dequeueBuffer: returning slot=8/12 buf=0xb40000781943d610 flags=0
17:06:51.896  8362  8612 I Producer: dequeueBuffer: returning slot=4/13 buf=0xb40000781949b240 flags=0
% No free slot, dequeue count = max count, INVALID_OPERATION error
17:06:51.897  8362  8612 E Producer: dequeueBuffer: BufferQueue INVALID_OPERATION
% Queue 7, acquire 7. Now dequeued 0 1 2 3 4 6 8, acquired 5 7
17:06:51.900  8362 29197 I Producer: queueBuffer: slot=7/15 time=3334213323597 dataSpace=260 validHdrMetadataTypes=0x0 crop=[0,0,720,1280] transform=0 scale=SCALE_TO_WINDOW
17:06:51.900  8362 29197 I Consumer: acquireBuffer: acquiring { slot=7/15 buffer=0xb400007819490ce0 }
% Queue 3, acquire 3. Now dequeued 0 1 2 4 6 8, acquired 3 5 7
17:06:51.902  8362 29197 I Producer: queueBuffer: slot=3/16 time=3334246656927 dataSpace=260 validHdrMetadataTypes=0x0 crop=[0,0,720,1280] transform=0 scale=SCALE_TO_WINDOW
17:06:51.902  8362 29197 I Consumer: acquireBuffer: acquiring { slot=3/16 buffer=0xb400007819484ad0 }
% No free slot, dequeue count < max count, TIMED_OUT error
17:06:51.908  8362  8612 E Producer: dequeueBuffer: BufferQueue TIMED_OUT
% Release 7 5. Now dequeued 0 1 2 4 6 8, acquired 3, free 5 7
17:06:51.915  8362 12718 I Consumer: releaseBuffer: releasing slot 7
17:06:51.920  8362 18747 I Consumer: releaseBuffer: releasing slot 5
% Dequeue 7 5. Now dequeued 0 1 2 4 5 6 7 8, acquired 3
17:06:51.986  8362  8612 I Producer: dequeueBuffer: returning slot=7/15 buf=0xb400007819490ce0 flags=0
17:06:51.987  8362  8612 I Producer: dequeueBuffer: returning slot=5/14 buf=0xb40000781943a760 flags=0
% No free slot, dequeue count = max count, INVALID_OPERATION error
17:06:51.989  8362  8612 E Producer: dequeueBuffer: BufferQueue INVALID_OPERATION
% Queue 5, acquire 5. Now dequeued 0 1 2 4 6 7 8, acquired 3 5
17:06:51.994  8362 29197 I Producer: queueBuffer: slot=5/17 time=3334313323587 dataSpace=260 validHdrMetadataTypes=0x0 crop=[0,0,720,1280] transform=0 scale=SCALE_TO_WINDOW
17:06:51.994  8362 29197 I Consumer: acquireBuffer: acquiring { slot=5/17 buffer=0xb40000781943a760 }
% Cancel 1. Not dequeued 0 2 4 6 7 8, acquired 3 5, free 1
17:06:51.993  8362 29197 I Producer: cancelBuffer: slot 1
% Dequeue 1. Now dequeued 0 1 2 4 6 7 8, acquired 3 5
17:06:51.999  8362  8612 I Producer: dequeueBuffer: returning slot=1/0 buf=0xb400007819428f40 flags=0
% No free slot, dequeue count < max count, TIMED_OUT error
17:06:51.999  8362  8612 E Producer: dequeueBuffer: BufferQueue TIMED_OUT
% Release 3. Now dequeued 0 1 2 4 6 7 8, acquired 5, free 3
17:06:52.004  8362 11816 I Consumer: releaseBuffer: releasing slot 3
% Dequeue 3. Now dequeued 0 1 2 3 4 6 7 8, acquired 5
17:06:52.078  8362  8612 I Producer: dequeueBuffer: returning slot=3/16 buf=0xb400007819484ad0 flags=0
% No free slot, dequeue count = max count, INVALID_OPERATION error
17:06:52.079  8362  8612 E Producer: dequeueBuffer: BufferQueue INVALID_OPERATION
% Cancel 7. Not dequeued 0 1 2 3 4 6 8, acquired 5, free 7
17:06:52.084  8362 29197 I Producer: cancelBuffer: slot 7
% Dequeue 7. Now dequeued 0 1 2 3 4 6 7 8, acquired 5
17:06:52.089  8362  8612 I Producer: dequeueBuffer: returning slot=7/15 buf=0xb400007819490ce0 flags=0
% No free slot, dequeue count = max count, INVALID_OPERATION error
17:06:52.089  8362  8612 E Producer: dequeueBuffer: BufferQueue INVALID_OPERATION
17:06:52.168  8362  8612 E Producer: dequeueBuffer: BufferQueue INVALID_OPERATION
17:06:52.246  8362  8612 E Producer: dequeueBuffer: BufferQueue INVALID_OPERATION
% No more queue, hang...

17:06:51.994 最后一次 queue buffer,17:06:52.089 dequeue 了最后一个 free buffer,之后达到了最大限制无法再 dequeue,一直打印 INVALID_OPERATION 错误。

Untitled

接下来需要 codec 确认没有 queue buffer 的原因。

问题修复

高通提供了 CL,如下所示:

Untitled

http://gerrit.it.chehejia.com:8080/c/hmi/mercury/q-common/proprietary/+/1021722