Added log messages for important call setup events: first packet sent/received

Added log messages for some important call setup events:

 - First audio RTP packet sent / received
 - First RTP packet of the first video frame sent / received
 - Last RTP packet of the first video frame sent / received
These timestamps should make it easier to measure how fast the call
becomes established from the user's perspective.

Committed: https://crrev.com/98bb6640d22e9fe03696054b5e054f174db7739f
Cr-Commit-Position: refs/heads/master@{#12287}

[skvlad, 2016-03-03 00:59:49]

skvlad@webrtc.org changed reviewers:
+ marpan@webrtc.org, mflodman@webrtc.org, pthatcher@webrtc.org,
stefan@webrtc.org

[pthatcher1, 2016-03-05 01:17:05]

lgtm,

Just little nits

I'm not an owner, though :)

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
File webrtc/modules/rtp_rtcp/source/rtp_receiver_impl.cc (right):

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
webrtc/modules/rtp_rtcp/source/rtp_receiver_impl.cc:232: (is_audio_ ? "audio" :
"video") << " frame received";
Nit: I think I'd prefer the text to start with "Received": "Received first RTP
packet of the first X frame."

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
File webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc (right):

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc:355: }
Nit: This might be more clear as:

bool firstPacket = false;
...

if (!_firstPacketSent) {
  firstPacket = true;
  _firstPacketSent = true;
}

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
File webrtc/modules/rtp_rtcp/source/rtp_sender_video.cc (right):

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
webrtc/modules/rtp_rtcp/source/rtp_sender_video.cc:247: }
Similar here

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
webrtc/modules/rtp_rtcp/source/rtp_sender_video.cc:326: LOG(LS_INFO) << "Last
RTP packet of the first video frame sent";
Nit: Same here;  put "Sent first ..." or "Sent last ...."

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/video_coding/j...
File webrtc/modules/video_coding/jitter_buffer.cc (right):

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/video_coding/j...
webrtc/modules/video_coding/jitter_buffer.cc:1247: LOG(LS_INFO) << "First
completed key frame received";
Nit: And here: "Received first ..."

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/video_coding/v...
File webrtc/modules/video_coding/video_receiver.cc (right):

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/video_coding/v...
webrtc/modules/video_coding/video_receiver.cc:318: (frame->Complete() ? "true" :
"false");
And here :) "Received first ...

