964127 - Add a/v sync info to about:webrtc stats, logs and telemetry

Status: RESOLVED FIXED

(Core :: WebRTC: Audio/Video, defect)

Description

[Randell Jesup [:jesup] (needinfo me)]

May be a moderate pain to expose - we'll see.

Roughly: 
state (synced, slewing, unsynced (best effort)) - this should be pretty easy
a/v delta in ms (signed).

Note that to calculate this *correctly* we need info including the time to run through the audio chain and the video compositor.

Comment 1

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Add logging of webrtc a/v sync status

Comment 2

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Add logging of webrtc a/v sync status

Comment 3

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Attachment: Add a/v sync status to about:webrtc

Rough patch showing a/v sync and jitter buffer delay in about:webrtc.

Stats are currently written on MSG thread (same place as logged) and read on STS thread.

That's likely not our preferred threading model, but it works. Access seems protected by the ChannelOwner lock, so I can probably copy the code to where I query these stats instead (which is STS thread).

Comment 4

[Randell Jesup [:jesup] (needinfo me)]

Trying it in pc_test.html I noticed only audio1 was showing stats; audio0 wasn't.

Comment 5

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Look at the SSRCs, as the ids are confusing. When I run that test, outbound_rtp_audio_0 corresponds to inbound_rtp_audio_1 on both PCs. I see A/V stats on the incoming audio of both PCs. Also note that the info for each PC is a page apart, so make sure to scroll to see both.

Also, with feedback+ do you mean fine to land as is or with my pondered changes (moving code)?

Comment 6

[Randell Jesup [:jesup] (needinfo me)]

As you indicated it was a rough patch, I didn't do a final review; I'm not sure I know exactly what the  tradeoff you're mentioning is without looking closer.  If the data is being read cross-thread, we need to have some type of lock or other barrier, or change it to something other than a cross-thread read.  (and my base logging patch may need modification for thread-safety as well.)

Comment 7

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Attachment: Add a/v sync status to about:webrtc (2)

Removed dependence on logging-site.

Comment 8

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Thanks! I assume you'll land once your patch is reviewed.

Comment 9

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Part 1: Add logging of webrtc a/v sync status

Comment 10

[Randell Jesup [:jesup] (needinfo me)]

Comment on attachment 8389999 [details] [diff] [review]
Part 1: Add logging of webrtc a/v sync status

Cleaned up the API (your patch will need minor un-bitrotting)

Comment 11

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Comment on attachment 8389999 [details] [diff] [review]
Part 1: Add logging of webrtc a/v sync status

Review of attachment 8389999 [details] [diff] [review]:
-----------------------------------------------------------------

r+ with some nits.

