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

chromeos/device_event_log.h

Index: chromeos/device_event_log.h
diff --git a/chromeos/device_event_log.h b/chromeos/device_event_log.h
index 34f02e3678b1d179ac864dd4e5d631e30e7d8fc0..094638941a5c36756709eb0a060f6a4963fe9fa5 100644
--- a/chromeos/device_event_log.h
+++ b/chromeos/device_event_log.h
@@ -9,6 +9,7 @@
 #include <sstream>
 
 #include "base/basictypes.h"
+#include "base/timer/elapsed_timer.h"
 #include "chromeos/chromeos_export.h"
 
 namespace chromeos {
@@ -39,6 +40,15 @@ namespace chromeos {
   ::chromeos::device_event_log::internal::DeviceEventLogInstance( \
       __FILE__, __LINE__, type, level).stream()
 
+// Declare NET_LOG_IF_SLOW() at the top of a method to log slow methods
+// where "slow" is defined by kSlowMethodThresholdMs in the .cc file.
+#define NET_LOG_IF_SLOW() \

[satorux1, 2014/12/16 03:29:43]

Maybe SCOPED_NET_LOG_IF_SLOW() because it depends on a scoped object?

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

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

+  DEVICE_LOG_IF_SLOW(::chromeos::device_event_log::LOG_TYPE_NETWORK)
+
+#define DEVICE_LOG_IF_SLOW(type)                                     \

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

this looks like a generic tool. maybe define this before NET_LOG_IF_SLOW, and
add some comment?

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

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.

+  ::chromeos::device_event_log::internal::DeviceLogIfSlow _elapsed_( \

[satorux1, 2014/12/16 03:29:43]

is _elapsed_ a variable name? names starting with _ are reserved for the
compiler. maybe drop _?

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

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

[satorux1, 2014/12/18 05:18:51]

Would something like work?

elapsed_ ## __LINE__

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

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

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

+      type, __FILE__, __func__)

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

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.

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

__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.

[satorux1, 2014/12/18 05:18:51]

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

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

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

+
 namespace device_event_log {
 
 // Used to specify the type of event. NOTE: Be sure to update LogTypeFromString
@@ -137,6 +147,18 @@ class CHROMEOS_EXPORT DeviceEventLogInstance {
   DISALLOW_COPY_AND_ASSIGN(DeviceEventLogInstance);
 };
 
+class CHROMEOS_EXPORT DeviceLogIfSlow {

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

Add some comment?

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

Done.

+ public:
+  DeviceLogIfSlow(LogType type, const char* file, const std::string& name);
+  ~DeviceLogIfSlow();
+
+ private:
+  const char* file_;
+  LogType type_;
+  std::string name_;
+  base::ElapsedTimer timer_;
+};
+
 }  // namespace internal
 
 }  // namespace device_event_log