[danilchap, 2016-03-07 09:29:11]

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
File webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc (right):

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc:368: int32_t sendResult =
_rtpSender->SendToNetwork(dataBuffer, payloadSize,
SendToNetwork doesn't send packet immediately. It post packet to pacer that send
it in a different thread.
You may want to check RtpSender::SendPacketToNework instead.
Also, RtpSender already has a flag media_has_been_sent_ that is set to true
after first sent packet.

[pthatcher1, 2016-03-07 17:28:33]

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
File webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc (right):

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc:368: int32_t sendResult =
_rtpSender->SendToNetwork(dataBuffer, payloadSize,
On 2016/03/07 09:29:11, danilchap wrote:
> SendToNetwork doesn't send packet immediately. It post packet to pacer that
send
> it in a different thread.
> You may want to check RtpSender::SendPacketToNework instead.
> Also, RtpSender already has a flag media_has_been_sent_ that is set to true
> after first sent packet.

That's a good point.  

Actually, we might want to record *both* timestamps, before and after the pacer,
so we know the impact of the pacer on the latency of the first frame.  

So, perhaps just note in these logs statements that it's pre-pacer.  

As for when we really send something on the network, we'd actually want push
that further than the RtpSender, but all the way out to perhaps MediaChannel or
maybe even P2pTransportChannel.  To do so, we'd need that layer to know it's a
special packet.  Luckily, we already have a mechanism in which the
P2pTransportChannel reports back when a specific packet has been sent.  Perhaps
we could use that to know when a packet really hits the network.

All that said, I think we could do so in a secondary CL.  For our purposes right
now, knowing the pre-pacer time is probably enough, as long as we log that it's
pre-pacer.

[skvlad, 2016-03-07 19:36:53]

Rephrased the log statements to begin with "Sent"/"Received"

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
File webrtc/modules/rtp_rtcp/source/rtp_receiver_impl.cc (right):

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
webrtc/modules/rtp_rtcp/source/rtp_receiver_impl.cc:232: (is_audio_ ? "audio" :
"video") << " frame received";
On 2016/03/05 01:17:05, pthatcher1 wrote:
> Nit: I think I'd prefer the text to start with "Received": "Received first RTP
> packet of the first X frame."

Done.

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
File webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc (right):

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc:355: }
On 2016/03/05 01:17:05, pthatcher1 wrote:
> Nit: This might be more clear as:
> 
> bool firstPacket = false;
> ...
> 
> if (!_firstPacketSent) {
>   firstPacket = true;
>   _firstPacketSent = true;
> }

Done.

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc:368: int32_t sendResult =
_rtpSender->SendToNetwork(dataBuffer, payloadSize,
On 2016/03/07 17:28:33, pthatcher1 wrote:
> On 2016/03/07 09:29:11, danilchap wrote:
> > SendToNetwork doesn't send packet immediately. It post packet to pacer that
> send
> > it in a different thread.
> > You may want to check RtpSender::SendPacketToNework instead.
> > Also, RtpSender already has a flag media_has_been_sent_ that is set to true
> > after first sent packet.
> 
> That's a good point.  
> 
> Actually, we might want to record *both* timestamps, before and after the
pacer,
> so we know the impact of the pacer on the latency of the first frame.  
> 
> So, perhaps just note in these logs statements that it's pre-pacer.  
> 
> As for when we really send something on the network, we'd actually want push
> that further than the RtpSender, but all the way out to perhaps MediaChannel
or
> maybe even P2pTransportChannel.  To do so, we'd need that layer to know it's a
> special packet.  Luckily, we already have a mechanism in which the
> P2pTransportChannel reports back when a specific packet has been sent. 
Perhaps
> we could use that to know when a packet really hits the network.
> 
> All that said, I think we could do so in a secondary CL.  For our purposes
right
> now, knowing the pre-pacer time is probably enough, as long as we log that
it's
> pre-pacer.

Changed the log line to say the packet hasn't gone through the pacer yet.

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
File webrtc/modules/rtp_rtcp/source/rtp_sender_video.cc (right):

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
webrtc/modules/rtp_rtcp/source/rtp_sender_video.cc:247: }
On 2016/03/05 01:17:05, pthatcher1 wrote:
> Similar here

Done.

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/rtp_rtcp/sourc...
webrtc/modules/rtp_rtcp/source/rtp_sender_video.cc:326: LOG(LS_INFO) << "Last
RTP packet of the first video frame sent";
On 2016/03/05 01:17:05, pthatcher1 wrote:
> Nit: Same here;  put "Sent first ..." or "Sent last ...."

Done.

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/video_coding/j...
File webrtc/modules/video_coding/jitter_buffer.cc (right):

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/video_coding/j...
webrtc/modules/video_coding/jitter_buffer.cc:1247: LOG(LS_INFO) << "First
completed key frame received";
On 2016/03/05 01:17:05, pthatcher1 wrote:
> Nit: And here: "Received first ..."

Done.

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/video_coding/v...
File webrtc/modules/video_coding/video_receiver.cc (right):

https://codereview.webrtc.org/1765443002/diff/1/webrtc/modules/video_coding/v...
webrtc/modules/video_coding/video_receiver.cc:318: (frame->Complete() ? "true" :
"false");
On 2016/03/05 01:17:05, pthatcher1 wrote:
> And here :) "Received first ...

Done.

[skvlad, 2016-03-08 23:57:35]

Please take a look when you have time. This is just a logging change, it
shouldn't take more than a few minutes to review. Thanks!

[mflodman, 2016-03-15 11:05:46]

