Add in some infrastructure to make tracing of logical requests broken over async callbacks easier.

Create a concept of a TraceContext that holds a current Tracer which can be
used to create a timeseries sequence of events.

This implementation extends the functionality of RunnableMethod and
NewRunnableMethod() to create a parallel TracedMethod, and NewTracedMethod().
These new Traced methods methods and types know how to propogate the current
TraceContext to create a logical sequence of annotations through the servicing
of one logical action.

Currently, the code is controlled via define macro which changes
NewTracedMethod back into NewRunnableMethod if the hook is disabled.

BUG=52883
TEST=compiles, and client can connect to host.

Review URL: http://codereview.chromium.org/3169047

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@57992 0039d316-1c4b-4281-b951-d872f2087c98

5 files changed, 512 insertions, 0 deletions

diff --git a/remoting/base/protocol/chromotocol.gyp b/remoting/base/protocol/chromotocol.gyp
index bdcb845..f3167ad 100644
--- a/remoting/base/protocol/chromotocol.gyp
+++ b/remoting/base/protocol/chromotocol.gyp
@@ -69,6 +69,69 @@
         '<(out_dir)/chromotocol.pb.h',
       ],
     },
+
+    {
+      # Protobuf compiler / generate rule for trace.proto.
+      'target_name': 'trace_proto',
+      'type': 'none',
+      'sources': [
+        'trace.proto',
+      ],
+      'rules': [
+        {
+          'rule_name': 'genproto',
+          'extension': 'proto',
+          'inputs': [
+            '<(PRODUCT_DIR)/<(EXECUTABLE_PREFIX)protoc<(EXECUTABLE_SUFFIX)',
+          ],
+          'outputs': [
+            '<(PRODUCT_DIR)/pyproto/<(RULE_INPUT_ROOT)_pb/'
+               '<(RULE_INPUT_ROOT)_pb2.py',
+            '<(out_dir)/<(RULE_INPUT_ROOT).pb.cc',
+            '<(out_dir)/<(RULE_INPUT_ROOT).pb.h',
+          ],
+          'action': [
+            '<(PRODUCT_DIR)/<(EXECUTABLE_PREFIX)protoc<(EXECUTABLE_SUFFIX)',
+            '--proto_path=.',
+            './<(RULE_INPUT_ROOT)<(RULE_INPUT_EXT)',
+            '--cpp_out=<(out_dir)',
+            '--python_out=<(PRODUCT_DIR)/pyproto/<(RULE_INPUT_ROOT)_pb',
+          ],
+          'message': 'Generating C++ and Python code from <(RULE_INPUT_PATH)',
+        },
+      ],
+      'dependencies': [
+        '../../../third_party/protobuf2/protobuf.gyp:protoc#host',
+      ],
+      # This target exports a hard dependency because it generates header
+      # files.
+      'hard_dependency': 1,
+    },
+
+    {
+      'target_name': 'trace_proto_lib',
+      'type': '<(library)',
+      'export_dependent_settings': [
+        '../../../third_party/protobuf2/protobuf.gyp:protobuf_lite',
+        'trace_proto',
+      ],
+      'dependencies': [
+        '../../../third_party/protobuf2/protobuf.gyp:protobuf_lite',
+        'trace_proto',
+      ],
+      # This target exports a hard dependency because depedents require
+      # chromotocol_proto to compile.
+      'hard_dependency': 1,
+      'direct_dependent_settings': {
+        'include_dirs': [
+          '<(SHARED_INTERMEDIATE_DIR)/protoc_out',
+        ],
+      },
+      'sources': [
+        '<(out_dir)/trace.pb.cc',
+        '<(out_dir)/trace.pb.h',
+      ],
+    },
   ],
 }
 
