Refactored CL for moving the output to a separate thread.

Refactored CL for moving the output to a separate thread.

The logging thread is always active. The main thread uses SwapQueues to pass events to the logging thread. The logging thread moves the events to either a RingBuffer history in memory, or to a string which is written to disc.

RtcEventLogImpl constructor takes a clock for easier testing.

BUG=webrtc:4741
Committed: https://crrev.com/4311ba59d8186400b892eafff2b71529a7e25a85
Cr-Commit-Position: refs/heads/master@{#12476}

[terelius, 2016-02-10 01:55:24]

Description was changed from

==========
Refactored CL for moving the output to a separate thread.

The logging thread is always active. The main thread uses SwapQueues to pass
events to the logging thread. The logging thread moves the events to either a
RingBuffer history in memory, or to a string which is written to disc.

RtcEventLogImpl constructor takes a clock for easier testing.

BUG=webrtc:4741
==========

to

==========
Refactored CL for moving the output to a separate thread.

The logging thread is always active. The main thread uses SwapQueues to pass
events to the logging thread. The logging thread moves the events to either a
RingBuffer history in memory, or to a string which is written to disc.

RtcEventLogImpl constructor takes a clock for easier testing.

BUG=webrtc:4741
==========

[terelius, 2016-02-10 01:55:24]

terelius@webrtc.org changed reviewers:
+ ivoc@webrtc.org, solenberg@webrtc.org, stefan@webrtc.org

[terelius, 2016-02-10 01:57:30]

Please take a look at this refactored CL.

[the sun, 2016-02-10 10:47:23]

Thanks for doing this, I think it is looking a lot better!

I have one bigger request, which is to pull out the logger thread state into its
own class, which would help unit testing and hopefully avoid all locking outside
of the SwapQueues.

Grab me if you want to discuss!

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log.cc
File webrtc/call/rtc_event_log.cc (right):

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:124: void LogToMemory()
EXCLUSIVE_LOCKS_REQUIRED(crit_);
To make things even clearer, the parts of this class that are only accessed from
the logging thread, could be pulled out into a separate class, in its separate
file.

class LoggerThread {
 public:
  LoggerThread(SwapQueue<rtclog::Event>* config_queue, SwapQueue<rtclog::Event>*
config_queue, ..., rtc::Event* file_finished_event);
...
then many fields could be tucked away in this class.

You could also make the state machine simpler by adding a
SwapQueue<MyMessageStruct> to the ctor, and pass state transitions in the queue
instead of synchronizing access to the state_ variable. The message struct could
be a proto buffer or just a simple struct/union (it would then be defined in
rtc_event_logger.h together with the state enum).

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:131: SwapQueue<rtclog::Event> config_buffer_;
I think it is better to call these config_queue_ etc.

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:162: bool valid_config_event_;
You may be able to avoid these by using rtc::Optional

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:733: switch (state_) {
Pull this switch out into a separate function of the suggested LoggerThread
class, and you can add unit tests for the logic!

[ivoc, 2016-02-10 13:07:54]

After scanning through the code and thinking about it for a while I have a few
general remarks about the new structure:

- I don't really understand why there are separate SwapQueues for the different
event types in the new setup. To me it would make more sense to put them all
onto one big queue, since they're now the same type anyway. This would have the
advantage that the logging would start at one single point in time, instead of
having different start times for each event type (depending on buffer size).

- I think it would make sense to add all state-changes as events on the queue,
for example when starting the log, just add a StartLogging event to the (single)
queue, so the thread can process all events and state changes chronologically.

[terelius, 2016-02-11 21:27:28]

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log.cc
File webrtc/call/rtc_event_log.cc (right):

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:124: void LogToMemory()
EXCLUSIVE_LOCKS_REQUIRED(crit_);
On 2016/02/10 10:47:23, the sun wrote:
> To make things even clearer, the parts of this class that are only accessed
from
> the logging thread, could be pulled out into a separate class, in its separate
> file.
> 
> class LoggerThread {
>  public:
>   LoggerThread(SwapQueue<rtclog::Event>* config_queue,
SwapQueue<rtclog::Event>*
> config_queue, ..., rtc::Event* file_finished_event);
> ...
> then many fields could be tucked away in this class.
> 
> You could also make the state machine simpler by adding a
> SwapQueue<MyMessageStruct> to the ctor, and pass state transitions in the
queue
> instead of synchronizing access to the state_ variable. The message struct
could
> be a proto buffer or just a simple struct/union (it would then be defined in
> rtc_event_logger.h together with the state enum).
> 

One side effect of moving the state to a separate class is that we would not be
able to know whether a call (e.g. StartLogging) has succeeded or not. We would
probably have to duplicate at least parts of the state in both the event log and
the new class.

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:131: SwapQueue<rtclog::Event> config_buffer_;
On 2016/02/10 10:47:23, the sun wrote:
> I think it is better to call these config_queue_ etc.

Done.

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:162: bool valid_config_event_;
On 2016/02/10 10:47:23, the sun wrote:
> You may be able to avoid these by using rtc::Optional

There are several reasons why Optional won't work. To begin with, although our
Optional always contains a value, the std::optional does not, so the code would
break if we move to std::optional in the future. Secondly, the normal access
functions actually check that has_value is set when you try to access the value.
In other words, you can't obtain a pointer to pass to the SwapQueue::Remove()
unless the has_value bit is set. Finally, there is no clean way to set or clear
the has_value bit, so we can't get the return value from Insert and Remove into
the Optional..

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:733: switch (state_) {
On 2016/02/10 10:47:23, the sun wrote:
> Pull this switch out into a separate function of the suggested LoggerThread
> class, and you can add unit tests for the logic!

I don't understand what logic you want to test. WriteLog() is just a simple
message loop that dispatches to the functions that do the actual work based on
the state of the log.

[terelius, 2016-02-11 22:05:38]

On 2016/02/10 13:07:54, ivoc wrote:
> After scanning through the code and thinking about it for a while I have a few
> general remarks about the new structure:
> 
> - I don't really understand why there are separate SwapQueues for the
different
> event types in the new setup. To me it would make more sense to put them all
> onto one big queue, since they're now the same type anyway. This would have
the
> advantage that the logging would start at one single point in time, instead of
> having different start times for each event type (depending on buffer size).

This CL is an attempt to break the change down into smaller pieces since the
full
thing turned out to be very difficult to land. However, this means that there
will be
some parts that aren't final yet.

Although we should move away from using protobuf events in memory (or switch
to a protobuf version that supports oneof) there is still some advantage to
having
several queues. Compared to having a single queue, we reduce lock contention if
different logging functions are called on different threads.

Regardless, the logging does start at a single point in time since the events
are
kept together in the history; it is just the "message queues" that are separated
based on event type.

> - I think it would make sense to add all state-changes as events on the queue,
> for example when starting the log, just add a StartLogging event to the
(single)
> queue, so the thread can process all events and state changes chronologically.

This might not be a good idea when we want to terminate the logging thread. We
need to close the file and make sure the logging thread doesn't try to access
the
event log after it has been destroyed, but we probably don't want to wait for
thread
to empty it's buffers.

[the sun, 2016-02-12 09:37:32]

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log.cc
File webrtc/call/rtc_event_log.cc (right):

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:124: void LogToMemory()
EXCLUSIVE_LOCKS_REQUIRED(crit_);
On 2016/02/11 21:27:28, terelius wrote:
> On 2016/02/10 10:47:23, the sun wrote:
> > To make things even clearer, the parts of this class that are only accessed
> from
> > the logging thread, could be pulled out into a separate class, in its
separate
> > file.
> > 
> > class LoggerThread {
> >  public:
> >   LoggerThread(SwapQueue<rtclog::Event>* config_queue,
> SwapQueue<rtclog::Event>*
> > config_queue, ..., rtc::Event* file_finished_event);
> > ...
> > then many fields could be tucked away in this class.
> > 
> > You could also make the state machine simpler by adding a
> > SwapQueue<MyMessageStruct> to the ctor, and pass state transitions in the
> queue
> > instead of synchronizing access to the state_ variable. The message struct
> could
> > be a proto buffer or just a simple struct/union (it would then be defined in
> > rtc_event_logger.h together with the state enum).
> > 
> 
> One side effect of moving the state to a separate class is that we would not
be
> able to know whether a call (e.g. StartLogging) has succeeded or not. We would
> probably have to duplicate at least parts of the state in both the event log
and
> the new class.

For StartLogging() it would likely make sense to open the output file in
RtcEventLogImpl and pass the file pointer to the thread class in the START_FILE
message. For StopLogging() my suggestion was to keep the event as now, to be
able to block until the whole buffer has been purged and the file closed (by the
logging thread). If you want more status information at that point, you could
use an event queue in the thread->rtceventlogimpl direction too.

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:733: switch (state_) {
On 2016/02/11 21:27:28, terelius wrote:
> On 2016/02/10 10:47:23, the sun wrote:
> > Pull this switch out into a separate function of the suggested LoggerThread
> > class, and you can add unit tests for the logic!
> 
> I don't understand what logic you want to test. WriteLog() is just a simple
> message loop that dispatches to the functions that do the actual work based on
> the state of the log.

I was thinking mostly about the stuff in the functions called from here, in
particular the transitive calls to ProcessInOrder().

More importantly though, by pulling the switch out (and using a message queue)
you can easily tailor test cases for different scenarios. 
1. log to memory, terminate thread
2. log to memory, log to file, terminate thread
3. log to memory, log to file, log to memory, terminate thread
...

The key is to make the logic testable in a reproducible and consistent manner
*without* threads or locks interfering.

[terelius, 2016-02-12 14:13:38]

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log.cc
File webrtc/call/rtc_event_log.cc (right):

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:124: void LogToMemory()
EXCLUSIVE_LOCKS_REQUIRED(crit_);
On 2016/02/12 09:37:32, the sun wrote:
> On 2016/02/11 21:27:28, terelius wrote:
> > On 2016/02/10 10:47:23, the sun wrote:
> > > To make things even clearer, the parts of this class that are only
accessed
> > from
> > > the logging thread, could be pulled out into a separate class, in its
> separate
> > > file.
> > > 
> > > class LoggerThread {
> > >  public:
> > >   LoggerThread(SwapQueue<rtclog::Event>* config_queue,
> > SwapQueue<rtclog::Event>*
> > > config_queue, ..., rtc::Event* file_finished_event);
> > > ...
> > > then many fields could be tucked away in this class.
> > > 
> > > You could also make the state machine simpler by adding a
> > > SwapQueue<MyMessageStruct> to the ctor, and pass state transitions in the
> > queue
> > > instead of synchronizing access to the state_ variable. The message struct
> > could
> > > be a proto buffer or just a simple struct/union (it would then be defined
in
> > > rtc_event_logger.h together with the state enum).
> > > 
> > 
> > One side effect of moving the state to a separate class is that we would not
> be
> > able to know whether a call (e.g. StartLogging) has succeeded or not. We
would
> > probably have to duplicate at least parts of the state in both the event log
> and
> > the new class.
> 
> For StartLogging() it would likely make sense to open the output file in
> RtcEventLogImpl and pass the file pointer to the thread class in the
START_FILE
> message. For StopLogging() my suggestion was to keep the event as now, to be
> able to block until the whole buffer has been purged and the file closed (by
the
> logging thread). If you want more status information at that point, you could
> use an event queue in the thread->rtceventlogimpl direction too.

But even if StartLogging opens the file we wouldn't know whether we are already
logging. We could add a bool in the RtcEventLog, set it in   StartLogging and
clear it in StopLogging, but that would not detect whether the log has stopped
on it's own due to file size or time limitations.

Another problem is how we terminate the thread. Presumably, the three main types
of messages would be START_FILE, STOP_FILE and TERMINATE_THREAD. The
TERMINATE_THREAD message would be sent by the RtcEventLog destructor.  If we
process all events (including messages) in time order, then the destructor would
wait for any remaining events to be copied (to file ot memory). This is clearly
not the ideal behavior if the user is trying to close a malfunctioning browser
tab. Even if we treated the messages separately from other events we could end
up with the same problem if there is a STOP_FILE message before the
TERMINATE_THREAD message.

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:733: switch (state_) {
On 2016/02/12 09:37:32, the sun wrote:
> On 2016/02/11 21:27:28, terelius wrote:
> > On 2016/02/10 10:47:23, the sun wrote:
> > > Pull this switch out into a separate function of the suggested
LoggerThread
> > > class, and you can add unit tests for the logic!
> > 
> > I don't understand what logic you want to test. WriteLog() is just a simple
> > message loop that dispatches to the functions that do the actual work based
on
> > the state of the log.
> 
> I was thinking mostly about the stuff in the functions called from here, in
> particular the transitive calls to ProcessInOrder().
> 
> More importantly though, by pulling the switch out (and using a message queue)
> you can easily tailor test cases for different scenarios. 
> 1. log to memory, terminate thread
> 2. log to memory, log to file, terminate thread
> 3. log to memory, log to file, log to memory, terminate thread
> ...
> 
> The key is to make the logic testable in a reproducible and consistent manner
> *without* threads or locks interfering.

I still don't understand what you want to pull out and how it would help
testing. Do you mean that you want to have
while (1) {
  DoSwitch()
}
or do you mean that we shouldn't have any switch statement because we wouldn't
need any state enum if we had a message queue.

[the sun, 2016-02-12 15:37:27]

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log.cc
File webrtc/call/rtc_event_log.cc (right):

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:124: void LogToMemory()
EXCLUSIVE_LOCKS_REQUIRED(crit_);
On 2016/02/12 14:13:38, terelius wrote:
> On 2016/02/12 09:37:32, the sun wrote:
> > On 2016/02/11 21:27:28, terelius wrote:
> > > On 2016/02/10 10:47:23, the sun wrote:
> > > > To make things even clearer, the parts of this class that are only
> accessed
> > > from
> > > > the logging thread, could be pulled out into a separate class, in its
> > separate
> > > > file.
> > > > 
> > > > class LoggerThread {
> > > >  public:
> > > >   LoggerThread(SwapQueue<rtclog::Event>* config_queue,
> > > SwapQueue<rtclog::Event>*
> > > > config_queue, ..., rtc::Event* file_finished_event);
> > > > ...
> > > > then many fields could be tucked away in this class.
> > > > 
> > > > You could also make the state machine simpler by adding a
> > > > SwapQueue<MyMessageStruct> to the ctor, and pass state transitions in
the
> > > queue
> > > > instead of synchronizing access to the state_ variable. The message
struct
> > > could
> > > > be a proto buffer or just a simple struct/union (it would then be
defined
> in
> > > > rtc_event_logger.h together with the state enum).
> > > > 
> > > 
> > > One side effect of moving the state to a separate class is that we would
not
> > be
> > > able to know whether a call (e.g. StartLogging) has succeeded or not. We
> would
> > > probably have to duplicate at least parts of the state in both the event
log
> > and
> > > the new class.
> > 
> > For StartLogging() it would likely make sense to open the output file in
> > RtcEventLogImpl and pass the file pointer to the thread class in the
> START_FILE
> > message. For StopLogging() my suggestion was to keep the event as now, to be
> > able to block until the whole buffer has been purged and the file closed (by
> the
> > logging thread). If you want more status information at that point, you
could
> > use an event queue in the thread->rtceventlogimpl direction too.
> 
> But even if StartLogging opens the file we wouldn't know whether we are
already
> logging. We could add a bool in the RtcEventLog, set it in   StartLogging and
> clear it in StopLogging, but that would not detect whether the log has stopped
> on it's own due to file size or time limitations.
> 
> Another problem is how we terminate the thread. Presumably, the three main
types
> of messages would be START_FILE, STOP_FILE and TERMINATE_THREAD. The
> TERMINATE_THREAD message would be sent by the RtcEventLog destructor.  If we
> process all events (including messages) in time order, then the destructor
would
> wait for any remaining events to be copied (to file ot memory). This is
clearly
> not the ideal behavior if the user is trying to close a malfunctioning browser
> tab. Even if we treated the messages separately from other events we could end
> up with the same problem if there is a STOP_FILE message before the
> TERMINATE_THREAD message.

You probably want to process the control messages first in the thread. If you
want everything in a strict order, you should likely use the same queue. But
really, if there are pending messages in the event queues when a stop message is
forwarded, you can purge those queues, or just drop the pending messages. I
don't think it matters a lot.

If the time that the destructor may take is a problem (it sounds rather unlikely
IMO) then you could allow an interface to register a Future to signal that the
file has been written, instead of using the event to signal. That is one option,
but I doubt we need that.

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:733: switch (state_) {
On 2016/02/12 14:13:38, terelius wrote:
> On 2016/02/12 09:37:32, the sun wrote:
> > On 2016/02/11 21:27:28, terelius wrote:
> > > On 2016/02/10 10:47:23, the sun wrote:
> > > > Pull this switch out into a separate function of the suggested
> LoggerThread
> > > > class, and you can add unit tests for the logic!
> > > 
> > > I don't understand what logic you want to test. WriteLog() is just a
simple
> > > message loop that dispatches to the functions that do the actual work
based
> on
> > > the state of the log.
> > 
> > I was thinking mostly about the stuff in the functions called from here, in
> > particular the transitive calls to ProcessInOrder().
> > 
> > More importantly though, by pulling the switch out (and using a message
queue)
> > you can easily tailor test cases for different scenarios. 
> > 1. log to memory, terminate thread
> > 2. log to memory, log to file, terminate thread
> > 3. log to memory, log to file, log to memory, terminate thread
> > ...
> > 
> > The key is to make the logic testable in a reproducible and consistent
manner
> > *without* threads or locks interfering.
> 
> I still don't understand what you want to pull out and how it would help
> testing. Do you mean that you want to have
> while (1) {
>   DoSwitch()
> }
> or do you mean that we shouldn't have any switch statement because we wouldn't
> need any state enum if we had a message queue.

Yes, I think you could pretty pretty much write the thread function as you
suggest (add the sleep section as well).

Your test(s) could then be:
1. put event on nn queue
2. put event on oo queue
3. DoSwitch()
4. Verify contents of file+memory
5. put TO_FILE on command queue
6. put event on nn queue
7. DoSwitch()
8. Verify contents of file+memory
...

[terelius, 2016-02-12 16:22:25]

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log.cc
File webrtc/call/rtc_event_log.cc (right):

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:124: void LogToMemory()
EXCLUSIVE_LOCKS_REQUIRED(crit_);
On 2016/02/12 15:37:27, the sun wrote:
> On 2016/02/12 14:13:38, terelius wrote:
> > On 2016/02/12 09:37:32, the sun wrote:
> > > On 2016/02/11 21:27:28, terelius wrote:
> > > > On 2016/02/10 10:47:23, the sun wrote:
> > > > > To make things even clearer, the parts of this class that are only
> > accessed
> > > > from
> > > > > the logging thread, could be pulled out into a separate class, in its
> > > separate
> > > > > file.
> > > > > 
> > > > > class LoggerThread {
> > > > >  public:
> > > > >   LoggerThread(SwapQueue<rtclog::Event>* config_queue,
> > > > SwapQueue<rtclog::Event>*
> > > > > config_queue, ..., rtc::Event* file_finished_event);
> > > > > ...
> > > > > then many fields could be tucked away in this class.
> > > > > 
> > > > > You could also make the state machine simpler by adding a
> > > > > SwapQueue<MyMessageStruct> to the ctor, and pass state transitions in
> the
> > > > queue
> > > > > instead of synchronizing access to the state_ variable. The message
> struct
> > > > could
> > > > > be a proto buffer or just a simple struct/union (it would then be
> defined
> > in
> > > > > rtc_event_logger.h together with the state enum).
> > > > > 
> > > > 
> > > > One side effect of moving the state to a separate class is that we would
> not
> > > be
> > > > able to know whether a call (e.g. StartLogging) has succeeded or not. We
> > would
> > > > probably have to duplicate at least parts of the state in both the event
> log
> > > and
> > > > the new class.
> > > 
> > > For StartLogging() it would likely make sense to open the output file in
> > > RtcEventLogImpl and pass the file pointer to the thread class in the
> > START_FILE
> > > message. For StopLogging() my suggestion was to keep the event as now, to
be
> > > able to block until the whole buffer has been purged and the file closed
(by
> > the
> > > logging thread). If you want more status information at that point, you
> could
> > > use an event queue in the thread->rtceventlogimpl direction too.
> > 
> > But even if StartLogging opens the file we wouldn't know whether we are
> already
> > logging. We could add a bool in the RtcEventLog, set it in   StartLogging
and
> > clear it in StopLogging, but that would not detect whether the log has
stopped
> > on it's own due to file size or time limitations.
> > 
> > Another problem is how we terminate the thread. Presumably, the three main
> types
> > of messages would be START_FILE, STOP_FILE and TERMINATE_THREAD. The
> > TERMINATE_THREAD message would be sent by the RtcEventLog destructor.  If we
> > process all events (including messages) in time order, then the destructor
> would
> > wait for any remaining events to be copied (to file ot memory). This is
> clearly
> > not the ideal behavior if the user is trying to close a malfunctioning
browser
> > tab. Even if we treated the messages separately from other events we could
end
> > up with the same problem if there is a STOP_FILE message before the
> > TERMINATE_THREAD message.
> 
> You probably want to process the control messages first in the thread. If you
> want everything in a strict order, you should likely use the same queue. But
> really, if there are pending messages in the event queues when a stop message
is
> forwarded, you can purge those queues, or just drop the pending messages. I
> don't think it matters a lot.
> 
> If the time that the destructor may take is a problem (it sounds rather
unlikely
> IMO) then you could allow an interface to register a Future to signal that the
> file has been written, instead of using the event to signal. That is one
option,
> but I doubt we need that.

Though if we process the control messages before the events, what would happen
if we are logging to file and the message queue contains STOP_FILE followed by
START_FILE? We'd first pop the STOP_FILE message and set the new time limit.
Then we'd look at the START_FILE and presumably discard it because we are
already logging, right? If we process all control messages first, it seems we
wouldn't be using a message queue but rather the same type of state signalling
that is in place right now.

If we process the control messages first, then I agree that the destructor won't
be a problem. What I am worried about is if we process all events and messages
strictly in time order so we won't see the TERMINATE_THREAD message until we
have written all RTP events. I don't know whether it'll be significant, but in
any case I think it is bad practice to do extensive computations or unnecessary
I/O in the destructor.

[the sun, 2016-02-16 13:29:15]

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log.cc
File webrtc/call/rtc_event_log.cc (right):

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:124: void LogToMemory()
EXCLUSIVE_LOCKS_REQUIRED(crit_);
On 2016/02/12 16:22:24, terelius wrote:
> On 2016/02/12 15:37:27, the sun wrote:
> > On 2016/02/12 14:13:38, terelius wrote:
> > > On 2016/02/12 09:37:32, the sun wrote:
> > > > On 2016/02/11 21:27:28, terelius wrote:
> > > > > On 2016/02/10 10:47:23, the sun wrote:
> > > > > > To make things even clearer, the parts of this class that are only
> > > accessed
> > > > > from
> > > > > > the logging thread, could be pulled out into a separate class, in
its
> > > > separate
> > > > > > file.
> > > > > > 
> > > > > > class LoggerThread {
> > > > > >  public:
> > > > > >   LoggerThread(SwapQueue<rtclog::Event>* config_queue,
> > > > > SwapQueue<rtclog::Event>*
> > > > > > config_queue, ..., rtc::Event* file_finished_event);
> > > > > > ...
> > > > > > then many fields could be tucked away in this class.
> > > > > > 
> > > > > > You could also make the state machine simpler by adding a
> > > > > > SwapQueue<MyMessageStruct> to the ctor, and pass state transitions
in
> > the
> > > > > queue
> > > > > > instead of synchronizing access to the state_ variable. The message
> > struct
> > > > > could
> > > > > > be a proto buffer or just a simple struct/union (it would then be
> > defined
> > > in
> > > > > > rtc_event_logger.h together with the state enum).
> > > > > > 
> > > > > 
> > > > > One side effect of moving the state to a separate class is that we
would
> > not
> > > > be
> > > > > able to know whether a call (e.g. StartLogging) has succeeded or not.
We
> > > would
> > > > > probably have to duplicate at least parts of the state in both the
event
> > log
> > > > and
> > > > > the new class.
> > > > 
> > > > For StartLogging() it would likely make sense to open the output file in
> > > > RtcEventLogImpl and pass the file pointer to the thread class in the
> > > START_FILE
> > > > message. For StopLogging() my suggestion was to keep the event as now,
to
> be
> > > > able to block until the whole buffer has been purged and the file closed
> (by
> > > the
> > > > logging thread). If you want more status information at that point, you
> > could
> > > > use an event queue in the thread->rtceventlogimpl direction too.
> > > 
> > > But even if StartLogging opens the file we wouldn't know whether we are
> > already
> > > logging. We could add a bool in the RtcEventLog, set it in   StartLogging
> and
> > > clear it in StopLogging, but that would not detect whether the log has
> stopped
> > > on it's own due to file size or time limitations.
> > > 
> > > Another problem is how we terminate the thread. Presumably, the three main
> > types
> > > of messages would be START_FILE, STOP_FILE and TERMINATE_THREAD. The
> > > TERMINATE_THREAD message would be sent by the RtcEventLog destructor.  If
we
> > > process all events (including messages) in time order, then the destructor
> > would
> > > wait for any remaining events to be copied (to file ot memory). This is
> > clearly
> > > not the ideal behavior if the user is trying to close a malfunctioning
> browser
> > > tab. Even if we treated the messages separately from other events we could
> end
> > > up with the same problem if there is a STOP_FILE message before the
> > > TERMINATE_THREAD message.
> > 
> > You probably want to process the control messages first in the thread. If
you
> > want everything in a strict order, you should likely use the same queue. But
> > really, if there are pending messages in the event queues when a stop
message
> is
> > forwarded, you can purge those queues, or just drop the pending messages. I
> > don't think it matters a lot.
> > 
> > If the time that the destructor may take is a problem (it sounds rather
> unlikely
> > IMO) then you could allow an interface to register a Future to signal that
the
> > file has been written, instead of using the event to signal. That is one
> option,
> > but I doubt we need that.
> 
> Though if we process the control messages before the events, what would happen
> if we are logging to file and the message queue contains STOP_FILE followed by
> START_FILE? We'd first pop the STOP_FILE message and set the new time limit.
> Then we'd look at the START_FILE and presumably discard it because we are
> already logging, right? If we process all control messages first, it seems we
> wouldn't be using a message queue but rather the same type of state signalling
> that is in place right now.

I thought a START_FILE message would contain the file resource to log to. Then
in this case STOP_FILE would purge current buffers and close the current file,
and START_FILE starts logging to a new file, but writes nothing to it, yet.

> 
> If we process the control messages first, then I agree that the destructor
won't
> be a problem. What I am worried about is if we process all events and messages
> strictly in time order so we won't see the TERMINATE_THREAD message until we
> have written all RTP events. I don't know whether it'll be significant, but in
> any case I think it is bad practice to do extensive computations or
unnecessary
> I/O in the destructor.

a) If processing control messages first, you can choose what to do when you see
the TERMINATE_THREAD: purge buffers or close file+terminate. I don't think it
matters much if you have a few messages pending in the queues (the 10s backlog
should have been written out at START_FILE).
b) Destructors are not different from other code. Compare:

delete myResource;    // d-tor purges.

to 

myResource.Purge();
delete myResource;    // d-tor doesn't purge.

They run on the same thread, same order. It's not like the d-tor runs under any
real time requirements.

The biggest "downside" with doing work in the d-tor is that calls to them are
implicit, so they may be called in a context you don't expect (that is, if you
do not take proper care managing your object life times). A less surprising
attribute is that you can't return an error code from the d-tor, or (in C++)
throw an exception.

[terelius, 2016-02-16 14:36:58]

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log.cc
File webrtc/call/rtc_event_log.cc (right):

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:124: void LogToMemory()
EXCLUSIVE_LOCKS_REQUIRED(crit_);
On 2016/02/16 13:29:15, the sun wrote:
> On 2016/02/12 16:22:24, terelius wrote:
> > On 2016/02/12 15:37:27, the sun wrote:
> > > On 2016/02/12 14:13:38, terelius wrote:
> > > > On 2016/02/12 09:37:32, the sun wrote:
> > > > > On 2016/02/11 21:27:28, terelius wrote:
> > > > > > On 2016/02/10 10:47:23, the sun wrote:
> > > > > > > To make things even clearer, the parts of this class that are only
> > > > accessed
> > > > > > from
> > > > > > > the logging thread, could be pulled out into a separate class, in
> its
> > > > > separate
> > > > > > > file.
> > > > > > > 
> > > > > > > class LoggerThread {
> > > > > > >  public:
> > > > > > >   LoggerThread(SwapQueue<rtclog::Event>* config_queue,
> > > > > > SwapQueue<rtclog::Event>*
> > > > > > > config_queue, ..., rtc::Event* file_finished_event);
> > > > > > > ...
> > > > > > > then many fields could be tucked away in this class.
> > > > > > > 
> > > > > > > You could also make the state machine simpler by adding a
> > > > > > > SwapQueue<MyMessageStruct> to the ctor, and pass state transitions
> in
> > > the
> > > > > > queue
> > > > > > > instead of synchronizing access to the state_ variable. The
message
> > > struct
> > > > > > could
> > > > > > > be a proto buffer or just a simple struct/union (it would then be
> > > defined
> > > > in
> > > > > > > rtc_event_logger.h together with the state enum).
> > > > > > > 
> > > > > > 
> > > > > > One side effect of moving the state to a separate class is that we
> would
> > > not
> > > > > be
> > > > > > able to know whether a call (e.g. StartLogging) has succeeded or
not.
> We
> > > > would
> > > > > > probably have to duplicate at least parts of the state in both the
> event
> > > log
> > > > > and
> > > > > > the new class.
> > > > > 
> > > > > For StartLogging() it would likely make sense to open the output file
in
> > > > > RtcEventLogImpl and pass the file pointer to the thread class in the
> > > > START_FILE
> > > > > message. For StopLogging() my suggestion was to keep the event as now,
> to
> > be
> > > > > able to block until the whole buffer has been purged and the file
closed
> > (by
> > > > the
> > > > > logging thread). If you want more status information at that point,
you
> > > could
> > > > > use an event queue in the thread->rtceventlogimpl direction too.
> > > > 
> > > > But even if StartLogging opens the file we wouldn't know whether we are
> > > already
> > > > logging. We could add a bool in the RtcEventLog, set it in  
StartLogging
> > and
> > > > clear it in StopLogging, but that would not detect whether the log has
> > stopped
> > > > on it's own due to file size or time limitations.
> > > > 
> > > > Another problem is how we terminate the thread. Presumably, the three
main
> > > types
> > > > of messages would be START_FILE, STOP_FILE and TERMINATE_THREAD. The
> > > > TERMINATE_THREAD message would be sent by the RtcEventLog destructor. 
If
> we
> > > > process all events (including messages) in time order, then the
destructor
> > > would
> > > > wait for any remaining events to be copied (to file ot memory). This is
> > > clearly
> > > > not the ideal behavior if the user is trying to close a malfunctioning
> > browser
> > > > tab. Even if we treated the messages separately from other events we
could
> > end
> > > > up with the same problem if there is a STOP_FILE message before the
> > > > TERMINATE_THREAD message.
> > > 
> > > You probably want to process the control messages first in the thread. If
> you
> > > want everything in a strict order, you should likely use the same queue.
But
> > > really, if there are pending messages in the event queues when a stop
> message
> > is
> > > forwarded, you can purge those queues, or just drop the pending messages.
I
> > > don't think it matters a lot.
> > > 
> > > If the time that the destructor may take is a problem (it sounds rather
> > unlikely
> > > IMO) then you could allow an interface to register a Future to signal that
> the
> > > file has been written, instead of using the event to signal. That is one
> > option,
> > > but I doubt we need that.
> > 
> > Though if we process the control messages before the events, what would
happen
> > if we are logging to file and the message queue contains STOP_FILE followed
by
> > START_FILE? We'd first pop the STOP_FILE message and set the new time limit.
> > Then we'd look at the START_FILE and presumably discard it because we are
> > already logging, right? If we process all control messages first, it seems
we
> > wouldn't be using a message queue but rather the same type of state
signalling
> > that is in place right now.
> 
> I thought a START_FILE message would contain the file resource to log to. Then
> in this case STOP_FILE would purge current buffers and close the current file,
> and START_FILE starts logging to a new file, but writes nothing to it, yet.

Oh, so you are saying that you would always process one "batch" of events in
between each control message?

Yeah, START_FILE would contain the file resource, but my view was that we would
process all control messages before the regular events. Since we can't close the
file until we have processed all events earlier than the  STOP message, we
wouldn't actually have stopped when we get the second START event.

> > 
> > If we process the control messages first, then I agree that the destructor
> won't
> > be a problem. What I am worried about is if we process all events and
messages
> > strictly in time order so we won't see the TERMINATE_THREAD message until we
> > have written all RTP events. I don't know whether it'll be significant, but
in
> > any case I think it is bad practice to do extensive computations or
> unnecessary
> > I/O in the destructor.
> 
> a) If processing control messages first, you can choose what to do when you
see
> the TERMINATE_THREAD: purge buffers or close file+terminate. I don't think it
> matters much if you have a few messages pending in the queues (the 10s backlog
> should have been written out at START_FILE).
> b) Destructors are not different from other code. Compare:
> 
> delete myResource;    // d-tor purges.
> 
> to 
> 
> myResource.Purge();
> delete myResource;    // d-tor doesn't purge.
> 
> They run on the same thread, same order. It's not like the d-tor runs under
any
> real time requirements.
> 
> The biggest "downside" with doing work in the d-tor is that calls to them are
> implicit, so they may be called in a context you don't expect (that is, if you
> do not take proper care managing your object life times). A less surprising
> attribute is that you can't return an error code from the d-tor, or (in C++)
> throw an exception.

Assuming we're processing control messages first, then we're in agreement
regarding the destructor.

That said, guaranteeing exception-freeness is quite difficult imo. In
particular, new can throw (unless we're using some special compiler flags?), so
I tend to assume that any computation I don't fully control can throw. The
second reason is more of a UI thing; people might be ok with a loading screen
because initialization takes a while, but program termination is still expected
to be near instantaneous. If we were processing regular events before control
messages, then we would copy all regular events to the history buffer and after
that read the TERMINATE_THREAD message and throw away the history buffer. My
point was just that I want to process control messages before regular events to
avoid this unnecessary buffer copying (or similar if logging to file).

[the sun, 2016-02-17 09:44:20]

We have discussed this CL at length now (+ the previous one on the same topic).

Is it time to draw up a detailed design doc?

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log.cc
File webrtc/call/rtc_event_log.cc (right):

https://codereview.webrtc.org/1687703002/diff/20001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:124: void LogToMemory()
EXCLUSIVE_LOCKS_REQUIRED(crit_);
On 2016/02/16 14:36:58, terelius wrote:
> On 2016/02/16 13:29:15, the sun wrote:
> > On 2016/02/12 16:22:24, terelius wrote:
> > > On 2016/02/12 15:37:27, the sun wrote:
> > > > On 2016/02/12 14:13:38, terelius wrote:
> > > > > On 2016/02/12 09:37:32, the sun wrote:
> > > > > > On 2016/02/11 21:27:28, terelius wrote:
> > > > > > > On 2016/02/10 10:47:23, the sun wrote:
> > > > > > > > To make things even clearer, the parts of this class that are
only
> > > > > accessed
> > > > > > > from
> > > > > > > > the logging thread, could be pulled out into a separate class,
in
> > its
> > > > > > separate
> > > > > > > > file.
> > > > > > > > 
> > > > > > > > class LoggerThread {
> > > > > > > >  public:
> > > > > > > >   LoggerThread(SwapQueue<rtclog::Event>* config_queue,
> > > > > > > SwapQueue<rtclog::Event>*
> > > > > > > > config_queue, ..., rtc::Event* file_finished_event);
> > > > > > > > ...
> > > > > > > > then many fields could be tucked away in this class.
> > > > > > > > 
> > > > > > > > You could also make the state machine simpler by adding a
> > > > > > > > SwapQueue<MyMessageStruct> to the ctor, and pass state
transitions
> > in
> > > > the
> > > > > > > queue
> > > > > > > > instead of synchronizing access to the state_ variable. The
> message
> > > > struct
> > > > > > > could
> > > > > > > > be a proto buffer or just a simple struct/union (it would then
be
> > > > defined
> > > > > in
> > > > > > > > rtc_event_logger.h together with the state enum).
> > > > > > > > 
> > > > > > > 
> > > > > > > One side effect of moving the state to a separate class is that we
> > would
> > > > not
> > > > > > be
> > > > > > > able to know whether a call (e.g. StartLogging) has succeeded or
> not.
> > We
> > > > > would
> > > > > > > probably have to duplicate at least parts of the state in both the
> > event
> > > > log
> > > > > > and
> > > > > > > the new class.
> > > > > > 
> > > > > > For StartLogging() it would likely make sense to open the output
file
> in
> > > > > > RtcEventLogImpl and pass the file pointer to the thread class in the
> > > > > START_FILE
> > > > > > message. For StopLogging() my suggestion was to keep the event as
now,
> > to
> > > be
> > > > > > able to block until the whole buffer has been purged and the file
> closed
> > > (by
> > > > > the
> > > > > > logging thread). If you want more status information at that point,
> you
> > > > could
> > > > > > use an event queue in the thread->rtceventlogimpl direction too.
> > > > > 
> > > > > But even if StartLogging opens the file we wouldn't know whether we
are
> > > > already
> > > > > logging. We could add a bool in the RtcEventLog, set it in  
> StartLogging
> > > and
> > > > > clear it in StopLogging, but that would not detect whether the log has
> > > stopped
> > > > > on it's own due to file size or time limitations.
> > > > > 
> > > > > Another problem is how we terminate the thread. Presumably, the three
> main
> > > > types
> > > > > of messages would be START_FILE, STOP_FILE and TERMINATE_THREAD. The
> > > > > TERMINATE_THREAD message would be sent by the RtcEventLog destructor. 
> If
> > we
> > > > > process all events (including messages) in time order, then the
> destructor
> > > > would
> > > > > wait for any remaining events to be copied (to file ot memory). This
is
> > > > clearly
> > > > > not the ideal behavior if the user is trying to close a malfunctioning
> > > browser
> > > > > tab. Even if we treated the messages separately from other events we
> could
> > > end
> > > > > up with the same problem if there is a STOP_FILE message before the
> > > > > TERMINATE_THREAD message.
> > > > 
> > > > You probably want to process the control messages first in the thread.
If
> > you
> > > > want everything in a strict order, you should likely use the same queue.
> But
> > > > really, if there are pending messages in the event queues when a stop
> > message
> > > is
> > > > forwarded, you can purge those queues, or just drop the pending
messages.
> I
> > > > don't think it matters a lot.
> > > > 
> > > > If the time that the destructor may take is a problem (it sounds rather
> > > unlikely
> > > > IMO) then you could allow an interface to register a Future to signal
that
> > the
> > > > file has been written, instead of using the event to signal. That is one
> > > option,
> > > > but I doubt we need that.
> > > 
> > > Though if we process the control messages before the events, what would
> happen
> > > if we are logging to file and the message queue contains STOP_FILE
followed
> by
> > > START_FILE? We'd first pop the STOP_FILE message and set the new time
limit.
> > > Then we'd look at the START_FILE and presumably discard it because we are
> > > already logging, right? If we process all control messages first, it seems
> we
> > > wouldn't be using a message queue but rather the same type of state
> signalling
> > > that is in place right now.
> > 
> > I thought a START_FILE message would contain the file resource to log to.
Then
> > in this case STOP_FILE would purge current buffers and close the current
file,
> > and START_FILE starts logging to a new file, but writes nothing to it, yet.
> 
> Oh, so you are saying that you would always process one "batch" of events in
> between each control message?

No, I would handle all the control messages first, so that all updates to the
thread state go first, then handle the event queues. Yes, that would mean giving
up on precise timing between the control messages and log events, but I don't
think that would matter too much. The important bit is that events in the log
are in order.

That said, the devil is in the details, so I can't tell you exactly *how* the
solution would end up if I were to do it. But I would definitely break out the
state that belongs to the logging thread into its own class, so that we can
avoid explicit use of locks. 

> Yeah, START_FILE would contain the file resource, but my view was that we
would
> process all control messages before the regular events. Since we can't close
the
> file until we have processed all events earlier than the  STOP message, we
> wouldn't actually have stopped when we get the second START event.
> 
> > > 
> > > If we process the control messages first, then I agree that the destructor
> > won't
> > > be a problem. What I am worried about is if we process all events and
> messages
> > > strictly in time order so we won't see the TERMINATE_THREAD message until
we
> > > have written all RTP events. I don't know whether it'll be significant,
but
> in
> > > any case I think it is bad practice to do extensive computations or
> > unnecessary
> > > I/O in the destructor.
> > 
> > a) If processing control messages first, you can choose what to do when you
> see
> > the TERMINATE_THREAD: purge buffers or close file+terminate. I don't think
it
> > matters much if you have a few messages pending in the queues (the 10s
backlog
> > should have been written out at START_FILE).
> > b) Destructors are not different from other code. Compare:
> > 
> > delete myResource;    // d-tor purges.
> > 
> > to 
> > 
> > myResource.Purge();
> > delete myResource;    // d-tor doesn't purge.
> > 
> > They run on the same thread, same order. It's not like the d-tor runs under
> any
> > real time requirements.
> > 
> > The biggest "downside" with doing work in the d-tor is that calls to them
are
> > implicit, so they may be called in a context you don't expect (that is, if
you
> > do not take proper care managing your object life times). A less surprising
> > attribute is that you can't return an error code from the d-tor, or (in C++)
> > throw an exception.
> 
> Assuming we're processing control messages first, then we're in agreement
> regarding the destructor.
> 
> That said, guaranteeing exception-freeness is quite difficult imo. In
> particular, new can throw (unless we're using some special compiler flags?),
so
> I tend to assume that any computation I don't fully control can throw. The
> second reason is more of a UI thing; people might be ok with a loading screen
> because initialization takes a while, but program termination is still
expected
> to be near instantaneous. If we were processing regular events before control
> messages, then we would copy all regular events to the history buffer and
after
> that read the TERMINATE_THREAD message and throw away the history buffer. My
> point was just that I want to process control messages before regular events
to
> avoid this unnecessary buffer copying (or similar if logging to file).

We do not use exceptions in Chromium/WebRTC C++ and I believe the code is
compiled without exception support/RTTI (otherwise it would unnecessarily bloat
the binary and invite use of exceptions). In Chrome, set_new_handler() is used
in the render process to output log messages in OOM situations, though curiously
the process isn't terminated so we will continue, likely causing an access
violation instead.

Likewise, you can assume that no libraries that Chrome uses will throw
exceptions, and certainly not the FileWrapper you use to write the file here.

[terelius, 2016-02-17 14:21:17]

> > 
> > Oh, so you are saying that you would always process one "batch" of events in
> > between each control message?
> 
> No, I would handle all the control messages first, so that all updates to the
> thread state go first, then handle the event queues. Yes, that would mean
giving
> up on precise timing between the control messages and log events, but I don't
> think that would matter too much. The important bit is that events in the log
> are in order.
> 
> That said, the devil is in the details, so I can't tell you exactly *how* the
> solution would end up if I were to do it. But I would definitely break out the
> state that belongs to the logging thread into its own class, so that we can
> avoid explicit use of locks. 
> 

I've tried doing that, but now I am stuck at a problem where the lack of state
can cause StopLogging to wait indefinitely. StopLogging supposedly places a
STOP_LOGGING message in the message queue and then waits for the file to finish.
However, if we aren't logging then the file will never finish so StopLogging
will never return.

We could try to avoid this by setting the file_finished event every time we
process a STOP_LOGGING message (even if we are not logging), but then we get the
same problem if two different threads call StopLogging at the same time. An
rtc::Event can afaik only be set or unset, so we can't detect that it has been
set twice.

We could try adding another message queue for returning the thread status to the
event log. However, we would lose the clean way of Wait()ing for the file to
finish. Instead, it seems we would have to spin lock until the message queue
contains a response.

[the sun, 2016-02-17 14:51:42]

On 2016/02/17 14:21:17, terelius wrote:
> > > 
> > > Oh, so you are saying that you would always process one "batch" of events
in
> > > between each control message?
> > 
> > No, I would handle all the control messages first, so that all updates to
the
> > thread state go first, then handle the event queues. Yes, that would mean
> giving
> > up on precise timing between the control messages and log events, but I
don't
> > think that would matter too much. The important bit is that events in the
log
> > are in order.
> > 
> > That said, the devil is in the details, so I can't tell you exactly *how*
the
> > solution would end up if I were to do it. But I would definitely break out
the
> > state that belongs to the logging thread into its own class, so that we can
> > avoid explicit use of locks. 
> > 
> 
> I've tried doing that, but now I am stuck at a problem where the lack of state
> can cause StopLogging to wait indefinitely. StopLogging supposedly places a
> STOP_LOGGING message in the message queue and then waits for the file to
finish.
> However, if we aren't logging then the file will never finish so StopLogging
> will never return.
> 
> We could try to avoid this by setting the file_finished event every time we
> process a STOP_LOGGING message (even if we are not logging), but then we get
the
> same problem if two different threads call StopLogging at the same time. An
> rtc::Event can afaik only be set or unset, so we can't detect that it has been
> set twice.

Does RtcEventLogImpl::StopLogging() really need to be multi thread safe? I would
have opted to make it single-threaded and add a thread checker to document that.

> We could try adding another message queue for returning the thread status to
the
> event log. However, we would lose the clean way of Wait()ing for the file to
> finish. Instead, it seems we would have to spin lock until the message queue
> contains a response.

Maybe there should be a blocking wait function on SwapQueue. Then you could use
that instead of an event.

[terelius, 2016-02-17 16:10:33]

On 2016/02/17 14:51:42, the sun wrote:
> On 2016/02/17 14:21:17, terelius wrote:
> > > > 
> > > > Oh, so you are saying that you would always process one "batch" of
events
> in
> > > > between each control message?
> > > 
> > > No, I would handle all the control messages first, so that all updates to
> the
> > > thread state go first, then handle the event queues. Yes, that would mean
> > giving
> > > up on precise timing between the control messages and log events, but I
> don't
> > > think that would matter too much. The important bit is that events in the
> log
> > > are in order.
> > > 
> > > That said, the devil is in the details, so I can't tell you exactly *how*
> the
> > > solution would end up if I were to do it. But I would definitely break out
> the
> > > state that belongs to the logging thread into its own class, so that we
can
> > > avoid explicit use of locks. 
> > > 
> > 
> > I've tried doing that, but now I am stuck at a problem where the lack of
state
> > can cause StopLogging to wait indefinitely. StopLogging supposedly places a
> > STOP_LOGGING message in the message queue and then waits for the file to
> finish.
> > However, if we aren't logging then the file will never finish so StopLogging
> > will never return.
> > 
> > We could try to avoid this by setting the file_finished event every time we
> > process a STOP_LOGGING message (even if we are not logging), but then we get
> the
> > same problem if two different threads call StopLogging at the same time. An
> > rtc::Event can afaik only be set or unset, so we can't detect that it has
been
> > set twice.
> 
> Does RtcEventLogImpl::StopLogging() really need to be multi thread safe? I
would
> have opted to make it single-threaded and add a thread checker to document
that.

This might work. There are (or will be) two call paths that lead to StopLogging
in Chrome, but they might be on the same thread. I'll look into it.

I am not very familiar with the thread checker, but as far as I understand, you
add a ThreadChecker member to the class and then
DCHECK(thread_checker.CalledOnValidThread()). However, the thread checker
decides which thread is valid in the constructor, so the naive implementation
would require that StopLogging is called on the same thread as the RtcEventLog
constructor. I don't think we want to make that assumption.

> > We could try adding another message queue for returning the thread status to
> the
> > event log. However, we would lose the clean way of Wait()ing for the file to
> > finish. Instead, it seems we would have to spin lock until the message queue
> > contains a response.
> 
> Maybe there should be a blocking wait function on SwapQueue. Then you could
use
> that instead of an event.

That would be nice, but I don't see how to implement the function using the
existing thread primitives.

[the sun, 2016-02-17 16:33:53]

On 2016/02/17 16:10:33, terelius wrote:
> On 2016/02/17 14:51:42, the sun wrote:
> > On 2016/02/17 14:21:17, terelius wrote:
> > > > > 
> > > > > Oh, so you are saying that you would always process one "batch" of
> events
> > in
> > > > > between each control message?
> > > > 
> > > > No, I would handle all the control messages first, so that all updates
to
> > the
> > > > thread state go first, then handle the event queues. Yes, that would
mean
> > > giving
> > > > up on precise timing between the control messages and log events, but I
> > don't
> > > > think that would matter too much. The important bit is that events in
the
> > log
> > > > are in order.
> > > > 
> > > > That said, the devil is in the details, so I can't tell you exactly
*how*
> > the
> > > > solution would end up if I were to do it. But I would definitely break
out
> > the
> > > > state that belongs to the logging thread into its own class, so that we
> can
> > > > avoid explicit use of locks. 
> > > > 
> > > 
> > > I've tried doing that, but now I am stuck at a problem where the lack of
> state
> > > can cause StopLogging to wait indefinitely. StopLogging supposedly places
a
> > > STOP_LOGGING message in the message queue and then waits for the file to
> > finish.
> > > However, if we aren't logging then the file will never finish so
StopLogging
> > > will never return.
> > > 
> > > We could try to avoid this by setting the file_finished event every time
we
> > > process a STOP_LOGGING message (even if we are not logging), but then we
get
> > the
> > > same problem if two different threads call StopLogging at the same time.
An
> > > rtc::Event can afaik only be set or unset, so we can't detect that it has
> been
> > > set twice.
> > 
> > Does RtcEventLogImpl::StopLogging() really need to be multi thread safe? I
> would
> > have opted to make it single-threaded and add a thread checker to document
> that.
> 
> This might work. There are (or will be) two call paths that lead to
StopLogging
> in Chrome, but they might be on the same thread. I'll look into it.
> 
> I am not very familiar with the thread checker, but as far as I understand,
you
> add a ThreadChecker member to the class and then
> DCHECK(thread_checker.CalledOnValidThread()). However, the thread checker
> decides which thread is valid in the constructor, so the naive implementation
> would require that StopLogging is called on the same thread as the RtcEventLog
> constructor. I don't think we want to make that assumption.

Call tc->DetachFromThread() in the ctor and it will lock to whatever thread uses
it next. Shop around and see how they are used.

> > > We could try adding another message queue for returning the thread status
to
> > the
> > > event log. However, we would lose the clean way of Wait()ing for the file
to
> > > finish. Instead, it seems we would have to spin lock until the message
queue
> > > contains a response.
> > 
> > Maybe there should be a blocking wait function on SwapQueue. Then you could
> use
> > that instead of an event.
> 
> That would be nice, but I don't see how to implement the function using the
> existing thread primitives.

It would be a spin lock or semaphore.

[terelius, 2016-02-19 14:30:39]

Please take a look.

(The trybot failures on asan&friends is caused by a bug in FileWrapper::Write. I
have a CL to fix that bug.)

[the sun, 2016-02-25 15:23:19]

Thanks, I think this is moving in the right direction. I'd like to focus on
simplifying the logic now.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log.cc
File webrtc/call/rtc_event_log.cc (right):

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:56: using RtcEventLog::StartLogging;
Not necessary.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:88: using RtcEventLog::StartLogging;
Not necessary.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:108: SwapQueue<EventLogMessage> message_queue_;
Note, you don't really need one queue per event type. To avoid contention (at
all costs) you need one queue per *thread* which is logging. But perhaps that is
the same in this case?

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:244:
RTC_DCHECK(thread_checker_.CalledOnValidThread());
Why just here? Add to StartLogging() too?

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:43: log_to_memory_(true),
log_to_memory and file_ represent the same information? If you just leave file_
as nullptr until you get a StartLogging message it may simplify your logic.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:63: clock_(clock) {
Add RTC_DCHECK(message_queue), and the other pointer arguments.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:142: while ((valid_config_event_ ||
valid_rtp_event_ || valid_rtcp_event_ ||
This handling doesn't look right to me. Have you unit tested?

What about this scenario:

queues contain:
config : t=10
rtp : t=5
output = rtp, config

next time function is called queues contain:
rtp : t=7

total output = rtp, config, rtp
but should have been = rtp, rtp, config

it seems you can only write when you have time stamps for all the most recent
packets on the queues.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:314: bool valid_message = false;
not needed

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:322: while (valid_message) {
while (message_queue_->Remove(&message)) {

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:329:
file_.reset(message.file.release());
file_.swap(message.file);

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:353: valid_message =
message_queue_->Remove(&message);
remove

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.h:40: struct EventLogMessage {
Move inside RtcEventLogHelperThread and rename to ControlMessage

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.h:48: friend void swap(EventLogMessage&
x, EventLogMessage& y) {
it's common to use rhs and lhs for the arguments in these types of functions.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.h:51: FileWrapper* xfile =
x.file.release();
scoped_ptr supports swap(). Just x.file.swap(y.file) should work.

[stefan-webrtc, 2016-03-01 09:44:16]

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/ringbuffer.h
File webrtc/call/ringbuffer.h (right):

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/ringbuffer.h#...
webrtc/call/ringbuffer.h:27: data_ = new T[capacity + 1];
Comment on "capacity + 1", and/or make it named variable which explains it.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/ringbuffer.h#...
webrtc/call/ringbuffer.h:37: front_++;
++front_

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/ringbuffer.h#...
webrtc/call/ringbuffer.h:47: back_++;
++back_

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/ringbuffer.h#...
webrtc/call/ringbuffer.h:52: front_++;
++front_

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/ringbuffer.h#...
webrtc/call/ringbuffer.h:66: T* data_;
Can you make data_ a unique_ptr?

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log.cc
File webrtc/call/rtc_event_log.cc (right):

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:108: SwapQueue<EventLogMessage> message_queue_;
On 2016/02/25 15:23:19, the sun wrote:
> Note, you don't really need one queue per event type. To avoid contention (at
> all costs) you need one queue per *thread* which is logging. But perhaps that
is
> the same in this case?

We plan on using the event log in other places too, which may not have the same
threading model as webrtc. Therefore I think it's easier if we keep a queue per
type.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:253: return;
Will we be able to make sure the caller tries to stop the thread again if this
happens, or how are we failing?

Can this happen if the we have reached the max size? Or when is there a risk of
this happening?

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:142: while ((valid_config_event_ ||
valid_rtp_event_ || valid_rtcp_event_ ||
On 2016/02/25 15:23:19, the sun wrote:
> This handling doesn't look right to me. Have you unit tested?
> 
> What about this scenario:
> 
> queues contain:
> config : t=10
> rtp : t=5
> output = rtp, config
> 
> next time function is called queues contain:
> rtp : t=7
> 
> total output = rtp, config, rtp
> but should have been = rtp, rtp, config
> 
> it seems you can only write when you have time stamps for all the most recent
> packets on the queues.

I'm not sure I follow this. Do you mean that we should only write events if all
event queues have valid events? E.g.,

rtp queue has events: t=5, t=10
rtcp queue has events: t=20
playout queue has events: t=6, t=16
loss event queue has events: t=10

In this case we only write events up to t=10 because we can't know if the rtp
queue and loss event queue have pending events but are blocked on something?
What if some events are very rare, would that become a problem? It seems like
the config events will be rare enough that we can't block writing on them?

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:188: }
Lines 184-188 may be possible to break out to a helper function

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.h:2: *  Copyright (c) 2015 The WebRTC
project authors. All Rights Reserved.
2016 perhaps?

[ivoc, 2016-03-01 10:04:57]

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log.cc
File webrtc/call/rtc_event_log.cc (right):

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:108: SwapQueue<EventLogMessage> message_queue_;
On 2016/03/01 09:44:16, stefan-webrtc (holmer) wrote:
> On 2016/02/25 15:23:19, the sun wrote:
> > Note, you don't really need one queue per event type. To avoid contention
(at
> > all costs) you need one queue per *thread* which is logging. But perhaps
that
> is
> > the same in this case?
> 
> We plan on using the event log in other places too, which may not have the
same
> threading model as webrtc. Therefore I think it's easier if we keep a queue
per
> type.

I'm still not convinced that a single queue is a bad idea. Swaps are really fast
operations. If we take a lock only while swapping a new message onto a single
queue, there should hardly be any contention. Having a single queue would
simplify the RtcEventLog class by quite a bit, and has the advantage that
logging starts at a single point in time for all different types of messages
(which I think would be nice to have). WDYT?

[terelius, 2016-03-01 11:24:04]

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log.cc
File webrtc/call/rtc_event_log.cc (right):

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:108: SwapQueue<EventLogMessage> message_queue_;
On 2016/03/01 10:04:57, ivoc wrote:
> On 2016/03/01 09:44:16, stefan-webrtc (holmer) wrote:
> > On 2016/02/25 15:23:19, the sun wrote:
> > > Note, you don't really need one queue per event type. To avoid contention
> (at
> > > all costs) you need one queue per *thread* which is logging. But perhaps
> that
> > is
> > > the same in this case?
> > 
> > We plan on using the event log in other places too, which may not have the
> same
> > threading model as webrtc. Therefore I think it's easier if we keep a queue
> per
> > type.
> 
> I'm still not convinced that a single queue is a bad idea. Swaps are really
fast
> operations. If we take a lock only while swapping a new message onto a single
> queue, there should hardly be any contention. Having a single queue would
> simplify the RtcEventLog class by quite a bit, and has the advantage that
> logging starts at a single point in time for all different types of messages
> (which I think would be nice to have). WDYT?

We *are* logging from a single point in time.

Having a single event queue would prevent future optimizations such as  storing
the events in the native C types, or reuse the memory allocated by an old
protobuf event. Note that when you swap protobuf events into a common queue you
get back another event of "random" type. Suppose we insert a playout event, and
happen to get back an RTP header. The next time the playout function inserts an
event, we're either going to insert an event with extra memory to hold an RTP
header, or we have to free the memory (and allocate new memory when we insert an
RTP packet).

Although we're not doing these optimizations right now, I think it's valuable to
maintain the flexibility.

[the sun, 2016-03-02 10:09:16]

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log.cc
File webrtc/call/rtc_event_log.cc (right):

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:108: SwapQueue<EventLogMessage> message_queue_;
On 2016/03/01 11:24:04, terelius wrote:
> On 2016/03/01 10:04:57, ivoc wrote:
> > On 2016/03/01 09:44:16, stefan-webrtc (holmer) wrote:
> > > On 2016/02/25 15:23:19, the sun wrote:
> > > > Note, you don't really need one queue per event type. To avoid
contention
> > (at
> > > > all costs) you need one queue per *thread* which is logging. But perhaps
> > that
> > > is
> > > > the same in this case?
> > > 
> > > We plan on using the event log in other places too, which may not have the
> > same
> > > threading model as webrtc. Therefore I think it's easier if we keep a
queue
> > per
> > > type.
> > 
> > I'm still not convinced that a single queue is a bad idea. Swaps are really
> fast
> > operations. If we take a lock only while swapping a new message onto a
single
> > queue, there should hardly be any contention. Having a single queue would
> > simplify the RtcEventLog class by quite a bit, and has the advantage that
> > logging starts at a single point in time for all different types of messages
> > (which I think would be nice to have). WDYT?
> 
> We *are* logging from a single point in time.
> 
> Having a single event queue would prevent future optimizations such as 
storing
> the events in the native C types, or reuse the memory allocated by an old
> protobuf event. Note that when you swap protobuf events into a common queue
you
> get back another event of "random" type. Suppose we insert a playout event,
and
> happen to get back an RTP header. The next time the playout function inserts
an
> event, we're either going to insert an event with extra memory to hold an RTP
> header, or we have to free the memory (and allocate new memory when we insert
an
> RTP packet).
> 
> Although we're not doing these optimizations right now, I think it's valuable
to
> maintain the flexibility.

But since we're not using any of those optimizations right now, and since having
these multiple queues makes the code more complicated, why don't we make it a
single queue for now? We already get the big benefit of this change, which is to
do the actual disk writing in a separate thread. Then we can get some mileage
and see whether we actually need to worry about contention.

Adding flexibility very rarely pays off. And besides, doing so won't require
changes to the RtcEventLog clients, as the interface won't change, and will be
easier to do once we know the simple threaded solution works and we have
adequate tests for it.

[the sun, 2016-03-03 14:31:43]

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:121: // Extract the head of each
queue.
Could you organize the code something like this:

for (;;) {
  if (!valid_nn_event) {
    valid_nn_event = nn_queue->Remove(..)
  }
  // (repeated)

  rtc::Event* event_to_write = nullptr;
  bool* event_to_invalidate = nullptr;

  int64_t first_timestamp = ...
  if (valid_nn_event && nn_event_.timestam_up() < first_timestamp) {
    event_to_write = &nn_event_;
    event_to_invalidate = &valid_nn_event;
  }
  // (repeated)

  if (event_to_write) {
    AppendEventToString(event_to_write);
    *event_to_invalidate = false;
  } else {
    break;
  }
}

Just an example, devil is in the detail, and could likely be nicer, but looks
like it could shave off some 50 lines.

[terelius, 2016-03-09 19:49:40]

Please take another look.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/ringbuffer.h
File webrtc/call/ringbuffer.h (right):

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/ringbuffer.h#...
webrtc/call/ringbuffer.h:27: data_ = new T[capacity + 1];
On 2016/03/01 09:44:16, stefan-webrtc (holmer) wrote:
> Comment on "capacity + 1", and/or make it named variable which explains it.

Done.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/ringbuffer.h#...
webrtc/call/ringbuffer.h:37: front_++;
On 2016/03/01 09:44:16, stefan-webrtc (holmer) wrote:
> ++front_

Done. However, the preincrement form has no real advantage since we increment a
raw pointer and don't use the result.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/ringbuffer.h#...
webrtc/call/ringbuffer.h:47: back_++;
On 2016/03/01 09:44:16, stefan-webrtc (holmer) wrote:
> ++back_

Done.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/ringbuffer.h#...
webrtc/call/ringbuffer.h:52: front_++;
On 2016/03/01 09:44:16, stefan-webrtc (holmer) wrote:
> ++front_

Done.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/ringbuffer.h#...
webrtc/call/ringbuffer.h:66: T* data_;
On 2016/03/01 09:44:16, stefan-webrtc (holmer) wrote:
> Can you make data_ a unique_ptr?

Done.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log.cc
File webrtc/call/rtc_event_log.cc (right):

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:56: using RtcEventLog::StartLogging;
On 2016/02/25 15:23:19, the sun wrote:
> Not necessary.

Fixed.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:88: using RtcEventLog::StartLogging;
On 2016/02/25 15:23:19, the sun wrote:
> Not necessary.

Fixed.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:244:
RTC_DCHECK(thread_checker_.CalledOnValidThread());
On 2016/02/25 15:23:19, the sun wrote:
> Why just here? Add to StartLogging() too?

Done.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log.cc:253: return;
On 2016/03/01 09:44:16, stefan-webrtc (holmer) wrote:
> Will we be able to make sure the caller tries to stop the thread again if this
> happens, or how are we failing?
> 
> Can this happen if the we have reached the max size? Or when is there a risk
of
> this happening?

This would happen if the user tries to start logging more than 5 times before
the helper thread gets it's next time slice. Currently, the messages are
processed every 100ms, so you'd have to start or stop on average 50 times per
second to hit this consistently.

Nevertheless, I've reworked this so that it clears any pending START messages
and tries sending a STOP again. This relies on only having one call to
StopLogging at a time, which is verified by the thread checker.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:43: log_to_memory_(true),
On 2016/02/25 15:23:19, the sun wrote:
> log_to_memory and file_ represent the same information? If you just leave
file_
> as nullptr until you get a StartLogging message it may simplify your logic.

Done.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:63: clock_(clock) {
On 2016/02/25 15:23:19, the sun wrote:
> Add RTC_DCHECK(message_queue), and the other pointer arguments.

Done.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:121: // Extract the head of each
queue.
On 2016/03/03 14:31:42, the sun wrote:
> Could you organize the code something like this:
> 
> for (;;) {
>   if (!valid_nn_event) {
>     valid_nn_event = nn_queue->Remove(..)
>   }
>   // (repeated)
> 
>   rtc::Event* event_to_write = nullptr;
>   bool* event_to_invalidate = nullptr;
> 
>   int64_t first_timestamp = ...
>   if (valid_nn_event && nn_event_.timestam_up() < first_timestamp) {
>     event_to_write = &nn_event_;
>     event_to_invalidate = &valid_nn_event;
>   }
>   // (repeated)
> 
>   if (event_to_write) {
>     AppendEventToString(event_to_write);
>     *event_to_invalidate = false;
>   } else {
>     break;
>   }
> }
> 
> Just an example, devil is in the detail, and could likely be nicer, but looks
> like it could shave off some 50 lines.

Done something similar.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:142: while ((valid_config_event_ ||
valid_rtp_event_ || valid_rtcp_event_ ||
On 2016/03/01 09:44:16, stefan-webrtc (holmer) wrote:
> On 2016/02/25 15:23:19, the sun wrote:
> > This handling doesn't look right to me. Have you unit tested?
> > 
> > What about this scenario:
> > 
> > queues contain:
> > config : t=10
> > rtp : t=5
> > output = rtp, config
> > 
> > next time function is called queues contain:
> > rtp : t=7
> > 
> > total output = rtp, config, rtp
> > but should have been = rtp, rtp, config
> > 
> > it seems you can only write when you have time stamps for all the most
recent
> > packets on the queues.
> 
> I'm not sure I follow this. Do you mean that we should only write events if
all
> event queues have valid events? E.g.,
> 
> rtp queue has events: t=5, t=10
> rtcp queue has events: t=20
> playout queue has events: t=6, t=16
> loss event queue has events: t=10
> 
> In this case we only write events up to t=10 because we can't know if the rtp
> queue and loss event queue have pending events but are blocked on something?
> What if some events are very rare, would that become a problem? It seems like
> the config events will be rare enough that we can't block writing on them?
> 

I agree with Stefan; we can't wait for all types of events.

Getting elements out of order can only happen in the rare case where the
scheduler switches thread between when the timestamp is set and the event is
added to the queue. This is unavoidable in any multithreaded application unless
writing the timestamp, inserting the message into the queue and extracting the
message from the queue is guarded by the same lock.

Furthermore, reordering can only happen between events logged on different
threads. Assuming each event type is logged from at most one thread and you only
compare timestamps between evetns of the same type, they will be ordered. If you
need to copare events logged from differeent threads, you can sort the file when
you process it instead of during the real-time logging phase.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:188: }
On 2016/03/01 09:44:16, stefan-webrtc (holmer) wrote:
> Lines 184-188 may be possible to break out to a helper function

Refactored in a different way.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:314: bool valid_message = false;
On 2016/02/25 15:23:19, the sun wrote:
> not needed

Done.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:322: while (valid_message) {
On 2016/02/25 15:23:19, the sun wrote:
> while (message_queue_->Remove(&message)) {

Done.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:329:
file_.reset(message.file.release());
On 2016/02/25 15:23:19, the sun wrote:
> file_.swap(message.file);

Done.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.cc:353: valid_message =
message_queue_->Remove(&message);
On 2016/02/25 15:23:19, the sun wrote:
> remove

Done.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.h:2: *  Copyright (c) 2015 The WebRTC
project authors. All Rights Reserved.
On 2016/03/01 09:44:16, stefan-webrtc (holmer) wrote:
> 2016 perhaps?

Done.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.h:40: struct EventLogMessage {
On 2016/02/25 15:23:19, the sun wrote:
> Move inside RtcEventLogHelperThread and rename to ControlMessage

Done.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.h:48: friend void swap(EventLogMessage&
x, EventLogMessage& y) {
On 2016/02/25 15:23:19, the sun wrote:
> it's common to use rhs and lhs for the arguments in these types of functions.

Done.

https://codereview.webrtc.org/1687703002/diff/80001/webrtc/call/rtc_event_log...
webrtc/call/rtc_event_log_helper_thread.h:51: FileWrapper* xfile =
x.file.release();
On 2016/02/25 15:23:19, the sun wrote:
> scoped_ptr supports swap(). Just x.file.swap(y.file) should work.

Done.

[stefan-webrtc, 2016-03-10 13:03:15]

LG

please take a look at the test failures though.

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:162: // Configuration nees special
treatment since we want to store them in
needs

Also maybe mention why we want to store them in config_history_ both when we
write to memory and when we write to file?

[terelius, 2016-03-10 13:47:41]

The errors are expected and caused by the FileWrapper closing the file after
writing an empty string. I have a CL which changes the behavior of the
FileWrapper, but I'd like to discuss it again with grunell@ before I land it.

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:162: // Configuration nees special
treatment since we want to store them in
On 2016/03/10 13:03:15, stefan-webrtc (holmer) wrote:
> needs
> 
> Also maybe mention why we want to store them in config_history_ both when we
> write to memory and when we write to file?

Done.

[the sun, 2016-03-11 13:21:57]

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/ringbuffer.h
File webrtc/call/ringbuffer.h (right):

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/ringbuffer.h...
webrtc/call/ringbuffer.h:15: #include "webrtc/base/checks.h"
- There should be a unit test for this class
- It should include what it uses (the unit test would have found that).
- Wouldn't it be more natural to use a std::vector<T> as container?
- You shouldn't need to copy the front element.
- Manipulating indexes is usually simpler than messing with pointers.

As per comment in RtcEventLogHelperThread, consider using std::queue instead.

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:21: const int kEventsInHistory =
10000;
I thought we wanted e.g. a 10s back buffer. Does 10000 events resolve to any
particular time interval?

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:43: file_(FileWrapper::Create()),
Why not just let it be null?

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:98: // Is this guaranteed to work
e.g. in future versions of protobuf?
https://developers.google.com/protocol-buffers/docs/encoding#simple

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:195: RTC_DCHECK(!file_->Open());
Why not RTC_DCHECK(!file_); ?

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:219: for (int i = 0;
!history_.empty() && !stop; i++) {
What is "i" for?

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:220: stop =
AppendEventToString(&history_.front());
Does this mean output_string will now have grown to the full size of the ring
buffer, and won't shrink again? Do we want to use up all that memory?

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:36: namespace webrtc {
Enclose the whole contents with "#if ENABLE_RTC_EVENT_LOG". Right now it looks
like it won't compile.

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:46: int64_t max_size_bytes;           
 // Only used with START_FILE.
Add default initialization

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:93: RingBuffer<rtclog::Event>
history_;
How about using a std::queue instead of the RingBuffer, and implement time
window based purge within the confines of this class?

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:101: int64_t max_size_bytes_;
Use non-static member initialization. It is not as easy to forget as relying on
everything to be in the ctor init list.

[ivoc, 2016-03-11 13:29:53]

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:96: // TODO(terelius): We create a
new event strem per event, but it will look
strem -> stream

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:102: max_size_bytes_) {
Can this be moved to the previous line? The formatting looks strange to me here.

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:48: int64_t stop_time;                
 // Used with all 3 message types.
This feature is not currently used on the API, right? How about removing it
until we need it?

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:109: rtclog::Event config_event_;
These events as well as the valid_<X> flags below only seem to be used in the
ProcessInOrder function, how about moving them to being static variables inside
of that function?

[the sun, 2016-03-11 13:37:47]

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:109: rtclog::Event config_event_;
On 2016/03/11 13:29:53, ivoc wrote:
> These events as well as the valid_<X> flags below only seem to be used in the
> ProcessInOrder function, how about moving them to being static variables
inside
> of that function?

No. That is tantamount to making them global, in the sense that there can only
ever be ONE RtcEventLogHelperThread object. Static variables should be avoided.

[ivoc, 2016-03-11 13:40:27]

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:109: rtclog::Event config_event_;
On 2016/03/11 13:37:47, the sun wrote:
> On 2016/03/11 13:29:53, ivoc wrote:
> > These events as well as the valid_<X> flags below only seem to be used in
the
> > ProcessInOrder function, how about moving them to being static variables
> inside
> > of that function?
> 
> No. That is tantamount to making them global, in the sense that there can only
> ever be ONE RtcEventLogHelperThread object. Static variables should be
avoided.

Oops, my bad, you're absolutely right.

[terelius, 2016-03-18 14:03:25]

This CL is currently blocked on moving swap_queue.h to base/

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:96: // TODO(terelius): We create a
new event strem per event, but it will look
On 2016/03/11 13:29:53, ivoc wrote:
> strem -> stream

Done.

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:102: max_size_bytes_) {
On 2016/03/11 13:29:53, ivoc wrote:
> Can this be moved to the previous line? The formatting looks strange to me
here.

Done.

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/100001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:48: int64_t stop_time;                
 // Used with all 3 message types.
On 2016/03/11 13:29:53, ivoc wrote:
> This feature is not currently used on the API, right? How about removing it
> until we need it?

It is not pat of the API, but it is used by StopLogging to ensure that we only
log events that came before the call to StopLogging. (I.e. not events that were
queued between the call to StopLogging and the next time slice for the logging
thread.)

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/ringbuffer.h
File webrtc/call/ringbuffer.h (right):

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/ringbuffer.h...
webrtc/call/ringbuffer.h:15: #include "webrtc/base/checks.h"
On 2016/03/11 13:21:56, the sun wrote:
> - There should be a unit test for this class
> - It should include what it uses (the unit test would have found that).
> - Wouldn't it be more natural to use a std::vector<T> as container?
> - You shouldn't need to copy the front element.
> - Manipulating indexes is usually simpler than messing with pointers.
> 
> As per comment in RtcEventLogHelperThread, consider using std::queue instead.

-Added unit test.
-Fixed include.
-We are not using any of the vector features, and I don't see how the code would
be simpler by using it.
-I'm not copying the front element. I'm keeping a pointer to the beginning of
the allocated memory and another to the first element in the queue.
-If using indices, we would need an index for the first element, an index for
the last element (or the number of elements), a pointer to the memory region and
an integer for the size of the memory region. I could change the implementation,
but I don't think if makes much difference. It could allow us to skip allocating
one extra element, I guess.
-A std::deque would be less efficient and less natural. We want a fixed size
queue that reuses memory.

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:21: const int kEventsInHistory =
10000;
On 2016/03/11 13:21:57, the sun wrote:
> I thought we wanted e.g. a 10s back buffer. Does 10000 events resolve to any
> particular time interval?

Imo it is much better to set the history limit based on memory usage rather than
time. If you have enough memory, why would you want to discard events that are
older than 10s? If you are somehow generating events at a much greater rate than
expected, why would you want the memory usage to grow without bounds?

Ball-park estimate of event frequencies:
Audio playouts should occur every 10ms -> 100 playout events/s.
Assuming each audio packet contains 10ms audio -> 100 incoming audio packets/s.
Same assumption -> 100 outgoing audio packets/s.
At 2MB/s with video packets at 1000 bytes each -> 250 incoming video packets/s.
Same assumption -> 250 outgoing video packets/s.
20 incoming RTCP per second.
20 outgoing RTCP per second.
One bandwidth update per incoming RTCP -> 20 updates/s.

This gives a total of 860 events per second. So, 10000 events should be good for
10 seconds worth of data at a relatively high bitrate. The exact amount is open
for tuning.

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:43: file_(FileWrapper::Create()),
On 2016/03/11 13:21:57, the sun wrote:
> Why not just let it be null?

I could do that, but I don't think there is much difference. The current
approach always has a valid FileWrapper which can be either open or closed. The
other way would be to have either an open FileWrapper or a null-pointer. I chose
the former because FileWrapper can decide to close the file on it's own (in
exceptional circumstances), and the current check would make it log to memory
instead. If we tested the pointer for null, we would instead attempt to write to
the file and the FileWrapper would ignore it. In other words, we would end up
with events written neither to file nor to memory.

I don't think this makes much difference either way since this should not
normally happen, but the first approached seemed a bit cleaner.

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:98: // Is this guaranteed to work
e.g. in future versions of protobuf?
On 2016/03/11 13:21:57, the sun wrote:
> https://developers.google.com/protocol-buffers/docs/encoding#simple

Acknowledged.

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:195: RTC_DCHECK(!file_->Open());
On 2016/03/11 13:21:57, the sun wrote:
> Why not RTC_DCHECK(!file_); ?

That would work too, but see discussion above.

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:219: for (int i = 0;
!history_.empty() && !stop; i++) {
On 2016/03/11 13:21:57, the sun wrote:
> What is "i" for?

Done, thanks. Was used for debugging.

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:220: stop =
AppendEventToString(&history_.front());
On 2016/03/11 13:21:57, the sun wrote:
> Does this mean output_string will now have grown to the full size of the ring
> buffer, and won't shrink again? Do we want to use up all that memory?

Yes it does, but the string version uses significantly less memory than the
protobuf ringbuffer. I've added code to release the memory since you are
concerned.

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:36: namespace webrtc {
On 2016/03/11 13:21:57, the sun wrote:
> Enclose the whole contents with "#if ENABLE_RTC_EVENT_LOG". Right now it looks
> like it won't compile.

Done.

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:46: int64_t max_size_bytes;           
 // Only used with START_FILE.
On 2016/03/11 13:21:57, the sun wrote:
> Add default initialization

Not sure why, but done.

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:93: RingBuffer<rtclog::Event>
history_;
On 2016/03/11 13:21:57, the sun wrote:
> How about using a std::queue instead of the RingBuffer, and implement time
> window based purge within the confines of this class?

A space based limit is more efficient and more natural. (See discussion about
history length in event_log_helper_thread.cc comment.)

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:101: int64_t max_size_bytes_;
On 2016/03/11 13:21:57, the sun wrote:
> Use non-static member initialization. It is not as easy to forget as relying
on
> everything to be in the ctor init list.

I think the general consensus in the video team is to do all initialization in
the constructor.

[stefan-webrtc, 2016-03-23 12:51:42]

ping, any chance we can get this in this week?

[terelius, 2016-03-23 12:59:03]

On 2016/03/23 12:51:42, stefan-webrtc (holmer) wrote:
> ping, any chance we can get this in this week?

The swap_queue move is landing right now. I still need a several lgtms for this
CL though.

[stefan-webrtc, 2016-03-23 13:05:49]

On 2016/03/23 12:59:03, terelius wrote:
> On 2016/03/23 12:51:42, stefan-webrtc (holmer) wrote:
> > ping, any chance we can get this in this week?
> 
> The swap_queue move is landing right now. I still need a several lgtms for
this
> CL though.

Ack. I missed the comment that this was blocked on moving the swap queue... Can
we make progress on reviewing this CL in the meantime?

[terelius, 2016-03-23 13:08:23]

On 2016/03/23 13:05:49, stefan-webrtc (holmer) wrote:
> On 2016/03/23 12:59:03, terelius wrote:
> > On 2016/03/23 12:51:42, stefan-webrtc (holmer) wrote:
> > > ping, any chance we can get this in this week?
> > 
> > The swap_queue move is landing right now. I still need a several lgtms for
> this
> > CL though.
> 
> Ack. I missed the comment that this was blocked on moving the swap queue...
Can
> we make progress on reviewing this CL in the meantime?

Yes. The only thing I expect to update after moving swap_queue.h is the include
path.

[the sun, 2016-03-23 13:18:21]

On 2016/03/23 13:08:23, terelius wrote:
> On 2016/03/23 13:05:49, stefan-webrtc (holmer) wrote:
> > On 2016/03/23 12:59:03, terelius wrote:
> > > On 2016/03/23 12:51:42, stefan-webrtc (holmer) wrote:
> > > > ping, any chance we can get this in this week?
> > > 
> > > The swap_queue move is landing right now. I still need a several lgtms for
> > this
> > > CL though.
> > 
> > Ack. I missed the comment that this was blocked on moving the swap queue...
> Can
> > we make progress on reviewing this CL in the meantime?
> 
> Yes. The only thing I expect to update after moving swap_queue.h is the
include
> path.

Have you uploaded the latest patch set? I don't see the ringbuffer unit test
that you claim to have added.

[the sun, 2016-03-23 13:18:22]

On 2016/03/23 13:08:23, terelius wrote:
> On 2016/03/23 13:05:49, stefan-webrtc (holmer) wrote:
> > On 2016/03/23 12:59:03, terelius wrote:
> > > On 2016/03/23 12:51:42, stefan-webrtc (holmer) wrote:
> > > > ping, any chance we can get this in this week?
> > > 
> > > The swap_queue move is landing right now. I still need a several lgtms for
> > this
> > > CL though.
> > 
> > Ack. I missed the comment that this was blocked on moving the swap queue...
> Can
> > we make progress on reviewing this CL in the meantime?
> 
> Yes. The only thing I expect to update after moving swap_queue.h is the
include
> path.

Have you uploaded the latest patch set? I don't see the ringbuffer unit test
that you claim to have added.

[terelius, 2016-03-23 13:51:32]

On 2016/03/23 13:18:22, the sun wrote:
> On 2016/03/23 13:08:23, terelius wrote:
> > On 2016/03/23 13:05:49, stefan-webrtc (holmer) wrote:
> > > On 2016/03/23 12:59:03, terelius wrote:
> > > > On 2016/03/23 12:51:42, stefan-webrtc (holmer) wrote:
> > > > > ping, any chance we can get this in this week?
> > > > 
> > > > The swap_queue move is landing right now. I still need a several lgtms
for
> > > this
> > > > CL though.
> > > 
> > > Ack. I missed the comment that this was blocked on moving the swap
queue...
> > Can
> > > we make progress on reviewing this CL in the meantime?
> > 
> > Yes. The only thing I expect to update after moving swap_queue.h is the
> include
> > path.
> 
> Have you uploaded the latest patch set? I don't see the ringbuffer unit test
> that you claim to have added.

Oops. The upload probably failed because of the new DEPS check. I've changed the
include path to base/, so now it gets uploaded but it won't compile until
swap_queue.h has been moved.

[the sun, 2016-03-24 13:49:44]

Keeping a preset size ring buffer of non-serialized proto mesages is not a good
long term solution to keep memory usage within limits.

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:21: const int kEventsInHistory =
10000;
On 2016/03/18 14:03:25, terelius wrote:
> On 2016/03/11 13:21:57, the sun wrote:
> > I thought we wanted e.g. a 10s back buffer. Does 10000 events resolve to any
> > particular time interval?
> 
> Imo it is much better to set the history limit based on memory usage rather
than
> time. If you have enough memory, why would you want to discard events that are
> older than 10s? If you are somehow generating events at a much greater rate
than
> expected, why would you want the memory usage to grow without bounds?

But that's exactly one of the problems with the current solution - it's entirely
possible to log 10000 large messages (if such a type is added) and use up large
amounts of memory. I think we need to decide which is the most important -
limited memory usage, or a specific back window. The current solution guarantees
neither.

> Ball-park estimate of event frequencies:
> Audio playouts should occur every 10ms -> 100 playout events/s.
> Assuming each audio packet contains 10ms audio -> 100 incoming audio
packets/s.
> Same assumption -> 100 outgoing audio packets/s.
> At 2MB/s with video packets at 1000 bytes each -> 250 incoming video
packets/s.
> Same assumption -> 250 outgoing video packets/s.
> 20 incoming RTCP per second.
> 20 outgoing RTCP per second.
> One bandwidth update per incoming RTCP -> 20 updates/s.
> 
> This gives a total of 860 events per second. So, 10000 events should be good
for
> 10 seconds worth of data at a relatively high bitrate. The exact amount is
open
> for tuning.

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:279: file_->CloseFile();
file_.reset(nullptr);

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:291: if (!file_->Open()) {
Checking file_ != nullptr should be enough. file_->Open() is implicit when file_
is valid.

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:299: message.file->CloseFile();
I understand closing the old file handle, but why not handle the message?

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:40: class RtcEventLogHelperThread {
final

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:51: rtc::scoped_ptr<FileWrapper> file;
 // Only used with START_FILE.
unique_ptr

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:99: RingBuffer<rtclog::Event>
history_;
I realize we've been at this before, but using a buffer of rtclog::Event:s for
the history feels wrong to me. I think either you're interested in keeping the
last N seconds of events (in which case you need to use a variable size queue
and look at time stamps), or you're interested in limiting the memory required
for the history (in which case you are best off serializing the messages as they
go into the history).

A buffer of a preset number of proto messages will achieve neither of the above.
When the distribution changes (e.g. new log points are added), you may either
start overusing memory, or keeping a too short history. The results aren't very
deterministic with the current solution.

The best option is likely to keep a buffer of serialized protos to limit the
runtime memory footprint. Incidentally that should make the code simpler too, as
there is less difference between logging to file/memory.

[terelius, 2016-03-29 09:38:32]

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:21: const int kEventsInHistory =
10000;
On 2016/03/24 13:49:43, the sun wrote:
> On 2016/03/18 14:03:25, terelius wrote:
> > On 2016/03/11 13:21:57, the sun wrote:
> > > I thought we wanted e.g. a 10s back buffer. Does 10000 events resolve to
any
> > > particular time interval?
> > 
> > Imo it is much better to set the history limit based on memory usage rather
> than
> > time. If you have enough memory, why would you want to discard events that
are
> > older than 10s? If you are somehow generating events at a much greater rate
> than
> > expected, why would you want the memory usage to grow without bounds?
> 
> But that's exactly one of the problems with the current solution - it's
entirely
> possible to log 10000 large messages (if such a type is added) and use up
large
> amounts of memory. I think we need to decide which is the most important -
> limited memory usage, or a specific back window. The current solution
guarantees
> neither.
> 

But there is no very large event type. Even if all 10000 events used 200 bytes
each, the history would be limited to 2 MB. Although this is a bit more than we
are aiming for, I don't think it is a terrible worst case scenario.

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:99: RingBuffer<rtclog::Event>
history_;
On 2016/03/24 13:49:43, the sun wrote:
> I realize we've been at this before, but using a buffer of rtclog::Event:s for
> the history feels wrong to me. I think either you're interested in keeping the
> last N seconds of events (in which case you need to use a variable size queue
> and look at time stamps), or you're interested in limiting the memory required
> for the history (in which case you are best off serializing the messages as
they
> go into the history).
> 
> A buffer of a preset number of proto messages will achieve neither of the
above.
> When the distribution changes (e.g. new log points are added), you may either
> start overusing memory, or keeping a too short history. The results aren't
very
> deterministic with the current solution.
> 
> The best option is likely to keep a buffer of serialized protos to limit the
> runtime memory footprint. Incidentally that should make the code simpler too,
as
> there is less difference between logging to file/memory.

As discussed in a previous comment, I would like to keep a history of serialized
events. However, the natural way to do this (without keeping memory unused or
allocating new memory for each event) requires a custom ringbuffer where you can
request space for a certain number of bytes. While this isn't difficult, it is
more complicated than the current ring buffer so I figured it would be better to
not try cramming it into the same CL.

[the sun, 2016-03-30 09:12:39]

stefan@, I leave it to you to decide whether the current design is acceptable in
the short term. If there is a strong need to have the feature soon, it may make
sense to land the CL even though there are things that need to be addressed.

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:21: const int kEventsInHistory =
10000;
On 2016/03/29 09:38:32, terelius wrote:
> On 2016/03/24 13:49:43, the sun wrote:
> > On 2016/03/18 14:03:25, terelius wrote:
> > > On 2016/03/11 13:21:57, the sun wrote:
> > > > I thought we wanted e.g. a 10s back buffer. Does 10000 events resolve to
> any
> > > > particular time interval?
> > > 
> > > Imo it is much better to set the history limit based on memory usage
rather
> > than
> > > time. If you have enough memory, why would you want to discard events that
> are
> > > older than 10s? If you are somehow generating events at a much greater
rate
> > than
> > > expected, why would you want the memory usage to grow without bounds?
> > 
> > But that's exactly one of the problems with the current solution - it's
> entirely
> > possible to log 10000 large messages (if such a type is added) and use up
> large
> > amounts of memory. I think we need to decide which is the most important -
> > limited memory usage, or a specific back window. The current solution
> guarantees
> > neither.
> > 
> 
> But there is no very large event type. Even if all 10000 events used 200 bytes
> each, the history would be limited to 2 MB. Although this is a bit more than
we
> are aiming for, I don't think it is a terrible worst case scenario.

So what happens then if a large event type is *added*? Remember that one
objective with a design is to make it hard for someone to mess it up *in the
future*. Things will change. The logging frequency of these events will change.
The events being logged will change. Someone who isn't you is going to introduce
such changes, and that someone won't know, or have the time to get to know, all
details about the logging mechanism. Give them something simple and which can't
break.

Besides, if you're so certain of RAM never ever being an issue, why don't you
instead set an exact time limit? The current approach is a half-way
non-solution.

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:99: RingBuffer<rtclog::Event>
history_;
On 2016/03/29 09:38:32, terelius wrote:
> On 2016/03/24 13:49:43, the sun wrote:
> > I realize we've been at this before, but using a buffer of rtclog::Event:s
for
> > the history feels wrong to me. I think either you're interested in keeping
the
> > last N seconds of events (in which case you need to use a variable size
queue
> > and look at time stamps), or you're interested in limiting the memory
required
> > for the history (in which case you are best off serializing the messages as
> they
> > go into the history).
> > 
> > A buffer of a preset number of proto messages will achieve neither of the
> above.
> > When the distribution changes (e.g. new log points are added), you may
either
> > start overusing memory, or keeping a too short history. The results aren't
> very
> > deterministic with the current solution.
> > 
> > The best option is likely to keep a buffer of serialized protos to limit the
> > runtime memory footprint. Incidentally that should make the code simpler
too,
> as
> > there is less difference between logging to file/memory.
> 
> As discussed in a previous comment, I would like to keep a history of
serialized
> events. However, the natural way to do this (without keeping memory unused or
> allocating new memory for each event) requires a custom ringbuffer where you
can
> request space for a certain number of bytes. While this isn't difficult, it is
> more complicated than the current ring buffer so I figured it would be better
to
> not try cramming it into the same CL.

One custom ring buffer for another custom ring buffer? Hmm.

Well. *maybe* we have to land this anyway and go back and refine it. Stefan,
wdyt?

[stefan-webrtc, 2016-03-30 09:23:55]

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:99: RingBuffer<rtclog::Event>
history_;
On 2016/03/30 09:12:39, the sun wrote:
> On 2016/03/29 09:38:32, terelius wrote:
> > On 2016/03/24 13:49:43, the sun wrote:
> > > I realize we've been at this before, but using a buffer of rtclog::Event:s
> for
> > > the history feels wrong to me. I think either you're interested in keeping
> the
> > > last N seconds of events (in which case you need to use a variable size
> queue
> > > and look at time stamps), or you're interested in limiting the memory
> required
> > > for the history (in which case you are best off serializing the messages
as
> > they
> > > go into the history).
> > > 
> > > A buffer of a preset number of proto messages will achieve neither of the
> > above.
> > > When the distribution changes (e.g. new log points are added), you may
> either
> > > start overusing memory, or keeping a too short history. The results aren't
> > very
> > > deterministic with the current solution.
> > > 
> > > The best option is likely to keep a buffer of serialized protos to limit
the
> > > runtime memory footprint. Incidentally that should make the code simpler
> too,
> > as
> > > there is less difference between logging to file/memory.
> > 
> > As discussed in a previous comment, I would like to keep a history of
> serialized
> > events. However, the natural way to do this (without keeping memory unused
or
> > allocating new memory for each event) requires a custom ringbuffer where you
> can
> > request space for a certain number of bytes. While this isn't difficult, it
is
> > more complicated than the current ring buffer so I figured it would be
better
> to
> > not try cramming it into the same CL.
> 
> One custom ring buffer for another custom ring buffer? Hmm.
> 
> Well. *maybe* we have to land this anyway and go back and refine it. Stefan,
> wdyt?

I would very much prefer landing something sooner rather than later. Would it be
reasonable to go back and refine this when we have tried it out a bit and have a
better idea what we want to optimize for?

We don't know if there's a point in optimizing for even less memory usage, once
we decide it is we should write a short design doc of how to improve and agree
on the optimal solution. SG? :)

We'll continue working on this in Q2, but we really need something like this CL
sooner rather than later.

[terelius, 2016-03-30 10:36:59]

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/120001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:21: const int kEventsInHistory =
10000;
On 2016/03/30 09:12:38, the sun wrote:
> On 2016/03/29 09:38:32, terelius wrote:
> > On 2016/03/24 13:49:43, the sun wrote:
> > > On 2016/03/18 14:03:25, terelius wrote:
> > > > On 2016/03/11 13:21:57, the sun wrote:
> > > > > I thought we wanted e.g. a 10s back buffer. Does 10000 events resolve
to
> > any
> > > > > particular time interval?
> > > > 
> > > > Imo it is much better to set the history limit based on memory usage
> rather
> > > than
> > > > time. If you have enough memory, why would you want to discard events
that
> > are
> > > > older than 10s? If you are somehow generating events at a much greater
> rate
> > > than
> > > > expected, why would you want the memory usage to grow without bounds?
> > > 
> > > But that's exactly one of the problems with the current solution - it's
> > entirely
> > > possible to log 10000 large messages (if such a type is added) and use up
> > large
> > > amounts of memory. I think we need to decide which is the most important -
> > > limited memory usage, or a specific back window. The current solution
> > guarantees
> > > neither.
> > > 
> > 
> > But there is no very large event type. Even if all 10000 events used 200
bytes
> > each, the history would be limited to 2 MB. Although this is a bit more than
> we
> > are aiming for, I don't think it is a terrible worst case scenario.
> 
> So what happens then if a large event type is *added*? Remember that one
> objective with a design is to make it hard for someone to mess it up *in the
> future*. Things will change. The logging frequency of these events will
change.
> The events being logged will change. Someone who isn't you is going to
introduce
> such changes, and that someone won't know, or have the time to get to know,
all
> details about the logging mechanism. Give them something simple and which
can't
> break.
> 
> Besides, if you're so certain of RAM never ever being an issue, why don't you
> instead set an exact time limit? The current approach is a half-way
> non-solution.

This code will break the memory limit if a new event type is added *and* the new
event is large *and* the new log points comprise a significant fraction of the
currently logged events.

A time based window will break the memory limit if large events are added *or*
if a significant fraction of new log points are added *or* if the actual rate of
events differs from what we expect (for example because we are in a multi-party
call on a fully connected mesh network).

In addition, the time based solution is more computationally expensive, has more
memory overhead, requires extra code to prune old events, and likely has worse
cache locality. (Though to be honest, the cache locality probably won't have
much impact due to the way we fill the history buffer).

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:99: RingBuffer<rtclog::Event>
history_;
On 2016/03/30 09:12:39, the sun wrote:
> On 2016/03/29 09:38:32, terelius wrote:
> > On 2016/03/24 13:49:43, the sun wrote:
> > > I realize we've been at this before, but using a buffer of rtclog::Event:s
> for
> > > the history feels wrong to me. I think either you're interested in keeping
> the
> > > last N seconds of events (in which case you need to use a variable size
> queue
> > > and look at time stamps), or you're interested in limiting the memory
> required
> > > for the history (in which case you are best off serializing the messages
as
> > they
> > > go into the history).
> > > 
> > > A buffer of a preset number of proto messages will achieve neither of the
> > above.
> > > When the distribution changes (e.g. new log points are added), you may
> either
> > > start overusing memory, or keeping a too short history. The results aren't
> > very
> > > deterministic with the current solution.
> > > 
> > > The best option is likely to keep a buffer of serialized protos to limit
the
> > > runtime memory footprint. Incidentally that should make the code simpler
> too,
> > as
> > > there is less difference between logging to file/memory.
> > 
> > As discussed in a previous comment, I would like to keep a history of
> serialized
> > events. However, the natural way to do this (without keeping memory unused
or
> > allocating new memory for each event) requires a custom ringbuffer where you
> can
> > request space for a certain number of bytes. While this isn't difficult, it
is
> > more complicated than the current ring buffer so I figured it would be
better
> to
> > not try cramming it into the same CL.
> 
> One custom ring buffer for another custom ring buffer? Hmm.
> 
> Well. *maybe* we have to land this anyway and go back and refine it. Stefan,
> wdyt?

The point is that the ringbuffer for serialized events would be significantly
more complicated. You need to keep track of where each event start and end, and
you need to handle serialized events that wrap across the memory boundary. This
is not technically difficult, but will make the code more complex. To keep the
code as simple as possible (as you requested) I prefer to go for a solution that
improves both the usefulness of the log and the robustness to changes even
though the solution isn't optimal.

Compared to a time based window, the produced logs will be more useful since we
can keep more events in memory if we have space to spare, and it is more robust
since adding new small-ish event types or more log calls does not increase
memory usage.

[stefan-webrtc, 2016-04-01 13:46:25]

If we can agree on landing this as a first version, it would be good to get the
current comments fixed, and any final comments submitted (if any).

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:99: RingBuffer<rtclog::Event>
history_;
On 2016/03/30 10:36:59, terelius wrote:
> On 2016/03/30 09:12:39, the sun wrote:
> > On 2016/03/29 09:38:32, terelius wrote:
> > > On 2016/03/24 13:49:43, the sun wrote:
> > > > I realize we've been at this before, but using a buffer of
rtclog::Event:s
> > for
> > > > the history feels wrong to me. I think either you're interested in
keeping
> > the
> > > > last N seconds of events (in which case you need to use a variable size
> > queue
> > > > and look at time stamps), or you're interested in limiting the memory
> > required
> > > > for the history (in which case you are best off serializing the messages
> as
> > > they
> > > > go into the history).
> > > > 
> > > > A buffer of a preset number of proto messages will achieve neither of
the
> > > above.
> > > > When the distribution changes (e.g. new log points are added), you may
> > either
> > > > start overusing memory, or keeping a too short history. The results
aren't
> > > very
> > > > deterministic with the current solution.
> > > > 
> > > > The best option is likely to keep a buffer of serialized protos to limit
> the
> > > > runtime memory footprint. Incidentally that should make the code simpler
> > too,
> > > as
> > > > there is less difference between logging to file/memory.
> > > 
> > > As discussed in a previous comment, I would like to keep a history of
> > serialized
> > > events. However, the natural way to do this (without keeping memory unused
> or
> > > allocating new memory for each event) requires a custom ringbuffer where
you
> > can
> > > request space for a certain number of bytes. While this isn't difficult,
it
> is
> > > more complicated than the current ring buffer so I figured it would be
> better
> > to
> > > not try cramming it into the same CL.
> > 
> > One custom ring buffer for another custom ring buffer? Hmm.
> > 
> > Well. *maybe* we have to land this anyway and go back and refine it. Stefan,
> > wdyt?
> 
> The point is that the ringbuffer for serialized events would be significantly
> more complicated. You need to keep track of where each event start and end,
and
> you need to handle serialized events that wrap across the memory boundary.
This
> is not technically difficult, but will make the code more complex. To keep the
> code as simple as possible (as you requested) I prefer to go for a solution
that
> improves both the usefulness of the log and the robustness to changes even
> though the solution isn't optimal.
> 
> Compared to a time based window, the produced logs will be more useful since
we
> can keep more events in memory if we have space to spare, and it is more
robust
> since adding new small-ish event types or more log calls does not increase
> memory usage.

Sounds like a reasonable trade-off to me for the first version. I suggest we
move it in either direction once we know what we really want (reduce memory
footprint or a true time limit, or both).

Solis, let me know if you disagree.

[the sun, 2016-04-01 15:57:01]

On 2016/04/01 13:46:25, stefan-webrtc (holmer) wrote:
> If we can agree on landing this as a first version, it would be good to get
the
> current comments fixed, and any final comments submitted (if any).
> 
>
https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
> File webrtc/call/rtc_event_log_helper_thread.h (right):
> 
>
https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
> webrtc/call/rtc_event_log_helper_thread.h:99: RingBuffer<rtclog::Event>
> history_;
> On 2016/03/30 10:36:59, terelius wrote:
> > On 2016/03/30 09:12:39, the sun wrote:
> > > On 2016/03/29 09:38:32, terelius wrote:
> > > > On 2016/03/24 13:49:43, the sun wrote:
> > > > > I realize we've been at this before, but using a buffer of
> rtclog::Event:s
> > > for
> > > > > the history feels wrong to me. I think either you're interested in
> keeping
> > > the
> > > > > last N seconds of events (in which case you need to use a variable
size
> > > queue
> > > > > and look at time stamps), or you're interested in limiting the memory
> > > required
> > > > > for the history (in which case you are best off serializing the
messages
> > as
> > > > they
> > > > > go into the history).
> > > > > 
> > > > > A buffer of a preset number of proto messages will achieve neither of
> the
> > > > above.
> > > > > When the distribution changes (e.g. new log points are added), you may
> > > either
> > > > > start overusing memory, or keeping a too short history. The results
> aren't
> > > > very
> > > > > deterministic with the current solution.
> > > > > 
> > > > > The best option is likely to keep a buffer of serialized protos to
limit
> > the
> > > > > runtime memory footprint. Incidentally that should make the code
simpler
> > > too,
> > > > as
> > > > > there is less difference between logging to file/memory.
> > > > 
> > > > As discussed in a previous comment, I would like to keep a history of
> > > serialized
> > > > events. However, the natural way to do this (without keeping memory
unused
> > or
> > > > allocating new memory for each event) requires a custom ringbuffer where
> you
> > > can
> > > > request space for a certain number of bytes. While this isn't difficult,
> it
> > is
> > > > more complicated than the current ring buffer so I figured it would be
> > better
> > > to
> > > > not try cramming it into the same CL.
> > > 
> > > One custom ring buffer for another custom ring buffer? Hmm.
> > > 
> > > Well. *maybe* we have to land this anyway and go back and refine it.
Stefan,
> > > wdyt?
> > 
> > The point is that the ringbuffer for serialized events would be
significantly
> > more complicated. You need to keep track of where each event start and end,
> and
> > you need to handle serialized events that wrap across the memory boundary.
> This
> > is not technically difficult, but will make the code more complex. To keep
the
> > code as simple as possible (as you requested) I prefer to go for a solution
> that
> > improves both the usefulness of the log and the robustness to changes even
> > though the solution isn't optimal.
> > 
> > Compared to a time based window, the produced logs will be more useful since
> we
> > can keep more events in memory if we have space to spare, and it is more
> robust
> > since adding new small-ish event types or more log calls does not increase
> > memory usage.
> 
> Sounds like a reasonable trade-off to me for the first version. I suggest we
> move it in either direction once we know what we really want (reduce memory
> footprint or a true time limit, or both).
> 
> Solis, let me know if you disagree.

There are obviously things in here that I don't agree with, but given that the
system is well sand-boxed it may make sense anyway to go ahead and try it out.

In the current state however, I cannot give it my l-g-t-m, so I'm removing
myself as reviewer.

[the sun, 2016-04-01 15:57:21]

solenberg@webrtc.org changed reviewers:
- solenberg@webrtc.org

[ivoc, 2016-04-05 14:57:09]

Although I somewhat agree with Fredrik on some points, I think it would be good
to not delay this CL any further. Although perhaps not perfect, it does contain
useful functionality and is an improvement over the current implementation. So
here is my LGTM, if necessary we can always discuss a redesign later on.

[the sun, 2016-04-08 08:33:21]

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

[the sun, 2016-04-08 08:40:18]

Björn and I had an offline discussion today and are in agreement that we should
go forward with landing this feature now. Additional improvements can be
addressed in subsequent CLs, if necessary.

LGTM.

[stefan-webrtc, 2016-04-12 15:48:50]

lgtm

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:102: max_size_bytes_) {
Shouldn't this be moved to the line above?

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:129: const size_t kNumberOfQueues =
5;
You should be able to write sizeof(queue)/sizeof(queue[0]) instead

[terelius, 2016-04-16 23:29:24]

I switched to a using a single queue for all types of events since I won't have
time for further optimizations. Also overloaded push_back for rvalue references
in the Ringbuffer. Please take a look.

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:102: max_size_bytes_) {
On 2016/04/12 15:48:50, stefan-webrtc (holmer) wrote:
> Shouldn't this be moved to the line above?

It is automatically formatted. I agree it isn't very pretty, but there is a
certain logic to the formatting. (Split the line at the operator with least
precedence and start both lhs and rhs at the same indentations.) I can do some
manual formatting if you prefer.

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:129: const size_t kNumberOfQueues =
5;
On 2016/04/12 15:48:50, stefan-webrtc (holmer) wrote:
> You should be able to write sizeof(queue)/sizeof(queue[0]) instead

I removed this completely.

[stefan-webrtc, 2016-04-19 08:23:04]

lgtm again with nits fixed.

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/ringbuffer.h
File webrtc/call/ringbuffer.h (right):

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/ringbuffer.h...
webrtc/call/ringbuffer.h:70: swap(*back_, elem);
I'd prefer std::swap() without using.

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/ringbuffer_u...
File webrtc/call/ringbuffer_unittest.cc (right):

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/ringbuffer_u...
webrtc/call/ringbuffer_unittest.cc:91: int capacity = 100;
size_t

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/ringbuffer_u...
webrtc/call/ringbuffer_unittest.cc:92: int insertions = 3 * capacity + 25;
size_t

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:130: // having more event in the
queue.
more events

[stefan-webrtc, 2016-04-19 08:23:04]

lgtm again with nits fixed.

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/ringbuffer.h
File webrtc/call/ringbuffer.h (right):

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/ringbuffer.h...
webrtc/call/ringbuffer.h:70: swap(*back_, elem);
I'd prefer std::swap() without using.

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/ringbuffer_u...
File webrtc/call/ringbuffer_unittest.cc (right):

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/ringbuffer_u...
webrtc/call/ringbuffer_unittest.cc:91: int capacity = 100;
size_t

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/ringbuffer_u...
webrtc/call/ringbuffer_unittest.cc:92: int insertions = 3 * capacity + 25;
size_t

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:130: // having more event in the
queue.
more events

[terelius, 2016-04-19 09:21:56]

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/ringbuffer.h
File webrtc/call/ringbuffer.h (right):

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/ringbuffer.h...
webrtc/call/ringbuffer.h:70: swap(*back_, elem);
On 2016/04/19 08:23:04, stefan-webrtc (holmer) wrote:
> I'd prefer std::swap() without using.

I believe "using std::swap" is the idiomatic way to swap things in templated
code. After "using std::swap", argument dependent lookup will resolve swap to
T::swap if that's available and std::swap otherwise.

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/ringbuffer_u...
File webrtc/call/ringbuffer_unittest.cc (right):

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/ringbuffer_u...
webrtc/call/ringbuffer_unittest.cc:91: int capacity = 100;
On 2016/04/19 08:23:04, stefan-webrtc (holmer) wrote:
> size_t

Done.

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/ringbuffer_u...
webrtc/call/ringbuffer_unittest.cc:92: int insertions = 3 * capacity + 25;
On 2016/04/19 08:23:04, stefan-webrtc (holmer) wrote:
> size_t

Done.

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:130: // having more event in the
queue.
On 2016/04/19 08:23:04, stefan-webrtc (holmer) wrote:
> more events

Done.

[stefan-webrtc, 2016-04-19 09:33:32]

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/ringbuffer.h
File webrtc/call/ringbuffer.h (right):

https://codereview.webrtc.org/1687703002/diff/200001/webrtc/call/ringbuffer.h...
webrtc/call/ringbuffer.h:70: swap(*back_, elem);
On 2016/04/19 09:21:56, terelius wrote:
> On 2016/04/19 08:23:04, stefan-webrtc (holmer) wrote:
> > I'd prefer std::swap() without using.
> 
> I believe "using std::swap" is the idiomatic way to swap things in templated
> code. After "using std::swap", argument dependent lookup will resolve swap to
> T::swap if that's available and std::swap otherwise.

I see, I thought

using std::swap;
swap(*back_, elem);

was identical to:

std::swap(*back_, elem);

[the sun, 2016-04-20 11:30:15]

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:51: rtc::scoped_ptr<FileWrapper> file;
 // Only used with START_FILE.
On 2016/03/24 13:49:43, the sun wrote:
> unique_ptr

Still want this.

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/mock/mock_rt...
File webrtc/call/mock/mock_rtc_event_log.h (right):

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/mock/mock_rt...
webrtc/call/mock/mock_rtc_event_log.h:25: bool(const std::string& file_name,
int64_t max_size_bytes_));
nit: We don't use trailing _ in arguments

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/ringbuffer.h
File webrtc/call/ringbuffer.h (right):

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/ringbuffer.h...
webrtc/call/ringbuffer.h:68: void push_back(T&& elem) {
1. If you want to swap the element with something in the buffer, make the
argument a T* instead.
or
2. If you want to support in-place construction, follow the STL pattern to have
an emplace_back() method.

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log.cc (right):

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log.cc:245: std::unique_ptr<rtclog::Event> event(new
rtclog::Event);
nit: rtclog::Event() - include the parenthesis

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:101: // Traverses the SwapQueues in
timestamp order and copies all events earlier
nit: "SwapQueues" isn't strictly true

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:113:
config_history_.push_back(std::move(most_recent_event_));
Is it really ok that config_history_ will grow without bounds? I don't see where
it is emptied.

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:97: rtc::scoped_ptr<FileWrapper>
file_;
unique_ptr

[terelius, 2016-04-21 08:10:41]

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:40: class RtcEventLogHelperThread {
On 2016/03/24 13:49:43, the sun wrote:
> final

Done.

https://codereview.webrtc.org/1687703002/diff/140001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:51: rtc::scoped_ptr<FileWrapper> file;
 // Only used with START_FILE.
On 2016/04/20 11:30:15, the sun wrote:
> On 2016/03/24 13:49:43, the sun wrote:
> > unique_ptr
> 
> Still want this.

Done.

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/mock/mock_rt...
File webrtc/call/mock/mock_rtc_event_log.h (right):

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/mock/mock_rt...
webrtc/call/mock/mock_rtc_event_log.h:25: bool(const std::string& file_name,
int64_t max_size_bytes_));
On 2016/04/20 11:30:15, the sun wrote:
> nit: We don't use trailing _ in arguments

Done.

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/ringbuffer.h
File webrtc/call/ringbuffer.h (right):

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/ringbuffer.h...
webrtc/call/ringbuffer.h:68: void push_back(T&& elem) {
On 2016/04/20 11:30:15, the sun wrote:
> 1. If you want to swap the element with something in the buffer, make the
> argument a T* instead.
> or
> 2. If you want to support in-place construction, follow the STL pattern to
have
> an emplace_back() method.

Using std::move instead, as discussed offline.

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log.cc (right):

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log.cc:245: std::unique_ptr<rtclog::Event> event(new
rtclog::Event);
On 2016/04/20 11:30:15, the sun wrote:
> nit: rtclog::Event() - include the parenthesis

Done.

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:101: // Traverses the SwapQueues in
timestamp order and copies all events earlier
On 2016/04/20 11:30:15, the sun wrote:
> nit: "SwapQueues" isn't strictly true

Ack. Since this function basically consists of two if-statements that are called
from LogToMemory and LogToFile respectively, I inlined the relevant parts and
removed this function. The total line count is essentially the same (+1 or 2
lines), but we get less nested if-statements and the logic is spread out between
fewer functions.

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:113:
config_history_.push_back(std::move(most_recent_event_));
On 2016/04/20 11:30:15, the sun wrote:
> Is it really ok that config_history_ will grow without bounds? I don't see
where
> it is emptied.

You are right; it is never emptied. This is the same behavior as the current
implementation, however.

(The problem is that there is no good way to know when a stream configuration is
no longer needed. Even if we have no packets on a particular SSRC in the history
right now, we still need to keep the config in case we receive packets again
later.)

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.h (right):

https://codereview.webrtc.org/1687703002/diff/220001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.h:97: rtc::scoped_ptr<FileWrapper>
file_;
On 2016/04/20 11:30:15, the sun wrote:
> unique_ptr

Done.

[ivoc, 2016-04-21 08:24:26]

Nice change, still LGTM. 

As a FYI, I recently came across arena allocators for protobuf (see
https://developers.google.com/protocol-buffers/docs/reference/arenas ), which I
think can be used to get many of the performance benefits of the previous code
structure while using a single event queue. If we find out that we need better
performance later on, we can have a closer look at it.

[the sun, 2016-04-22 08:35:51]

On 2016/04/21 08:24:26, ivoc wrote:
> Nice change, still LGTM. 
> 
> As a FYI, I recently came across arena allocators for protobuf (see
> https://developers.google.com/protocol-buffers/docs/reference/arenas ), which
I
> think can be used to get many of the performance benefits of the previous code
> structure while using a single event queue. If we find out that we need better
> performance later on, we can have a closer look at it.

That's interesting!

Still LGTM.

[terelius, 2016-04-22 09:58:20]

The CQ bit was checked by terelius@webrtc.org

[terelius, 2016-04-22 09:58:21]

The patchset sent to the CQ was uploaded after l-g-t-m from stefan@webrtc.org
Link to the patchset: https://codereview.webrtc.org/1687703002/#ps240001 (title:
"Comments from solenberg")

[commit-bot: I haz the power, 2016-04-22 09:58:31]

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

[commit-bot: I haz the power, 2016-04-22 10:16:42]

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

[commit-bot: I haz the power, 2016-04-22 10:16:43]

Try jobs failed on following builders:
  presubmit on tryserver.webrtc (JOB_FAILED,
http://build.chromium.org/p/tryserver.webrtc/builders/presubmit/builds/4997)

[terelius, 2016-04-22 10:39:34]

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

[terelius, 2016-04-22 10:41:50]

kjellander, I need approval for adding new files to webrtc/BUILD.gn. Please take
a look.

[kjellander_webrtc, 2016-04-22 11:19:53]

On 2016/04/22 10:41:50, terelius wrote:
> kjellander, I need approval for adding new files to webrtc/BUILD.gn. Please
take
> a look.

lgtm

[terelius, 2016-04-22 12:24:54]

The CQ bit was checked by terelius@webrtc.org

[commit-bot: I haz the power, 2016-04-22 12:25:12]

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

[commit-bot: I haz the power, 2016-04-22 12:28:19]

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

[commit-bot: I haz the power, 2016-04-22 12:28:20]

Try jobs failed on following builders:
  presubmit on tryserver.webrtc (JOB_FAILED,
http://build.chromium.org/p/tryserver.webrtc/builders/presubmit/builds/5007)

[terelius, 2016-04-22 12:55:26]

Description was changed from

==========
Refactored CL for moving the output to a separate thread.

The logging thread is always active. The main thread uses SwapQueues to pass
events to the logging thread. The logging thread moves the events to either a
RingBuffer history in memory, or to a string which is written to disc.

RtcEventLogImpl constructor takes a clock for easier testing.

BUG=webrtc:4741
==========

to

==========
Refactored CL for moving the output to a separate thread.

The logging thread is always active. The main thread uses SwapQueues to pass
events to the logging thread. The logging thread moves the events to either a
RingBuffer history in memory, or to a string which is written to disc.

RtcEventLogImpl constructor takes a clock for easier testing.

NOPRESUBMIT=True
BUG=webrtc:4741
==========

[terelius, 2016-04-22 12:57:09]

The CQ bit was checked by terelius@webrtc.org

[terelius, 2016-04-22 12:57:10]

The patchset sent to the CQ was uploaded after l-g-t-m from
solenberg@webrtc.org, ivoc@webrtc.org, kjellander@webrtc.org, stefan@webrtc.org
Link to the patchset: https://codereview.webrtc.org/1687703002/#ps260001 (title:
"No-op")

[commit-bot: I haz the power, 2016-04-22 12:57:20]

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

[commit-bot: I haz the power, 2016-04-22 14:40:46]

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

[commit-bot: I haz the power, 2016-04-22 14:40:48]

Try jobs failed on following builders:
  android_arm64_rel on tryserver.webrtc (JOB_TIMED_OUT, no build URL)

[kjellander_webrtc, 2016-04-22 19:34:42]

Description was changed from

==========
Refactored CL for moving the output to a separate thread.

The logging thread is always active. The main thread uses SwapQueues to pass
events to the logging thread. The logging thread moves the events to either a
RingBuffer history in memory, or to a string which is written to disc.

RtcEventLogImpl constructor takes a clock for easier testing.

NOPRESUBMIT=True
BUG=webrtc:4741
==========

to

==========
Refactored CL for moving the output to a separate thread.

The logging thread is always active. The main thread uses SwapQueues to pass
events to the logging thread. The logging thread moves the events to either a
RingBuffer history in memory, or to a string which is written to disc.

RtcEventLogImpl constructor takes a clock for easier testing.

BUG=webrtc:4741
==========

[kjellander_webrtc, 2016-04-22 19:35:25]

On 2016/04/22 14:40:48, commit-bot: I haz the power wrote:
> Try jobs failed on following builders:
>   android_arm64_rel on tryserver.webrtc (JOB_TIMED_OUT, no build URL)

https://bugs.chromium.org/p/webrtc/issues/detail?id=5818 should now be fixed so
I removed the NOPRESUBMIT=True entry and will CQ this to try it out (the timed
out tryjob has now completed).

[kjellander_webrtc, 2016-04-22 19:35:37]

The CQ bit was checked by kjellander@webrtc.org

[commit-bot: I haz the power, 2016-04-22 19:35:44]

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

[commit-bot: I haz the power, 2016-04-22 19:40:42]

Description was changed from

==========
Refactored CL for moving the output to a separate thread.

The logging thread is always active. The main thread uses SwapQueues to pass
events to the logging thread. The logging thread moves the events to either a
RingBuffer history in memory, or to a string which is written to disc.

RtcEventLogImpl constructor takes a clock for easier testing.

BUG=webrtc:4741
==========

to

==========
Refactored CL for moving the output to a separate thread.

The logging thread is always active. The main thread uses SwapQueues to pass
events to the logging thread. The logging thread moves the events to either a
RingBuffer history in memory, or to a string which is written to disc.

RtcEventLogImpl constructor takes a clock for easier testing.

BUG=webrtc:4741
==========

[commit-bot: I haz the power, 2016-04-22 19:40:44]

Committed patchset #14 (id:260001)

[commit-bot: I haz the power, 2016-04-22 19:41:26]

Description was changed from

==========
Refactored CL for moving the output to a separate thread.

The logging thread is always active. The main thread uses SwapQueues to pass
events to the logging thread. The logging thread moves the events to either a
RingBuffer history in memory, or to a string which is written to disc.

RtcEventLogImpl constructor takes a clock for easier testing.

BUG=webrtc:4741
==========

to

==========
Refactored CL for moving the output to a separate thread.

The logging thread is always active. The main thread uses SwapQueues to pass
events to the logging thread. The logging thread moves the events to either a
RingBuffer history in memory, or to a string which is written to disc.

RtcEventLogImpl constructor takes a clock for easier testing.

BUG=webrtc:4741

Committed: https://crrev.com/4311ba59d8186400b892eafff2b71529a7e25a85
Cr-Commit-Position: refs/heads/master@{#12476}
==========

[commit-bot: I haz the power, 2016-04-22 19:41:28]

Patchset 14 (id:??) landed as
https://crrev.com/4311ba59d8186400b892eafff2b71529a7e25a85
Cr-Commit-Position: refs/heads/master@{#12476}

[tommi, 2016-05-24 21:47:03]

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

[tommi, 2016-05-24 21:47:04]

https://codereview.webrtc.org/1687703002/diff/260001/webrtc/call/rtc_event_lo...
File webrtc/call/rtc_event_log_helper_thread.cc (right):

https://codereview.webrtc.org/1687703002/diff/260001/webrtc/call/rtc_event_lo...
webrtc/call/rtc_event_log_helper_thread.cc:273: wake_up_->Wait(50);
Please see chromium:614192.  Looks like this thread is running while it
shouldn't.