Sorry for the late review, I missed this coming back from my vacation.

https://codereview.webrtc.org/1765443002/diff/20001/webrtc/modules/rtp_rtcp/s...
File webrtc/modules/rtp_rtcp/source/rtp_receiver_impl.cc (right):

https://codereview.webrtc.org/1765443002/diff/20001/webrtc/modules/rtp_rtcp/s...
webrtc/modules/rtp_rtcp/source/rtp_receiver_impl.cc:230: if
(is_first_packet_in_first_frame) {
I'd prefer to put this logic in RTPReceiver[Audio/Video]::ParseRtpPacket and
avoid adding is_audio_ to this class.

[pthatcher1, 2016-03-15 16:44:30]

https://codereview.webrtc.org/1765443002/diff/20001/webrtc/modules/rtp_rtcp/s...
File webrtc/modules/rtp_rtcp/source/rtp_receiver_impl.cc (right):

https://codereview.webrtc.org/1765443002/diff/20001/webrtc/modules/rtp_rtcp/s...
webrtc/modules/rtp_rtcp/source/rtp_receiver_impl.cc:230: if
(is_first_packet_in_first_frame) {
On 2016/03/15 11:05:45, mflodman wrote:
> I'd prefer to put this logic in RTPReceiver[Audio/Video]::ParseRtpPacket and
> avoid adding is_audio_ to this class.

I think it's strange that a parse method would modify state, but looking at the
code, it seems like these methods are more like "ProcessRtpPacket", since they
do more than just parse.

Note that we'll also have to add some state in the RTPRecieverAudio/Video to
keep track if it's seen a packet or not (like the last_receive_time_) is being
used here.

[skvlad, 2016-03-16 02:05:56]

Moved logging of the first received packet from RtpReceiverImpl to
RtpReceiver[Audio|Video] per mflodman's suggestion.

https://codereview.webrtc.org/1765443002/diff/20001/webrtc/modules/rtp_rtcp/s...
File webrtc/modules/rtp_rtcp/source/rtp_receiver_impl.cc (right):

https://codereview.webrtc.org/1765443002/diff/20001/webrtc/modules/rtp_rtcp/s...
webrtc/modules/rtp_rtcp/source/rtp_receiver_impl.cc:230: if
(is_first_packet_in_first_frame) {
On 2016/03/15 11:05:45, mflodman wrote:
> I'd prefer to put this logic in RTPReceiver[Audio/Video]::ParseRtpPacket and
> avoid adding is_audio_ to this class.

Done.

[pthatcher1, 2016-03-16 04:55:27]

https://codereview.webrtc.org/1765443002/diff/40001/webrtc/modules/rtp_rtcp/s...
File webrtc/modules/rtp_rtcp/source/rtp_receiver_video.h (right):

https://codereview.webrtc.org/1765443002/diff/40001/webrtc/modules/rtp_rtcp/s...
webrtc/modules/rtp_rtcp/source/rtp_receiver_video.h:59: bool
first_packet_received_ = false;
Strange indentation

https://codereview.webrtc.org/1765443002/diff/40001/webrtc/modules/rtp_rtcp/s...
File webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc (right):

https://codereview.webrtc.org/1765443002/diff/40001/webrtc/modules/rtp_rtcp/s...
webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc:352: if (_firstPacketSent) {
Should this be if(!_firstPacketSent) ?

[mflodman, 2016-03-16 14:30:54]

https://codereview.webrtc.org/1765443002/diff/20001/webrtc/modules/rtp_rtcp/s...
File webrtc/modules/rtp_rtcp/source/rtp_receiver_impl.cc (right):

https://codereview.webrtc.org/1765443002/diff/20001/webrtc/modules/rtp_rtcp/s...
webrtc/modules/rtp_rtcp/source/rtp_receiver_impl.cc:230: if
(is_first_packet_in_first_frame) {
On 2016/03/15 16:44:30, pthatcher1 wrote:
> On 2016/03/15 11:05:45, mflodman wrote:
> > I'd prefer to put this logic in RTPReceiver[Audio/Video]::ParseRtpPacket and
> > avoid adding is_audio_ to this class.
> 
> I think it's strange that a parse method would modify state, but looking at
the
> code, it seems like these methods are more like "ProcessRtpPacket", since they
> do more than just parse.
> 
> Note that we'll also have to add some state in the RTPRecieverAudio/Video to
> keep track if it's seen a packet or not (like the last_receive_time_) is being
> used here.

True, but I do prefer that over adding back a audio/video state in this class.

https://codereview.webrtc.org/1765443002/diff/40001/webrtc/modules/rtp_rtcp/s...
File webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc (right):

https://codereview.webrtc.org/1765443002/diff/40001/webrtc/modules/rtp_rtcp/s...
webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc:352: if (_firstPacketSent) {
On 2016/03/16 04:55:27, pthatcher1 wrote:
> Should this be if(!_firstPacketSent) ?

Yes.

[pbos-webrtc, 2016-03-16 14:36:14]

pbos@webrtc.org changed reviewers:
+ pbos@webrtc.org

[pbos-webrtc, 2016-03-16 14:36:15]

Is this something that we need submitted? I'm thinking better points to log are
when we get audio into libjingle, when the first corresponding packet is sent
onto the network (per SSRC in libjingle). It'd also make more sense to me to log
when we first render audio. Not these in-between points somewhere in the middle
of the stack.

These look too much like local printf hacks that you do when debugging locally,
and that usually doesn't get upstreamed. Also whenever we recreate a
VideoSendStream/VideoReceiveStream, which we do when some extensions change etc.
then we'll get new logs. If we have multiple streams we won't be able to tie
these logs back to the SSRCs sent on.

[pthatcher1, 2016-03-16 15:06:56]

On 2016/03/16 14:36:15, pbos-webrtc wrote:
> Is this something that we need submitted? 

Yes, this is the most important information we are lacking right now to know
what is taking so long to send/recv the first media.
 
> I'm thinking better points to log are when we get audio into libjingle, 

We have a long list of timestamps we want to record.  This is just the first of
many.  Right now we're focusing on video.  Audio will come later.

> when the first corresponding packet is sent onto the network (per SSRC in
libjingle). 

We don't really care about per-SSRC information.  I don't see how that would
help with our investigation.   

> It'd also make more sense to me to log when we first render audio. 
> Not these in-between points somewhere in the middle of the stack.

Audio will come later, and so will other points.  But we want all the points,
and these are the most critical to our investigation right now.

> 
> These look too much like local printf hacks that you do when debugging
locally,
> and that usually doesn't get upstreamed. 

We'll later add a more sophisticated metric system, but we need something sooner
than that, and we also need to know which points in time are most relevant to be
used in the more sophisticated system later.  

> Also whenever we recreate a VideoSendStream/VideoReceiveStream, which we do
when some extensions change etc.
> then we'll get new logs. 

Hmm.... that's a good point, and it would be nice to avoid that.  Do you have
any ideas for how to avoid that problem?  Can we carry some state from one
stream to another when it's recreated?

> If we have multiple streams we won't be able to tie
> these logs back to the SSRCs sent on.

That's not really relevant to our investigation right now.  And I don't think it
ever would be, really.  Even if we had multiple incoming streams, we'd still
only care about when we got the first video frame.

[skvlad, 2016-03-16 19:07:04]

Fixed the inverted if condition (if (!_firstPacketSent))

https://codereview.webrtc.org/1765443002/diff/40001/webrtc/modules/rtp_rtcp/s...
File webrtc/modules/rtp_rtcp/source/rtp_receiver_video.h (right):

https://codereview.webrtc.org/1765443002/diff/40001/webrtc/modules/rtp_rtcp/s...
webrtc/modules/rtp_rtcp/source/rtp_receiver_video.h:59: bool
first_packet_received_ = false;
On 2016/03/16 04:55:27, pthatcher1 wrote:
> Strange indentation
Are you talking about the single space before "private"? If so - this is how it
seems to be across most of the codebase.

https://codereview.webrtc.org/1765443002/diff/40001/webrtc/modules/rtp_rtcp/s...
File webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc (right):

https://codereview.webrtc.org/1765443002/diff/40001/webrtc/modules/rtp_rtcp/s...
webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc:352: if (_firstPacketSent) {
On 2016/03/16 14:30:54, mflodman wrote:
> On 2016/03/16 04:55:27, pthatcher1 wrote:
> > Should this be if(!_firstPacketSent) ?
> 
> Yes.

Good catch, fixed!

[pthatcher1, 2016-03-16 19:17:26]

lgtm

https://codereview.webrtc.org/1765443002/diff/40001/webrtc/modules/rtp_rtcp/s...
File webrtc/modules/rtp_rtcp/source/rtp_receiver_video.h (right):

https://codereview.webrtc.org/1765443002/diff/40001/webrtc/modules/rtp_rtcp/s...
webrtc/modules/rtp_rtcp/source/rtp_receiver_video.h:59: bool
first_packet_received_ = false;
On 2016/03/16 19:07:04, skvlad wrote:
> On 2016/03/16 04:55:27, pthatcher1 wrote:
> > Strange indentation
> Are you talking about the single space before "private"? If so - this is how
it
> seems to be across most of the codebase.

Oh, you're right.  I guess I'm not used to seeing the *first* member variable
added :).

[skvlad, 2016-03-24 00:47:10]

I've introduced a small helper class (webrtc::OneTimeEvent) to simplify the
logic of logging something the first time it happens.
As for the placement of these log statements - this seems to be the minimally
invasive way to capture these events as soon as we know they happened. Here are
some more approaches we considered, and why they seemed suboptimal:
 1. Add an "event listener" interface and use it to report events - the
reference to the listener would have to be made available to every class that
needs to report events. This would require changing a lot of unrelated code just
to pass the reference down.
 2. Capture the timestamp the packet arrived, and carry it along with the
packets as they go through the pipeline, get placed into the jitter buffer,
assembled into frames, etc. - this requires changing even more code and adds the
overhead of tracking history of every packet when we really only need 2 or 3.
 3. Do something similar to #2 in reverse in the send path - record a timestamp
the frame was captured, encoded, etc. - and carry this along with every packet
of that frame; report the timestamps when the packet is finally passed to the OS
for transmission. While this would give us very detailed history of every
packet, it also requires changing a lot of code and introduces overhead when we
don't need it.

In contrast, this change touches the smallest amount of code while giving us a
view into the first few milliseconds of call setup.


Please take a look and share your feedback.
Thanks!

[skvlad, 2016-03-24 00:48:50]

skvlad@webrtc.org changed reviewers:
+ pbos-webrtc; kjellander@webrtc.org
- pbos@webrtc.org

[skvlad, 2016-03-24 00:48:51]

Added kjellander@ to take a look at the .gn file.

[pthatcher1, 2016-03-25 22:35:23]

I like the use of OneTimeEvent.

https://codereview.webrtc.org/1765443002/diff/80001/webrtc/base/onetimeevent.h
File webrtc/base/onetimeevent.h (right):

https://codereview.webrtc.org/1765443002/diff/80001/webrtc/base/onetimeevent....
webrtc/base/onetimeevent.h:32: rtc::CritScope cs(&critsect_);
Would it make sense to allow the OneTimeEvent to choose whether it's thread-safe
or not?  I'm guessing many won't need to be.

And to be extra explicit, we could have a separate class called
ThreadUnsafeOneTimeEvent or something like that.

https://codereview.webrtc.org/1765443002/diff/80001/webrtc/base/onetimeevent....
webrtc/base/onetimeevent.h:35: return first_time;
Might be a little more clear as:

if (happened_) {
  return false;
}
happend_ = true;
return true;

https://codereview.webrtc.org/1765443002/diff/80001/webrtc/modules/rtp_rtcp/s...
File webrtc/modules/rtp_rtcp/source/rtp_receiver_audio.h (right):

https://codereview.webrtc.org/1765443002/diff/80001/webrtc/modules/rtp_rtcp/s...
webrtc/modules/rtp_rtcp/source/rtp_receiver_audio.h:125: OneTimeEvent
first_packet_received_;
This one could be thread-unsafe, right?

https://codereview.webrtc.org/1765443002/diff/80001/webrtc/modules/rtp_rtcp/s...
File webrtc/modules/rtp_rtcp/source/rtp_sender_audio.h (right):

https://codereview.webrtc.org/1765443002/diff/80001/webrtc/modules/rtp_rtcp/s...
webrtc/modules/rtp_rtcp/source/rtp_sender_audio.h:104: OneTimeEvent
first_packet_sent_;
But I'm guessing this one needs to be thread-safe.

[skvlad, 2016-03-26 02:00:08]

I've added the non-thread-safe version of OneTimeEvent. Please take a look.

https://codereview.webrtc.org/1765443002/diff/80001/webrtc/base/onetimeevent.h
File webrtc/base/onetimeevent.h (right):

https://codereview.webrtc.org/1765443002/diff/80001/webrtc/base/onetimeevent....
webrtc/base/onetimeevent.h:32: rtc::CritScope cs(&critsect_);
On 2016/03/25 22:35:22, pthatcher1 wrote:
> Would it make sense to allow the OneTimeEvent to choose whether it's
thread-safe
> or not?  I'm guessing many won't need to be.
> 
> And to be extra explicit, we could have a separate class called
> ThreadUnsafeOneTimeEvent or something like that.

I've added the thread-unsafe version, however, out of the 5 usages in this CL
(audio/video RTP senders/receivers and VideoReceiver) only one (the
VideoReceiver) is accessing the event while holding a critical section and
therefore can use the thread-unsafe version.

https://codereview.webrtc.org/1765443002/diff/80001/webrtc/base/onetimeevent....
webrtc/base/onetimeevent.h:35: return first_time;
On 2016/03/25 22:35:23, pthatcher1 wrote:
> Might be a little more clear as:
> 
> if (happened_) {
>   return false;
> }
> happend_ = true;
> return true;

Done.

https://codereview.webrtc.org/1765443002/diff/80001/webrtc/modules/rtp_rtcp/s...
File webrtc/modules/rtp_rtcp/source/rtp_receiver_audio.h (right):

https://codereview.webrtc.org/1765443002/diff/80001/webrtc/modules/rtp_rtcp/s...
webrtc/modules/rtp_rtcp/source/rtp_receiver_audio.h:125: OneTimeEvent
first_packet_received_;
On 2016/03/25 22:35:23, pthatcher1 wrote:
> This one could be thread-unsafe, right?

Looks like it cannot be - from the looks of it, the RTPReceiverStrategy objects
can be called from multiple threads, and the ParseRtpPacket for the audio
receiver does not take a lock. So this event should be the thread safe version.
Since it's doing something relatively unimportant - just logging - it might make
sense to just use a volatile variable, but it's unlikely to give noticeable
performance improvements as the incoming packet code path is already taking a
large number of locks.

https://codereview.webrtc.org/1765443002/diff/80001/webrtc/modules/rtp_rtcp/s...
File webrtc/modules/rtp_rtcp/source/rtp_sender_audio.h (right):

https://codereview.webrtc.org/1765443002/diff/80001/webrtc/modules/rtp_rtcp/s...
webrtc/modules/rtp_rtcp/source/rtp_sender_audio.h:104: OneTimeEvent
first_packet_sent_;
On 2016/03/25 22:35:23, pthatcher1 wrote:
> But I'm guessing this one needs to be thread-safe.

I think it does, too.

https://codereview.webrtc.org/1765443002/diff/80001/webrtc/modules/video_codi...
File webrtc/modules/video_coding/video_receiver.cc (right):

https://codereview.webrtc.org/1765443002/diff/80001/webrtc/modules/video_codi...
webrtc/modules/video_coding/video_receiver.cc:327: if (first_frame_received_())
{
This is the only place in this CL where the OneTimeEvent is accessed while
holding a critical section, and where the thread-unsafe version can be used.

[pthatcher1, 2016-03-28 16:33:48]

lgtm

https://codereview.webrtc.org/1765443002/diff/100001/webrtc/base/onetimeevent.h
File webrtc/base/onetimeevent.h (right):

https://codereview.webrtc.org/1765443002/diff/100001/webrtc/base/onetimeevent...
webrtc/base/onetimeevent.h:37: }
Is it worth writing a small unit test for these?

[kjellander_webrtc, 2016-03-29 08:32:12]

kjellander@webrtc.org changed reviewers:
+ kjellander@webrtc.org

[kjellander_webrtc, 2016-03-29 08:32:13]

https://codereview.webrtc.org/1765443002/diff/100001/webrtc/base/BUILD.gn
File webrtc/base/BUILD.gn (right):

https://codereview.webrtc.org/1765443002/diff/100001/webrtc/base/BUILD.gn#new...
webrtc/base/BUILD.gn:273: "onetimeevent.h",
The source files that use this header belong to target that don't depend on
rtc_base (they indirectly depend on rtc_base_approved via system_wrappers).
Please move this to the rtc_base_approved target instead (applies to the
base.gyp as well).

[skvlad, 2016-03-30 23:06:08]

Moved the header into the correct target (rtc_base_approved); added a unit test
for OneTimeEvent.

https://codereview.webrtc.org/1765443002/diff/100001/webrtc/base/BUILD.gn
File webrtc/base/BUILD.gn (right):

https://codereview.webrtc.org/1765443002/diff/100001/webrtc/base/BUILD.gn#new...
webrtc/base/BUILD.gn:273: "onetimeevent.h",
On 2016/03/29 08:32:13, kjellander (webrtc) wrote:
> The source files that use this header belong to target that don't depend on
> rtc_base (they indirectly depend on rtc_base_approved via system_wrappers).
> Please move this to the rtc_base_approved target instead (applies to the
> base.gyp as well).

Done.

https://codereview.webrtc.org/1765443002/diff/100001/webrtc/base/onetimeevent.h
File webrtc/base/onetimeevent.h (right):

https://codereview.webrtc.org/1765443002/diff/100001/webrtc/base/onetimeevent...
webrtc/base/onetimeevent.h:37: }
On 2016/03/28 16:33:48, pthatcher1 wrote:
> Is it worth writing a small unit test for these?

Done.

[pthatcher1, 2016-03-30 23:20:33]

lgtm

https://codereview.webrtc.org/1765443002/diff/120001/nohup.out
File nohup.out (right):

https://codereview.webrtc.org/1765443002/diff/120001/nohup.out#newcode5
nohup.out:5: New clock: GstSystemClock
What's this?

[kjellander_webrtc, 2016-03-31 05:52:55]

*.gn and *.gyp: lgtm

[skvlad, 2016-04-04 21:06:40]

skvlad@webrtc.org changed reviewers:
+ asapersson@webrtc.org, henrik.lundin@webrtc.org

[skvlad, 2016-04-04 21:06:41]

modules/rtp_rtcp and modules/video_coding owners, please take a look.

[skvlad, 2016-04-07 00:52:47]

Ping, please take a quick look when you have a few minutes. It's just a logging
change, but it's important to help troubleshoot slow call setup in applications.

[stefan-webrtc, 2016-04-07 08:57:36]

lgtm

https://codereview.webrtc.org/1765443002/diff/140001/webrtc/modules/rtp_rtcp/...
File webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc (right):

https://codereview.webrtc.org/1765443002/diff/140001/webrtc/modules/rtp_rtcp/...
webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc:353: int32_t sendResult =
_rtpSender->SendToNetwork(
send_result

https://codereview.webrtc.org/1765443002/diff/140001/webrtc/modules/rtp_rtcp/...
webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc:358: LOG(LS_INFO) << "First
audio RTP packet sent";
"sent to pacer" is a better description.

https://codereview.webrtc.org/1765443002/diff/140001/webrtc/modules/video_cod...
File webrtc/modules/video_coding/video_receiver.cc (right):

https://codereview.webrtc.org/1765443002/diff/140001/webrtc/modules/video_cod...
webrtc/modules/video_coding/video_receiver.cc:329: << (frame->Complete() ?
"true" : "false");
Maybe:
"Received first decodable video frame, " << (frame->Complete() ? "complete" :
"incomplete");

[skvlad, 2016-04-07 21:36:34]

https://codereview.webrtc.org/1765443002/diff/140001/webrtc/modules/rtp_rtcp/...
File webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc (right):

https://codereview.webrtc.org/1765443002/diff/140001/webrtc/modules/rtp_rtcp/...
webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc:353: int32_t sendResult =
_rtpSender->SendToNetwork(
On 2016/04/07 08:57:36, stefan-webrtc (holmer) wrote:
> send_result

Done. The rest of the function seems to use camelCased variable names though.

https://codereview.webrtc.org/1765443002/diff/140001/webrtc/modules/rtp_rtcp/...
webrtc/modules/rtp_rtcp/source/rtp_sender_audio.cc:358: LOG(LS_INFO) << "First
audio RTP packet sent";
On 2016/04/07 08:57:36, stefan-webrtc (holmer) wrote:
> "sent to pacer" is a better description.

Done.

https://codereview.webrtc.org/1765443002/diff/140001/webrtc/modules/video_cod...
File webrtc/modules/video_coding/video_receiver.cc (right):

https://codereview.webrtc.org/1765443002/diff/140001/webrtc/modules/video_cod...
webrtc/modules/video_coding/video_receiver.cc:329: << (frame->Complete() ?
"true" : "false");
On 2016/04/07 08:57:36, stefan-webrtc (holmer) wrote:
> Maybe:
> "Received first decodable video frame, " << (frame->Complete() ? "complete" :
> "incomplete");

Done.

[skvlad, 2016-04-07 21:38:45]

The CQ bit was checked by skvlad@webrtc.org

[skvlad, 2016-04-07 21:38:46]

The patchset sent to the CQ was uploaded after l-g-t-m from
pthatcher@webrtc.org, stefan@webrtc.org, kjellander@webrtc.org
Link to the patchset: https://codereview.webrtc.org/1765443002/#ps160001 (title:
"Corrected naming")

[commit-bot: I haz the power, 2016-04-07 21:38:55]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1765443002/160001
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1765443002/160001

[commit-bot: I haz the power, 2016-04-07 22:36:49]

Committed patchset #9 (id:160001)

[commit-bot: I haz the power, 2016-04-07 22:36:58]

Description was changed from

==========
Added log messages for some important call setup events:

 - First audio RTP packet sent / received
 - First RTP packet of the first video frame sent / received
 - Last RTP packet of the first video frame sent / received
These timestamps should make it easier to measure how fast the call
becomes established from the user's perspective.
==========

to

==========
Added log messages for some important call setup events:

 - First audio RTP packet sent / received
 - First RTP packet of the first video frame sent / received
 - Last RTP packet of the first video frame sent / received
These timestamps should make it easier to measure how fast the call
becomes established from the user's perspective.

Committed: https://crrev.com/98bb6640d22e9fe03696054b5e054f174db7739f
Cr-Commit-Position: refs/heads/master@{#12287}
==========

[commit-bot: I haz the power, 2016-04-07 22:37:00]

Patchset 9 (id:??) landed as
https://crrev.com/98bb6640d22e9fe03696054b5e054f174db7739f
Cr-Commit-Position: refs/heads/master@{#12287}