New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 669067 link

Starred by 2 users

Issue metadata

Status: WontFix
Owner:
Last visit > 30 days ago
Closed: Dec 2016
Cc:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 2
Type: Bug-Regression



Sign in to add a comment

1%-33.3% regression in webrtc_perf_tests at 15240:15240

Project Member Reported by ivoc@chromium.org, Nov 28 2016

Issue description

See graphs below.
 

Comment 2 by ivoc@chromium.org, Nov 28 2016

Labels: -M-54 Performance M-57
Owner: asapersson@chromium.org
Hi Asa, It looks like this CL, https://codereview.webrtc.org/2493893003, is causing a few small perf improvements, and some significant regressions in receiver_time/conference_motion_hd_2000kbps_100ms_32pkts_queue. Could you have a look at this?
Cc: marpan@chromium.org

Comment 4 by marpan@google.com, Nov 28 2016

Don't see any reason why the receiver time increases (for the conference_hd clip) with change in https://codereview.webrtc.org/2493893003. The other metrics
(sender_time, media_bitrate, encoder_usage) all seem normal/fine. And the PSNR
increase in the other graphs is a good perf improvement, as it corresponds to ~0.4-0.5dB.

When running FullStackTest.ConferenceMotionHd2000kbps100msLimitedQueue with and without the change in https://codereview.webrtc.org/2493893003, the average and max frame size are:
with change, avg: ~4800 bytes, max: ~24000 bytes
without change: avg: ~4500 bytes, max: ~12000 bytes

The larger _maxFrameSize results in higher jitter estimate:

VCMJitterEstimator::CalculateEstimate:
double ret = _theta[0] * (_maxFrameSize - _avgFrameSize) + NoiseThreshold();

with change: ~75 ms (receive time: 85 ms)
without change: ~50 ms (receive time: 57 ms)


With change:
VCMJitterEstimator::UpdateEstimate, frameDelayMs 0, frameSizeBytes 19567   // Logged if frameSizeBytes > 10000
(bitrate_allocator.cc:79): Current BWE 2270073
VCMJitterEstimator::CalculateEstimate, 500: ret 21, _theta:0.0013, _maxFrameSize:19060, _avgFrameSize:5369, noiseTh:3.02
VCMJitterEstimator::UpdateEstimate, frameDelayMs 65, frameSizeBytes 23478
(bitrate_allocator.cc:79): Current BWE 1937807
VCMJitterEstimator::CalculateEstimate, 1000: ret 59, _theta[0]:0.0032, _maxFrameSize:22918, _avgFrameSize:4882, noiseTh:1.0
VCMJitterEstimator::UpdateEstimate, frameDelayMs 74, frameSizeBytes 22577
(bitrate_allocator.cc:79): Current BWE 1946874
VCMJitterEstimator::CalculateEstimate, 1500: ret 66, _theta[0]:0.0036, _maxFrameSize:22355, _avgFrameSize:4572, noiseTh:1.0
VCMJitterEstimator::UpdateEstimate, frameDelayMs 75, frameSizeBytes 26108
(bitrate_allocator.cc:79): Current BWE 1862389
VCMJitterEstimator::CalculateEstimate, 2000: ret 76, _theta[0]:0.0035, _maxFrameSize:25745, _avgFrameSize:4699, noiseTh:1.0
VCMJitterEstimator::UpdateEstimate, frameDelayMs 70, frameSizeBytes 21354
(bitrate_allocator.cc:79): Current BWE 1892417
VCMJitterEstimator::CalculateEstimate, 2500: ret 76, _theta[0]:0.003711 _maxFrameSize:25111, _avgFrameSize:4645, noiseTh:1.0
VCMJitterEstimator::UpdateEstimate, frameDelayMs 69, frameSizeBytes 21368
(bitrate_allocator.cc:79): Current BWE 1967918
VCMJitterEstimator::CalculateEstimate, 3000: ret 75, _theta[0]:0.0038, _maxFrameSize:24491, _avgFrameSize:4866, noiseTh:1.0
(bitrate_allocator.cc:79): Current BWE 2323721
VCMJitterEstimator::CalculateEstimate, 3500: ret 71, _theta[0]:0.0037, _maxFrameSize:23889, _avgFrameSize:5344, noiseTh:1.0
VCMJitterEstimator::UpdateEstimate, frameDelayMs 75, frameSizeBytes 26806
(bitrate_allocator.cc:79): Current BWE 1885693
VCMJitterEstimator::CalculateEstimate, 4000: ret 79, _theta[0]:0.0036, _maxFrameSize:26175, _avgFrameSize:4707, noiseTh:1.0
VCMJitterEstimator::UpdateEstimate, frameDelayMs 70, frameSizeBytes 22266

