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

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.

Committed: http://src.chromium.org/viewvc/chrome?view=rev&revision=57992

[awong, 2010-08-26 01:40:57]

You guys are going to kill me...

I still have to clean this up (eg., 80-char issues in tracer.h), but it's
"working" as is and ready for a look to see if this seems even sane to pursue...

[scherkus (not reviewing), 2010-08-26 19:04:13]

http://codereview.chromium.org/3169047/diff/1/2
File remoting/base/protocol/chromotocol.proto (right):

http://codereview.chromium.org/3169047/diff/1/2#newcode13
remoting/base/protocol/chromotocol.proto:13: // TODO(ajwong): Move the trace
protocol messages out of the chromotocol.proto
wondering how serious we are about keeping this stuff, otherwise I'd say move it
now and rip out the optional fields below until we implement them

thoughts?

http://codereview.chromium.org/3169047/diff/1/3
File remoting/base/tracer.cc (right):

http://codereview.chromium.org/3169047/diff/1/3#newcode19
remoting/base/tracer.cc:19: void Tracer::PrintString(const std::string& s) {
consider using the fancy operator<<(ostream&, string&) but that can wait until
later

http://codereview.chromium.org/3169047/diff/1/3#newcode26
remoting/base/tracer.cc:26:
record->set_thread_id(reinterpret_cast<intptr_t>(MessageLoop::current()));
take a look at PlatformThread::CurrentId()

http://codereview.chromium.org/3169047/diff/1/4
File remoting/base/tracer.h (right):

http://codereview.chromium.org/3169047/diff/1/4#newcode16
remoting/base/tracer.h:16: 
nit: remove extra blank line

http://codereview.chromium.org/3169047/diff/1/4#newcode45
remoting/base/tracer.h:45: class TraceContext {
any reason for not using base/singleton.h?

it seems to take care of both atomic creation and using AtExitManager for
deletion at program termination

http://codereview.chromium.org/3169047/diff/1/4#newcode82
remoting/base/tracer.h:82: Tracer* GetTracerInternal() {
potential locks + refcounting sadness: you're returning a raw pointer outside
the locked context

it's possible we don't AddRef the Tracer before another thread calls
PopTracerInternal and the Trace gets deleted

might have to change the API to:
static void tracer(scoped_refptr<Tracer>& tracer_out);

:(

http://codereview.chromium.org/3169047/diff/1/4#newcode116
remoting/base/tracer.h:116: // NewRunnableMethod called NewTracedMethod,
NewTracedCallback
remove mention of NewTracedCallback?

should we clean up this comment to remove references to callbacks or will it be
possible to use this stuff in callbacks?  (I think so as you can pull a similar
trick with CallbackImpl and pushing/popping the tracer inside RunWithParams())

http://codereview.chromium.org/3169047/diff/1/4#newcode131
remoting/base/tracer.h:131: tracer_(TraceContext::tracer()) {
wait a tick...

1) I create a ScopedTracer A
2) Tracer A gets pushed on stack
3) I create a TracedMethod
4) Tracer A is saved inside TracedMethod via TraceContext::tracer()

What if a different thread came along between (2) and (4) that created a
different ScopedTracer B and now (4) uses Tracer B instead of A?

http://codereview.chromium.org/3169047/diff/1/4#newcode197
remoting/base/tracer.h:197: const C& c, const D& d, const E& e,
>80 chars

http://codereview.chromium.org/3169047/diff/1/4#newcode211
remoting/base/tracer.h:211: const C& c, const D& d, const E& e,
>80 chars

http://codereview.chromium.org/3169047/diff/1/4#newcode227
remoting/base/tracer.h:227: #endif // REMOTING_BASE_TRACER_H_
two spaces between #endif and //

http://codereview.chromium.org/3169047/diff/1/6
File remoting/host/chromoting_host.cc (right):

http://codereview.chromium.org/3169047/diff/1/6#newcode35
remoting/host/chromoting_host.cc:35: ChromotingHost::~ChromotingHost() {
wait is this file supposed to be in this CL??

http://codereview.chromium.org/3169047/diff/1/6#newcode39
remoting/host/chromoting_host.cc:39: if (MessageLoop::current() !=
context_->main_message_loop()) {
as a side I've wondered if its worth making a macro for this somehow...

http://codereview.chromium.org/3169047/diff/1/6#newcode67
remoting/host/chromoting_host.cc:67: LOG(ERROR) << "XMMP credentials are not
defined in config.";
XMMP -> XMPP

http://codereview.chromium.org/3169047/diff/1/9
File remoting/host/session_manager.cc (right):

http://codereview.chromium.org/3169047/diff/1/9#newcode254
remoting/host/session_manager.cc:254: capturer()->width(),
capturer()->height()));
indentation

[awong, 2010-08-26 19:19:52]

early responses.  Still fixing code.

http://codereview.chromium.org/3169047/diff/1/2
File remoting/base/protocol/chromotocol.proto (right):

http://codereview.chromium.org/3169047/diff/1/2#newcode13
remoting/base/protocol/chromotocol.proto:13: // TODO(ajwong): Move the trace
protocol messages out of the chromotocol.proto
On 2010/08/26 19:04:13, scherkus wrote:
> wondering how serious we are about keeping this stuff, otherwise I'd say move
it
> now and rip out the optional fields below until we implement them
> 
> thoughts?

I'll break it out before the next revision, but wanted to respond first.

I'm really not super certain I want to keep this.  The idea of forking the
NewRunnableMethod implementation kinda scares me.

Also, Dave pointed out that we might be able to get much of this functionality
using Dtrace scripts.   That having been said, Dtrace isn't available for
windows, so maybe this might be useful?

http://codereview.chromium.org/3169047/diff/1/3
File remoting/base/tracer.cc (right):

http://codereview.chromium.org/3169047/diff/1/3#newcode26
remoting/base/tracer.cc:26:
record->set_thread_id(reinterpret_cast<intptr_t>(MessageLoop::current()));
On 2010/08/26 19:04:13, scherkus wrote:
> take a look at PlatformThread::CurrentId()

Ooh. Thanks.

http://codereview.chromium.org/3169047/diff/1/4
File remoting/base/tracer.h (right):

http://codereview.chromium.org/3169047/diff/1/4#newcode45
remoting/base/tracer.h:45: class TraceContext {
On 2010/08/26 19:04:13, scherkus wrote:
> any reason for not using base/singleton.h?
> 
> it seems to take care of both atomic creation and using AtExitManager for
> deletion at program termination


Nope! Was just hacking code. Should switch over.

http://codereview.chromium.org/3169047/diff/1/4#newcode131
remoting/base/tracer.h:131: tracer_(TraceContext::tracer()) {
On 2010/08/26 19:04:13, scherkus wrote:
> wait a tick...
> 
> 1) I create a ScopedTracer A
> 2) Tracer A gets pushed on stack
> 3) I create a TracedMethod
> 4) Tracer A is saved inside TracedMethod via TraceContext::tracer()
> 
> What if a different thread came along between (2) and (4) that created a
> different ScopedTracer B and now (4) uses Tracer B instead of A?

