Cast: Provide more meaningful stats.

Cast: Provide more meaningful stats.

- Instead of giving generic stats for each event type,
  StatsEventSubsriber will now provide more specific stats. It also
  provide new kinds of stats (packet loss %, latency)
- stats_util to convert output of StatsEventSubscriber to a
  base::DictionaryValue is moved into the subscriber implementation.
- Introduced ReceiverTimeOffsetEstimator to estimate receiver offset
  based on raw events received. It is used by StatsEventSubscriber to
  determine stats such as latency. The estimator itself is implemented
  as a RawEventSubscriber and is shared between the audio and video
  StatsEventSubscriber objects.
- Move stats related structs from logging_defines.{cc,h} into
  stats_event_subscriber.{cc,h}
BUG=353019
Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=266574

[imcheng, 2014-04-12 00:28:21]

Yuri / Hubbe, please review. This is a large patch but a lot of it are moving
existing code around and tests. The main parts to pay attention are
StatsEventSubscriber implementation and ReceiverTimeOffsetEstimatorImpl.

Thanks!

[hubbe, 2014-04-15 00:23:22]

A few initial comments..

https://codereview.chromium.org/236123003/diff/20001/chrome/renderer/media/ca...
File chrome/renderer/media/cast_session_delegate.h (right):

https://codereview.chromium.org/236123003/diff/20001/chrome/renderer/media/ca...
chrome/renderer/media/cast_session_delegate.h:113:
scoped_ptr<media::cast::ReceiverTimeOffsetEstimator>
Why a scoped_ptr? why not just put the object here?

https://codereview.chromium.org/236123003/diff/20001/media/cast/logging/recei...
File media/cast/logging/receiver_time_offset_estimator_impl.h (right):