RESULT psnr: conference_motion_hd_2000kbps_100ms_32pkts_queue = {37.690408, 1.595677} dB
RESULT ssim: conference_motion_hd_2000kbps_100ms_32pkts_queue = {0.945928, 0.014418} score
RESULT sender_time: conference_motion_hd_2000kbps_100ms_32pkts_queue = {17.755516, 8.129142} ms
RESULT receiver_time: conference_motion_hd_2000kbps_100ms_32pkts_queue = {84.878883, 31.197331} ms
RESULT total_delay_incl_network: conference_motion_hd_2000kbps_100ms_32pkts_queue = {224.583521, 25.743057} ms
RESULT time_between_rendered_frames: conference_motion_hd_2000kbps_100ms_32pkts_queue = {20.204505, 3.518494} ms
RESULT encoded_frame_size: conference_motion_hd_2000kbps_100ms_32pkts_queue = {4816.407924, 1258.998752} bytes // <=
RESULT encode_frame_rate: conference_motion_hd_2000kbps_100ms_32pkts_queue = {49.333333, 4.422166} fps
RESULT encode_time: conference_motion_hd_2000kbps_100ms_32pkts_queue = {11.068182, 1.615236} ms
RESULT encode_usage_percent: conference_motion_hd_2000kbps_100ms_32pkts_queue = {49.136364, 4.605288} percent
RESULT media_bitrate: conference_motion_hd_2000kbps_100ms_32pkts_queue = {1917517.288889, 236669.031914} bps
RESULT dropped_frames: conference_motion_hd_2000kbps_100ms_32pkts_queue = 29 frames
RESULT dropped_frames_before_first_encode: conference_motion_hd_2000kbps_100ms_32pkts_queue = 0 frames
RESULT dropped_frames_before_rendering: conference_motion_hd_2000kbps_100ms_32pkts_queue = 0 frames

WebRTC.Video.EncodeTimeInMs 11
WebRTC.Video.SendSideDelayInMs 17,
WebRTC.Video.SendSideDelayMaxInMs 32

VideoReceiveStream stats: {w: 1280, h: 720, key: 1, delta: 2226, network_fps: 50, decode_fps: 51, render_fps: 51}
WebRTC.Video.DecodeTimeInMs 5
WebRTC.Video.JitterBufferDelayInMs 77, WebRTC.Video.TargetDelayInMs 95, WebRTC.Video.CurrentDelayInMs 94
WebRTC.Video.BitrateReceivedInKbps 1940
WebRTC.Call.EstimatedSendBitrateInKbps 1950


Without change:
VCMJitterEstimator::UpdateEstimate, frameDelayMs 0, frameSizeBytes 19568   // Logged if frameSizeBytes > 10000
(bitrate_allocator.cc:79): Current BWE 1661193
VCMJitterEstimator::CalculateEstimate, 500: ret 24, _theta[0]:0.0015, _maxFrameSize:19061, _avgFrameSize:4864, noiseTh:2.84
VCMJitterEstimator::UpdateEstimate, frameDelayMs 24, frameSizeBytes 10546
(bitrate_allocator.cc:79): Current BWE 1724007
VCMJitterEstimator::CalculateEstimate, 1000: ret 42, _theta[0]:0.0029, _maxFrameSize:18593, _avgFrameSize:4278, noiseTh:1.0
VCMJitterEstimator::UpdateEstimate, frameDelayMs 27, frameSizeBytes 11229
(bitrate_allocator.cc:79): Current BWE 1795895
VCMJitterEstimator::CalculateEstimate, 1500: ret 48, _theta[0]:0.0034, _maxFrameSize:18134, _avgFrameSize:4311, noiseTh:1.0
VCMJitterEstimator::UpdateEstimate, frameDelayMs 34, frameSizeBytes 12306
(bitrate_allocator.cc:79): Current BWE 1869775
VCMJitterEstimator::CalculateEstimate, 2000: ret 46, _theta[0]:0.0034, _maxFrameSize:17688, _avgFrameSize:4569, noiseTh:1.0
VCMJitterEstimator::UpdateEstimate, frameDelayMs 35, frameSizeBytes 13201
(bitrate_allocator.cc:79): Current BWE 1657378
VCMJitterEstimator::CalculateEstimate, 2500: ret 46, _theta[0]:0.0034, _maxFrameSize:17251, _avgFrameSize:4346, noiseTh:1.0
VCMJitterEstimator::UpdateEstimate, frameDelayMs 25, frameSizeBytes 10523
(bitrate_allocator.cc:79): Current BWE 1734827
VCMJitterEstimator::CalculateEstimate, 3000: ret 44, _theta[0]:0.0034, _maxFrameSize:16827, _avgFrameSize:4230, noiseTh:1.0
(bitrate_allocator.cc:79): Current BWE 1803551
VCMJitterEstimator::CalculateEstimate, 3500: ret 40, _theta[0]:0.0033, _maxFrameSize:16411, _avgFrameSize:4393, noiseTh:1.0
VCMJitterEstimator::UpdateEstimate, frameDelayMs 26, frameSizeBytes 11847
(bitrate_allocator.cc:79): Current BWE 1876599
VCMJitterEstimator::CalculateEstimate, 4000: ret 37, _theta[0]:0.0032, _maxFrameSize:16007, _avgFrameSize:4588, noiseTh:1.0
VCMJitterEstimator::UpdateEstimate, frameDelayMs 30, frameSizeBytes 12158