diff --git a/remoting/base/protocol/trace.proto b/remoting/base/protocol/trace.proto
new file mode 100644
index 0000000..dbbabcf
--- /dev/null
+++ b/remoting/base/protocol/trace.proto
@@ -0,0 +1,37 @@
+// Copyright (c) 2010 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.
+//
+// Protocol buffers for creating performance traces on requests.
+
+syntax = "proto2";
+
+option optimize_for = LITE_RUNTIME;
+
+package remoting;
+
+// Represents one entry in the TraceBuffer below.  Collates information that
+// would be useful for analyzing the performance in a program trace.
+message TraceRecord {
+  required string annotation = 1;
+  required int64 timestamp = 2;  // In micros from epoch.
+
+  // -- Information for constructing a distributed trace. --
+  // TODO(ajwong): Decide which of these are useful, and remove rest.
+
+  // Identifies the machine.
+  optional int64 source_id = 3 [ default = -1 ];
+
+  // Identifies the thread on the machine.
+  optional fixed64 thread_id = 4;
+
+  // Estimated skew from master clock.
+  optional int64 clock_skew = 5 [ default = 0 ];
+}
+
+// Protocol buffer used for collecting stats, and performance data.
+message TraceBuffer {
+  required string name = 1;  // Name of this trace.
+  repeated TraceRecord record = 2;
+}
+
diff --git a/remoting/base/tracer.cc b/remoting/base/tracer.cc
new file mode 100644
index 0000000..c9df2f0
--- /dev/null
+++ b/remoting/base/tracer.cc
@@ -0,0 +1,144 @@
+// Copyright (c) 2010 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.
+
+#include "remoting/base/tracer.h"
+
+#include <list>
+
+#include "base/basictypes.h"
+#include "base/condition_variable.h"
+#include "base/message_loop.h"
+#include "base/rand_util.h"
+#include "base/ref_counted.h"
+#include "base/stl_util-inl.h"
+#include "base/thread.h"
+#include "base/time.h"
+
+namespace remoting {
+
+namespace {
+
+class OutputLogger {
+ public:
+  OutputLogger()
+      : thread_("logging_thread"),
+        stopped_(false),
+        wake_(&lock_) {
+    thread_.Start();
+    thread_.message_loop()->PostTask(
+        FROM_HERE,
+        NewRunnableMethod(this, &OutputLogger::PrintLogs));
+  }
+
+  void OutputTrace(TraceBuffer* buffer) {
+    scoped_ptr<TraceBuffer> buffer_ref_(buffer);
+    AutoLock l(lock_);
+
+    // Drop messages if we're overwhelming the logger.
+    if (buffers_.size() < 10) {
+      buffers_.push_front(buffer_ref_.release());
+      wake_.Signal();
+    } else {
+      // TODO(ajwong): Remove this cause it just overwhelms the logging more.
+      LOG(WARNING) << "Message dropped.";
+    }
+  }
+
+  void LogOneTrace(TraceBuffer* buffer) {
+    LOG(INFO) << "Trace: " << buffer->name();
+    base::Time last_timestamp;
+    for (int i = 0; i < buffer->record_size(); ++i) {
+      const TraceRecord& record = buffer->record(i);
+      base::Time timestamp = base::Time::FromInternalValue(record.timestamp());
+      if (i == 0) {
+        LOG(INFO) << "  TS: " << record.timestamp()
+                  << " msg: " << record.annotation();
+      } else {
+        base::TimeDelta delta = timestamp - last_timestamp;
+        LOG(INFO) << "  TS: " << record.timestamp()
+                  << " msg: " << record.annotation()
+                  << " [ " << delta.InMilliseconds() << "ms ]";
+      }
+      last_timestamp = timestamp;
+    }
+  }
+
+  void PrintLogs() {
+    while(!stopped_) {
+      TraceBuffer* buffer = NULL;
+      {
+        AutoLock l(lock_);
+        if (buffers_.size() == 0) {
+          wake_.Wait();
+        }
+        // Check again since we might have woken for a stop signal.
+        if (buffers_.size() != 0) {
+          buffer = buffers_.back();
+          buffers_.pop_back();
+        }
+      }
+
+      if (buffer) {
+        LogOneTrace(buffer);
+        delete buffer;
+      }
+    }
+  }
+
+ private:
+  friend struct DefaultSingletonTraits<OutputLogger>;
+
+  ~OutputLogger() {
+    {
+      AutoLock l(lock_);
+      stopped_ = true;
+      wake_.Signal();
+    }
+
+    thread_.Stop();
+    STLDeleteElements(&buffers_);
+  }
+
+  Lock lock_;
+  base::Thread thread_;
+  bool stopped_;
+  ConditionVariable wake_;
+  std::list<TraceBuffer*> buffers_;
+};
+
+}  // namespace
+
+Tracer::Tracer(const std::string& name, double sample_percent) {
+  if (sample_percent > base::RandDouble()) {
+    buffer_.reset(new TraceBuffer());
+    buffer_->set_name(name);
+  }
+}
+
+void Tracer::PrintString(const std::string& s) {
+  AutoLock l(lock_);
+  if (!buffer_.get()) {
+    return;
+  }
+
+  TraceRecord* record = buffer_->add_record();
+  record->set_annotation(s);
+  record->set_timestamp(base::Time::Now().ToInternalValue());
+
+  // Take the pointer for the current messageloop as identifying for the
+  // current thread.
+  record->set_thread_id(static_cast<uint64>(PlatformThread::CurrentId()));
+}
+
+Tracer::~Tracer() {
+  AutoLock l(lock_);
+
+  if (buffer_.get()) {
+    Singleton<OutputLogger>::get()->OutputTrace(buffer_.release());
+  }
+}
+
+}  // namespace remoting
+
+DISABLE_RUNNABLE_METHOD_REFCOUNT(remoting::OutputLogger);
diff --git a/remoting/base/tracer.h b/remoting/base/tracer.h
new file mode 100644
index 0000000..739648d
--- /dev/null
+++ b/remoting/base/tracer.h
@@ -0,0 +1,265 @@
+// Copyright (c) 2010 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.
+
+// Tracer objects uresed to record an annotated timeline of events for use in
+// gathering performance data.  It wraps a TraceBuffer which is the raw data
+// for a trace. Tracer is threadsafe.
+//
+// TraceContext is a singleton that is used to give information for the current
+// trace. Clients should query TraceContext to find the current tracer and then
+// use that for logging annotations. TraceContext is threadsafe.
+//
+// ScopedTracer pushes a new Tracer on the TraceContext.  It's scoped in that
+// this tracer is popped off the context when ScopedTracer goes out of scope.
+// However, if a call to NewTracedMethod is made while the ScopedTracer is in
+// scope, then a reference to the Tracer will be kept in the resulting Task and
+// repushed onto the stack when the Task is run.  Conceptually, this simulates
+// the current context being continued when the Task is invoked.  You usually
+// will want to declare a ScopedTracer at the start of a logical flow of
+// operations.
+//
+// Example Usage:
+//
+// void Decoder::StartDecode() {
+//   ScopedTracer tracer("decode_start");
+//
+//   TraceContext::current()->PrintString("Decode starting");
+//
+//   // DoDecode takes 2 parameters. The first is a callback invoked for each
+//   // finished frame of output.  The second is invoked when the task is done.
+//   DoDecode(NewTracedMethod(this, &Decoder::OnFrameOutput),
+//            NewTracedMethod(this, &Decoder::DecodeDone));
+//   }
+// }
+//
+// void Decoder::OnFrameOutput() {
+//   TraceContext::current()->PrintString("Frame outputed");
+//   ...
+// }
+//
+// void Decoder::DecodeDone() {
+//   TraceContext::current()->PrintString("decode done");
+//   ...
+// }
+//
+// For each call of StartDecode(), the related calls to OnFrameOutput() and
+// DecodeDone() will be annotated to the Tracer created by the ScopedTracer
+// declaration allowing for creating of timing information over the related
+// asynchronous Task invocations.
+
+#ifndef REMOTING_BASE_TRACER_H_
+#define REMOTING_BASE_TRACER_H_
+
+#include <string>
+
+#include "base/lock.h"
+#include "base/ref_counted.h"
+#include "base/singleton.h"
+#include "base/task.h"
+#include "base/scoped_ptr.h"
+#include "base/thread_local.h"
+#include "remoting/base/protocol/trace.pb.h"
+
+namespace remoting {
+
+class Tracer : public base::RefCountedThreadSafe<Tracer> {
+ public:
+  // The |name| is just a label for the given tracer. It is recorder into the
+  // trace buffer and printed at the end. Use it specify one logical flow such
+  // as "Host Update Request".  The sample_percent is to allow for gathering a
+  // random sampling of the traces. This allows the tracer to be used in a
+  // high-frequency code path without spamming the log, or putting undo load on
+  // the system.  Use 0.0 to disable the tracer completely, and 1.0 to log
+  // everything.
+  Tracer(const std::string& name, double sample_percent);
+
+  // TODO(ajwong): Consider using an ostream interface similar to DLOG.
+  void PrintString(const std::string& s);
+
+  void OutputTrace();
+
+ private:
+  friend class base::RefCountedThreadSafe<Tracer>;
+  virtual ~Tracer();
+
+  Lock lock_;
+  scoped_ptr<TraceBuffer> buffer_;
+
+  DISALLOW_COPY_AND_ASSIGN(Tracer);
+};
+
+class TraceContext {
+ public:
+  // Set the current tracer.
+  static Tracer* tracer() {
+    return Get()->GetTracerInternal();
+  }
+
+  static void PushTracer(Tracer* tracer) {
+    Get()->PushTracerInternal(tracer);
+  }
+
+  static void PopTracer() {
+    Get()->PopTracerInternal();
+  }
+
+  static TraceContext* Get() {
+    TraceContext* context =
+        Singleton<base::ThreadLocalPointer<TraceContext> >::get()->Get();
+    if (context == NULL) {
+      context = new TraceContext();
+      context->PushTracerInternal(new Tracer("default", 0.0));
+      Singleton<base::ThreadLocalPointer<TraceContext> >::get()->Set(context);
+    }
+    return context;
+  }
+
+ private:
+  TraceContext() {
+  }
+
+  ~TraceContext() {}
+
+  void PushTracerInternal(Tracer* tracer) { tracers_.push_back(tracer); }
+
+  void PopTracerInternal() { tracers_.pop_back(); }
+
+  Tracer* GetTracerInternal() { return tracers_.back(); }
+
+  std::vector<scoped_refptr<Tracer> > tracers_;
+
+  DISALLOW_COPY_AND_ASSIGN(TraceContext);
+};
+
+// Used to create a new tracer that NewRunnableMethod can propogate from.
+//
+// Declare this at the logical start of a "trace."  Calls to NewTracedMethod
+// that are done with the ScopedTracer object is alive will take a reference
+// to this tracer.  When such a method is invoked, it will push the trace back
+// onto the top of the TraceContext stack.  The result is that all asynchronous
+// tasks that are part of one logical flow will share the same trace.
+class ScopedTracer {
+ public:
+  ScopedTracer(const std::string& name) {
+    scoped_refptr<Tracer> tracer = new Tracer(name, 1.00);
+    TraceContext::PushTracer(tracer);
+  }
+
+  ~ScopedTracer() {
+    TraceContext::PopTracer();
+  }
+};
+
+// This is experimental code.  I'm creating a set of analogues to
+// the NewRunnableMethod functions called NewTracedMethod, which should be
+// API equivalent to the former.  In fact, they must be enabled by setting
+// USE_TRACE 1 for now.
+//
+// The idea is to add hooks for performance traces into the Task/Callback
+// mechanisms.  If it works well enough, will think about generalizing into the
+// original NewRunnableMethod and NewCallback systems.
+#if defined(USE_TRACE)
+
+template <class T, class Method, class Params>
+class TracedMethod : public RunnableMethod<T, Method, Params> {
+ public:
+  TracedMethod(T* obj, Method meth, const Params& params)
+      : RunnableMethod<T, Method, Params>(obj, meth, params),
+        tracer_(TraceContext::tracer()) {
+  }
+
+  virtual ~TracedMethod() {
+  }
+
+  virtual void Run() {
+    TraceContext::PushTracer(tracer_);
+    RunnableMethod<T, Method, Params>::Run();
+    TraceContext::PopTracer();
+  }
+
+ private:
+  scoped_refptr<Tracer> tracer_;
+};
+
+template <class T, class Method>
+inline CancelableTask* NewTracedMethod(T* object, Method method) {
+  return new TracedMethod<T, Method, Tuple0>(object, method, MakeTuple());
+}
+
+template <class T, class Method, class A>
+inline CancelableTask* NewTracedMethod(T* object, Method method, const A& a) {
+  return new TracedMethod<T, Method, Tuple1<A> >(object,
+                                                 method,
+                                                 MakeTuple(a));
+}
+
+template <class T, class Method, class A, class B>
+inline CancelableTask* NewTracedMethod(T* object, Method method,
+                                       const A& a, const B& b) {
+  return new TracedMethod<T, Method, Tuple2<A, B> >(object, method,
+                                                    MakeTuple(a, b));
+}
+
+template <class T, class Method, class A, class B, class C>
+inline CancelableTask* NewTracedMethod(T* object, Method method,
+                                       const A& a, const B& b, const C& c) {
+  return new TracedMethod<T, Method, Tuple3<A, B, C> >(object, method,
+                                                       MakeTuple(a, b, c));
+}
+
+template <class T, class Method, class A, class B, class C, class D>
+inline CancelableTask* NewTracedMethod(T* object, Method method,
+                                       const A& a, const B& b,
+                                       const C& c, const D& d) {
+  return new TracedMethod<T, Method, Tuple4<A, B, C, D> >(object, method,
+                                                          MakeTuple(a, b,
+                                                                    c, d));
+}
+
+template <class T, class Method, class A, class B, class C, class D, class E>
+inline CancelableTask* NewTracedMethod(T* object, Method method,
+                                       const A& a, const B& b,
+                                       const C& c, const D& d, const E& e) {
+  return new TracedMethod<T,
+  Method,
+  Tuple5<A, B, C, D, E> >(object,
+                          method,
+                          MakeTuple(a, b, c, d, e));
+}
+
+template <class T, class Method, class A, class B, class C, class D, class E,
+          class F>
+inline CancelableTask* NewTracedMethod(T* object, Method method,
+                                       const A& a, const B& b,
+                                       const C& c, const D& d,
+                                       const E& e, const F& f) {
+  return new TracedMethod<T,
+                          Method,
+                          Tuple6<A, B, C, D, E, F> >(object,
+                                                     method,
+                                                     MakeTuple(a, b, c, d, e,
+                                                               f));
+}
+
+template <class T, class Method, class A, class B, class C, class D, class E,
+          class F, class G>
+inline CancelableTask* NewTracedMethod(T* object, Method method,
+                                       const A& a, const B& b,
+                                       const C& c, const D& d, const E& e,
+                                       const F& f, const G& g) {
+  return new TracedMethod<T,
+                          Method,
+                          Tuple7<A, B, C, D, E, F, G> >(object,
+                                                        method,
+                                                        MakeTuple(a, b, c, d,
+                                                                  e, f, g));
+}
+
+#else
+#  define NewTracedMethod NewRunnableMethod
+#endif
+
+}  // namespace remoting
+
+#endif  // REMOTING_BASE_TRACER_H_
diff --git a/remoting/remoting.gyp b/remoting/remoting.gyp
index 9754ddf2..e117977 100644
--- a/remoting/remoting.gyp
+++ b/remoting/remoting.gyp
@@ -116,6 +116,7 @@
         '../third_party/protobuf2/protobuf.gyp:protobuf_lite',
         '../third_party/zlib/zlib.gyp:zlib',
         'base/protocol/chromotocol.gyp:chromotocol_proto_lib',
+        'base/protocol/chromotocol.gyp:trace_proto_lib',
         'chromoting_jingle_glue',
         # TODO(hclam): Enable VP8 in the build.
         #'third_party/on2/on2.gyp:vp8',
@@ -158,6 +159,8 @@
         'base/protocol_decoder.h',
         'base/protocol_util.cc',
         'base/protocol_util.h',
+        'base/tracer.cc',
+        'base/tracer.h',
         'base/types.h',
       ],
     },  # end of target 'chromoting_base'