Ooh good catch.

I think the right fix is to make TraceContext thread-local.  That should also
alleviate the raw pointer issue above I think.

[scherkus (not reviewing), 2010-08-26 19:21:58]

http://codereview.chromium.org/3169047/diff/1/4
File remoting/base/tracer.h (right):

http://codereview.chromium.org/3169047/diff/1/4#newcode131
remoting/base/tracer.h:131: tracer_(TraceContext::tracer()) {
On 2010/08/26 19:19:52, awong wrote:
> On 2010/08/26 19:04:13, scherkus wrote:
> > wait a tick...
> > 
> > 1) I create a ScopedTracer A
> > 2) Tracer A gets pushed on stack
> > 3) I create a TracedMethod
> > 4) Tracer A is saved inside TracedMethod via TraceContext::tracer()
> > 
> > What if a different thread came along between (2) and (4) that created a
> > different ScopedTracer B and now (4) uses Tracer B instead of A?
> 
> Ooh good catch.
> 
> I think the right fix is to make TraceContext thread-local.  That should also
> alleviate the raw pointer issue above I think.

Yeah I was thinking TLS would fix this

[awong, 2010-08-31 02:32:08]

Updated this.

I'm thinking of checking it in for now.  Will need to reevaluate the longevity
of this change in a few weeks.  On the bright side, it's easy to find all uses
and revert from NewTracedMethod to NewRunnableMethod.

