920325 - Log latency from capture until MediaStreamTrack insertion

Status: RESOLVED FIXED

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

Description

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

Follow-on to bug 904617.  Add measurements from capture time until insertion into MSG graph (or direct insertion (bug 884365) into PeerConnection).

Comment 1

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

Attachment: Add WebRTC latency logging from capture to RTP and from RTP to speakers

Still needs mods to other audio devices; only linux is done so far.  Applies on top of padenot's patch queue from Try

Comment 2

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

Attachment: Add WebRTC latency logging from capture to RTP and from RTP to speakers

only supports the new latency monitoring for Linux; separate patch coming to enable it for other platforms, but I wanted to get this under review for the majority of the code (the platform-specific changes mostly are in the webrtc audio_device code - adding a few calls to local capture creation and sampling)

Comment 3

[Paul Adenot (:padenot)]

Comment on attachment 818302 [details] [diff] [review]
Add WebRTC latency logging from capture to RTP and from RTP to speakers

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

I'll like to a do second review on this with all those fixed, since it's quite big.

::: content/media/AudioStream.cpp
@@ +358,5 @@
>  
>    long DataCallback(void* aBuffer, long aFrames);
>    void StateCallback(cubeb_state aState);
>  
> +  long GetUnprocessed(void* aBuffer, long aFrames, int64_t &aTime);

Comment on all the new TimeStamp parameter. It's obvious why you would pass a buffer and a length, but not a TimeStamp :-)

@@ +651,5 @@
>      mCubebStream.reset();
>    }
>  }
>  
> +// aTime is the time in ms the sample block was inserted into MediaStreamGraph

Ha, the comment is here. I'd rather have it on the declaration.

@@ +663,5 @@
>    NS_ASSERTION(mState == INITIALIZED || mState == STARTED,
>      "Stream write in unexpected state.");
>  
>    const uint8_t* src = reinterpret_cast<const uint8_t*>(aBuf);
>    uint32_t bytesToCopy = FramesToBytes(aFrames);

Maybe it would be good to guard all this by the Log check? AsyncLatencyLogger::Get grabs a mutex that might have a high-ish contention.

@@ +674,5 @@
> +    timeMs = (*aTime - mStartTime).ToMilliseconds();
> +  } else {
> +    timeMs = 0;
> +  }
> +  mInsertTimes.AppendElement(timeMs);

Why not have a single array of a struct here? We are doing appends/remove by pairs. I have some plans to remove the locks in this class, and it would be great to limit allocations (because the underlying implementation might lock).

@@ +897,5 @@
> +    mInsertFrames.RemoveElementAt(0);
> +  }
> +  // offset for amount already read
> +  // XXX Note: could misreport if we couldn't find a block in the right timeframe
> +  aTimeMs = mInsertTimes[0] + (mReadPoint*1000/mOutRate);

Spaces around operators, please.

@@ +935,5 @@
> +    mInsertTimes.RemoveElementAt(0);
> +    mInsertFrames.RemoveElementAt(0);
> +  }
> +  // offset for amount already read
> +  aTimeMs = mInsertTimes[0] + (mReadPoint*1000/mOutRate);

This block should be factored out with a meaningful name.

@@ +981,5 @@
> +    mInsertTimes.RemoveElementAt(0);
> +    mInsertFrames.RemoveElementAt(0);
> +  }
> +  // offset for amount already read
> +  aTimeMs = mInsertTimes[0] + (mReadPoint*1000/mOutRate);

nit: spaces around operators.

