Event tracing for sync events

Event tracing for sync events

Adds a "sync" trace event category that traces the following events:
- model association time
- time spent in each step of the syncer state machine
- transactions

Also included is a "sync_lock_contention" category that tracks the time spent
acquiring the sync lock. This information would normally clutter up the logs,
but it is useful information when we suspect lock contention is an issue.

To trace model association tracing, I needed to have a set of strings with
application lifetime representing each model type.  I have changed the
return type of ModelTypeToString from std::string to const char* to meet this
need.

In the interest of avoiding duplicate functionality, this change also removes
other mechanisms for tracing transaction time. In particular, some of the log
messages around acquiring and releasing transactions have been removed.

BUG=104353
TEST=Run with '--trace-startup=sync,sync_lock_contention', open resulting
chrometrace.log in about:tracing.


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

[rlarocque, 2011-11-15 19:45:06]

John: Please take a quick look to make sure I'm not misusing this feature. 
Neither myself nor the other reviewers are very familiar with trace events.  

Others: Here is the long promised patch to add tracing to sync.  Please make
sure that you won't miss any of the logs this will remove.

http://codereview.chromium.org/8573011/diff/1/chrome/browser/sync/syncable/sy...
File chrome/browser/sync/syncable/syncable.cc (right):

http://codereview.chromium.org/8573011/diff/1/chrome/browser/sync/syncable/sy...
chrome/browser/sync/syncable/syncable.cc:1150:
&TransactionObserver::OnTransactionStart, from_here_, writer_);
I'm tempted to remove the OnTransactionStart and OnTransactionEnd events.  These
events are somewhat expensive and impossible to disable.  The trace events will
collect the same information at lower cost and lower latency (we don't need to
wait for the sync thread to be free to get the results).

Are there any objections to removing them?

[tim (not reviewing), 2011-11-15 20:03:03]

+Fred for review for relatedness to about:sync and quickness :)

[jbates, 2011-11-16 00:46:57]

LGTM if it's working for you, with the caveats in the comments below...

Currently, if your BEGIN/END events are pipelined, like:

BEGIN1
BEGIN2
END1
END2

Those would be paired incorrectly as (BEGIN2,END1) and (BEGIN1,END2).

The START/FINISH macros will allow you to specify an id to uniquely associate a
pair of START/FINISH events:

TRACE_EVENT_START1("sync", "name", (uint64)this, ...)
...
TRACE_EVENT_FINISH1("sync", "name", (uint64)this, ...)

http://codereview.chromium.org/8573011/diff/1/chrome/browser/sync/engine/sync...
File chrome/browser/sync/engine/syncer.cc (right):