http://codereview.chromium.org/3169047/diff/1/3
File remoting/base/tracer.cc (right):

http://codereview.chromium.org/3169047/diff/1/3#newcode19
remoting/base/tracer.cc:19: void Tracer::PrintString(const std::string& s) {
On 2010/08/26 19:04:13, scherkus wrote:
> consider using the fancy operator<<(ostream&, string&) but that can wait until
> later

Added a TODO.

http://codereview.chromium.org/3169047/diff/1/3#newcode26
remoting/base/tracer.cc:26:
record->set_thread_id(reinterpret_cast<intptr_t>(MessageLoop::current()));
On 2010/08/26 19:19:52, awong wrote:
> On 2010/08/26 19:04:13, scherkus wrote:
> > take a look at PlatformThread::CurrentId()
> 
> Ooh. Thanks.

Done.

http://codereview.chromium.org/3169047/diff/1/4
File remoting/base/tracer.h (right):

http://codereview.chromium.org/3169047/diff/1/4#newcode16
remoting/base/tracer.h:16: 
On 2010/08/26 19:04:13, scherkus wrote:
> nit: remove extra blank line

Done.

http://codereview.chromium.org/3169047/diff/1/4#newcode45
remoting/base/tracer.h:45: class TraceContext {
On 2010/08/26 19:19:52, awong wrote:
> On 2010/08/26 19:04:13, scherkus wrote:
> > any reason for not using base/singleton.h?
> > 
> > it seems to take care of both atomic creation and using AtExitManager for
> > deletion at program termination
> 
> 
> Nope! Was just hacking code. Should switch over.

Done.

http://codereview.chromium.org/3169047/diff/1/4#newcode82
remoting/base/tracer.h:82: Tracer* GetTracerInternal() {
On 2010/08/26 19:04:13, scherkus wrote:
> potential locks + refcounting sadness: you're returning a raw pointer outside
> the locked context
> 
> it's possible we don't AddRef the Tracer before another thread calls
> PopTracerInternal and the Trace gets deleted
> 
> might have to change the API to:
> static void tracer(scoped_refptr<Tracer>& tracer_out);
> 
> :(

Moved to using TLS for the TraceContext. This means that the TLS context will
hold a ref to the buffer always making this function safe to return a raw
pointer.

http://codereview.chromium.org/3169047/diff/1/4#newcode116
remoting/base/tracer.h:116: // NewRunnableMethod called NewTracedMethod,
NewTracedCallback
On 2010/08/26 19:04:13, scherkus wrote:
> remove mention of NewTracedCallback?
> 
> should we clean up this comment to remove references to callbacks or will it
be
> possible to use this stuff in callbacks?  (I think so as you can pull a
similar
> trick with CallbackImpl and pushing/popping the tracer inside RunWithParams())

Done.

I'm less certain we actually want this done with callbacks.

Actually, we might just be happy instrumenting the ControlFlow construct you're
talking about creating. :)

In Chromium code, the tasks aren't always part of log chains, which makes this
assumption about propagation of a trace context less useful.

http://codereview.chromium.org/3169047/diff/1/4#newcode131
remoting/base/tracer.h:131: tracer_(TraceContext::tracer()) {
On 2010/08/26 19:21:58, scherkus wrote:
> On 2010/08/26 19:19:52, awong wrote:
> > On 2010/08/26 19:04:13, scherkus wrote:
> > > wait a tick...
> > > 
> > > 1) I create a ScopedTracer A
> > > 2) Tracer A gets pushed on stack
> > > 3) I create a TracedMethod
> > > 4) Tracer A is saved inside TracedMethod via TraceContext::tracer()
> > > 
> > > What if a different thread came along between (2) and (4) that created a
> > > different ScopedTracer B and now (4) uses Tracer B instead of A?
> > 
> > Ooh good catch.
> > 
> > I think the right fix is to make TraceContext thread-local.  That should
also
> > alleviate the raw pointer issue above I think.
> 
> Yeah I was thinking TLS would fix this