@@ +1021,5 @@
>      mon.NotifyAll();
> +  } else {
> +    // offset for amount already read
> +    if (mInsertTimes.Length() > 0) {
> +      insertTime = mInsertTimes[0] + (mReadPoint*1000/mOutRate);

nit: space around operators.

@@ +1053,5 @@
> +
> +    mLatencyLog->Log(AsyncLatencyLogger::AudioStream, reinterpret_cast<uint64_t>(this),
> +                     insertTime, now);
> +    mLatencyLog->Log(AsyncLatencyLogger::Cubeb, reinterpret_cast<uint64_t>(mCubebStream.get()),
> +                     (latency * 1000) / mOutRate, now);

I'd rather use the Latency.h functions here, not using directly methods, for consistency.

@@ +1140,5 @@
>    return (GetPosition() * mOutRate) / USECS_PER_S;
>  }
>  
>  void AudioClock::SetPlaybackRate(double aPlaybackRate)
>  {

This is somewhat unrelated, although correct. Maybe it would be good to split it off so mercurial archeology is easier.

::: content/media/AudioStream.h
@@ +204,5 @@
>    AudioClock mAudioClock;
>    nsAutoPtr<soundtouch::SoundTouch> mTimeStretcher;
>    nsRefPtr<AsyncLatencyLogger> mLatencyLog;
>    LatencyRequest mLatencyRequest;
> +

Add comments explaining what those are for.

::: content/media/Latency.cpp
@@ +212,5 @@
>  
> +void AsyncLatencyLogger::Log(LatencyLogIndex aIndex, uint64_t aID, int64_t aValue, bool stamp)
> +{
> +  TimeStamp temp = stamp ? TimeStamp::Now() : TimeStamp();
> +  Log(aIndex, aID, aValue, temp);

Why a boolean when you could just not use another method with a meaningful name? aVariable if you keep the boolean, in any case.

::: content/media/Latency.h
@@ +48,2 @@
>      _MAX_INDEX
>    };

Comment over every functions, especially the different overloads.

@@ +79,5 @@
>  void LogLatency(AsyncLatencyLogger::LatencyLogIndex index, uint64_t aID, int64_t value);
> +void LogLatency(uint32_t index, uint64_t aID, int64_t value);
> +void LogTime(AsyncLatencyLogger::LatencyLogIndex index, uint64_t aID, int64_t value);
> +void LogTime(AsyncLatencyLogger::LatencyLogIndex index, uint64_t aID, int64_t value, mozilla::TimeStamp &aTime);
> +void LogTime(uint32_t index, uint64_t aID, int64_t value);

Could you normalize all those with arguments using the aParameter form?

::: content/media/MediaStreamGraph.cpp
@@ +856,5 @@
>                               aStream, MediaTimeToSeconds(t), MediaTimeToSeconds(end),
>                               startTicks, endTicks));
>        }
> +      // Need unique id for stream & track - and we want it to match the inserter
> +      output.WriteTo((((uint64_t)aStream) & ~0x0F) | track->GetID(),

uintptr_t

::: content/media/test/graph_latency.py
@@ +68,5 @@
> +            final_data[name] = ([], [])
> +# sanity-check values
> +        if int(tupl[3]) < 10*1000:
> +            final_data[name][0].append(int(tupl[4]))
> +            final_data[name][1].append(int(tupl[3]))

Warn if we find outliers here?

@@ +73,5 @@
> +
> +def graph_smoothed(lines, divisor):
> +    '''
> +    Graph lines
> +    '''

Update the docstring

@@ +78,5 @@
> +    value = 0
> +    for tupl in lines:
> +        name = tupl[0]
> +        if tupl[1] != 0:
> +            track = tupl[1] # str(int(tupl[1]) & 0x0f)

This comment should go away.

@@ +89,5 @@
> +                value = (value*(divisor-1) + int(tupl[3]))/divisor
> +            else:
> +                value = int(tupl[3])
> +            final_data[name][0].append(int(tupl[4]))
> +            final_data[name][1].append(value)

Same here, warn if the value is too high.

@@ +94,5 @@
> +
> +def graph_plus(lines, base, additional, divisor):
> +    '''
> +    Graph lines
> +    '''

Update the docstring.

@@ +102,5 @@
> +    print base
> +    for tupl in lines:
> +        name = tupl[0]
> +        if tupl[1] != 0:
> +            track = tupl[1] # str(int(tupl[1]) & 0x0f)

Drop the comment.

@@ +108,5 @@
> +        if name not in final_data.keys():
> +            final_data[name] = ([], [])
> +        # find base value for the time
> +        while j < len(base):
> +            print j,len(base),len(base[0]),int(tupl[4]),base[0][j]

Either drop the print, or make it conditional based on the |latency| variable.

@@ +121,5 @@
> +                value = (value*(divisor-1) + int(tupl[3]))/divisor
> +            else:
> +                value = int(tupl[3])
> +            final_data[name][0].append(int(tupl[4]))
> +            final_data[name][1].append(value + curr_base + additional)

Else clause to warn.

@@ +130,5 @@
> +    '''
> +    for tupl in lines:
> +        name = tupl[0]
> +        if tupl[1] != 0:
> +            track = tupl[1] #str(int(tupl[1]) & 0x0f)

Drop the comment.

@@ +139,5 @@
> +# sanity-check values
> +        value = (int(tupl[4]) - int(tupl[3])) + input_block_time
> +        if value < 1*1000:
> +            final_data[name][0].append(int(tupl[4]))
> +            final_data[name][1].append(value)

Else clause to catch mistakes.

@@ +151,5 @@
> +    j = 0
> +    for tupl in lines:
> +        name = tupl[0]
> +        if tupl[1] != 0:
> +            track = tupl[1] #str(int(tupl[1]) & 0x0f)

Drop the comment.

@@ +164,5 @@
> +                return
> +        new_value = (int(tupl[4]) - int(tupl[3])) + input_block_time
> +        new_value = new_value + int(lines2[j][3])
> +        if new_value > 3000:
> +            continue

?

@@ +245,5 @@
> +# build SourceMediaStream->TrackUnion stream mappings
> +mediastream_map = {}
> +audiostream_map = {}
> +for tupl in mscreate:
> +    #mediastream_map[tupl[1]] = tupl[3]

drop the comment

@@ +249,5 @@
> +    #mediastream_map[tupl[1]] = tupl[3]
> +    mediastream_map[str(int(tupl[1]) & ~0x0F)] = str(int(tupl[3]) & ~0x0F)
> +# build SourceMediaStream->AudioStream stream mappings
> +for tupl in ascreate:
> +    #audiostream_map[tupl[1]] = tupl[3]

drop the comment

@@ +250,5 @@
> +    mediastream_map[str(int(tupl[1]) & ~0x0F)] = str(int(tupl[3]) & ~0x0F)
> +# build SourceMediaStream->AudioStream stream mappings
> +for tupl in ascreate:
> +    #audiostream_map[tupl[1]] = tupl[3]
> +    audiostream_map[str(int(tupl[1]) & ~0x0F)] = str(int(tupl[3]) & ~0x0F)

Factor this bit manipulation out with a meaningful name, please.

@@ +264,2 @@
>      name = tupl[0]
> +    if True:

if True: ?

@@ +264,5 @@
>      name = tupl[0]
> +    if True:
> +        temp = name + " delta from expected"
> +        if temp not in final_data.keys():
> +            final_data[temp] = ([], [])

you do something like that:

> final_data = defaultdict(lambda: ([], []))

so that if you have a `temp` that does not exist, ([], []) is created automatically, like when using the STL <map> in C++.

@@ +267,5 @@
> +        if temp not in final_data.keys():
> +            final_data[temp] = ([], [])
> +        final_data[temp][0].append(int(tupl[2]))
> +        # this is delta from when we think it should be captured (delta from a steady 10ms beat)
> +        final_data[temp][1].append(int(tupl[2])-(int(base[0][4])+i))

Maybe we could use namedtuples [1] to avoid this unmaintainable madness.

[1]: http://docs.python.org/2/library/collections.html#collections.namedtuple

@@ +281,5 @@
> +        # this is the time from should-be-captured until insertion into the graph - usually near 0
> +        value = int(insert[0][4]) - int(tupl[2])
> +        if value > -50:
> +            # smooth
> +            capture_avg = value #(capture_avg*3 + value)/4

Does not seem super smooth with the lowpass commented out.

@@ +298,2 @@
>  
> +# FIX assume for now no dropped data - 10ms into graph, 10ms out

Can't you detect dropped data based on the tstamp?

::: content/media/webrtc/MediaEngineWebRTCAudio.cpp
@@ +382,5 @@
>        // This is safe from any thread, and is safe if the track is Finished
>        // or Destroyed
> +      // make sure we include the stream and the track
> +      LogTime(AsyncLatencyLogger::AudioTrackInsertion, (((uint64_t) source) & ~0x0F) | mTrackID,
> +              (i+1 < len) ? 0 : 1, insertTime);

Maybe it would be good to factor out this track id logic into a function in Latency.h so we don't have to keep it in sync in multiple locations.

@@ +383,5 @@
>        // or Destroyed
> +      // make sure we include the stream and the track
> +      LogTime(AsyncLatencyLogger::AudioTrackInsertion, (((uint64_t) source) & ~0x0F) | mTrackID,
> +              (i+1 < len) ? 0 : 1, insertTime);
> +

I'm not entirely sure what the 

> (i+1 < len) ? 0 : 1

bit means.

::: dom/media/MediaManager.cpp
@@ +570,5 @@
> +    // Make sure logger starts before capture
> +    AsyncLatencyLogger::Get(true);
> +    LogLatency(AsyncLatencyLogger::MediaStreamCreate,
> +               reinterpret_cast<uint64_t>(stream.get()),
> +               reinterpret_cast<int64_t>(trackunion->GetStream()));

uintptr_t

::: media/webrtc/signaling/src/media-conduit/AudioConduit.cpp
@@ +619,5 @@
> +            LogTime(AsyncLatencyLogger::AudioRecvRTP, ((uint64_t) this), delta);
> +            break;
> +          }
> +          mProcessing.RemoveElementAt(0);
> +          mProcessingTS.RemoveElementAt(0);

Merge those into a single array?

@@ +641,5 @@
>    {
> +#ifdef MOZILLA_INTERNAL_API
> +    if (PR_LOG_TEST(GetLatencyLog(), PR_LOG_DEBUG)) {
> +      mProcessing.AppendElement(TimeStamp::Now());
> +      mProcessingTS.AppendElement(ntohl(static_cast<const uint32_t *>(data)[1])); // timestamp is at 32 bits in

The comment got cut? Also, comment about the [1], it seems a bit magic.

::: media/webrtc/trunk/webrtc/modules/audio_device/linux/audio_device_alsa_linux.cc
@@ +23,5 @@
> +
> +#define LOG_FIRST_CAPTURE(x) LogTime(AsyncLatencyLogger::AudioCaptureBase, \
> +                                     reinterpret_cast<uint64_t>(x), 0)
> +#define LOG_CAPTURE_FRAMES(x, frames) LogLatency(AsyncLatencyLogger::AudioCapture, \
> +                                                 reinterpret_cast<uint64_t>(x), frames)

I'm not entirely sure why you hide this behind macros. Is it because we want to limit the changes we do and won't upstream? Maybe it makes sense, I'll let you judge, you do the uplifts anyways :-)

Comment 4

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

(In reply to Paul Adenot (:padenot) from comment #3)
> Comment on attachment 818302 [details] [diff] [review]
> Add WebRTC latency logging from capture to RTP and from RTP to speakers
> 
> Review of attachment 818302 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> I'll like to a do second review on this with all those fixed, since it's
> quite big.
> 
> ::: content/media/AudioStream.cpp

> @@ +663,5 @@
> >    NS_ASSERTION(mState == INITIALIZED || mState == STARTED,
> >      "Stream write in unexpected state.");
> >  
> >    const uint8_t* src = reinterpret_cast<const uint8_t*>(aBuf);
> >    uint32_t bytesToCopy = FramesToBytes(aFrames);
> 
> Maybe it would be good to guard all this by the Log check?
> AsyncLatencyLogger::Get grabs a mutex that might have a high-ish contention.

Sure.

> 
> @@ +674,5 @@
> > +    timeMs = (*aTime - mStartTime).ToMilliseconds();
> > +  } else {
> > +    timeMs = 0;
> > +  }
> > +  mInsertTimes.AppendElement(timeMs);
> 
> Why not have a single array of a struct here? We are doing appends/remove by
> pairs. I have some plans to remove the locks in this class, and it would be
> great to limit allocations (because the underlying implementation might
> lock).

Yeah, a single array of a struct will be fine; it was just faster to do it this way.  It still may allocate in weird cases; I've made them Autos so even a single allocation there would be unusual, and they'd always be rare instances if they occur.

> 
> @@ +897,5 @@
> > +    mInsertFrames.RemoveElementAt(0);
> > +  }
> > +  // offset for amount already read
> > +  // XXX Note: could misreport if we couldn't find a block in the right timeframe
> > +  aTimeMs = mInsertTimes[0] + (mReadPoint*1000/mOutRate);
> 
> Spaces around operators, please.

Sure.

> 
> @@ +935,5 @@
> > +    mInsertTimes.RemoveElementAt(0);
> > +    mInsertFrames.RemoveElementAt(0);
> > +  }
> > +  // offset for amount already read
> > +  aTimeMs = mInsertTimes[0] + (mReadPoint*1000/mOutRate);
> 
> This block should be factored out with a meaningful name.

I'll look at that.

> 
> @@ +981,5 @@
> > +    mInsertTimes.RemoveElementAt(0);
> > +    mInsertFrames.RemoveElementAt(0);
> > +  }
> > +  // offset for amount already read
> > +  aTimeMs = mInsertTimes[0] + (mReadPoint*1000/mOutRate);
> 
> nit: spaces around operators.

Ok.  style differences.... 


> @@ +1053,5 @@
> > +
> > +    mLatencyLog->Log(AsyncLatencyLogger::AudioStream, reinterpret_cast<uint64_t>(this),
> > +                     insertTime, now);
> > +    mLatencyLog->Log(AsyncLatencyLogger::Cubeb, reinterpret_cast<uint64_t>(mCubebStream.get()),
> > +                     (latency * 1000) / mOutRate, now);
> 
> I'd rather use the Latency.h functions here, not using directly methods, for
> consistency.

This is on purpose to avoid calling ::Get() on each log statement to avoid locks. :-)

> 
> @@ +1140,5 @@
> >    return (GetPosition() * mOutRate) / USECS_PER_S;
> >  }
> >  
> >  void AudioClock::SetPlaybackRate(double aPlaybackRate)
> >  {
> 
> This is somewhat unrelated, although correct. Maybe it would be good to
> split it off so mercurial archeology is easier.

I'll put it in a separate patch.  It came along for the ride when I noticed it needed some love.

> ::: content/media/Latency.cpp
> @@ +212,5 @@
> >  
> > +void AsyncLatencyLogger::Log(LatencyLogIndex aIndex, uint64_t aID, int64_t aValue, bool stamp)
> > +{
> > +  TimeStamp temp = stamp ? TimeStamp::Now() : TimeStamp();
> > +  Log(aIndex, aID, aValue, temp);
> 
> Why a boolean when you could just not use another method with a meaningful
> name? aVariable if you keep the boolean, in any case.

Ok, I'll look at this.

> 
> ::: content/media/Latency.h
> @@ +48,2 @@
> >      _MAX_INDEX
> >    };
> 
> Comment over every functions, especially the different overloads.
> 
> @@ +79,5 @@
> >  void LogLatency(AsyncLatencyLogger::LatencyLogIndex index, uint64_t aID, int64_t value);
> > +void LogLatency(uint32_t index, uint64_t aID, int64_t value);
> > +void LogTime(AsyncLatencyLogger::LatencyLogIndex index, uint64_t aID, int64_t value);
> > +void LogTime(AsyncLatencyLogger::LatencyLogIndex index, uint64_t aID, int64_t value, mozilla::TimeStamp &aTime);
> > +void LogTime(uint32_t index, uint64_t aID, int64_t value);
> 
> Could you normalize all those with arguments using the aParameter form?

Sure.

> 
> ::: content/media/MediaStreamGraph.cpp
> @@ +856,5 @@
> >                               aStream, MediaTimeToSeconds(t), MediaTimeToSeconds(end),
> >                               startTicks, endTicks));
> >        }
> > +      // Need unique id for stream & track - and we want it to match the inserter
> > +      output.WriteTo((((uint64_t)aStream) & ~0x0F) | track->GetID(),
> 
> uintptr_t

Ah, yes.

> ::: content/media/test/graph_latency.py
> @@ +68,5 @@
> > +            final_data[name] = ([], [])
> > +# sanity-check values
> > +        if int(tupl[3]) < 10*1000:
> > +            final_data[name][0].append(int(tupl[4]))
> > +            final_data[name][1].append(int(tupl[3]))
> 
> Warn if we find outliers here?

Ok



> @@ +108,5 @@
> > +        if name not in final_data.keys():
> > +            final_data[name] = ([], [])
> > +        # find base value for the time
> > +        while j < len(base):
> > +            print j,len(base),len(base[0]),int(tupl[4]),base[0][j]
> 
> Either drop the print, or make it conditional based on the |latency|
> variable.

leftover debugging.
 


> @@ +164,5 @@
> > +                return
> > +        new_value = (int(tupl[4]) - int(tupl[3])) + input_block_time
> > +        new_value = new_value + int(lines2[j][3])
> > +        if new_value > 3000:
> > +            continue
> 
> ?

To avoid blowing up the graph so the graph is readable.


> @@ +264,2 @@
> >      name = tupl[0]
> > +    if True:
> 
> if True: ?

debugging...

> 
> @@ +264,5 @@
> >      name = tupl[0]
> > +    if True:
> > +        temp = name + " delta from expected"
> > +        if temp not in final_data.keys():
> > +            final_data[temp] = ([], [])
> 
> you do something like that:
> 
> > final_data = defaultdict(lambda: ([], []))
> 
> so that if you have a `temp` that does not exist, ([], []) is created
> automatically, like when using the STL <map> in C++.

useful.  I'm no python programmer ;-)

> 
> @@ +267,5 @@
> > +        if temp not in final_data.keys():
> > +            final_data[temp] = ([], [])
> > +        final_data[temp][0].append(int(tupl[2]))
> > +        # this is delta from when we think it should be captured (delta from a steady 10ms beat)
> > +        final_data[temp][1].append(int(tupl[2])-(int(base[0][4])+i))
> 
> Maybe we could use namedtuples [1] to avoid this unmaintainable madness.
> 
> [1]: http://docs.python.org/2/library/collections.html#collections.namedtuple

I'll look, but probably for a future update

> 
> @@ +281,5 @@
> > +        # this is the time from should-be-captured until insertion into the graph - usually near 0
> > +        value = int(insert[0][4]) - int(tupl[2])
> > +        if value > -50:
> > +            # smooth
> > +            capture_avg = value #(capture_avg*3 + value)/4
> 
> Does not seem super smooth with the lowpass commented out.

Good point :-)

> @@ +298,2 @@
> >  
> > +# FIX assume for now no dropped data - 10ms into graph, 10ms out
> 
> Can't you detect dropped data based on the tstamp?

Not necessarily; I'll have to look very carefully to see, or better yet to actually log such things so there's no guessing.

> 
> ::: content/media/webrtc/MediaEngineWebRTCAudio.cpp
> @@ +382,5 @@
> >        // This is safe from any thread, and is safe if the track is Finished
> >        // or Destroyed
> > +      // make sure we include the stream and the track
> > +      LogTime(AsyncLatencyLogger::AudioTrackInsertion, (((uint64_t) source) & ~0x0F) | mTrackID,
> > +              (i+1 < len) ? 0 : 1, insertTime);
> 
> Maybe it would be good to factor out this track id logic into a function in
> Latency.h so we don't have to keep it in sync in multiple locations.

perhaps so.  I needed some sort of way to correlate (and it will help us log this by stream/track in about:webrtc)

> 
> @@ +383,5 @@
> >        // or Destroyed
> > +      // make sure we include the stream and the track
> > +      LogTime(AsyncLatencyLogger::AudioTrackInsertion, (((uint64_t) source) & ~0x0F) | mTrackID,
> > +              (i+1 < len) ? 0 : 1, insertTime);
> > +
> 
> I'm not entirely sure what the 
> 
> > (i+1 < len) ? 0 : 1
> 
> bit means.

That's a flag to let me know when it's done inserting into all the different MSG tracks; I'll check the code to make sure it makes sense still and/or comment.


> ::: media/webrtc/signaling/src/media-conduit/AudioConduit.cpp
> @@ +619,5 @@
> > +            LogTime(AsyncLatencyLogger::AudioRecvRTP, ((uint64_t) this), delta);
> > +            break;
> > +          }
> > +          mProcessing.RemoveElementAt(0);
> > +          mProcessingTS.RemoveElementAt(0);
> 
> Merge those into a single array?

Probably makes sense.

> 
> @@ +641,5 @@
> >    {
> > +#ifdef MOZILLA_INTERNAL_API
> > +    if (PR_LOG_TEST(GetLatencyLog(), PR_LOG_DEBUG)) {
> > +      mProcessing.AppendElement(TimeStamp::Now());
> > +      mProcessingTS.AppendElement(ntohl(static_cast<const uint32_t *>(data)[1])); // timestamp is at 32 bits in
> 
> The comment got cut? Also, comment about the [1], it seems a bit magic.

Ok

> 
> :::
> media/webrtc/trunk/webrtc/modules/audio_device/linux/audio_device_alsa_linux.
> cc
> @@ +23,5 @@
> > +
> > +#define LOG_FIRST_CAPTURE(x) LogTime(AsyncLatencyLogger::AudioCaptureBase, \
> > +                                     reinterpret_cast<uint64_t>(x), 0)
> > +#define LOG_CAPTURE_FRAMES(x, frames) LogLatency(AsyncLatencyLogger::AudioCapture, \
> > +                                                 reinterpret_cast<uint64_t>(x), frames)
> 
> I'm not entirely sure why you hide this behind macros. Is it because we want
> to limit the changes we do and won't upstream? Maybe it makes sense, I'll
> let you judge, you do the uplifts anyways :-)

It's for ease in upstreaming; for upstream I can #define them to nothing.

Comment 5

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

Attachment: interdiffs for c++ changes

Comment 6

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

Attachment: Add WebRTC latency logging from capture to RTP and from RTP to speakers

Comment 7

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

Comment on attachment 822413 [details] [diff] [review]
Add WebRTC latency logging from capture to RTP and from RTP to speakers

Note: graph_latency.py changes still coming.  Interdiffs are in other attachment for easier reading

Comment 8

[Paul Adenot (:padenot)]

Comment on attachment 822413 [details] [diff] [review]
Add WebRTC latency logging from capture to RTP and from RTP to speakers

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

r+ based on the interdiff.

Comment 9

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

Attachment: python interdiffs

Comment 10

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

Attachment: Add WebRTC latency logging from capture to RTP and from RTP to speakers

with python folded in

Comment 11

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

Comment on attachment 822435 [details] [diff] [review]
Add WebRTC latency logging from capture to RTP and from RTP to speakers

Just r? for the python changes listed in the interdiff, r+ already on the rest.

Comment 12

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

This is the c++ portion already r+'d; the graph changes still up for review are NPOTB

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

leave-open for the graph patch (and for enabling on other platforms)

Comment 13

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

Backout for windows bustage (ntohl, darn it)
https://hg.mozilla.org/integration/mozilla-inbound/rev/370618d6e935

Comment 14

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

Reland after patch and try: https://tbpl.mozilla.org/?tree=Try&rev=acac3968385b

https://hg.mozilla.org/integration/mozilla-inbound/rev/c37be651071c
https://hg.mozilla.org/integration/mozilla-inbound/rev/32625a7468b2  (r=tbsaunde via IRC)

Comment 15

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/c37be651071c
https://hg.mozilla.org/mozilla-central/rev/32625a7468b2

Comment 18

[BugBot [:suhaib / :marco/ :calixte]]

The leave-open keyword is there and there is no activity for 6 months.
:jib, maybe it's time to close this bug?

Comment 19

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

Paul, is there anything left to land here, do you know? Comment 12 says "leave-open for the graph patch (and for enabling on other platforms)"

Comment 20

[Paul Adenot (:padenot)]

No this has been since removed from the tree. Thanks!