https://codereview.chromium.org/236123003/diff/20001/media/cast/logging/recei...
media/cast/logging/receiver_time_offset_estimator_impl.h:25: class
ReceiverTimeOffsetEstimatorImpl : public ReceiverTimeOffsetEstimator {
Why do you have a ReceiveTimeOffsetEstimator and a
ReceiverTimeOffsetEstimatorImpl?  Do we really need this level of abstraction?

https://codereview.chromium.org/236123003/diff/20001/media/cast/logging/stats...
File media/cast/logging/stats_event_subscriber.cc (right):

https://codereview.chromium.org/236123003/diff/20001/media/cast/logging/stats...
media/cast/logging/stats_event_subscriber.cc:25: CastLoggingEvent
GetCapturedEvent(EventMediaType media_type) {
Ouch, this level of repetition hurts my brain.

[imcheng, 2014-04-15 01:18:35]

https://codereview.chromium.org/236123003/diff/20001/chrome/renderer/media/ca...
File chrome/renderer/media/cast_session_delegate.h (right):

https://codereview.chromium.org/236123003/diff/20001/chrome/renderer/media/ca...
chrome/renderer/media/cast_session_delegate.h:113:
scoped_ptr<media::cast::ReceiverTimeOffsetEstimator>
On 2014/04/15 00:23:22, hubbe wrote:
> Why a scoped_ptr? why not just put the object here?

We don't need this object if logging is turned off.

https://codereview.chromium.org/236123003/diff/20001/media/cast/logging/recei...
File media/cast/logging/receiver_time_offset_estimator_impl.h (right):

https://codereview.chromium.org/236123003/diff/20001/media/cast/logging/recei...
media/cast/logging/receiver_time_offset_estimator_impl.h:25: class
ReceiverTimeOffsetEstimatorImpl : public ReceiverTimeOffsetEstimator {
On 2014/04/15 00:23:22, hubbe wrote:
> Why do you have a ReceiveTimeOffsetEstimator and a
> ReceiverTimeOffsetEstimatorImpl?  Do we really need this level of abstraction?

It makes testing of StatsEventSubscriber easier because I don't have to insert
just the right events to the estimator to obtain the desired offset. I also
don't want to expose a SetXXXForTest method in the impl class.

https://codereview.chromium.org/236123003/diff/20001/media/cast/logging/stats...
File media/cast/logging/stats_event_subscriber.cc (right):

https://codereview.chromium.org/236123003/diff/20001/media/cast/logging/stats...
media/cast/logging/stats_event_subscriber.cc:25: CastLoggingEvent
GetCapturedEvent(EventMediaType media_type) {
On 2014/04/15 00:23:22, hubbe wrote:
> Ouch, this level of repetition hurts my brain.

I can't think of much that can be done here. This is because we split events
types into audio/video, and this class needs to work for either audio or video.
The duplication has to happen somewhere. I tried to make these functions take up
less space.

[imcheng, 2014-04-15 20:51:03]

Ping.

[miu, 2014-04-15 21:29:42]

Some intital comments.  I'll sit down with this tonight and review the rest.

https://codereview.chromium.org/236123003/diff/20001/media/cast/logging/stats...
File media/cast/logging/stats_event_subscriber.cc (right):

https://codereview.chromium.org/236123003/diff/20001/media/cast/logging/stats...
media/cast/logging/stats_event_subscriber.cc:25: CastLoggingEvent
GetCapturedEvent(EventMediaType media_type) {
On 2014/04/15 01:18:36, imcheng1 wrote:
> On 2014/04/15 00:23:22, hubbe wrote:
> > Ouch, this level of repetition hurts my brain.
> 
> I can't think of much that can be done here. This is because we split events
> types into audio/video, and this class needs to work for either audio or
video.
> The duplication has to happen somewhere. I tried to make these functions take
up
> less space.

Suggestion (you probably want to put this in the header file where the enums are
declared):

#define CAST_LOGGING_EVENT(which, media_type)  \
  ((media_type) == AUDIO_EVENT ? kAudio##which : kVideo##which)

Usage example (lines 115-120 become):

  if (type == CAST_LOGGING_EVENT(FrameCaptured, event_media_type_)) {
    it->second.min_delay = frame_event.delay_delta;
    RecordFrameCapturedTime(frame_event);
  } else if (type == CAST_LOGGING_EVENT(PlayoutDelay, event_media_type_)) {
    RecordE2ELatency(frame_event);
  }

https://codereview.chromium.org/236123003/diff/40001/chrome/renderer/media/ca...
File chrome/renderer/media/cast_session_delegate.cc (right):

https://codereview.chromium.org/236123003/diff/40001/chrome/renderer/media/ca...
chrome/renderer/media/cast_session_delegate.cc:153: if
(!receiver_offset_estimator_.get()) {
There's a huge amount of copy-and-paste going throughout CastSessionDelegate,
and especially in this method.  Each EventSubscriber is basically going through
the same steps.

Suggestion: Rather than five separate scoped_ptr<> members, can you just keep a
list<linked_ptr<Subscriber>>?  Then your code becomes:

if (enable) {
  DCHECK(event_subscribers_.empty());
  event_subscribers_.push_back(new FooSubscriber(...));
  event_subscribers_.push_back(new BarSubscriber(...));
  event_subscribers_.push_back(new BazSubscriber(...));
  event_subscribers_.push_back(new GlarfSubscriber(...));
  for (it = event_subscribers_.begin(); it != end(); ++it)
    cast_environment_->Logging()->AddRawEventSubscriber(it->get());
} else {
  for (it = event_subscribers_.begin(); it != end(); ++it)
    cast_environment_->Logging()-RemovedRawEventSubscriber(it->get());
  event_subscribers_.clear();
}

[miu, 2014-04-17 02:14:14]

Still haven't reviewed everything, but here are some more comments:

https://codereview.chromium.org/236123003/diff/40001/media/cast/logging/recei...
File media/cast/logging/receiver_time_offset_estimator.h (right):

https://codereview.chromium.org/236123003/diff/40001/media/cast/logging/recei...
media/cast/logging/receiver_time_offset_estimator.h:18: // This interface
listens to raw events to figure out the bounds for the
s/This interface listens to/An implementation of this interface listens to/

https://codereview.chromium.org/236123003/diff/40001/media/cast/logging/recei...
media/cast/logging/receiver_time_offset_estimator.h:23: // - Convert from
receiver to sender time: receiver offset value from receiver
s/receiver offset/subtract offset/

https://codereview.chromium.org/236123003/diff/40001/media/cast/logging/recei...
File media/cast/logging/receiver_time_offset_estimator_impl.cc (right):

https://codereview.chromium.org/236123003/diff/40001/media/cast/logging/recei...
media/cast/logging/receiver_time_offset_estimator_impl.cc:96: void
ReceiverTimeOffsetEstimatorImpl::OnReceivePacketEvent(
Seems like RawEventSubscriber should not declare any of its methods as pure
virtual.  Instead, it should provide empty virtual methods so that subclasses
don't have to override the useless parts of the interface.

https://codereview.chromium.org/236123003/diff/40001/media/cast/logging/recei...
media/cast/logging/receiver_time_offset_estimator_impl.cc:119: VLOG(2) << "Got
bogus offset bound values [" << lower_bound.InMilliseconds()
Not sure, but maybe you should add a NOTREACHED() statement here so that we
crash on debug builds?

https://codereview.chromium.org/236123003/diff/40001/media/cast/logging/recei...
File media/cast/logging/receiver_time_offset_estimator_impl.h (right):

https://codereview.chromium.org/236123003/diff/40001/media/cast/logging/recei...
media/cast/logging/receiver_time_offset_estimator_impl.h:31: //
RawReventSubscriber implementations.
Please fix typo.

https://codereview.chromium.org/236123003/diff/40001/media/cast/test/fake_rec...
File media/cast/test/fake_receiver_time_offset_estimator.h (right):

https://codereview.chromium.org/236123003/diff/40001/media/cast/test/fake_rec...
media/cast/test/fake_receiver_time_offset_estimator.h:36: base::TimeDelta
offset_;
const, since member is never changed.

https://codereview.chromium.org/236123003/diff/40001/media/cast/test/sender.cc
File media/cast/test/sender.cc (right):

https://codereview.chromium.org/236123003/diff/40001/media/cast/test/sender.c...
media/cast/test/sender.cc:380: bool compress,
Remove this argument if it is unused.  Or, did you not intend to change the call
to SerializeEvent() on line 390?

https://codereview.chromium.org/236123003/diff/40001/media/cast/test/sender.c...
media/cast/test/sender.cc:441: void WriteStats(
naming: This method does more than just write the stats.  Suggestion:
DestroySubscribersAndWriteStats()

[imcheng, 2014-04-17 19:19:05]

Thank you both for the review.

https://codereview.chromium.org/236123003/diff/20001/media/cast/logging/stats...
File media/cast/logging/stats_event_subscriber.cc (right):

https://codereview.chromium.org/236123003/diff/20001/media/cast/logging/stats...
media/cast/logging/stats_event_subscriber.cc:25: CastLoggingEvent
GetCapturedEvent(EventMediaType media_type) {
Honestly I am not a huge fan of macros in a situation like this. It makes the
code harder to read and search. It also places restriction on event type
namings. (e.g. there are events called kDuplicate{Audio,Video}PacketReceived
which the macro won't work for, but putting the {Audio,Video} in the front
sounds strange). 

I did turn these functions into a one-liner using ternary operator though. We
can move these helper functions into logging_defines.{cc,h} if needed.


On 2014/04/15 21:29:43, miu wrote:
> On 2014/04/15 01:18:36, imcheng1 wrote:
> > On 2014/04/15 00:23:22, hubbe wrote:
> > > Ouch, this level of repetition hurts my brain.
> > 
> > I can't think of much that can be done here. This is because we split events
> > types into audio/video, and this class needs to work for either audio or
> video.
> > The duplication has to happen somewhere. I tried to make these functions
take
> up
> > less space.
> 
> Suggestion (you probably want to put this in the header file where the enums
are
> declared):
> 
> #define CAST_LOGGING_EVENT(which, media_type)  \
>   ((media_type) == AUDIO_EVENT ? kAudio##which : kVideo##which)
> 
> Usage example (lines 115-120 become):
> 
>   if (type == CAST_LOGGING_EVENT(FrameCaptured, event_media_type_)) {
>     it->second.min_delay = frame_event.delay_delta;
>     RecordFrameCapturedTime(frame_event);
>   } else if (type == CAST_LOGGING_EVENT(PlayoutDelay, event_media_type_)) {
>     RecordE2ELatency(frame_event);
>   }
>

https://codereview.chromium.org/236123003/diff/40001/chrome/renderer/media/ca...
File chrome/renderer/media/cast_session_delegate.cc (right):

https://codereview.chromium.org/236123003/diff/40001/chrome/renderer/media/ca...
chrome/renderer/media/cast_session_delegate.cc:153: if
(!receiver_offset_estimator_.get()) {
Per offline discussion I am defining a new struct to bundle the subscribers
together. But since we support switching on/off logging by stream, we have 2
sub-bundles. I am going to use a map from bool to sub-bundles to reduce some
code duplication (as opposed to "if(is_audio) ... else ..."). If we do support
more than 2 streams later, it will not be hard to change the key from bool to
int (stream id).


On 2014/04/15 21:29:43, miu wrote:
> There's a huge amount of copy-and-paste going throughout CastSessionDelegate,
> and especially in this method.  Each EventSubscriber is basically going
through
> the same steps.
> 
> Suggestion: Rather than five separate scoped_ptr<> members, can you just keep
a
> list<linked_ptr<Subscriber>>?  Then your code becomes:
> 
> if (enable) {
>   DCHECK(event_subscribers_.empty());
>   event_subscribers_.push_back(new FooSubscriber(...));
>   event_subscribers_.push_back(new BarSubscriber(...));
>   event_subscribers_.push_back(new BazSubscriber(...));
>   event_subscribers_.push_back(new GlarfSubscriber(...));
>   for (it = event_subscribers_.begin(); it != end(); ++it)
>     cast_environment_->Logging()->AddRawEventSubscriber(it->get());
> } else {
>   for (it = event_subscribers_.begin(); it != end(); ++it)
>     cast_environment_->Logging()-RemovedRawEventSubscriber(it->get());
>   event_subscribers_.clear();
> }

https://codereview.chromium.org/236123003/diff/40001/media/cast/logging/recei...
File media/cast/logging/receiver_time_offset_estimator.h (right):

https://codereview.chromium.org/236123003/diff/40001/media/cast/logging/recei...
media/cast/logging/receiver_time_offset_estimator.h:18: // This interface
listens to raw events to figure out the bounds for the
On 2014/04/17 02:14:14, miu wrote:
> s/This interface listens to/An implementation of this interface listens to/

Done.

https://codereview.chromium.org/236123003/diff/40001/media/cast/logging/recei...
media/cast/logging/receiver_time_offset_estimator.h:23: // - Convert from
receiver to sender time: receiver offset value from receiver
On 2014/04/17 02:14:14, miu wrote:
> s/receiver offset/subtract offset/

Done.

https://codereview.chromium.org/236123003/diff/40001/media/cast/logging/recei...
File media/cast/logging/receiver_time_offset_estimator_impl.cc (right):

https://codereview.chromium.org/236123003/diff/40001/media/cast/logging/recei...
media/cast/logging/receiver_time_offset_estimator_impl.cc:96: void
ReceiverTimeOffsetEstimatorImpl::OnReceivePacketEvent(
On 2014/04/17 02:14:14, miu wrote:
> Seems like RawEventSubscriber should not declare any of its methods as pure
> virtual.  Instead, it should provide empty virtual methods so that subclasses
> don't have to override the useless parts of the interface.

That's a good idea.I will do that in a follow up CL.

https://codereview.chromium.org/236123003/diff/40001/media/cast/logging/recei...
media/cast/logging/receiver_time_offset_estimator_impl.cc:119: VLOG(2) << "Got
bogus offset bound values [" << lower_bound.InMilliseconds()
On 2014/04/17 02:14:14, miu wrote:
> Not sure, but maybe you should add a NOTREACHED() statement here so that we
> crash on debug builds?

I don't really trust these values completely. Since we have many data points, we
can probably afford to be more tolerant of errors and not crash here.

https://codereview.chromium.org/236123003/diff/40001/media/cast/logging/recei...
File media/cast/logging/receiver_time_offset_estimator_impl.h (right):

https://codereview.chromium.org/236123003/diff/40001/media/cast/logging/recei...
media/cast/logging/receiver_time_offset_estimator_impl.h:31: //
RawReventSubscriber implementations.
On 2014/04/17 02:14:14, miu wrote:
> Please fix typo.

Done.

https://codereview.chromium.org/236123003/diff/40001/media/cast/test/fake_rec...
File media/cast/test/fake_receiver_time_offset_estimator.h (right):

https://codereview.chromium.org/236123003/diff/40001/media/cast/test/fake_rec...
media/cast/test/fake_receiver_time_offset_estimator.h:36: base::TimeDelta
offset_;
On 2014/04/17 02:14:14, miu wrote:
> const, since member is never changed.

Done.

https://codereview.chromium.org/236123003/diff/40001/media/cast/test/sender.cc
File media/cast/test/sender.cc (right):

https://codereview.chromium.org/236123003/diff/40001/media/cast/test/sender.c...
media/cast/test/sender.cc:380: bool compress,
On 2014/04/17 02:14:14, miu wrote:
> Remove this argument if it is unused.  Or, did you not intend to change the
call
> to SerializeEvent() on line 390?

The arg has been removed in another CL.

https://codereview.chromium.org/236123003/diff/40001/media/cast/test/sender.c...
media/cast/test/sender.cc:441: void WriteStats(
On 2014/04/17 02:14:14, miu wrote:
> naming: This method does more than just write the stats.  Suggestion:
> DestroySubscribersAndWriteStats()

Done. Also renamed the method above.

[miu, 2014-04-18 00:02:02]

https://codereview.chromium.org/236123003/diff/20001/media/cast/logging/stats...
File media/cast/logging/stats_event_subscriber.cc (right):

https://codereview.chromium.org/236123003/diff/20001/media/cast/logging/stats...
media/cast/logging/stats_event_subscriber.cc:25: CastLoggingEvent
GetCapturedEvent(EventMediaType media_type) {
On 2014/04/17 19:19:06, imcheng1 wrote:
> Honestly I am not a huge fan of macros in a situation like this. It makes the
> code harder to read and search. It also places restriction on event type
> namings. (e.g. there are events called kDuplicate{Audio,Video}PacketReceived
> which the macro won't work for, but putting the {Audio,Video} in the front
> sounds strange). 
> 
> I did turn these functions into a one-liner using ternary operator though. We
> can move these helper functions into logging_defines.{cc,h} if needed.

Thinking about this some more, the real problem is that the CastLoggingEvent
enum shouldn't define the same events for audio and video.  There should be one
set of events, and then the stream ID used to differentiate between the logging
for the audio or video stream.

Oh well.  Leave it this way for now if you want, and hopefully we can get rid of
this when logging is per-stream rather than just the two-stream audio/video bool
paradigm.

https://codereview.chromium.org/236123003/diff/100001/chrome/renderer/media/c...
File chrome/renderer/media/cast_session_delegate.h (right):

https://codereview.chromium.org/236123003/diff/100001/chrome/renderer/media/c...
chrome/renderer/media/cast_session_delegate.h:46: class
RawEventSubscriberBundleForStream {
Have you considered declaring/defining these two new classes in files under
src/media/cast/logging?

https://codereview.chromium.org/236123003/diff/100001/chrome/renderer/media/c...
chrome/renderer/media/cast_session_delegate.h:46: class
RawEventSubscriberBundleForStream {
Need class comments: What are these being used for and by which other classes?

https://codereview.chromium.org/236123003/diff/100001/chrome/renderer/media/c...
chrome/renderer/media/cast_session_delegate.h:51: const
scoped_refptr<media::cast::CastEnvironment>& cast_environment);
nit: For consistency with a lot of the other cast code, please put
cast_environment as the first ctor argument).

https://codereview.chromium.org/236123003/diff/100001/chrome/renderer/media/c...
chrome/renderer/media/cast_session_delegate.h:57:
scoped_refptr<media::cast::CastEnvironment> cast_environment_;
const scoped_refptr<...>

https://codereview.chromium.org/236123003/diff/100001/chrome/renderer/media/c...
chrome/renderer/media/cast_session_delegate.h:64: RawEventSubscriberBundle(
Needs explicit keyword.

https://codereview.chromium.org/236123003/diff/100001/chrome/renderer/media/c...
chrome/renderer/media/cast_session_delegate.h:79:
scoped_refptr<media::cast::CastEnvironment> cast_environment_;
const

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/prot...
File media/cast/logging/proto/raw_events.proto (right):

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/prot...
media/cast/logging/proto/raw_events.proto:79: optional int64
reference_timestamp_ms_at_unix_epoch = 5;
For reasons given in my comments for stats_event_subscriber.h/.cc, I'm concerned
that the precision of all these time values is in milliseconds and not
microseconds.  Seems like we're throwing away significant precision here.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
File media/cast/logging/stats_event_subscriber.cc (right):

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:231:
static_cast<double>(total_network_latency_ms_) /
See comment in .h file, and change this line to:

  total_network_latency_.InMillisecondsF()

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:239:
static_cast<double>(total_e2e_latency_ms_) / e2e_latency_datapoints_;
total_e2e_latency_.InMillisecondsF()

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:245: (end_time -
last_response_received_time_).InMilliseconds()));
InMillisecondsF()

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:281: int64 e2e_latency_ms =
(playout_time - it->second).InMilliseconds();
Don't truncate to milliseconds here.  To maintain precision:

  const base::TimeDelta e2e_latency = playout_time - it->second;

Also, there are lots of instances of this throughout the rest of this file that
should be changed...

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:285: if (e2e_latency_ms <= 0)
It's debatable, but what happens if we let this bad data in?  We would just have
a bad average at the beginning of a Cast session, but later the average would
converge back to a good value.

My concern here comes from the fact that if there is a bug somewhere upstream,
we want to know we're getting bad data by seeing a bad average value come out in
the logs.

Out of curiosity, when is Reset() called?  If it's never called, perhaps the
running average should be limited to the last N samples (for some reasonable
value of N)?

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:314: base::TimeTicks
packet_sent_time;
nit: Remove this line, and declare on line 320 where it is initialized.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:330: if (latency_ms <= 0)
Ditto on <= 0 hack.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
File media/cast/logging/stats_event_subscriber.h (right):

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.h:89: AVG_ENCODE_TIME_MS,
Why not microseconds for all of these?  Or, let's be sure there isn't any
upstream or downstream code that will static_cast the values to an integer data
type blindly (e.g., for the protobufs).

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.h:105: PACKET_LOSS_PERCENTAGE,
Suggest you use fraction instead of percentage here (i.e., don't multiply values
by 100).  It's likely packet loss will be measured using the basis point scale
in a normal WiFi environment (I hope, for the sake of our users!).

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.h:119: // // Assigns |stats_map| with
stats data. Used for testing.
nit: Duplicate //

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.h:141: EventMediaType
event_media_type_;
const, please.  :)

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.h:145: int64
total_network_latency_ms_;
This member and total_e2e_latency_ms_ should be base::TimeDelta.  The code in
the .cc file is throwing away the sub-milliseconds component of time (which is
significant), and then accumulating the errors over several
RecordPacketSendTime() and RecordE2ELatency() calls.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.h:162: base::TickClock* clock_;
Since clock_ and offset_estimator_ are unchanging pointers, injected via the
ctor, could you make them const and move them up to just after event_media_type_
above?

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
File media/cast/logging/stats_event_subscriber_unittest.cc (right):

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber_unittest.cc:107:
static_cast<double>(num_frames) / duration.InMilliseconds() * 1000,
Use InMillisecondsF(), not InMilliseconds() throughout this file.  Then, you
should be able to use EXPECT_DOUBLE_EQ(expected, actual) instead of
EXPECT_NEAR() to test your code for numerical stability.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber_unittest.cc:403: 
Given the issues of precision found in the .cc file, I suggest you add some code
to these unit tests to confirm microsecond-level precision isn't thrown away
(e.g., use AdvanceClocks(base::TimeDelta::FromMicroseconds(12345)), and other
"random pick" values).

[imcheng, 2014-04-18 18:20:26]

https://codereview.chromium.org/236123003/diff/20001/media/cast/logging/stats...
File media/cast/logging/stats_event_subscriber.cc (right):

https://codereview.chromium.org/236123003/diff/20001/media/cast/logging/stats...
media/cast/logging/stats_event_subscriber.cc:25: CastLoggingEvent
GetCapturedEvent(EventMediaType media_type) {
Yes, it is unfortunate that we have split event types, which sort of led to this
situation. It is already baked into RTCP so it is used by receiver
implementations as well. Changing this will not be easy, we will probably have
to define new event types and deprecate existing ones.

On 2014/04/18 00:02:03, miu wrote:
> On 2014/04/17 19:19:06, imcheng1 wrote:
> > Honestly I am not a huge fan of macros in a situation like this. It makes
the
> > code harder to read and search. It also places restriction on event type
> > namings. (e.g. there are events called kDuplicate{Audio,Video}PacketReceived
> > which the macro won't work for, but putting the {Audio,Video} in the front
> > sounds strange). 
> > 
> > I did turn these functions into a one-liner using ternary operator though.
We
> > can move these helper functions into logging_defines.{cc,h} if needed.
> 
> Thinking about this some more, the real problem is that the CastLoggingEvent
> enum shouldn't define the same events for audio and video.  There should be
one
> set of events, and then the stream ID used to differentiate between the
logging
> for the audio or video stream.
> 
> Oh well.  Leave it this way for now if you want, and hopefully we can get rid
of
> this when logging is per-stream rather than just the two-stream audio/video
bool
> paradigm.

https://codereview.chromium.org/236123003/diff/100001/chrome/renderer/media/c...
File chrome/renderer/media/cast_session_delegate.h (right):

https://codereview.chromium.org/236123003/diff/100001/chrome/renderer/media/c...
chrome/renderer/media/cast_session_delegate.h:46: class
RawEventSubscriberBundleForStream {
On 2014/04/18 00:02:03, miu wrote:
> Have you considered declaring/defining these two new classes in files under
> src/media/cast/logging?

Done.

https://codereview.chromium.org/236123003/diff/100001/chrome/renderer/media/c...
chrome/renderer/media/cast_session_delegate.h:46: class
RawEventSubscriberBundleForStream {
On 2014/04/18 00:02:03, miu wrote:
> Need class comments: What are these being used for and by which other classes?

Done.

https://codereview.chromium.org/236123003/diff/100001/chrome/renderer/media/c...
chrome/renderer/media/cast_session_delegate.h:51: const
scoped_refptr<media::cast::CastEnvironment>& cast_environment);
On 2014/04/18 00:02:03, miu wrote:
> nit: For consistency with a lot of the other cast code, please put
> cast_environment as the first ctor argument).

Done.

https://codereview.chromium.org/236123003/diff/100001/chrome/renderer/media/c...
chrome/renderer/media/cast_session_delegate.h:57:
scoped_refptr<media::cast::CastEnvironment> cast_environment_;
On 2014/04/18 00:02:03, miu wrote:
> const scoped_refptr<...>

Done.

https://codereview.chromium.org/236123003/diff/100001/chrome/renderer/media/c...
chrome/renderer/media/cast_session_delegate.h:64: RawEventSubscriberBundle(
On 2014/04/18 00:02:03, miu wrote:
> Needs explicit keyword.

Done.

https://codereview.chromium.org/236123003/diff/100001/chrome/renderer/media/c...
chrome/renderer/media/cast_session_delegate.h:79:
scoped_refptr<media::cast::CastEnvironment> cast_environment_;
On 2014/04/18 00:02:03, miu wrote:
> const

Done.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/prot...
File media/cast/logging/proto/raw_events.proto (right):

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/prot...
media/cast/logging/proto/raw_events.proto:79: optional int64
reference_timestamp_ms_at_unix_epoch = 5;
On 2014/04/18 00:02:03, miu wrote:
> For reasons given in my comments for stats_event_subscriber.h/.cc, I'm
concerned
> that the precision of all these time values is in milliseconds and not
> microseconds.  Seems like we're throwing away significant precision here.

For raw events, we are sacrificing precision of timing of events in return for a
significant savings in space (30%) due to variable length encoding in proto and
possibly difference encoding achieving better results in the gzip algorithm. It
is a tradeoff I made in order to have more logs under the size limit.

When we start uploading stats, we can use it (which have better precision) to
complement the raw events in generating certain graphs / summary in the backend.
A frame-level timeline will use raw events and will have millisecond precision.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
File media/cast/logging/stats_event_subscriber.cc (right):

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:231:
static_cast<double>(total_network_latency_ms_) /
On 2014/04/18 00:02:03, miu wrote:
> See comment in .h file, and change this line to:
> 
>   total_network_latency_.InMillisecondsF()

Done.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:239:
static_cast<double>(total_e2e_latency_ms_) / e2e_latency_datapoints_;
On 2014/04/18 00:02:03, miu wrote:
> total_e2e_latency_.InMillisecondsF()

Done.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:245: (end_time -
last_response_received_time_).InMilliseconds()));
On 2014/04/18 00:02:03, miu wrote:
> InMillisecondsF()

Done.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:281: int64 e2e_latency_ms =
(playout_time - it->second).InMilliseconds();
On 2014/04/18 00:02:03, miu wrote:
> Don't truncate to milliseconds here.  To maintain precision:
> 
>   const base::TimeDelta e2e_latency = playout_time - it->second;
> 
> Also, there are lots of instances of this throughout the rest of this file
that
> should be changed...

You are right. I made this change and other similar changes to this file so that
it will try to keep base::TimeDelta as long as it can. And only use
InXXXSecondsF() unless I am trying to detect if I am dividing by 0 in which case
I will use InMicroseconds().

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:285: if (e2e_latency_ms <= 0)
On 2014/04/18 00:02:03, miu wrote:
> It's debatable, but what happens if we let this bad data in?  We would just
have
> a bad average at the beginning of a Cast session, but later the average would
> converge back to a good value.
> 
> My concern here comes from the fact that if there is a bug somewhere upstream,
> we want to know we're getting bad data by seeing a bad average value come out
in
> the logs.
> 

Ok, I think I agree with you that we should record the "bad" values. I have
removed the checks.


> Out of curiosity, when is Reset() called?  If it's never called, perhaps the
> running average should be limited to the last N samples (for some reasonable
> value of N)?

It is called in CastSessionDelegate, following a call to
StatsEventSubscriber::GetStats().

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:314: base::TimeTicks
packet_sent_time;
On 2014/04/18 00:02:03, miu wrote:
> nit: Remove this line, and declare on line 320 where it is initialized.

Done.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:330: if (latency_ms <= 0)
On 2014/04/18 00:02:03, miu wrote:
> Ditto on <= 0 hack.

Done.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
File media/cast/logging/stats_event_subscriber.h (right):

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.h:89: AVG_ENCODE_TIME_MS,
On 2014/04/18 00:02:03, miu wrote:
> Why not microseconds for all of these?  Or, let's be sure there isn't any
> upstream or downstream code that will static_cast the values to an integer
data
> type blindly (e.g., for the protobufs).

I made sure of the latter.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.h:105: PACKET_LOSS_PERCENTAGE,
On 2014/04/18 00:02:03, miu wrote:
> Suggest you use fraction instead of percentage here (i.e., don't multiply
values
> by 100).  It's likely packet loss will be measured using the basis point scale
> in a normal WiFi environment (I hope, for the sake of our users!).

Done.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.h:119: // // Assigns |stats_map| with
stats data. Used for testing.
On 2014/04/18 00:02:03, miu wrote:
> nit: Duplicate //

Done.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.h:141: EventMediaType
event_media_type_;
On 2014/04/18 00:02:03, miu wrote:
> const, please.  :)

Done.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.h:145: int64
total_network_latency_ms_;
On 2014/04/18 00:02:03, miu wrote:
> This member and total_e2e_latency_ms_ should be base::TimeDelta.  The code in
> the .cc file is throwing away the sub-milliseconds component of time (which is
> significant), and then accumulating the errors over several
> RecordPacketSendTime() and RecordE2ELatency() calls.

Good catch. Thanks.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.h:162: base::TickClock* clock_;
On 2014/04/18 00:02:03, miu wrote:
> Since clock_ and offset_estimator_ are unchanging pointers, injected via the
> ctor, could you make them const and move them up to just after
event_media_type_
> above?

Done.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
File media/cast/logging/stats_event_subscriber_unittest.cc (right):

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber_unittest.cc:107:
static_cast<double>(num_frames) / duration.InMilliseconds() * 1000,
On 2014/04/18 00:02:03, miu wrote:
> Use InMillisecondsF(), not InMilliseconds() throughout this file.  Then, you
> should be able to use EXPECT_DOUBLE_EQ(expected, actual) instead of
> EXPECT_NEAR() to test your code for numerical stability.

Done.

https://codereview.chromium.org/236123003/diff/100001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber_unittest.cc:403: 
On 2014/04/18 00:02:03, miu wrote:
> Given the issues of precision found in the .cc file, I suggest you add some
code
> to these unit tests to confirm microsecond-level precision isn't thrown away
> (e.g., use AdvanceClocks(base::TimeDelta::FromMicroseconds(12345)), and other
> "random pick" values).

I have converted all AdvanceClock args to have sub-milliseconds.

[imcheng, 2014-04-22 15:18:09]

Ping.

[imcheng, 2014-04-22 15:18:13]

Ping.

[imcheng, 2014-04-22 15:18:13]

Ping.

[imcheng, 2014-04-22 15:18:13]

Ping.

[imcheng, 2014-04-22 15:19:01]

Oops, sorry for the duplicate pings. Hit the space bar accidentally.

[miu, 2014-04-22 19:38:04]

lgtm

https://codereview.chromium.org/236123003/diff/120001/media/cast/logging/stat...
File media/cast/logging/stats_event_subscriber.cc (right):

https://codereview.chromium.org/236123003/diff/120001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:329: if (duration.InMicroseconds()
!= 0)
nit:

  if (duration > base::TimeDelta()) {

https://codereview.chromium.org/236123003/diff/120001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:355: if (duration.InMicroseconds()
!= 0) {
nit:

  if (duration > base::TimeDelta()) {

https://codereview.chromium.org/236123003/diff/120001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:372: if (duration.InMicroseconds()
!= 0) {
nit:

  if (duration > base::TimeDelta()) {

[imcheng, 2014-04-22 19:57:20]

The CQ bit was checked by imcheng@chromium.org

[imcheng, 2014-04-22 19:57:26]

https://codereview.chromium.org/236123003/diff/120001/media/cast/logging/stat...
File media/cast/logging/stats_event_subscriber.cc (right):

https://codereview.chromium.org/236123003/diff/120001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:329: if (duration.InMicroseconds()
!= 0)
On 2014/04/22 19:38:04, miu wrote:
> nit:
> 
>   if (duration > base::TimeDelta()) {

Done.

https://codereview.chromium.org/236123003/diff/120001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:355: if (duration.InMicroseconds()
!= 0) {
On 2014/04/22 19:38:04, miu wrote:
> nit:
> 
>   if (duration > base::TimeDelta()) {

Done.

https://codereview.chromium.org/236123003/diff/120001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:372: if (duration.InMicroseconds()
!= 0) {
On 2014/04/22 19:38:04, miu wrote:
> nit:
> 
>   if (duration > base::TimeDelta()) {

Done.

[commit-bot: I haz the power, 2014-04-22 19:58:26]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/imcheng@chromium.org/236123003/140001

[commit-bot: I haz the power, 2014-04-22 20:06:44]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2014-04-22 20:06:45]

Try jobs failed on following builders:
  tryserver.chromium on chromium_presubmit

[imcheng, 2014-04-22 20:52:49]

Hubbe, could you please take a look too?

[miu, 2014-04-23 02:20:18]

On 2014/04/22 20:52:49, imcheng1 wrote:
> Hubbe, could you please take a look too?

imcheng: FYI--You'll need to rebase (my change to consolidate all the Cast GYP
files just landed).

[hubbe, 2014-04-24 22:53:54]

LGTM + one optional comment and one FYI

https://codereview.chromium.org/236123003/diff/140001/media/cast/logging/stat...
File media/cast/logging/stats_event_subscriber.cc (right):

https://codereview.chromium.org/236123003/diff/140001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:25: CastLoggingEvent
GetCapturedEvent(EventMediaType media_type) {
I'll be happy when we can get rid of these. :)

https://codereview.chromium.org/236123003/diff/140001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:331:
stats_map->insert(std::make_pair(stat, fps));
Why not just (*stats_map)[stats] = fps; ?

[imcheng, 2014-04-25 15:35:43]

https://codereview.chromium.org/236123003/diff/140001/media/cast/logging/stat...
File media/cast/logging/stats_event_subscriber.cc (right):

https://codereview.chromium.org/236123003/diff/140001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:25: CastLoggingEvent
GetCapturedEvent(EventMediaType media_type) {
On 2014/04/24 22:53:54, hubbe wrote:
> I'll be happy when we can get rid of these. :)

ACK.

https://codereview.chromium.org/236123003/diff/140001/media/cast/logging/stat...
media/cast/logging/stats_event_subscriber.cc:331:
stats_map->insert(std::make_pair(stat, fps));
On 2014/04/24 22:53:54, hubbe wrote:
> Why not just (*stats_map)[stats] = fps; ?

insert is supposed to be more efficient than operator[] + operator= but in this
case it doesn't really matter. I guess I am just used to using insert() all the
time.

[imcheng, 2014-04-25 15:36:10]

The CQ bit was checked by imcheng@chromium.org

[commit-bot: I haz the power, 2014-04-25 17:54:35]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/imcheng@chromium.org/236123003/200001

[commit-bot: I haz the power, 2014-04-25 23:45:38]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2014-04-25 23:45:38]

Try jobs failed on following builders:
  tryserver.chromium on linux_chromium_rel

[imcheng, 2014-04-26 00:05:13]

The CQ bit was checked by imcheng@chromium.org

[commit-bot: I haz the power, 2014-04-26 00:07:51]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/imcheng@chromium.org/236123003/200001

[commit-bot: I haz the power, 2014-04-26 00:14:13]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2014-04-26 00:14:14]

Try jobs failed on following builders:
  tryserver.chromium on win_chromium_rel

[imcheng, 2014-04-28 00:31:44]

The CQ bit was checked by imcheng@chromium.org

[commit-bot: I haz the power, 2014-04-28 00:32:32]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/imcheng@chromium.org/236123003/220001

[commit-bot: I haz the power, 2014-04-28 01:17:10]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2014-04-28 01:17:11]

Try jobs failed on following builders:
  tryserver.chromium on chromium_presubmit

[imcheng, 2014-04-28 03:06:10]

The CQ bit was checked by imcheng@chromium.org

[commit-bot: I haz the power, 2014-04-28 03:06:34]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/imcheng@chromium.org/236123003/220001

[commit-bot: I haz the power, 2014-04-28 03:50:30]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2014-04-28 03:50:31]

Try jobs failed on following builders:
  tryserver.chromium on chromium_presubmit

[imcheng, 2014-04-28 14:56:50]

The CQ bit was checked by imcheng@chromium.org

[commit-bot: I haz the power, 2014-04-28 14:57:28]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/imcheng@chromium.org/236123003/220001

[commit-bot: I haz the power, 2014-04-28 15:29:04]

Change committed as 266574