::: media/webrtc/signaling/src/media-conduit/AudioConduit.cpp
@@ +696,5 @@
> +    mPtrVoEVideoSync->GetDelayEstimate(mChannel,
> +                                       &jitter_buffer_delay_ms,
> +                                       &playout_buffer_delay_ms,
> +                                       &avsync_offset_ms); // ignore errors
> +    CSFLogError(logTag,"A/V sync: sync delta: %dms, audio jitter delay %dms, playout delay %dms",

Linebreak after first comma would shorten this line some.

::: media/webrtc/signaling/src/media-conduit/AudioConduit.h
@@ +267,5 @@
>    uint32_t mLastTimestamp;
>  #endif // MOZILLA_INTERNAL_API
> +
> +  uint32_t mSamples;
> +  uint32_t mLastSyncLog;

I don't think you need to store both.

uint32_t lastSyncLog = mSamples; on the stack should do, or increment mSamples at the end.

::: media/webrtc/trunk/webrtc/video_engine/vie_sync_module.cc
@@ +160,5 @@
>    // Calculate how much later or earlier the audio stream is compared to video.
> +
> +  result = sync_->ComputeRelativeDelay(audio_measurement_, video_measurement_,
> +                                       &relative_delay_ms);
> +  if (relative_delay_ms != 0) {

Relies on secondary result from a failing function. I prefer:

if (result && relative_delay_ms != 0) {

which also removes the need to initialize relative_delay_ms to zero.

@@ +168,1 @@
>      return 0;

How come nothing fails (-1) in this function?

::: media/webrtc/trunk/webrtc/voice_engine/channel.cc
@@ +2195,5 @@
>    header.payload_type_frequency =
>        rtp_payload_registry_->GetPayloadTypeFrequency(header.payloadType);
>    if (header.payload_type_frequency < 0)
>      return -1;
> +  bool in_order = IsPacketInOrder(header); // MUST call before IncomingPacket()!

Maybe say why?

::: media/webrtc/trunk/webrtc/voice_engine/channel.h
@@ +209,4 @@
>      int least_required_delay_ms() const { return least_required_delay_ms_; }
>      int SetInitialPlayoutDelay(int delay_ms);
>      int SetMinimumPlayoutDelay(int delayMs);
> +    int SetCurrentSyncOffset(int offsetMs) { _current_sync_offset = offsetMs; return 0; }

Maybe void?

::: media/webrtc/trunk/webrtc/voice_engine/test/auto_test/standard/video_sync_test.cc
@@ +38,4 @@
>        EXPECT_EQ(0, voe_vsync_->GetDelayEstimate(channel_,
>                                                  &jitter_buffer_delay_ms,
> +                                                &playout_buffer_delay_ms,
> +                                                &avsync_offset_ms));

This test doesn't do anything with avsync_offset_ms, should it?

::: media/webrtc/trunk/webrtc/voice_engine/voe_video_sync_impl.cc
@@ +149,5 @@
> +    voe::Channel* channelPtr = ch.channel();
> +    if (channelPtr == NULL)
> +    {
> +        _shared->SetLastError(VE_CHANNEL_NOT_VALID, kTraceError,
> +            "SetMinimumPlayoutDelay() failed to locate channel");

SetCurrentSyncOffset()

Comment 12

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Attachment: Part 2: Add a/v sync status to about:webrtc (3). r=jesup

Unbitrot. Carrying forward r+ from jesup.

Comment 13

[Randell Jesup [:jesup] (needinfo me)]

(In reply to Jan-Ivar Bruaroey [:jib] from comment #11)

> ::: media/webrtc/signaling/src/media-conduit/AudioConduit.h
> @@ +267,5 @@
> >    uint32_t mLastTimestamp;
> >  #endif // MOZILLA_INTERNAL_API
> > +
> > +  uint32_t mSamples;
> > +  uint32_t mLastSyncLog;
> 
> I don't think you need to store both.
> 
> uint32_t lastSyncLog = mSamples; on the stack should do, or increment
> mSamples at the end.

I need to store it to know when we've gone XXXX samples since the last log message. (poor man's timer)

> ::: media/webrtc/trunk/webrtc/video_engine/vie_sync_module.cc
> @@ +160,5 @@
> >    // Calculate how much later or earlier the audio stream is compared to video.
> > +
> > +  result = sync_->ComputeRelativeDelay(audio_measurement_, video_measurement_,
> > +                                       &relative_delay_ms);
> > +  if (relative_delay_ms != 0) {
> 
> Relies on secondary result from a failing function. I prefer:
> 
> if (result && relative_delay_ms != 0) {
> 
> which also removes the need to initialize relative_delay_ms to zero.

Better yet: if (!result) { return xxx; } then just use relative_delay_ms unconditionally.

> 
> @@ +168,1 @@
> >      return 0;
> 
> How come nothing fails (-1) in this function?

Ask Google/GIPS


> ::: media/webrtc/trunk/webrtc/voice_engine/channel.h
> @@ +209,4 @@
> >      int least_required_delay_ms() const { return least_required_delay_ms_; }
> >      int SetInitialPlayoutDelay(int delay_ms);
> >      int SetMinimumPlayoutDelay(int delayMs);
> > +    int SetCurrentSyncOffset(int offsetMs) { _current_sync_offset = offsetMs; return 0; }
> 
> Maybe void?

Sure, though that means I have to add a return 0 elsewhere.

> 
> :::
> media/webrtc/trunk/webrtc/voice_engine/test/auto_test/standard/
> video_sync_test.cc
> @@ +38,4 @@
> >        EXPECT_EQ(0, voe_vsync_->GetDelayEstimate(channel_,
> >                                                  &jitter_buffer_delay_ms,
> > +                                                &playout_buffer_delay_ms,
> > +                                                &avsync_offset_ms));
> 
> This test doesn't do anything with avsync_offset_ms, should it?

No, it doesn't.  I'll leave that for when we upstream this.

Comment 14

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

(In reply to Randell Jesup [:jesup] from comment #13)
> I need to store it to know when we've gone XXXX samples since the last log
> message. (poor man's timer)

Ah, I missed that. So this emits a log message every second. Is that a frequency we have in mind for telemetry as well, or are we looking just to count median or average or max avsync per call or something?

Comment 15

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Also, I still claim mLastSyncLog is redundant. You could reset mSamples when the sample frequency is reached. i.e. modulo sample frequency.

Comment 16

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

(In reply to Jan-Ivar Bruaroey [:jib] from comment #14)
> Is that a frequency we have in mind for telemetry as well,

I suppose if we counted every second of a call, then the numbers in each bin become seconds, which is nice, and the total of all bins is aggregate call time.

Comment 17

[Randell Jesup [:jesup] (needinfo me)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/0d44ffa10368
https://hg.mozilla.org/integration/mozilla-inbound/rev/8876cd22695b

Comment 18

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/0d44ffa10368
https://hg.mozilla.org/mozilla-central/rev/8876cd22695b

Comment 19

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Attachment: Part 3: Add a/v sync telemetry

Comment 20

[Byron Campen [:bwc]]

Comment on attachment 8391008 [details] [diff] [review]
Part 3: Add a/v sync telemetry

Review of attachment 8391008 [details] [diff] [review]:
-----------------------------------------------------------------

Looking at the code I don't think Telemetry::Accumulate is threadsafe; it can probably only be called safely from main. Not sure where this is called from; I don't see any thread asserts in any of GetAudioFrame's callers or callees, but I do see lots of mutex locking, which implies that this is not always used on a single thread.

Also, we really should not be ignoring errors from GetAVStats, since in that case we'll contaminate Telemetry with bogus 0s.

I wonder whether we should increase the maximum on these histograms; we've seen av go out of sync by more than 10 seconds before, right?

Comment 21

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

(In reply to Byron Campen [:bwc] from comment #20)

According to froydnj you can call it off main. Example: http://mxr.mozilla.org/mozilla-central/source/storage/src/TelemetryVFS.cpp#104

No locking is done, but the Telemetry code seems fine with that http://mxr.mozilla.org/mozilla-central/source/ipc/chromium/src/base/histogram.cc#780

Will update with other nits.

Comment 22

[Randell Jesup [:jesup] (needinfo me)]

If it goes out by 10seconds, there's a major underrun or clock drift issue.  Beyond 10s I don't really care *how* far it's off, just that it's at the untenable range.  So that's ok I think

Comment 23

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Attachment: Part 3: Add a/v sync telemetry (2)

Updated with feedback. Increased histogram range to 1 minute.

Forgot to say what thread this is on. It's on the MSG thread.

Comment 24

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Sorry, mid-aired. How do we feel about 60 seconds? The buckets are exponential, so we don't loose much resolution down low. Even if +10s is really wrong, it did happen in the past, so it may have some value knowing whether this happens in the field.

Comment 25

[Byron Campen [:bwc]]

Comment on attachment 8391461 [details] [diff] [review]
Part 3: Add a/v sync telemetry (2)

Review of attachment 8391461 [details] [diff] [review]:
-----------------------------------------------------------------

Looks ok, with a nit.

::: media/webrtc/signaling/src/media-conduit/AudioConduit.cpp
@@ +693,5 @@
>    if (mSamples >= mLastSyncLog + samplingFreqHz) {
>      int jitter_buffer_delay_ms = 0;
>      int playout_buffer_delay_ms = 0;
>      int avsync_offset_ms = 0;
> +    bool result = GetAVStats(&jitter_buffer_delay_ms,

Since we're finally in the process of purging our code of warnings in preparation for -Werror, we probably want to (void)result; or something so we don't get warnings when MOZILLA_INTERNAL_API isn't set.

Comment 26

[Randell Jesup [:jesup] (needinfo me)]

60s is ok, if it doesn't lose us resolution at the short end

Comment 27

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Attachment: Part 3: Add a/v sync telemetry (3) r=bwc

Dealt with result. Carrying forward r+ from bwc.

Comment 28

[Ryan VanderMeulen [:RyanVM]]

Please rebase.

Comment 29

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Attachment: Part 3: Add a/v sync telemetry (4) r=bwc

Rebased.

Comment 30

[Ryan VanderMeulen [:RyanVM]]

Thanks :)

https://hg.mozilla.org/integration/mozilla-inbound/rev/5eacab1442af

Comment 31

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

https://hg.mozilla.org/mozilla-central/rev/5eacab1442af