Done.

http://codereview.chromium.org/3169047/diff/1/6
File remoting/host/chromoting_host.cc (right):

http://codereview.chromium.org/3169047/diff/1/6#newcode35
remoting/host/chromoting_host.cc:35: ChromotingHost::~ChromotingHost() {
On 2010/08/26 19:04:13, scherkus wrote:
> wait is this file supposed to be in this CL??

Moved to another CL.

http://codereview.chromium.org/3169047/diff/1/6#newcode39
remoting/host/chromoting_host.cc:39: if (MessageLoop::current() !=
context_->main_message_loop()) {
On 2010/08/26 19:04:13, scherkus wrote:
> as a side I've wondered if its worth making a macro for this somehow...

We'd need to make a macro similar to TEST_F for Google test...one that wraps the
whole function declaration.  It's possible, but I think it's pretty ugly.

http://codereview.chromium.org/3169047/diff/1/6#newcode67
remoting/host/chromoting_host.cc:67: LOG(ERROR) << "XMMP credentials are not
defined in config.";
On 2010/08/26 19:04:13, scherkus wrote:
> XMMP -> XMPP

Fixed in another CL.

[scherkus (not reviewing), 2010-08-31 03:16:26]

probably good for now!

LGTM w/ nits

http://codereview.chromium.org/3169047/diff/20001/21003
File remoting/base/tracer.cc (right):

http://codereview.chromium.org/3169047/diff/20001/21003#newcode111
remoting/base/tracer.cc:111: double random_variable =
I think you want RandDouble() from src/base/rand_util.h

http://codereview.chromium.org/3169047/diff/20001/21004
File remoting/base/tracer.h (right):

http://codereview.chromium.org/3169047/diff/20001/21004#newcode68
remoting/base/tracer.h:68: Tracer(const std::string& name, double
sample_percent);
what's sample percent used for?

I could guess, but it seems that most usage is set to 1.0 (which I guess is
100%?) and there are no docs about how to use it

http://codereview.chromium.org/3169047/diff/20001/21004#newcode258
remoting/base/tracer.h:258: #endif // REMOTING_BASE_TRACER_H_
two spaces between #endif and //

[awong, 2010-08-31 04:27:14]

Fixed.

http://codereview.chromium.org/3169047/diff/20001/21003
File remoting/base/tracer.cc (right):

http://codereview.chromium.org/3169047/diff/20001/21003#newcode111
remoting/base/tracer.cc:111: double random_variable =
On 2010/08/31 03:16:27, scherkus wrote:
> I think you want RandDouble() from src/base/rand_util.h


Sure...that looks good.

http://codereview.chromium.org/3169047/diff/20001/21004
File remoting/base/tracer.h (right):

http://codereview.chromium.org/3169047/diff/20001/21004#newcode68
remoting/base/tracer.h:68: Tracer(const std::string& name, double
sample_percent);
On 2010/08/31 03:16:27, scherkus wrote:
> what's sample percent used for?
> 
> I could guess, but it seems that most usage is set to 1.0 (which I guess is
> 100%?) and there are no docs about how to use it

You don't want 100% always. That's going overwhelm the system possibly.  I've
actually been happy with about 1% most of the time.  I'll add some docs.