diff options
| -rw-r--r-- | remoting/base/protocol/chromotocol.gyp | 63 | ||||
| -rw-r--r-- | remoting/base/protocol/trace.proto | 37 | ||||
| -rw-r--r-- | remoting/base/tracer.cc | 144 | ||||
| -rw-r--r-- | remoting/base/tracer.h | 265 | ||||
| -rw-r--r-- | remoting/remoting.gyp | 3 |
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' |