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

chromeos/device_event_log.h

 // Copyright 2014 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #ifndef CHROMEOS_DEVICE_EVENT_LOG_H_
 #define CHROMEOS_DEVICE_EVENT_LOG_H_
 
 #include <cstring>
 #include <sstream>
 
 #include "base/basictypes.h"
+#include "base/timer/elapsed_timer.h"
 #include "chromeos/chromeos_export.h"
 
 namespace chromeos {
 
 // These macros can be used to log chromeos device related events.
 // The following values should be used for |level| in these macros:
 //  ERROR Unexpected events, or device level failures. Use sparingly.
 //  USER  Events initiated directly by a user (or Chrome) action.
 //  EVENT Default event type.
 //  DEBUG Debugging details that are usually not interesting.
@@ skipping 10 matching lines @@
 #define LOGIN_LOG(level)                                   \
   DEVICE_LOG(::chromeos::device_event_log::LOG_TYPE_LOGIN, \
              ::chromeos::device_event_log::LOG_LEVEL_##level)
 
 // Generally prefer the above macros unless |level| is not constant.
 
 #define DEVICE_LOG(type, level)                                   \
   ::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
 // and GetLogTypeString when adding entries to this enum. Also consider
 // updating chrome://device-log (see device_log_ui.cc).
 enum LogType {
   // Shill / network configuration related events.
   LOG_TYPE_NETWORK,
   // Power manager related events.
   LOG_TYPE_POWER,
@@ skipping 58 matching lines @@
 CHROMEOS_EXPORT std::string GetAsString(StringOrder order,
                                         const std::string& format,
                                         const std::string& types,
                                         LogLevel max_level,
                                         size_t max_events);
 
 CHROMEOS_EXPORT extern const LogLevel kDefaultLogLevel;
 
 namespace internal {
 
 class CHROMEOS_EXPORT DeviceEventLogInstance {

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

Add some class comment while you are at it?

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

Done.

  public:
   DeviceEventLogInstance(const char* file,
                          int line,
                          device_event_log::LogType type,
                          device_event_log::LogLevel level);
   ~DeviceEventLogInstance();
 
   std::ostream& stream() { return stream_; }
 
  private:
   const char* file_;
   const int line_;
   device_event_log::LogType type_;
   device_event_log::LogLevel level_;
   std::ostringstream stream_;
 
   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
 
 }  // namespace chromeos
 
 #endif  // CHROMEOS_DEVICE_EVENT_LOG_H_