Add logging for slow device events, limit network UI update rate

Add logging for slow device events, limit network UI update rate

This CL does the following:
* Cleans up some redundant code in the network UI.
* Disassociates Network UI updates from dbus calls and limits the
  frequency of UI updates by using a timer to trigger updates.
* Adds NET_LOG_IF_SLOW to device_event_log.h to log slow network events.

Note: I also did virtual/override cleanup while in there and ran clang format on the changed files.

BUG=441650
Committed: https://crrev.com/9cfc3f8f868ec7c38f1e5025554c0caf837750a5
Cr-Commit-Position: refs/heads/master@{#309083}

[stevenjb, 2014-12-16 01:45:03]

stevenjb@chromium.org changed reviewers:
+ hashimoto@chromium.org, sadrul@chromium.org, satorux@chromium.org

[stevenjb, 2014-12-16 01:45:04]

I tested this and we shouldn't be spending any significant time in the network
dbus calls any more. The UI updates can take ~20ms, and I didn't see any easy
way to fix that, but I did limit them to 1/s, which should reduce the overall
overhead considerably. I left in some logging so that we can keep an eye on
things.

[satorux1, 2014-12-16 03:29:44]

took a look at src/chromeos. looks neat.

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_log.h
File chromeos/device_event_log.h (right):

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_lo...
chromeos/device_event_log.h:45: #define NET_LOG_IF_SLOW() \
Maybe SCOPED_NET_LOG_IF_SLOW() because it depends on a scoped object?

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_lo...
chromeos/device_event_log.h:48: #define DEVICE_LOG_IF_SLOW(type)                
                    \
this looks like a generic tool. maybe define this before NET_LOG_IF_SLOW, and
add some comment?

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_lo...
chromeos/device_event_log.h:49:
::chromeos::device_event_log::internal::DeviceLogIfSlow _elapsed_( \
is _elapsed_ a variable name? names starting with _ are reserved for the
compiler. maybe drop _?

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_lo...
chromeos/device_event_log.h:50: type, __FILE__, __func__)
use __LINE__ as well?

Also it might be nicer to replace __func__ with a string parameter. Then you
client code can be a bit more flexible:

NET_LOG_IF_SLOW(__func__);  // logging by a function name.
NET_LOG_IF_SLOW("random text");  // logging by some text.

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_lo...
chromeos/device_event_log.h:130: class CHROMEOS_EXPORT DeviceEventLogInstance {
Add some class comment while you are at it?

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_lo...
chromeos/device_event_log.h:150: class CHROMEOS_EXPORT DeviceLogIfSlow {
Add some comment?

[stevenjb, 2014-12-16 19:12:58]

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_log.h
File chromeos/device_event_log.h (right):

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_lo...
chromeos/device_event_log.h:45: #define NET_LOG_IF_SLOW() \
On 2014/12/16 03:29:43, satorux1 wrote:
> Maybe SCOPED_NET_LOG_IF_SLOW() because it depends on a scoped object?

Hmm, I kind of like it short, but I guess a little extra verbosity is not a bad
thing here.
Done.

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_lo...
chromeos/device_event_log.h:48: #define DEVICE_LOG_IF_SLOW(type)                
                    \
On 2014/12/16 03:29:44, satorux1 wrote:
> this looks like a generic tool. maybe define this before NET_LOG_IF_SLOW, and
> add some comment?

I'll add a comment like I did above with DEVICE_LOG; this should only be used if
|type| were a variable, which is unlikely.

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_lo...
chromeos/device_event_log.h:49:
::chromeos::device_event_log::internal::DeviceLogIfSlow _elapsed_( \
On 2014/12/16 03:29:43, satorux1 wrote:
> is _elapsed_ a variable name? names starting with _ are reserved for the
> compiler. maybe drop _?

Hmm. I intentionally wanted to use a variable that wouldn't conflict with
anything local. Maybe I'll just make it longer instead.

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_lo...
chromeos/device_event_log.h:50: type, __FILE__, __func__)
On 2014/12/16 03:29:44, satorux1 wrote:
> use __LINE__ as well?
> 
> Also it might be nicer to replace __func__ with a string parameter. Then you
> client code can be a bit more flexible:
> 
> NET_LOG_IF_SLOW(__func__);  // logging by a function name.
> NET_LOG_IF_SLOW("random text");  // logging by some text.

__LINE__ doesn't add any info since we are timing the entire method.

I used __func__ so that we don't have to provide a string every time we add one
of these. This was really useful for adding a bunch of timers to track down the
problem, then removing most of them. I just pasted NET_LOG_IF_SLOW to the top of
the functions I wanted to time.

If a use case comes up for another version of this macro, we could add it then.

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_lo...
chromeos/device_event_log.h:130: class CHROMEOS_EXPORT DeviceEventLogInstance {
On 2014/12/16 03:29:43, satorux1 wrote:
> Add some class comment while you are at it?

Done.

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_lo...
chromeos/device_event_log.h:150: class CHROMEOS_EXPORT DeviceLogIfSlow {
On 2014/12/16 03:29:44, satorux1 wrote:
> Add some comment?

Done.

[satorux1, 2014-12-18 05:18:52]

chromeos/... LGTM. Sorry for the belated response. I was ooo yesterday.

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_log.h
File chromeos/device_event_log.h (right):

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_lo...
chromeos/device_event_log.h:49:
::chromeos::device_event_log::internal::DeviceLogIfSlow _elapsed_( \
On 2014/12/16 19:12:58, stevenjb wrote:
> On 2014/12/16 03:29:43, satorux1 wrote:
> > is _elapsed_ a variable name? names starting with _ are reserved for the
> > compiler. maybe drop _?
> 
> Hmm. I intentionally wanted to use a variable that wouldn't conflict with
> anything local. Maybe I'll just make it longer instead.

Would something like work?

elapsed_ ## __LINE__

(trying to add the line number in the variable name)

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_lo...
chromeos/device_event_log.h:50: type, __FILE__, __func__)
On 2014/12/16 19:12:58, stevenjb wrote:
> On 2014/12/16 03:29:44, satorux1 wrote:
> > use __LINE__ as well?
> > 
> > Also it might be nicer to replace __func__ with a string parameter. Then you
> > client code can be a bit more flexible:
> > 
> > NET_LOG_IF_SLOW(__func__);  // logging by a function name.
> > NET_LOG_IF_SLOW("random text");  // logging by some text.
> 
> __LINE__ doesn't add any info since we are timing the entire method.
> 
> I used __func__ so that we don't have to provide a string every time we add
one
> of these. This was really useful for adding a bunch of timers to track down
the
> problem, then removing most of them. I just pasted NET_LOG_IF_SLOW to the top
of
> the functions I wanted to time.
> 
> If a use case comes up for another version of this macro, we could add it
then.

SGTM. I originally thought this could be used multiple times from a function,
but I guess that's a YAGNI. :)

https://codereview.chromium.org/811623002/diff/40001/chromeos/device_event_log.h
File chromeos/device_event_log.h (right):

https://codereview.chromium.org/811623002/diff/40001/chromeos/device_event_lo...
chromeos/device_event_log.h:158: class CHROMEOS_EXPORT DeviceLogIfSlow {
Because macros are now prefixed SCOPED_, this class might want to have the same
prefix.

[stevenjb, 2014-12-18 18:15:18]

Patchset #4 (id:60001) has been deleted

[stevenjb, 2014-12-18 18:16:16]

stevenjb@chromium.org changed reviewers:
+ oshima@chromium.org

[stevenjb, 2014-12-18 18:16:17]

sadrul or oshima, PTAL at ash/

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_log.h
File chromeos/device_event_log.h (right):

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_lo...
chromeos/device_event_log.h:49:
::chromeos::device_event_log::internal::DeviceLogIfSlow _elapsed_( \
On 2014/12/18 05:18:51, satorux1 wrote:
> On 2014/12/16 19:12:58, stevenjb wrote:
> > On 2014/12/16 03:29:43, satorux1 wrote:
> > > is _elapsed_ a variable name? names starting with _ are reserved for the
> > > compiler. maybe drop _?
> > 
> > Hmm. I intentionally wanted to use a variable that wouldn't conflict with
> > anything local. Maybe I'll just make it longer instead.
> 
> Would something like work?
> 
> elapsed_ ## __LINE__
> 
> (trying to add the line number in the variable name)

That would have been clever, but I think the long name matching the macro is
reasonable.

https://codereview.chromium.org/811623002/diff/20001/chromeos/device_event_lo...
chromeos/device_event_log.h:50: type, __FILE__, __func__)
On 2014/12/18 05:18:51, satorux1 wrote:
> On 2014/12/16 19:12:58, stevenjb wrote:
> > On 2014/12/16 03:29:44, satorux1 wrote:
> > > use __LINE__ as well?
> > > 
> > > Also it might be nicer to replace __func__ with a string parameter. Then
you
> > > client code can be a bit more flexible:
> > > 
> > > NET_LOG_IF_SLOW(__func__);  // logging by a function name.
> > > NET_LOG_IF_SLOW("random text");  // logging by some text.
> > 
> > __LINE__ doesn't add any info since we are timing the entire method.
> > 
> > I used __func__ so that we don't have to provide a string every time we add
> one
> > of these. This was really useful for adding a bunch of timers to track down
> the
> > problem, then removing most of them. I just pasted NET_LOG_IF_SLOW to the
top
> of
> > the functions I wanted to time.
> > 
> > If a use case comes up for another version of this macro, we could add it
> then.
> 
> SGTM. I originally thought this could be used multiple times from a function,
> but I guess that's a YAGNI. :)

In theory it could be used within a scope, but yeah, I would just as soon add
that if/when we need it.

https://codereview.chromium.org/811623002/diff/40001/chromeos/device_event_log.h
File chromeos/device_event_log.h (right):

https://codereview.chromium.org/811623002/diff/40001/chromeos/device_event_lo...
chromeos/device_event_log.h:158: class CHROMEOS_EXPORT DeviceLogIfSlow {
On 2014/12/18 05:18:52, satorux1 wrote:
> Because macros are now prefixed SCOPED_, this class might want to have the
same
> prefix.

Done.

[oshima, 2014-12-18 18:35:57]

ash lgtm

[oshima, 2014-12-18 18:35:59]

ash lgtm

[stevenjb, 2014-12-18 18:47:24]

The CQ bit was checked by stevenjb@chromium.org

[commit-bot: I haz the power, 2014-12-18 18:48:31]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/811623002/80001

[commit-bot: I haz the power, 2014-12-18 22:04:19]

Committed patchset #4 (id:80001)

[commit-bot: I haz the power, 2014-12-18 22:05:45]

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