RESULT psnr: conference_motion_hd_2000kbps_100ms_32pkts_queue = {37.369665, 1.574900} dB
RESULT ssim: conference_motion_hd_2000kbps_100ms_32pkts_queue = {0.943633, 0.014260} score
RESULT sender_time: conference_motion_hd_2000kbps_100ms_32pkts_queue = {18.299099, 8.107704} ms
RESULT receiver_time: conference_motion_hd_2000kbps_100ms_32pkts_queue = {57.183784, 12.576451} ms
RESULT total_delay_incl_network: conference_motion_hd_2000kbps_100ms_32pkts_queue = {189.766216, 11.635525} ms
RESULT time_between_rendered_frames: conference_motion_hd_2000kbps_100ms_32pkts_queue = {20.187021, 3.715150} ms
RESULT encoded_frame_size: conference_motion_hd_2000kbps_100ms_32pkts_queue = {4484.889189, 742.300794} bytes  // <=
RESULT encode_frame_rate: conference_motion_hd_2000kbps_100ms_32pkts_queue = {49.311111, 4.569572} fps
RESULT encode_time: conference_motion_hd_2000kbps_100ms_32pkts_queue = {11.568182, 1.338210} ms
RESULT encode_usage_percent: conference_motion_hd_2000kbps_100ms_32pkts_queue = {51.045455, 4.078517} percent
RESULT media_bitrate: conference_motion_hd_2000kbps_100ms_32pkts_queue = {1785104.000000, 173355.510543} bps
RESULT dropped_frames: conference_motion_hd_2000kbps_100ms_32pkts_queue = 30 frames
RESULT dropped_frames_before_first_encode: conference_motion_hd_2000kbps_100ms_32pkts_queue = 0 frames
RESULT dropped_frames_before_rendering: conference_motion_hd_2000kbps_100ms_32pkts_queue = 0 frames

WebRTC.Video.EncodeTimeInMs 12
WebRTC.Video.SendSideDelayInMs 17,
WebRTC.Video.SendSideDelayMaxInMs 30

VideoReceiveStream stats: {w: 1280, h: 720, key: 1, delta: 2222, network_fps: 50, decode_fps: 51, render_fps: 51}
WebRTC.Video.DecodeTimeInMs 5
WebRTC.Video.JitterBufferDelayInMs 52, WebRTC.Video.TargetDelayInMs 70, WebRTC.Video.CurrentDelayInMs 69
WebRTC.Video.BitrateReceivedInKbps 1804
WebRTC.Call.EstimatedSendBitrateInKbps 1793

Comment 6 by marpan@chromium.org, Nov 30 2016

Took a look at the test. There are periodic big frames in the test
(with or without the change) that correspond to the clip being repeated
several times (the test runs about ~2000 frames but the conference_clip
is 300 frames). When the next frame loops back to the start of the clip,
then that frame will be fairly large in size (as it should, with or
without the change). But these restart frames do happen to be bigger
with the change. I'll take another look tomorrow to see why and if
there is any issue.
Cc: asapersson@chromium.org
Owner: marpan@chromium.org
Cc: mflodman@chromium.org
Status: WontFix (was: Untriaged)
The increase in frame size only happens on frames that flip back
to start frame of the clip (which is due to the test clip having 300 frames
and test running ~2000 frames). If the test clip is longer or if it doesn't reset to start of clip (i.e., just continues as normal), there would be no increase in frame size. So the behavior is peculiar to the test.

The reason it happens in this test for this change is that:
without the change (error_resilience = 1) the gf/arf references are always the
last key frame, which happens to be the first frame in the test (and so helps to
reduce the frame size/better predictor for this restart frame), but with the change (error_resilience=0), the gf/arf references are dynamically updated and they will generally be closer to the current frame (so farther from the start frame, and so bigger frame is expected for the restart frame).

We could make a change to keep/force the arf reference to always be last key frame,
but this will reduce quality a little in the normal cases, so marking this as won't fix.

Just a quick follow-up on this since I happened to stumble on this stats change.

On the bots it seems like the encoded frame size goes down, and the media bitrate drops significantly below the target of 2mbps. There is also an associated drop in quality. At the same time it seems the the max frame size is still high and so the receiver_time has increased.

Is this really expected?

Maybe we should have a look at what source of test video we're actually using. Might be useful to more closely match an actual common desktop or mobile stream.

Sign in to add a comment