Closed Bug 964127 Opened 6 years ago Closed 6 years ago

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

Categories

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

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla30

People

(Reporter: jesup, Assigned: jib)

Details

Attachments

(3 files, 7 obsolete files)

18.31 KB, patch
jib
: review+
Details | Diff | Splinter Review
12.56 KB, patch
jib
: review+
Details | Diff | Splinter Review
4.18 KB, patch
jib
: review+
Details | Diff | Splinter Review
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.
Attachment #8388736 - Attachment is obsolete: true
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).
Attachment #8388944 - Flags: feedback?(rjesup)
Attachment #8388944 - Flags: feedback?(rjesup) → feedback+
Trying it in pc_test.html I noticed only audio1 was showing stats; audio0 wasn't.
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)?
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.)
Removed dependence on logging-site.
Attachment #8388944 - Attachment is obsolete: true
Attachment #8389620 - Flags: review?(rjesup)
Attachment #8389620 - Flags: review?(rjesup) → review+
Thanks! I assume you'll land once your patch is reviewed.
Attachment #8388868 - Attachment is obsolete: true
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)
Attachment #8389999 - Flags: review?(jib)
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()
Attachment #8389999 - Flags: review?(jib) → review+
Attachment #8389999 - Attachment description: Add logging of webrtc a/v sync status → Part 1: Add logging of webrtc a/v sync status
Unbitrot. Carrying forward r+ from jesup.
Attachment #8389620 - Attachment is obsolete: true
Attachment #8390052 - Flags: review+
(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.
(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?
Also, I still claim mLastSyncLog is redundant. You could reset mSamples when the sample frequency is reached. i.e. modulo sample frequency.
(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.
Attached patch Part 3: Add a/v sync telemetry (obsolete) — Splinter Review
Attachment #8391008 - Flags: review?(docfaraday)
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?
Attachment #8391008 - Flags: review?(docfaraday) → review-
(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.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
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
Updated with feedback. Increased histogram range to 1 minute.

Forgot to say what thread this is on. It's on the MSG thread.
Attachment #8391008 - Attachment is obsolete: true
Attachment #8391461 - Flags: review?(docfaraday)
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 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.
Attachment #8391461 - Flags: review?(docfaraday) → review+
60s is ok, if it doesn't lose us resolution at the short end
Dealt with result. Carrying forward r+ from bwc.
Attachment #8391469 - Flags: review+
Attachment #8391461 - Attachment is obsolete: true
Summary: Add a/v sync info to about:webrtc stats (and logs) → Add a/v sync info to about:webrtc stats, logs and telemetry
Attachment #8391469 - Attachment description: Part 3: Add a/v sync telemetry (3) → Part 3: Add a/v sync telemetry (3) r=bwc
Please rebase.
Assignee: nobody → jib
Keywords: checkin-needed
Target Milestone: mozilla30 → ---
Rebased.
Attachment #8391469 - Attachment is obsolete: true
Attachment #8391771 - Flags: review+
https://hg.mozilla.org/mozilla-central/rev/5eacab1442af
Status: REOPENED → RESOLVED
Closed: 6 years ago6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla30
No longer blocks: webrtc_upstream_bugs
You need to log in before you can comment on or make changes to this bug.