http://codereview.chromium.org/8573011/diff/1/chrome/browser/sync/engine/sync...
chrome/browser/sync/engine/syncer.cc:126: TRACE_EVENT_BEGIN1("sync",
"SyncerStateMachine",
If you change this to TRACE_EVENT1 instead of TRACE_EVENT_BEGIN1, it will
automatically end when the scope ends (and then you wouldn't need the
TRACE_EVENT_END1 below).

http://codereview.chromium.org/8573011/diff/1/chrome/browser/sync/engine/sync...
chrome/browser/sync/engine/syncer.cc:312: TRACE_EVENT_END1("sync",
"SyncerStateMachine",
Could remove this as mentioned above.

http://codereview.chromium.org/8573011/diff/1/chrome/browser/sync/glue/data_t...
File chrome/browser/sync/glue/data_type_manager_impl.cc (right):

http://codereview.chromium.org/8573011/diff/1/chrome/browser/sync/glue/data_t...
chrome/browser/sync/glue/data_type_manager_impl.cc:297:
TRACE_EVENT_BEGIN1("sync", "ModelAssociation",
Does this show up OK in about:tracing? BEGIN..END pairs are assumed to occur in
one scope by about:tracing, so this might not look correct. Another thing to
note is that about:tracing only shows the begin event's arguments.

We have a bug filed to address this (ie: add START/FINISH events that have no
scoping assumptions http://code.google.com/p/chromium/issues/detail?id=100131).
I'm working on this now, but it will also require updates to the UI to display
global start/finish events in a unique way. Feel free to move forward with this
as is if it's working for you and we can patch it up later.

[rlarocque, 2011-11-16 01:03:40]

Thanks for the comments.

I had assumed that the parameters in the END statements had to match those in
the BEGIN.  Since it seems that's not the case, I will update the CL
accordingly.

http://codereview.chromium.org/8573011/diff/1/chrome/browser/sync/engine/sync...
File chrome/browser/sync/engine/syncer.cc (right):

http://codereview.chromium.org/8573011/diff/1/chrome/browser/sync/engine/sync...
chrome/browser/sync/engine/syncer.cc:126: TRACE_EVENT_BEGIN1("sync",
"SyncerStateMachine",
On 2011/11/16 00:46:57, jbates wrote:
> If you change this to TRACE_EVENT1 instead of TRACE_EVENT_BEGIN1, it will
> automatically end when the scope ends (and then you wouldn't need the
> TRACE_EVENT_END1 below).

I had considered that, but decided against it.  I was worried that the fact that
the 'current_step' will have changed by the time we leave the scope could have
confused the system.  I thought the parameters for BEGIN and END were supposed
to match perfectly.  

I take it from you other comments that this is not the case.  I think I will use
scoped events here.

http://codereview.chromium.org/8573011/diff/1/chrome/browser/sync/glue/data_t...
File chrome/browser/sync/glue/data_type_manager_impl.cc (right):

http://codereview.chromium.org/8573011/diff/1/chrome/browser/sync/glue/data_t...
chrome/browser/sync/glue/data_type_manager_impl.cc:297:
TRACE_EVENT_BEGIN1("sync", "ModelAssociation",
On 2011/11/16 00:46:57, jbates wrote:
> Does this show up OK in about:tracing? BEGIN..END pairs are assumed to occur
in
> one scope by about:tracing, so this might not look correct. Another thing to
> note is that about:tracing only shows the begin event's arguments.
> 
> We have a bug filed to address this (ie: add START/FINISH events that have no
> scoping assumptions
http://code.google.com/p/chromium/issues/detail?id=100131).
> I'm working on this now, but it will also require updates to the UI to display
> global start/finish events in a unique way. Feel free to move forward with
this
> as is if it's working for you and we can patch it up later.

That's odd.  The results I see in about:tracing seem to make sense.  

I will remove the matching END's arguments.

[rlarocque, 2011-11-16 19:30:48]

Updated and simplified this patch.  It looks a bit cleaner now that I don't
bother supplying matching arguments to each TRACE_BEGIN and TRACE_END pair.

These changes seem to have had no effect on the results in about:tracing, which
is what I expected.

[akalin, 2011-11-17 03:27:21]

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/engine/s...
File chrome/browser/sync/engine/syncer.cc (left):

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/engine/s...
chrome/browser/sync/engine/syncer.cc:8: #include "base/message_loop.h"
#include "base/logging.h"

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/engine/s...
File chrome/browser/sync/engine/syncer.cc (right):

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/engine/s...
chrome/browser/sync/engine/syncer.cc:77: ENUM_CASE(SYNCER_END);
default: NOTREACHED(); ?

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/engine/s...
File chrome/browser/sync/engine/syncer.h (right):

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/engine/s...
chrome/browser/sync/engine/syncer.h:131: const char* SyncerStepToString(const
SyncerStep);
"const SyncerStep" -> "SyncerStep step"

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/syncable...
File chrome/browser/sync/syncable/model_type.h (right):

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/syncable...
chrome/browser/sync/syncable/model_type.h:124: // Returns a pointer to a string
with application lifetime that represents
How hard would it be to just make ModelTypeToString return a const char*?  If
it's hard, have a TODO to do so.

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/syncable...
File chrome/browser/sync/syncable/syncable.cc (right):

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/syncable...
chrome/browser/sync/syncable/syncable.cc:1161: TRACE_EVENT_BEGIN2("sync",
"ReadTransaction",
What about adding the trace events to BaseTransaction/~BaseTransaction instead?

We already pass in a name to BaseTransaction.  If you change the passed-in names
to "ReadTransaction"/"WriteTransaction", you can then do:

BaseTransaction::BaseTransaction(...) : ... {
  TRACE_EVENT_BEGIN2("sync", name_, "src_file", ...);
  ...
}

and similarly in the destructor.

[akalin, 2011-11-17 03:35:30]

On 2011/11/15 19:45:06, rlarocque wrote:
>
http://codereview.chromium.org/8573011/diff/1/chrome/browser/sync/syncable/sy...
> chrome/browser/sync/syncable/syncable.cc:1150:
> &TransactionObserver::OnTransactionStart, from_here_, writer_);
> I'm tempted to remove the OnTransactionStart and OnTransactionEnd events. 
These
> events are somewhat expensive and impossible to disable.  The trace events
will
> collect the same information at lower cost and lower latency (we don't need to
> wait for the sync thread to be free to get the results).
> 
> Are there any objections to removing them?

Now that the tracing/profile stuff is in active development again (yay!), I
think we can migrate to it, as the Events tab in about:sync isn't working very
well, and I haven't had time to fix it.

So we can:

1) Remove the OnTransaction{Start,End} events.
2) Start migrating most the other events to use tracing.  The ones we can't
migrate are the heavyweight ones, like OnTransactionWrite and OnChangesApplied.
3) Change the Events tab in about:sync to basically a transaction/change
browser.
4) Figure out how and when to turn on tracing for sync events.

So, short answer, I don't have any objections to removing those events.

[rlarocque, 2011-11-17 19:37:53]

Most comments addressed in new patch.

I haven't removed OnTransaction{Start,End} in this patch because I noticed you
have some changes to that area of the code out for review.  We should coordinate
to reduce the chance of conflicts when checking in those changes.

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/engine/s...
File chrome/browser/sync/engine/syncer.cc (left):

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/engine/s...
chrome/browser/sync/engine/syncer.cc:8: #include "base/message_loop.h"
On 2011/11/17 03:27:21, akalin wrote:
> #include "base/logging.h"

Done.

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/engine/s...
File chrome/browser/sync/engine/syncer.cc (right):

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/engine/s...
chrome/browser/sync/engine/syncer.cc:77: ENUM_CASE(SYNCER_END);
On 2011/11/17 03:27:21, akalin wrote:
> default: NOTREACHED(); ?

Here's what happens when I try to comment out the last enum and compile:

../../chrome/browser/sync/engine/syncer.cc:61:11: error: enumeration value
'SYNCER_END' not handled in switch [-Werror,-Wswitch-enum]

If I put the default case in there, the compiler would not be able to notice
this, since all cases would technically be "handled".  

I prefer the compile time error over the run time error.

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/syncable...
File chrome/browser/sync/syncable/model_type.h (right):

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/syncable...
chrome/browser/sync/syncable/model_type.h:124: // Returns a pointer to a string
with application lifetime that represents
On 2011/11/17 03:27:21, akalin wrote:
> How hard would it be to just make ModelTypeToString return a const char*?  If
> it's hard, have a TODO to do so.

Turns out it's not very hard at all.  

Correct me if I'm wrong, but I think it's safe to trust the compiler to verify
this change.  I've made the change, fixed the compile errors, and everything
seems to work fine.

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/syncable...
File chrome/browser/sync/syncable/syncable.cc (right):

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/syncable...
chrome/browser/sync/syncable/syncable.cc:1161: TRACE_EVENT_BEGIN2("sync",
"ReadTransaction",
On 2011/11/17 03:27:21, akalin wrote:
> What about adding the trace events to BaseTransaction/~BaseTransaction
instead?
> 
> We already pass in a name to BaseTransaction.  If you change the passed-in
names
> to "ReadTransaction"/"WriteTransaction", you can then do:
> 
> BaseTransaction::BaseTransaction(...) : ... {
>   TRACE_EVENT_BEGIN2("sync", name_, "src_file", ...);
>   ...
> }
> 
> and similarly in the destructor.

I originally wanted to do it that way, but couldn't.  The TRACE_EVENT macros
only handle two arguments.  I think there's a cost associated with supporting
more arguments, so it's probably not a simple matter to add more.  

That being said, I'm pretty happy with how it turned out.  It's nice to see the
type of transaction displayed prominently in the UI.

[akalin, 2011-11-17 22:17:45]

I meant to remove OnTransaction{Start,End} in a separate CL.

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/engine/s...
File chrome/browser/sync/engine/syncer.cc (right):

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/engine/s...
chrome/browser/sync/engine/syncer.cc:58: #define ENUM_CASE(x) case x: return #x;
break
this can be:

case x: return #x

(you may have copied it from one of the other places where I wrote ENUM_CASE. 
if so, I don't know what I was thinking)

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/engine/s...
chrome/browser/sync/engine/syncer.cc:77: ENUM_CASE(SYNCER_END);
On 2011/11/17 19:37:53, rlarocque wrote:
> On 2011/11/17 03:27:21, akalin wrote:
> > default: NOTREACHED(); ?
> 
> Here's what happens when I try to comment out the last enum and compile:
> 
> ../../chrome/browser/sync/engine/syncer.cc:61:11: error: enumeration value
> 'SYNCER_END' not handled in switch [-Werror,-Wswitch-enum]
> 
> If I put the default case in there, the compiler would not be able to notice
> this, since all cases would technically be "handled".  
> 
> I prefer the compile time error over the run time error.

Hmm the set of enum values is still greater than the enum constants in general
(although in this case it's not since the number of constants is a power of 2).

What about putting NOTREACHED(); outside of the switch?  I think that gives both
a compile-time and a run-time error (which the compiler may elide).

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/syncable...
File chrome/browser/sync/syncable/syncable.cc (right):

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/syncable...
chrome/browser/sync/syncable/syncable.cc:1161: TRACE_EVENT_BEGIN2("sync",
"ReadTransaction",
On 2011/11/17 19:37:53, rlarocque wrote:

> I originally wanted to do it that way, but couldn't.  The TRACE_EVENT macros
> only handle two arguments.  I think there's a cost associated with supporting
> more arguments, so it's probably not a simple matter to add more.  

I'm not sure what you mean; my suggestion doesn't involve adding extra
arguments, but simply replacing the 'name' parameter to the macro with the name
parameter passed into BaseTransaction's constructor.

[akalin, 2011-11-17 22:18:59]

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/syncable...
File chrome/browser/sync/syncable/model_type.h (right):

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/syncable...
chrome/browser/sync/syncable/model_type.h:124: // Returns a pointer to a string
with application lifetime that represents
On 2011/11/17 19:37:53, rlarocque wrote:
> On 2011/11/17 03:27:21, akalin wrote:
> > How hard would it be to just make ModelTypeToString return a const char*? 
If
> > it's hard, have a TODO to do so.
> 
> Turns out it's not very hard at all.  
> 
> Correct me if I'm wrong, but I think it's safe to trust the compiler to verify
> this change.  I've made the change, fixed the compile errors, and everything
> seems to work fine.  

I think that's safe enough, although it's possible that this change would e.g.
reduce a 'string == const char*' comparison to a 'const char* == const char*'
comparison or something.  It may be worth doing 'git grep ModelTypeToString' and
quickly auditing the callsites.

[rlarocque, 2011-11-18 02:47:10]

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/engine/s...
File chrome/browser/sync/engine/syncer.cc (right):

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/engine/s...
chrome/browser/sync/engine/syncer.cc:58: #define ENUM_CASE(x) case x: return #x;
break
On 2011/11/17 22:17:45, akalin wrote:
> this can be:
> 
> case x: return #x
> 
> (you may have copied it from one of the other places where I wrote ENUM_CASE. 
> if so, I don't know what I was thinking)

Done.

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/engine/s...
chrome/browser/sync/engine/syncer.cc:77: ENUM_CASE(SYNCER_END);
On 2011/11/17 22:17:45, akalin wrote:
> On 2011/11/17 19:37:53, rlarocque wrote:
> > On 2011/11/17 03:27:21, akalin wrote:
> > > default: NOTREACHED(); ?
> > 
> > Here's what happens when I try to comment out the last enum and compile:
> > 
> > ../../chrome/browser/sync/engine/syncer.cc:61:11: error: enumeration value
> > 'SYNCER_END' not handled in switch [-Werror,-Wswitch-enum]
> > 
> > If I put the default case in there, the compiler would not be able to notice
> > this, since all cases would technically be "handled".  
> > 
> > I prefer the compile time error over the run time error.
> 
> Hmm the set of enum values is still greater than the enum constants in general
> (although in this case it's not since the number of constants is a power of
2).
> 

I don't think the number of constants has anything to do with it...

> What about putting NOTREACHED(); outside of the switch?  I think that gives
both
> a compile-time and a run-time error (which the compiler may elide).

It looks like I'll have to do that.  The windows compiler complains because it
doesn't realize I have all the cases covered.  It thinks it's possible to reach
the end of this function without returning a value.

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/syncable...
File chrome/browser/sync/syncable/model_type.h (right):

http://codereview.chromium.org/8573011/diff/5001/chrome/browser/sync/syncable...
chrome/browser/sync/syncable/model_type.h:124: // Returns a pointer to a string
with application lifetime that represents
On 2011/11/17 22:18:59, akalin wrote:
> On 2011/11/17 19:37:53, rlarocque wrote:
> > On 2011/11/17 03:27:21, akalin wrote:
> > > How hard would it be to just make ModelTypeToString return a const char*? 
> If
> > > it's hard, have a TODO to do so.
> > 
> > Turns out it's not very hard at all.  
> > 
> > Correct me if I'm wrong, but I think it's safe to trust the compiler to
verify
> > this change.  I've made the change, fixed the compile errors, and everything
> > seems to work fine.  
> 
> I think that's safe enough, although it's possible that this change would e.g.
> reduce a 'string == const char*' comparison to a 'const char* == const char*'
> comparison or something.  It may be worth doing 'git grep ModelTypeToString'
and
> quickly auditing the callsites.

Good point, I hadn't thought of that issue.  

The git-grep doesn't turn up anything suspicious, so I'm still feeling pretty
good about this change.

[akalin, 2011-11-19 00:32:13]

LGTM

http://codereview.chromium.org/8573011/diff/20001/chrome/browser/sync/syncabl...
File chrome/browser/sync/syncable/syncable.cc (right):

http://codereview.chromium.org/8573011/diff/20001/chrome/browser/sync/syncabl...
chrome/browser/sync/syncable/syncable.cc:1161: TRACE_EVENT_END0("sync",
"ReadTransaction");
"ReadTransaction" -> name_

[akalin, 2011-11-19 00:32:47]

On 2011/11/19 00:32:13, akalin wrote:
> LGTM
> 
>
http://codereview.chromium.org/8573011/diff/20001/chrome/browser/sync/syncabl...
> File chrome/browser/sync/syncable/syncable.cc (right):
> 
>
http://codereview.chromium.org/8573011/diff/20001/chrome/browser/sync/syncabl...
> chrome/browser/sync/syncable/syncable.cc:1161: TRACE_EVENT_END0("sync",
> "ReadTransaction");
> "ReadTransaction" -> name_

Also mention the ModelTypeToString change in the CL description

[commit-bot: I haz the power, 2011-11-22 22:18:09]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/rlarocque@chromium.org/8573011/26002

[commit-bot: I haz the power, 2011-11-22 22:18:20]

Presubmit check for 8573011-26002 failed and returned exit status 1.

Running presubmit commit checks ...

** Presubmit Messages **
You might be calling functions intended only for testing from
production code.  It is OK to ignore this warning if you know what
you are doing, as the heuristics used to detect the situation are
not perfect.  The commit queue will not block on this warning.
Email joi@chromium.org if you have questions.
  chrome/browser/sync/syncable/syncable.cc:1846
    EntryKernel* entry = GetPossibleLastChildForTest(lock, parent_id);

** Presubmit Warnings **
Found lines longer than 80 characters (first 5 shown).
  chrome/browser/sync/syncable/syncable.cc, line 1218, 86 chars \
  chrome/browser/sync/syncable/syncable.cc, line 1235, 86 chars

Presubmit checks took 2.8s to calculate.

[commit-bot: I haz the power, 2011-11-22 22:34:32]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/rlarocque@chromium.org/8573011/31001

[commit-bot: I haz the power, 2011-11-23 00:52:15]

Change committed as 111265