How to measure framerate, 99th/90th/50th percentiles of FPS on both tunneling and non-tunneling usecases. Ticket #4088 recommended to use the releaseTimeNs in the following segment to calculate framerate.
protected void renderOutputBufferV21(// inside MediaCodecVideoRenderer
MediaCodec codec, int index, long presentationTimeUs, long releaseTimeNs) {
It is viable solution for non-tunneling mode, but not for tunneling mode. In tunneling mode, such method is not invoked.
So we are trying to find another solution. The following is our proposal to record the time that video buffer being rendered on the screen. We are aware of it's impossible to get the real timing. But we want to get the information as accurate as possible, OFC, for both tunneling and non-tunneling mode.
@@ -1018,6 +1019,8 @@ public class MediaCodecVideoRenderer extends MediaCodecRenderer {
@CallSuper
@Override
protected void onProcessedOutputBuffer(long presentationTimeUs) {
// It's very simple, just save the time to an array, and the consumer would take it
// and reset the renderTimeIdx
+ decoderCounters.renderTime[decoderCounters.renderTimeIdx++] = System.nanoTime();
if (!tunneling) {
buffersInCodecCount--;
}
Is this feature in the road map? We are willing to develop this tiny feature and contribute to the community.
After digging a bit more into DebugMediaCodecVideoRenderer it seems like the method parameter presentationTimeUs indicates the actual buffer presentation time both with tunneling and w/o tunneling. Can you pls clarify this?
@Override
protected void onProcessedOutputBuffer(long presentationTimeUs) {
super.onProcessedOutputBuffer(presentationTimeUs);
bufferCount++;
long expectedTimestampUs = dequeueTimestamp();
if (expectedTimestampUs != presentationTimeUs) {
throw new IllegalStateException("Expected to dequeue video buffer with presentation "
+ "timestamp: " + expectedTimestampUs + ". Instead got: " + presentationTimeUs
+ " (Processed buffers since last flush: " + bufferCount + ").");
}
}
Your question is very similar to #7100, please read my comment https://github.com/google/ExoPlayer/issues/7100#issuecomment-604939224 for more detail.
To summarize, it is not possible to reliably tell if a frame is dropped _in tunneling mode_ as there are no guaranty that ExoPlayer receives a callback for each frame rendered.
Nevertheless, more experiments are needed to judge the reliability of onFrameRendered.
@@ -1018,6 +1019,8 @@ public class MediaCodecVideoRenderer extends MediaCodecRenderer { @CallSuper @Override protected void onProcessedOutputBuffer(long presentationTimeUs) { // It's very simple, just save the time to an array, and the consumer would take it // and reset the renderTimeIdx + decoderCounters.renderTime[decoderCounters.renderTimeIdx++] = System.nanoTime(); if (!tunneling) { buffersInCodecCount--; }
For non tunneling mode, onProcessedOutputBuffer will be significantly delayed, multiple calls can even be patched together, so the real time clock is unusable.
I would recommend to only use timestamps and ignore the system clock for tunneling mode. It should allow you to know if a frame was rendered. Even then, it might be unreliable depending on the tunneling implementation.
On the other hand, you can safely use the System clock in non tunneling mode to save when the frame was rendered.
@andrewlewis, why did you recommend to hook into renderOutputBufferV21 instead of onProcessedOutputBuffer in #4088?
Even then, it might be unreliable depending on the tunneling implementation.
Can I ask who implements this? Chipset vendor or ODM/OEM providers? My bet is chipset vendor.
Here's some specs about the test env
Here's the logic to record the time
protected void onProcessedOutputBuffer(long presentationTimeUs) {
+ timeBatch[idx] = System.nanoTime() / 1000;
+ timeBatch[idx + BATCH_CNT] = presentationTimeUs/1000;
Here's the snippet for print out.
for (int i = 0; i < BATCH_CNT; i++) {
sb.append("===>rt_time = " + times[i] + "\tpts = " + times[i + BATCH_CNT] + "\n");
}
And here's the result. It seems like the result is actually quite promising. What do you think, @krocard. I can test it on other cases, such as tunneling off and Mpeg-dash. I'm wondering how can I document that. We are willing to contribute to the community.
===>rt_time = 275540400591 pts = 1593155077854
===>rt_time = 275540452585 pts = 1593155077874
===>rt_time = 275540483283 pts = 1593155077894
===>rt_time = 275540483302 pts = 1593155077914
===>rt_time = 275540485420 pts = 1593155077934
===>rt_time = 275540489652 pts = 1593155077954
===>rt_time = 275540545561 pts = 1593155077974
===>rt_time = 275540545585 pts = 1593155077994
===>rt_time = 275540558404 pts = 1593155078014
===>rt_time = 275540591682 pts = 1593155078034
===>rt_time = 275540634572 pts = 1593155078054
===>rt_time = 275540634579 pts = 1593155078074
===>rt_time = 275540674587 pts = 1593155078094
===>rt_time = 275540674593 pts = 1593155078114
===>rt_time = 275540682657 pts = 1593155078134
===>rt_time = 275540689760 pts = 1593155078154
===>rt_time = 275540753595 pts = 1593155078174
===>rt_time = 275540753617 pts = 1593155078194
===>rt_time = 275540982952 pts = 1593155078214
===>rt_time = 275541214181 pts = 1593155078234
===>rt_time = 275541214636 pts = 1593155078254
===>rt_time = 275541214661 pts = 1593155078274
===>rt_time = 275541214683 pts = 1593155078294
===>rt_time = 275541214705 pts = 1593155078314
===>rt_time = 275541214727 pts = 1593155078334
===>rt_time = 275541214746 pts = 1593155078354
===>rt_time = 275541214768 pts = 1593155078374
===>rt_time = 275541405681 pts = 1593155078394
===>rt_time = 275541405689 pts = 1593155078414
===>rt_time = 275541405694 pts = 1593155078434
Can I ask who implements this? Chipset vendor or ODM/OEM providers? My bet is chipset vendor.
Probably chipset vendor, yes, but ODM/OEM could also have customized it.
Our STB box is based upon Broadcom reference board banff
If you only have only one/a few devices to support, then using the onFrameRendered callback is much more reliable as you can validate each hardware decoder/renderer behaviour.
And here's the result. It seems like the result is actually quite promising. What do you think, @krocard?
Your result is indeed promising for your device. I would still not rely on rt_time for your analysis. A burst of CPU activity could delay those callback leading to false positive drop frame detection.
The timestamps (pts) should be enough to detect frame drop.
I can test it on other cases, such as tunneling off and Mpeg-dash.
I would indeed test each format you want to support, nevertheless having one work as expected is a good sign for the others.
The result for other conditions have been attached as following. The result is too good to believe. Especially for the smooth streaming + tunneling on case
In our application, the MainActivity view is a semi transparent layer on top of the TvView, on which ExoPlayer outputs the video. There's a small animation in the MainActivity View. The animation has slowed down the video considerably - Both the video laggy and audio laggy are very obvious. And in the logcat logs, we have found AudioFlinger: pause because of UNDERRUN, framesReady = 239,minFrames = 240, mFormat = 0x1. But this video laggy is not reflected on this pts array. I'll modify the output logic to make the laggy easier to find.
One more interesting observation. With this setup (animation on top of the TvView) dash performs considerably better than smooth streaming. The most annoying part is the audio glitch/jank while using smooth streaming, it's way worse than dash.
Result for smooth streaming + tunneling off
===>rt_time = 318194306603 pts = 1593197740014
===>rt_time = 318194331514 pts = 1593197740034
===>rt_time = 318194365085 pts = 1593197740054
===>rt_time = 318194365784 pts = 1593197740074
===>rt_time = 318194384424 pts = 1593197740094
===>rt_time = 318194414166 pts = 1593197740114
===>rt_time = 318194438649 pts = 1593197740134
===>rt_time = 318194456490 pts = 1593197740154
===>rt_time = 318194466716 pts = 1593197740174
===>rt_time = 318194499829 pts = 1593197740194
===>rt_time = 318194511821 pts = 1593197740214
===>rt_time = 318194536873 pts = 1593197740234
===>rt_time = 318194555481 pts = 1593197740254
===>rt_time = 318194575834 pts = 1593197740274
===>rt_time = 318194586334 pts = 1593197740294
===>rt_time = 318194638449 pts = 1593197740314
===>rt_time = 318194639074 pts = 1593197740334
===>rt_time = 318194661900 pts = 1593197740354
===>rt_time = 318194671932 pts = 1593197740374
===>rt_time = 318194754276 pts = 1593197740394
===>rt_time = 318194754721 pts = 1593197740414
===>rt_time = 318194754989 pts = 1593197740434
===>rt_time = 318194755479 pts = 1593197740454
===>rt_time = 318194901463 pts = 1593197740474
===>rt_time = 318194902054 pts = 1593197740494
===>rt_time = 318194902978 pts = 1593197740514
===>rt_time = 318194904656 pts = 1593197740534
===>rt_time = 318194907330 pts = 1593197740554
===>rt_time = 318194909467 pts = 1593197740574
===>rt_time = 318194912441 pts = 1593197740594
===>rt_time = 318194915546 pts = 1593197740614
===>rt_time = 318194916814 pts = 1593197740634
===>rt_time = 318195038068 pts = 1593197740654
===>rt_time = 318195039799 pts = 1593197740674
===>rt_time = 318195040538 pts = 1593197740694
===>rt_time = 318195040968 pts = 1593197740714
===>rt_time = 318195041547 pts = 1593197740734
===>rt_time = 318195122260 pts = 1593197740754
===>rt_time = 318195123530 pts = 1593197740774
===>rt_time = 318195124227 pts = 1593197740794
===>rt_time = 318195124932 pts = 1593197740814
===>rt_time = 318195125850 pts = 1593197740834
===>rt_time = 318195195763 pts = 1593197740854
===>rt_time = 318195196313 pts = 1593197740874
===>rt_time = 318195197275 pts = 1593197740894
===>rt_time = 318195299058 pts = 1593197740914
===>rt_time = 318195299611 pts = 1593197740934
===>rt_time = 318195300592 pts = 1593197740954
Dash + tunneling off
===>rt_time = 318514306098 pts = 1593198061333
===>rt_time = 318514347276 pts = 1593198061373
===>rt_time = 318514382507 pts = 1593198061413
===>rt_time = 318514425691 pts = 1593198061453
===>rt_time = 318514466783 pts = 1593198061493
===>rt_time = 318514516834 pts = 1593198061533
===>rt_time = 318514551891 pts = 1593198061573
===>rt_time = 318514593418 pts = 1593198061613
===>rt_time = 318514627192 pts = 1593198061653
===>rt_time = 318514665650 pts = 1593198061693
===>rt_time = 318514708455 pts = 1593198061733
===>rt_time = 318514744716 pts = 1593198061773
===>rt_time = 318514784678 pts = 1593198061813
===>rt_time = 318514826632 pts = 1593198061853
===>rt_time = 318514873936 pts = 1593198061893
===>rt_time = 318514907780 pts = 1593198061933
===>rt_time = 318514947568 pts = 1593198061973
===>rt_time = 318514993282 pts = 1593198062013
===>rt_time = 318515026634 pts = 1593198062053
===>rt_time = 318515072802 pts = 1593198062093
===>rt_time = 318515113479 pts = 1593198062133
===>rt_time = 318515149745 pts = 1593198062173
===>rt_time = 318515183994 pts = 1593198062213
===>rt_time = 318515225805 pts = 1593198062253
===>rt_time = 318515273969 pts = 1593198062293
===>rt_time = 318515305610 pts = 1593198062333
===>rt_time = 318515370275 pts = 1593198062373
===>rt_time = 318515385342 pts = 1593198062413
===>rt_time = 318515440222 pts = 1593198062453
===>rt_time = 318515476656 pts = 1593198062493
===>rt_time = 318515507579 pts = 1593198062533
===>rt_time = 318515544200 pts = 1593198062573
===>rt_time = 318515595099 pts = 1593198062613
===>rt_time = 318515627980 pts = 1593198062653
===>rt_time = 318515675773 pts = 1593198062693
===>rt_time = 318515706675 pts = 1593198062733
===>rt_time = 318515749304 pts = 1593198062773
===>rt_time = 318515784724 pts = 1593198062813
===>rt_time = 318515825882 pts = 1593198062853
===>rt_time = 318515874219 pts = 1593198062893
===>rt_time = 318515913650 pts = 1593198062933
===>rt_time = 318515958088 pts = 1593198062973
===>rt_time = 318515989900 pts = 1593198063013
===>rt_time = 318516031570 pts = 1593198063053
===>rt_time = 318516072758 pts = 1593198063093
===>rt_time = 318516118950 pts = 1593198063133
===>rt_time = 318516153485 pts = 1593198063173
===>rt_time = 318516193843 pts = 1593198063213
===>rt_time = 318516226294 pts = 1593198063253
===>rt_time = 318516228496 pts = 1593198063253
===>rt_time = 318516250409 pts = 1593198063273
===>rt_time = 318516274883 pts = 1593198063293
===>rt_time = 318516286133 pts = 1593198063313
===>rt_time = 318516307095 pts = 1593198063333
===>rt_time = 318516327589 pts = 1593198063353
===>rt_time = 318516349346 pts = 1593198063373
===>rt_time = 318516373762 pts = 1593198063393
===>rt_time = 318516393445 pts = 1593198063413
===>rt_time = 318516404229 pts = 1593198063433
===>rt_time = 318516424319 pts = 1593198063453
===>rt_time = 318516453416 pts = 1593198063473
===>rt_time = 318516464359 pts = 1593198063493
===>rt_time = 318516485668 pts = 1593198063513
===>rt_time = 318516507268 pts = 1593198063533
===>rt_time = 318516525573 pts = 1593198063553
===>rt_time = 318516545585 pts = 1593198063573
===>rt_time = 318516570571 pts = 1593198063593
===>rt_time = 318516589357 pts = 1593198063613
===>rt_time = 318516609069 pts = 1593198063633
===>rt_time = 318516631622 pts = 1593198063653
===>rt_time = 318516651763 pts = 1593198063673
===>rt_time = 318516672556 pts = 1593198063693
===>rt_time = 318516692882 pts = 1593198063713
===>rt_time = 318516703868 pts = 1593198063733
===>rt_time = 318516731712 pts = 1593198063753
===>rt_time = 318516751951 pts = 1593198063773
===>rt_time = 318516777332 pts = 1593198063793
===>rt_time = 318516786998 pts = 1593198063813
===>rt_time = 318516808221 pts = 1593198063833
===>rt_time = 318516832709 pts = 1593198063853
===>rt_time = 318516843392 pts = 1593198063873
===>rt_time = 318516873139 pts = 1593198063893
===>rt_time = 318516883548 pts = 1593198063913
===>rt_time = 318516918303 pts = 1593198063933
===>rt_time = 318516928930 pts = 1593198063953
Dash + tunneling on
===>rt_time = 318637819216 pts = 1593198183333
===>rt_time = 318637819260 pts = 1593198183373
===>rt_time = 318637819292 pts = 1593198183493
===>rt_time = 318637819411 pts = 1593198183533
===>rt_time = 318637819501 pts = 1593198183573
===>rt_time = 318637947675 pts = 1593198183613
===>rt_time = 318637947745 pts = 1593198183653
===>rt_time = 318637947882 pts = 1593198183693
===>rt_time = 318637948075 pts = 1593198183733
===>rt_time = 318637948257 pts = 1593198183773
===>rt_time = 318638040745 pts = 1593198183813
===>rt_time = 318638040780 pts = 1593198183853
===>rt_time = 318638040873 pts = 1593198183893
===>rt_time = 318638040959 pts = 1593198183933
===>rt_time = 318638104379 pts = 1593198183973
===>rt_time = 318638104494 pts = 1593198184013
===>rt_time = 318638157466 pts = 1593198184053
===>rt_time = 318638178825 pts = 1593198184093
===>rt_time = 318638206317 pts = 1593198184133
===>rt_time = 318638206359 pts = 1593198184173
===>rt_time = 318638262659 pts = 1593198184213
===>rt_time = 318638278511 pts = 1593198184253
===>rt_time = 318638315636 pts = 1593198184293
===>rt_time = 318638392946 pts = 1593198184333
===>rt_time = 318638418579 pts = 1593198184373
===>rt_time = 318638457907 pts = 1593198184413
===>rt_time = 318638564966 pts = 1593198184453
===>rt_time = 318638565066 pts = 1593198184493
===>rt_time = 318638652144 pts = 1593198184533
===>rt_time = 318638652191 pts = 1593198184573
===>rt_time = 318638684719 pts = 1593198184613
===>rt_time = 318638704413 pts = 1593198184653
===>rt_time = 318638760263 pts = 1593198184693
===>rt_time = 318638826990 pts = 1593198184733
===>rt_time = 318638827083 pts = 1593198184773
===>rt_time = 318638881033 pts = 1593198184813
===>rt_time = 318638919420 pts = 1593198184853
===>rt_time = 318638952688 pts = 1593198184893
===>rt_time = 318638975063 pts = 1593198184933
===>rt_time = 318639038116 pts = 1593198184973
===>rt_time = 318639059104 pts = 1593198185013
===>rt_time = 318639066193 pts = 1593198185053
===>rt_time = 318639147573 pts = 1593198185093
===>rt_time = 318639219249 pts = 1593198185133
===>rt_time = 318639247581 pts = 1593198185173
===>rt_time = 318639266900 pts = 1593198185213
===>rt_time = 318639266949 pts = 1593198185253
===>rt_time = 318639439250 pts = 1593198185293
===>rt_time = 318639480419 pts = 1593198185333
===>rt_time = 318639480461 pts = 1593198185373
===>rt_time = 318639480494 pts = 1593198185413
===>rt_time = 318639515505 pts = 1593198185453
===>rt_time = 318639515633 pts = 1593198185493
===>rt_time = 318639566489 pts = 1593198185533
===>rt_time = 318639623657 pts = 1593198185573
===>rt_time = 318639645683 pts = 1593198185613
===>rt_time = 318639713433 pts = 1593198185653
===>rt_time = 318639723815 pts = 1593198185693
===>rt_time = 318639804231 pts = 1593198185733
===>rt_time = 318639852542 pts = 1593198185773
===>rt_time = 318639895085 pts = 1593198185813
===>rt_time = 318639996602 pts = 1593198185853
===>rt_time = 318639996642 pts = 1593198185893
===>rt_time = 318640040512 pts = 1593198185933
===>rt_time = 318640040571 pts = 1593198185973
===>rt_time = 318640079846 pts = 1593198186013
===>rt_time = 318640079896 pts = 1593198186053
===>rt_time = 318640108392 pts = 1593198186093
===>rt_time = 318640175268 pts = 1593198186133
===>rt_time = 318640340522 pts = 1593198186173
===>rt_time = 318640340660 pts = 1593198186213
===>rt_time = 318640340696 pts = 1593198186253
===>rt_time = 318640381552 pts = 1593198186293
===>rt_time = 318640381592 pts = 1593198186333
===>rt_time = 318640430387 pts = 1593198186373
===>rt_time = 318640461946 pts = 1593198186413
===>rt_time = 318640527638 pts = 1593198186453
===>rt_time = 318640527689 pts = 1593198186493
===>rt_time = 318640593595 pts = 1593198186533
===>rt_time = 318640618333 pts = 1593198186573
===>rt_time = 318640638063 pts = 1593198186613
===>rt_time = 318640691325 pts = 1593198186653
===>rt_time = 318640750400 pts = 1593198186693
===>rt_time = 318640837944 pts = 1593198186733
===>rt_time = 318640837985 pts = 1593198186773
My final version is here. I've adjusted the printout format so that it's eye friendly while scrolling down the logs to find inconsistent numbers.
My personal feeling is this solution is quite promising. While playing 50 FPS resource with MainActivity animation playing, I could feel the glitch, and they are reflected in the log. (The next step is to check whether the time of visual glitch matches the log) While playing a 25 FPS resource without the MainView animation. There's no visible glitch, and there's no inconsistency in the log.
Very promising, I think this solution works.
date +"%T.%3N" without pressing enter keyGlitching happens
canal_sat_bcm:/ $ date +"%T.%3N"
22:27:22.503
Logs around that time. The frame generation time 180 seems match the above mentioned. I'm using a Wifi network to connect to my box, and I'm not that fast. It is understandable that the time on adb shell is ~1 second late than the PTS time.
20 22:27:21.794 326
20 22:27:21.814 0
180 22:27:21.994 0 <========== frame drop
40 22:27:22.034 18
20 22:27:22.054 0
20 22:27:22.074 0
20 22:27:22.094 0
20 22:27:22.114 0
20 22:27:22.134 0
20 22:27:22.154 0
20 22:27:22.174 155
20 22:27:22.194 0
20 22:27:22.214 0
20 22:27:22.234 36
20 22:27:22.254 37
20 22:27:22.274 0
20 22:27:22.294 25
20 22:27:22.314 50
20 22:27:22.334 0
20 22:27:22.354 0
20 22:27:22.374 39
20 22:27:22.394 53
20 22:27:22.414 0
20 22:27:22.434 37
20 22:27:22.454 0
20 22:27:22.474 79
20 22:27:22.494 0
20 22:27:22.514 0
20 22:27:22.534 62
20 22:27:22.554 0
20 22:27:22.574 0
20 22:27:22.594 76
Adding the difference with the previous rt_time and pts makes the your log much more readable.
Looking at your result bellow (folded for readability):
Click to unfold the results posted previously appended with the delta with the previous line
$ awk '/rt_time/{print $0 "\tptrs += " $6-t "\trt_time += " $3-c} !/rt_time/{ print $0} {c=$3; t=$6}'
Smooth streaming + tunneling on
===>rt_time = 275540400591 pts = 1593155077854 ptrs += 1593155077854 rt_time += 275540400591
===>rt_time = 275540452585 pts = 1593155077874 ptrs += 20 rt_time += 51994
===>rt_time = 275540483283 pts = 1593155077894 ptrs += 20 rt_time += 30698
===>rt_time = 275540483302 pts = 1593155077914 ptrs += 20 rt_time += 19
===>rt_time = 275540485420 pts = 1593155077934 ptrs += 20 rt_time += 2118
===>rt_time = 275540489652 pts = 1593155077954 ptrs += 20 rt_time += 4232
===>rt_time = 275540545561 pts = 1593155077974 ptrs += 20 rt_time += 55909
===>rt_time = 275540545585 pts = 1593155077994 ptrs += 20 rt_time += 24
===>rt_time = 275540558404 pts = 1593155078014 ptrs += 20 rt_time += 12819
===>rt_time = 275540591682 pts = 1593155078034 ptrs += 20 rt_time += 33278
===>rt_time = 275540634572 pts = 1593155078054 ptrs += 20 rt_time += 42890
===>rt_time = 275540634579 pts = 1593155078074 ptrs += 20 rt_time += 7
===>rt_time = 275540674587 pts = 1593155078094 ptrs += 20 rt_time += 40008
===>rt_time = 275540674593 pts = 1593155078114 ptrs += 20 rt_time += 6
===>rt_time = 275540682657 pts = 1593155078134 ptrs += 20 rt_time += 8064
===>rt_time = 275540689760 pts = 1593155078154 ptrs += 20 rt_time += 7103
===>rt_time = 275540753595 pts = 1593155078174 ptrs += 20 rt_time += 63835
===>rt_time = 275540753617 pts = 1593155078194 ptrs += 20 rt_time += 22
===>rt_time = 275540982952 pts = 1593155078214 ptrs += 20 rt_time += 229335
===>rt_time = 275541214181 pts = 1593155078234 ptrs += 20 rt_time += 231229
===>rt_time = 275541214636 pts = 1593155078254 ptrs += 20 rt_time += 455
===>rt_time = 275541214661 pts = 1593155078274 ptrs += 20 rt_time += 25
===>rt_time = 275541214683 pts = 1593155078294 ptrs += 20 rt_time += 22
===>rt_time = 275541214705 pts = 1593155078314 ptrs += 20 rt_time += 22
===>rt_time = 275541214727 pts = 1593155078334 ptrs += 20 rt_time += 22
===>rt_time = 275541214746 pts = 1593155078354 ptrs += 20 rt_time += 19
===>rt_time = 275541214768 pts = 1593155078374 ptrs += 20 rt_time += 22
===>rt_time = 275541405681 pts = 1593155078394 ptrs += 20 rt_time += 190913
===>rt_time = 275541405689 pts = 1593155078414 ptrs += 20 rt_time += 8
===>rt_time = 275541405694 pts = 1593155078434 ptrs += 20 rt_time += 5
Result for smooth streaming + tunneling off
===>rt_time = 318194306603 pts = 1593197740014 ptrs += 1593197740014 rt_time += 318194306603
===>rt_time = 318194331514 pts = 1593197740034 ptrs += 20 rt_time += 24911
===>rt_time = 318194365085 pts = 1593197740054 ptrs += 20 rt_time += 33571
===>rt_time = 318194365784 pts = 1593197740074 ptrs += 20 rt_time += 699
===>rt_time = 318194384424 pts = 1593197740094 ptrs += 20 rt_time += 18640
===>rt_time = 318194414166 pts = 1593197740114 ptrs += 20 rt_time += 29742
===>rt_time = 318194438649 pts = 1593197740134 ptrs += 20 rt_time += 24483
===>rt_time = 318194456490 pts = 1593197740154 ptrs += 20 rt_time += 17841
===>rt_time = 318194466716 pts = 1593197740174 ptrs += 20 rt_time += 10226
===>rt_time = 318194499829 pts = 1593197740194 ptrs += 20 rt_time += 33113
===>rt_time = 318194511821 pts = 1593197740214 ptrs += 20 rt_time += 11992
===>rt_time = 318194536873 pts = 1593197740234 ptrs += 20 rt_time += 25052
===>rt_time = 318194555481 pts = 1593197740254 ptrs += 20 rt_time += 18608
===>rt_time = 318194575834 pts = 1593197740274 ptrs += 20 rt_time += 20353
===>rt_time = 318194586334 pts = 1593197740294 ptrs += 20 rt_time += 10500
===>rt_time = 318194638449 pts = 1593197740314 ptrs += 20 rt_time += 52115
===>rt_time = 318194639074 pts = 1593197740334 ptrs += 20 rt_time += 625
===>rt_time = 318194661900 pts = 1593197740354 ptrs += 20 rt_time += 22826
===>rt_time = 318194671932 pts = 1593197740374 ptrs += 20 rt_time += 10032
===>rt_time = 318194754276 pts = 1593197740394 ptrs += 20 rt_time += 82344
===>rt_time = 318194754721 pts = 1593197740414 ptrs += 20 rt_time += 445
===>rt_time = 318194754989 pts = 1593197740434 ptrs += 20 rt_time += 268
===>rt_time = 318194755479 pts = 1593197740454 ptrs += 20 rt_time += 490
===>rt_time = 318194901463 pts = 1593197740474 ptrs += 20 rt_time += 145984
===>rt_time = 318194902054 pts = 1593197740494 ptrs += 20 rt_time += 591
===>rt_time = 318194902978 pts = 1593197740514 ptrs += 20 rt_time += 924
===>rt_time = 318194904656 pts = 1593197740534 ptrs += 20 rt_time += 1678
===>rt_time = 318194907330 pts = 1593197740554 ptrs += 20 rt_time += 2674
===>rt_time = 318194909467 pts = 1593197740574 ptrs += 20 rt_time += 2137
===>rt_time = 318194912441 pts = 1593197740594 ptrs += 20 rt_time += 2974
===>rt_time = 318194915546 pts = 1593197740614 ptrs += 20 rt_time += 3105
===>rt_time = 318194916814 pts = 1593197740634 ptrs += 20 rt_time += 1268
===>rt_time = 318195038068 pts = 1593197740654 ptrs += 20 rt_time += 121254
===>rt_time = 318195039799 pts = 1593197740674 ptrs += 20 rt_time += 1731
===>rt_time = 318195040538 pts = 1593197740694 ptrs += 20 rt_time += 739
===>rt_time = 318195040968 pts = 1593197740714 ptrs += 20 rt_time += 430
===>rt_time = 318195041547 pts = 1593197740734 ptrs += 20 rt_time += 579
===>rt_time = 318195122260 pts = 1593197740754 ptrs += 20 rt_time += 80713
===>rt_time = 318195123530 pts = 1593197740774 ptrs += 20 rt_time += 1270
===>rt_time = 318195124227 pts = 1593197740794 ptrs += 20 rt_time += 697
===>rt_time = 318195124932 pts = 1593197740814 ptrs += 20 rt_time += 705
===>rt_time = 318195125850 pts = 1593197740834 ptrs += 20 rt_time += 918
===>rt_time = 318195195763 pts = 1593197740854 ptrs += 20 rt_time += 69913
===>rt_time = 318195196313 pts = 1593197740874 ptrs += 20 rt_time += 550
===>rt_time = 318195197275 pts = 1593197740894 ptrs += 20 rt_time += 962
===>rt_time = 318195299058 pts = 1593197740914 ptrs += 20 rt_time += 101783
===>rt_time = 318195299611 pts = 1593197740934 ptrs += 20 rt_time += 553
===>rt_time = 318195300592 pts = 1593197740954 ptrs += 20 rt_time += 981
Dash + tunneling off
===>rt_time = 318514306098 pts = 1593198061333 ptrs += 1593198061333 rt_time += 318514306098
===>rt_time = 318514347276 pts = 1593198061373 ptrs += 40 rt_time += 41178
===>rt_time = 318514382507 pts = 1593198061413 ptrs += 40 rt_time += 35231
===>rt_time = 318514425691 pts = 1593198061453 ptrs += 40 rt_time += 43184
===>rt_time = 318514466783 pts = 1593198061493 ptrs += 40 rt_time += 41092
===>rt_time = 318514516834 pts = 1593198061533 ptrs += 40 rt_time += 50051
===>rt_time = 318514551891 pts = 1593198061573 ptrs += 40 rt_time += 35057
===>rt_time = 318514593418 pts = 1593198061613 ptrs += 40 rt_time += 41527
===>rt_time = 318514627192 pts = 1593198061653 ptrs += 40 rt_time += 33774
===>rt_time = 318514665650 pts = 1593198061693 ptrs += 40 rt_time += 38458
===>rt_time = 318514708455 pts = 1593198061733 ptrs += 40 rt_time += 42805
===>rt_time = 318514744716 pts = 1593198061773 ptrs += 40 rt_time += 36261
===>rt_time = 318514784678 pts = 1593198061813 ptrs += 40 rt_time += 39962
===>rt_time = 318514826632 pts = 1593198061853 ptrs += 40 rt_time += 41954
===>rt_time = 318514873936 pts = 1593198061893 ptrs += 40 rt_time += 47304
===>rt_time = 318514907780 pts = 1593198061933 ptrs += 40 rt_time += 33844
===>rt_time = 318514947568 pts = 1593198061973 ptrs += 40 rt_time += 39788
===>rt_time = 318514993282 pts = 1593198062013 ptrs += 40 rt_time += 45714
===>rt_time = 318515026634 pts = 1593198062053 ptrs += 40 rt_time += 33352
===>rt_time = 318515072802 pts = 1593198062093 ptrs += 40 rt_time += 46168
===>rt_time = 318515113479 pts = 1593198062133 ptrs += 40 rt_time += 40677
===>rt_time = 318515149745 pts = 1593198062173 ptrs += 40 rt_time += 36266
===>rt_time = 318515183994 pts = 1593198062213 ptrs += 40 rt_time += 34249
===>rt_time = 318515225805 pts = 1593198062253 ptrs += 40 rt_time += 41811
===>rt_time = 318515273969 pts = 1593198062293 ptrs += 40 rt_time += 48164
===>rt_time = 318515305610 pts = 1593198062333 ptrs += 40 rt_time += 31641
===>rt_time = 318515370275 pts = 1593198062373 ptrs += 40 rt_time += 64665
===>rt_time = 318515385342 pts = 1593198062413 ptrs += 40 rt_time += 15067
===>rt_time = 318515440222 pts = 1593198062453 ptrs += 40 rt_time += 54880
===>rt_time = 318515476656 pts = 1593198062493 ptrs += 40 rt_time += 36434
===>rt_time = 318515507579 pts = 1593198062533 ptrs += 40 rt_time += 30923
===>rt_time = 318515544200 pts = 1593198062573 ptrs += 40 rt_time += 36621
===>rt_time = 318515595099 pts = 1593198062613 ptrs += 40 rt_time += 50899
===>rt_time = 318515627980 pts = 1593198062653 ptrs += 40 rt_time += 32881
===>rt_time = 318515675773 pts = 1593198062693 ptrs += 40 rt_time += 47793
===>rt_time = 318515706675 pts = 1593198062733 ptrs += 40 rt_time += 30902
===>rt_time = 318515749304 pts = 1593198062773 ptrs += 40 rt_time += 42629
===>rt_time = 318515784724 pts = 1593198062813 ptrs += 40 rt_time += 35420
===>rt_time = 318515825882 pts = 1593198062853 ptrs += 40 rt_time += 41158
===>rt_time = 318515874219 pts = 1593198062893 ptrs += 40 rt_time += 48337
===>rt_time = 318515913650 pts = 1593198062933 ptrs += 40 rt_time += 39431
===>rt_time = 318515958088 pts = 1593198062973 ptrs += 40 rt_time += 44438
===>rt_time = 318515989900 pts = 1593198063013 ptrs += 40 rt_time += 31812
===>rt_time = 318516031570 pts = 1593198063053 ptrs += 40 rt_time += 41670
===>rt_time = 318516072758 pts = 1593198063093 ptrs += 40 rt_time += 41188
===>rt_time = 318516118950 pts = 1593198063133 ptrs += 40 rt_time += 46192
===>rt_time = 318516153485 pts = 1593198063173 ptrs += 40 rt_time += 34535
===>rt_time = 318516193843 pts = 1593198063213 ptrs += 40 rt_time += 40358
===>rt_time = 318516226294 pts = 1593198063253 ptrs += 40 rt_time += 32451
===>rt_time = 318516228496 pts = 1593198063253 ptrs += 0 rt_time += 2202
===>rt_time = 318516250409 pts = 1593198063273 ptrs += 20 rt_time += 21913
===>rt_time = 318516274883 pts = 1593198063293 ptrs += 20 rt_time += 24474
===>rt_time = 318516286133 pts = 1593198063313 ptrs += 20 rt_time += 11250
===>rt_time = 318516307095 pts = 1593198063333 ptrs += 20 rt_time += 20962
===>rt_time = 318516327589 pts = 1593198063353 ptrs += 20 rt_time += 20494
===>rt_time = 318516349346 pts = 1593198063373 ptrs += 20 rt_time += 21757
===>rt_time = 318516373762 pts = 1593198063393 ptrs += 20 rt_time += 24416
===>rt_time = 318516393445 pts = 1593198063413 ptrs += 20 rt_time += 19683
===>rt_time = 318516404229 pts = 1593198063433 ptrs += 20 rt_time += 10784
===>rt_time = 318516424319 pts = 1593198063453 ptrs += 20 rt_time += 20090
===>rt_time = 318516453416 pts = 1593198063473 ptrs += 20 rt_time += 29097
===>rt_time = 318516464359 pts = 1593198063493 ptrs += 20 rt_time += 10943
===>rt_time = 318516485668 pts = 1593198063513 ptrs += 20 rt_time += 21309
===>rt_time = 318516507268 pts = 1593198063533 ptrs += 20 rt_time += 21600
===>rt_time = 318516525573 pts = 1593198063553 ptrs += 20 rt_time += 18305
===>rt_time = 318516545585 pts = 1593198063573 ptrs += 20 rt_time += 20012
===>rt_time = 318516570571 pts = 1593198063593 ptrs += 20 rt_time += 24986
===>rt_time = 318516589357 pts = 1593198063613 ptrs += 20 rt_time += 18786
===>rt_time = 318516609069 pts = 1593198063633 ptrs += 20 rt_time += 19712
===>rt_time = 318516631622 pts = 1593198063653 ptrs += 20 rt_time += 22553
===>rt_time = 318516651763 pts = 1593198063673 ptrs += 20 rt_time += 20141
===>rt_time = 318516672556 pts = 1593198063693 ptrs += 20 rt_time += 20793
===>rt_time = 318516692882 pts = 1593198063713 ptrs += 20 rt_time += 20326
===>rt_time = 318516703868 pts = 1593198063733 ptrs += 20 rt_time += 10986
===>rt_time = 318516731712 pts = 1593198063753 ptrs += 20 rt_time += 27844
===>rt_time = 318516751951 pts = 1593198063773 ptrs += 20 rt_time += 20239
===>rt_time = 318516777332 pts = 1593198063793 ptrs += 20 rt_time += 25381
===>rt_time = 318516786998 pts = 1593198063813 ptrs += 20 rt_time += 9666
===>rt_time = 318516808221 pts = 1593198063833 ptrs += 20 rt_time += 21223
===>rt_time = 318516832709 pts = 1593198063853 ptrs += 20 rt_time += 24488
===>rt_time = 318516843392 pts = 1593198063873 ptrs += 20 rt_time += 10683
===>rt_time = 318516873139 pts = 1593198063893 ptrs += 20 rt_time += 29747
===>rt_time = 318516883548 pts = 1593198063913 ptrs += 20 rt_time += 10409
===>rt_time = 318516918303 pts = 1593198063933 ptrs += 20 rt_time += 34755
===>rt_time = 318516928930 pts = 1593198063953 ptrs += 20 rt_time += 10627
Dash + tunneling on
===>rt_time = 318637819216 pts = 1593198183333 ptrs += 1593198183333 rt_time += 318637819216
===>rt_time = 318637819260 pts = 1593198183373 ptrs += 40 rt_time += 44
===>rt_time = 318637819292 pts = 1593198183493 ptrs += 120 rt_time += 32
===>rt_time = 318637819411 pts = 1593198183533 ptrs += 40 rt_time += 119
===>rt_time = 318637819501 pts = 1593198183573 ptrs += 40 rt_time += 90
===>rt_time = 318637947675 pts = 1593198183613 ptrs += 40 rt_time += 128174
===>rt_time = 318637947745 pts = 1593198183653 ptrs += 40 rt_time += 70
===>rt_time = 318637947882 pts = 1593198183693 ptrs += 40 rt_time += 137
===>rt_time = 318637948075 pts = 1593198183733 ptrs += 40 rt_time += 193
===>rt_time = 318637948257 pts = 1593198183773 ptrs += 40 rt_time += 182
===>rt_time = 318638040745 pts = 1593198183813 ptrs += 40 rt_time += 92488
===>rt_time = 318638040780 pts = 1593198183853 ptrs += 40 rt_time += 35
===>rt_time = 318638040873 pts = 1593198183893 ptrs += 40 rt_time += 93
===>rt_time = 318638040959 pts = 1593198183933 ptrs += 40 rt_time += 86
===>rt_time = 318638104379 pts = 1593198183973 ptrs += 40 rt_time += 63420
===>rt_time = 318638104494 pts = 1593198184013 ptrs += 40 rt_time += 115
===>rt_time = 318638157466 pts = 1593198184053 ptrs += 40 rt_time += 52972
===>rt_time = 318638178825 pts = 1593198184093 ptrs += 40 rt_time += 21359
===>rt_time = 318638206317 pts = 1593198184133 ptrs += 40 rt_time += 27492
===>rt_time = 318638206359 pts = 1593198184173 ptrs += 40 rt_time += 42
===>rt_time = 318638262659 pts = 1593198184213 ptrs += 40 rt_time += 56300
===>rt_time = 318638278511 pts = 1593198184253 ptrs += 40 rt_time += 15852
===>rt_time = 318638315636 pts = 1593198184293 ptrs += 40 rt_time += 37125
===>rt_time = 318638392946 pts = 1593198184333 ptrs += 40 rt_time += 77310
===>rt_time = 318638418579 pts = 1593198184373 ptrs += 40 rt_time += 25633
===>rt_time = 318638457907 pts = 1593198184413 ptrs += 40 rt_time += 39328
===>rt_time = 318638564966 pts = 1593198184453 ptrs += 40 rt_time += 107059
===>rt_time = 318638565066 pts = 1593198184493 ptrs += 40 rt_time += 100
===>rt_time = 318638652144 pts = 1593198184533 ptrs += 40 rt_time += 87078
===>rt_time = 318638652191 pts = 1593198184573 ptrs += 40 rt_time += 47
===>rt_time = 318638684719 pts = 1593198184613 ptrs += 40 rt_time += 32528
===>rt_time = 318638704413 pts = 1593198184653 ptrs += 40 rt_time += 19694
===>rt_time = 318638760263 pts = 1593198184693 ptrs += 40 rt_time += 55850
===>rt_time = 318638826990 pts = 1593198184733 ptrs += 40 rt_time += 66727
===>rt_time = 318638827083 pts = 1593198184773 ptrs += 40 rt_time += 93
===>rt_time = 318638881033 pts = 1593198184813 ptrs += 40 rt_time += 53950
===>rt_time = 318638919420 pts = 1593198184853 ptrs += 40 rt_time += 38387
===>rt_time = 318638952688 pts = 1593198184893 ptrs += 40 rt_time += 33268
===>rt_time = 318638975063 pts = 1593198184933 ptrs += 40 rt_time += 22375
===>rt_time = 318639038116 pts = 1593198184973 ptrs += 40 rt_time += 63053
===>rt_time = 318639059104 pts = 1593198185013 ptrs += 40 rt_time += 20988
===>rt_time = 318639066193 pts = 1593198185053 ptrs += 40 rt_time += 7089
===>rt_time = 318639147573 pts = 1593198185093 ptrs += 40 rt_time += 81380
===>rt_time = 318639219249 pts = 1593198185133 ptrs += 40 rt_time += 71676
===>rt_time = 318639247581 pts = 1593198185173 ptrs += 40 rt_time += 28332
===>rt_time = 318639266900 pts = 1593198185213 ptrs += 40 rt_time += 19319
===>rt_time = 318639266949 pts = 1593198185253 ptrs += 40 rt_time += 49
===>rt_time = 318639439250 pts = 1593198185293 ptrs += 40 rt_time += 172301
===>rt_time = 318639480419 pts = 1593198185333 ptrs += 40 rt_time += 41169
===>rt_time = 318639480461 pts = 1593198185373 ptrs += 40 rt_time += 42
===>rt_time = 318639480494 pts = 1593198185413 ptrs += 40 rt_time += 33
===>rt_time = 318639515505 pts = 1593198185453 ptrs += 40 rt_time += 35011
===>rt_time = 318639515633 pts = 1593198185493 ptrs += 40 rt_time += 128
===>rt_time = 318639566489 pts = 1593198185533 ptrs += 40 rt_time += 50856
===>rt_time = 318639623657 pts = 1593198185573 ptrs += 40 rt_time += 57168
===>rt_time = 318639645683 pts = 1593198185613 ptrs += 40 rt_time += 22026
===>rt_time = 318639713433 pts = 1593198185653 ptrs += 40 rt_time += 67750
===>rt_time = 318639723815 pts = 1593198185693 ptrs += 40 rt_time += 10382
===>rt_time = 318639804231 pts = 1593198185733 ptrs += 40 rt_time += 80416
===>rt_time = 318639852542 pts = 1593198185773 ptrs += 40 rt_time += 48311
===>rt_time = 318639895085 pts = 1593198185813 ptrs += 40 rt_time += 42543
===>rt_time = 318639996602 pts = 1593198185853 ptrs += 40 rt_time += 101517
===>rt_time = 318639996642 pts = 1593198185893 ptrs += 40 rt_time += 40
===>rt_time = 318640040512 pts = 1593198185933 ptrs += 40 rt_time += 43870
===>rt_time = 318640040571 pts = 1593198185973 ptrs += 40 rt_time += 59
===>rt_time = 318640079846 pts = 1593198186013 ptrs += 40 rt_time += 39275
===>rt_time = 318640079896 pts = 1593198186053 ptrs += 40 rt_time += 50
===>rt_time = 318640108392 pts = 1593198186093 ptrs += 40 rt_time += 28496
===>rt_time = 318640175268 pts = 1593198186133 ptrs += 40 rt_time += 66876
===>rt_time = 318640340522 pts = 1593198186173 ptrs += 40 rt_time += 165254
===>rt_time = 318640340660 pts = 1593198186213 ptrs += 40 rt_time += 138
===>rt_time = 318640340696 pts = 1593198186253 ptrs += 40 rt_time += 36
===>rt_time = 318640381552 pts = 1593198186293 ptrs += 40 rt_time += 40856
===>rt_time = 318640381592 pts = 1593198186333 ptrs += 40 rt_time += 40
===>rt_time = 318640430387 pts = 1593198186373 ptrs += 40 rt_time += 48795
===>rt_time = 318640461946 pts = 1593198186413 ptrs += 40 rt_time += 31559
===>rt_time = 318640527638 pts = 1593198186453 ptrs += 40 rt_time += 65692
===>rt_time = 318640527689 pts = 1593198186493 ptrs += 40 rt_time += 51
===>rt_time = 318640593595 pts = 1593198186533 ptrs += 40 rt_time += 65906
===>rt_time = 318640618333 pts = 1593198186573 ptrs += 40 rt_time += 24738
===>rt_time = 318640638063 pts = 1593198186613 ptrs += 40 rt_time += 19730
===>rt_time = 318640691325 pts = 1593198186653 ptrs += 40 rt_time += 53262
===>rt_time = 318640750400 pts = 1593198186693 ptrs += 40 rt_time += 59075
===>rt_time = 318640837944 pts = 1593198186733 ptrs += 40 rt_time += 87544
===>rt_time = 318640837985 pts = 1593198186773 ptrs += 40 rt_time += 41
We can learn that:
onProcessedOutputBuffer was called twice with the same timestamp (not sure why, @andrewlewis an idea?) ===>rt_time = 318637819260 pts = 1593198183373 ptrs += 40 rt_time += 44
===>rt_time = 318637819292 pts = 1593198183493 ptrs += 120 rt_time += 32
===>rt_time = 318637819411 pts = 1593198183533 ptrs += 40 rt_time += 119
I've add more logs for different cases. The following is the script that I used to get the logs
chang@p300a:~/git-root/ngp$ adb logcat -c && date && adb logcat com.canaldigital.ngp:I *:S FPS:V > TvViewOverlaidByAnim_SS_tunnelingOn.log
l酶. 27. juni 12:26:09 +0200 2020
^C
chang@p300a:~/git-root/ngp$ adb logcat -c && date && adb logcat com.canaldigital.ngp:I *:S FPS:V > TvViewOnly_SS_tunnelingOn.log
l酶. 27. juni 12:37:34 +0200 2020
^C
chang@p300a:~/git-root/ngp$ adb logcat -c && date && adb logcat com.canaldigital.ngp:I *:S FPS:V > TvViewOverlaidByAnim_Dash_tunnelingOn.log
l酶. 27. juni 12:50:16 +0200 2020
^C
chang@p300a:~/git-root/ngp$ adb logcat -c && date && adb logcat com.canaldigital.ngp:I *:S FPS:V > TvViewOnly_Dash_tunnelingOn.log
l酶. 27. juni 12:58:35 +0200 2020
^C
There are four log files in the zip. Regarding the name convention
@andrewlewis, why did you recommend to hook into renderOutputBufferV21 instead of onProcessedOutputBuffer in #4088?
An output buffer is counted as processed if it's dropped. Using the frame release time in nanoseconds (= the nanosecond time the frame will be presented) seems closest to what was requested in #4088, although frame timestamps (presentation times) will give very similar results.
once in "Dash + tunneling off" onProcessedOutputBuffer was called twice with the same timestamp (not sure why, @andrewlewis an idea?)
There may be an edge case like a period transition where the duration of the first period was unexpectedly equal to its last sample presentation time, but that seems unlikely so I'm not sure.
Thanks for your effort, both @andrewlewis and @krocard. Our test result seems very promising on our two HW platforms. And the result reflects the janky/laggy behavior correctly. Do you have the intention to add this feature? We are very willing to contribute it to the community.
Tunneling frame statistics is not on our short to mid term roadmap to add such feature, nevertheless we always gladly welcome pull requests.
It would be interesting if the change also updated existing non tunneling informations, like DecoderCounter in tunneling, especially droppedBufferCount was requested in #7100.
But even just a pull request of your current approach could help other ExoPlayer users to implement their own quality metrics.
OK, got it. Will submit a pull request can we can start the talk there.