trace_event: distinguish between scoped begin/end and global start/finish events

trace_event: distinguish between scoped begin/end and global start/finish events

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

[jbates, 2011-11-17 01:15:28]

PTAL

http://codereview.chromium.org/8590015/diff/1/base/debug/trace_event.cc
File base/debug/trace_event.cc (right):

http://codereview.chromium.org/8590015/diff/1/base/debug/trace_event.cc#newco...
base/debug/trace_event.cc:81: StringAppendF(out, "%llu", static_cast<unsigned
long long>(as_uint()));
Cleanup to match other instances of StringAppendF in this file.

http://codereview.chromium.org/8590015/diff/1/base/debug/trace_event.cc#newco...
base/debug/trace_event.cc:92: StringAppendF(out, "\"%llx\"",
static_cast<unsigned long long>(
Storing the pointer as a string instead of an int, because JSON doesn't support
64-bit ints. The string will prevent data loss when the pointer value is
extracted from json.

http://codereview.chromium.org/8590015/diff/1/base/debug/trace_event.cc#newco...
base/debug/trace_event.cc:214: case TRACE_EVENT_PHASE_END:
Reordered these to match the order in the enum.

http://codereview.chromium.org/8590015/diff/1/base/debug/trace_event.h
File base/debug/trace_event.h (right):

http://codereview.chromium.org/8590015/diff/1/base/debug/trace_event.h#newcod...
base/debug/trace_event.h:587: // Note: these are ordered by size (largest first)
for optimal packing.
Since I'm adding data to this struct, I took some time to optimize the data
layout for packing and removed the unnecessary process id member.

http://codereview.chromium.org/8590015/diff/1/base/debug/trace_event.h#newcod...
base/debug/trace_event.h:596: int thread_id_;
Changed thread_id to int to save 32-bits in the 64-bit builds, because we
eventually cast to int when this is stored in json.

[nduca, 2011-11-17 19:13:06]

Tests && JSON file?

The begin/end events dont' have IDs, would it make sense to have two
AddTraceEvent entries instead of one? I'm getting concerned with the number of
arguments we shovel into that method that we don't actually care about...

http://codereview.chromium.org/8590015/diff/1/base/debug/trace_event.h
File base/debug/trace_event.h (left):

http://codereview.chromium.org/8590015/diff/1/base/debug/trace_event.h#oldcod...
base/debug/trace_event.h:256: 
Docs in the top of the header?

Can we remove the explicit BEGIN_END macros entirely? The few cases I know that
use them are traceevent bindings to other trace-event frontends [java, webkit]
so they can call TraceEvent::addTraceLog directly.

The benefit of not having the begin/end macros is that we avoid people
inadvertently using begin/end when a start/finish was correct.

http://codereview.chromium.org/8590015/diff/1/base/debug/trace_event.h
File base/debug/trace_event.h (right):

http://codereview.chromium.org/8590015/diff/1/base/debug/trace_event.h#newcod...
base/debug/trace_event.h:260: // does nothing.
Should explain what a start is.

http://codereview.chromium.org/8590015/diff/1/base/debug/trace_event.h#newcod...
base/debug/trace_event.h:288: // - category and name strings must have
application lifetime (statics or
Should explai what a finish is.

[nduca, 2011-11-18 07:10:26]

On 2011/11/17 19:13:06, nduca wrote:
> Tests && JSON file?
> 
My bad haha, didn't see those.

Hey, one thing that just caused me some issues is that 0 is treated as "no id."
I don't think that works ... we probably need to just keep a bool. Does that
work for you?

[jbates, 2011-11-18 19:46:51]

On 2011/11/18 07:10:26, nduca wrote:
> On 2011/11/17 19:13:06, nduca wrote:
> > Tests && JSON file?
> > 
> My bad haha, didn't see those.
> 
> Hey, one thing that just caused me some issues is that 0 is treated as "no
id."
> I don't think that works ... we probably need to just keep a bool. Does that
> work for you?

Good point, I'll add a flag.

[jbates, 2011-11-23 00:41:10]

Regarding the increase in parameters: it may be possible to reduce code bloat in
exchange for increased runtime overhead of tracing by wrapping AddTraceEvent
with specialized versions that have fewer parameters. Before going down that
path, let's measure to make sure the assembly reduction is significant enough to
warrant the extra branch and parameter marshaling introduced by the wrapper.

By the way, I wonder if we should remove the TRACE_IF_LONGER_THAN macros. I
don't think they've been used... That would remove two parameters.

http://codereview.chromium.org/8590015/diff/1/base/debug/trace_event.h
File base/debug/trace_event.h (left):

http://codereview.chromium.org/8590015/diff/1/base/debug/trace_event.h#oldcod...
base/debug/trace_event.h:256: 
On 2011/11/17 19:13:06, nduca wrote:
> Docs in the top of the header?
> 
> Can we remove the explicit BEGIN_END macros entirely? The few cases I know
that
> use them are traceevent bindings to other trace-event frontends [java, webkit]
> so they can call TraceEvent::addTraceLog directly.
> 
> The benefit of not having the begin/end macros is that we avoid people
> inadvertently using begin/end when a start/finish was correct.

I think we should remove them, but there are a few users of them as you
mentioned. Let's do it in a future CL.

http://codereview.chromium.org/8590015/diff/1/base/debug/trace_event.h
File base/debug/trace_event.h (right):

http://codereview.chromium.org/8590015/diff/1/base/debug/trace_event.h#newcod...
base/debug/trace_event.h:260: // does nothing.
On 2011/11/17 19:13:06, nduca wrote:
> Should explain what a start is.

Done.

http://codereview.chromium.org/8590015/diff/1/base/debug/trace_event.h#newcod...
base/debug/trace_event.h:288: // - category and name strings must have
application lifetime (statics or
On 2011/11/17 19:13:06, nduca wrote:
> Should explai what a finish is.

Done.

[jbates, 2011-11-23 22:36:59]

+phajdan for base/test owners

PTAL

[Paweł Hajdan Jr., 2011-11-24 08:33:27]

base/test LGTM

[jar (doing other things), 2011-12-01 01:47:49]

Mostly readability comments, with a few substance questions/comments.

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.cc
File base/debug/trace_event.cc (right):

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.cc#n...
base/debug/trace_event.cc:81: StringAppendF(out, "%llu", static_cast<unsigned
long long>(as_uint()));
Have you looked at using the "portable" definitions described in
http://src.chromium.org/svn/trunk/src/base/format_macros.h

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.cc#n...
base/debug/trace_event.cc:668: process_id_hash_ = (14695981039346656037ull ^
pid) * 1099511628211ull;
nit: Add a comment (url?) as a reference, or mention this is an FNV hash?  It
would also help to name the variables, rather than using raw constants inline.

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.cc#n...
base/debug/trace_event.cc:686: p_data_->name, 0,
It would really help readability if you assigned these constants to well named
variables.  I still wouldn't be sure that you got the order right (there are a
lot of args... probably enough that you should use a struct), but at least I'd
know the intent.

For instance, when you put the 0 here, what did you mean to pass in as zero??

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.h
File base/debug/trace_event.h (right):

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.h#ne...
base/debug/trace_event.h:45: //     static int recv_count = 0;
This is not multi-thread safe.  At first, I thought all you'd lose is an
occasional mis-match... but then I realized that once you had a collision during
the increment, you'd (probably) never re-align.  Have you looked at the cost of
an atomic increment in this scenario?

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.h#ne...
base/debug/trace_event.h:59: //     TRACE_EVENT_FINISH0("memory", "malloc",
ptr);
FYI: If you put the free after the event, then you'd be guaranteed uniqueness
(within a process, for the lifetime of the event).  

This code gives you the moral equivalent of a lock, but uses only TLS (inside
TCMalloc) to get a unique count.  Given the cost of the malloc, I'd bet than an
atomic increment would be much cheaper.  You could then pass along the counter
value as a fully unique selector for the event you are following (much cheaper
than a malloc), and it would probably only be 32 bits, which would be easier to
hash into an int64 (with a 32 bit PID?).

I'd suggest providing functionality to do exactly this, so that users won't have
to write the code that messes with such stuff.

[nduca, 2011-12-01 02:55:26]

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.h
File base/debug/trace_event.h (left):

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.h#ol...
base/debug/trace_event.h:412: 
<3

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.h
File base/debug/trace_event.h (right):

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.h#ne...
base/debug/trace_event.h:37: // BEGIN and END events should typically be used in
the same scope. To trace
typically->clearly state the nesting requirement. Move or copy to the part of
the doc that explains begin/end.

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.h#ne...
base/debug/trace_event.h:45: //     static int recv_count = 0;
+1, even though its docs, it should be "legitimate."

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.h#ne...
base/debug/trace_event.h:59: //     TRACE_EVENT_FINISH0("memory", "malloc",
ptr);
I suggest using an example closer to that ReadTransaction class where you put
the START/FINISH in the constructor destructor to avoid triggering malloc/free
type debates.

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.h#ne...
base/debug/trace_event.h:856: uint64 GetIntraProcessID(uint64 id) const { return
id ^ process_id_hash_; }
Why this versus just tracking id and a bool flag saying "you need to put the
pid", then making the id a string in the json? You could get pretty unlucky in
this scheme, I worry.

http://codereview.chromium.org/8590015/diff/15001/chrome/browser/resources/tr...
File chrome/browser/resources/tracing/tests/start_finish.json (right):

http://codereview.chromium.org/8590015/diff/15001/chrome/browser/resources/tr...
chrome/browser/resources/tracing/tests/start_finish.json:1:
[{"cat":"renderer","pid":1,"tid":1,"ts":50,"ph":"S","name":"Long","args":{},"ext","1a"},{"cat":"renderer","pid":1,"tid":1,"ts":100,"ph":"S","name":"Cat","args":{},"ext","1"},{"cat":"renderer","pid":1,"tid":1,"ts":120,"ph":"B","name":"Scoped","args":{}},{"cat":"renderer","pid":1,"tid":1,"ts":150,"ph":"F","name":"Mismatch","args":{},"ext","beef1"},{"cat":"renderer","pid":1,"tid":1,"ts":170,"ph":"E","name":"Scoped","args":{}},{"cat":"renderer","pid":1,"tid":1,"ts":200,"ph":"S","name":"Cat","args":{},"ext","2"},{"cat":"renderer","pid":1,"tid":1,"ts":220,"ph":"B","name":"Scoped","args":{}},{"cat":"renderer","pid":1,"tid":1,"ts":230,"ph":"B","name":"SubScoped","args":{}},{"cat":"renderer","pid":1,"tid":1,"ts":250,"ph":"S","name":"Long","args":{},"ext","2a"},{"cat":"renderer","pid":1,"tid":1,"ts":270,"ph":"E","name":"SubScoped","args":{}},{"cat":"renderer","pid":1,"tid":1,"ts":300,"ph":"F","name":"Cat","args":{},"ext","1"},{"cat":"renderer","pid":1,"tid":1,"ts":350,"ph":"E","name":"Scoped","args":{}},{"cat":"renderer","pid":1,"tid":1,"ts":400,"ph":"F","name":"Cat","args":{},"ext","2"},{"cat":"renderer","pid":2,"tid":2,"ts":500,"ph":"S","name":"Dog","args":{},"ext","1"},{"cat":"renderer","pid":2,"tid":3,"ts":600,"ph":"S","name":"Dog","args":{},"ext","2"},{"cat":"renderer","pid":3,"tid":4,"ts":700,"ph":"F","name":"Dog","args":{},"ext","1"},{"cat":"renderer","pid":1,"tid":1,"ts":725,"ph":"S","name":"Mismatch","args":{},"ext","beef2"},{"cat":"renderer","pid":1,"tid":1,"ts":750,"ph":"F","name":"Long","args":{},"ext","2a"},{"cat":"renderer","pid":3,"tid":5,"ts":800,"ph":"F","name":"Dog","args":{},"ext","2"},{"cat":"renderer","pid":1,"tid":1,"ts":900,"ph":"F","name":"Long","args":{},"ext","1a"}]
80cols, follow style of simple_trace.json

Are both mangled-pointers and regular IDs in here?

[jbates, 2011-12-01 23:07:50]

jar, nduca: ptal

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.cc
File base/debug/trace_event.cc (right):

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.cc#n...
base/debug/trace_event.cc:81: StringAppendF(out, "%llu", static_cast<unsigned
long long>(as_uint()));
On 2011/12/01 01:47:49, jar wrote:
> Have you looked at using the "portable" definitions described in
> http://src.chromium.org/svn/trunk/src/base/format_macros.h

Done.

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.cc#n...
base/debug/trace_event.cc:668: process_id_hash_ = (14695981039346656037ull ^
pid) * 1099511628211ull;
On 2011/12/01 01:47:49, jar wrote:
> nit: Add a comment (url?) as a reference, or mention this is an FNV hash?  It
> would also help to name the variables, rather than using raw constants inline.

Done.

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.cc#n...
base/debug/trace_event.cc:686: p_data_->name, 0,
On 2011/12/01 01:47:49, jar wrote:
> It would really help readability if you assigned these constants to well named
> variables.  I still wouldn't be sure that you got the order right (there are a
> lot of args... probably enough that you should use a struct), but at least I'd
> know the intent.
> 
> For instance, when you put the 0 here, what did you mean to pass in as zero??

Done.

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.h
File base/debug/trace_event.h (right):

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.h#ne...
base/debug/trace_event.h:37: // BEGIN and END events should typically be used in
the same scope. To trace
On 2011/12/01 02:55:26, nduca wrote:
> typically->clearly state the nesting requirement. Move or copy to the part of
> the doc that explains begin/end.

Done.

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.h#ne...
base/debug/trace_event.h:45: //     static int recv_count = 0;
On 2011/12/01 01:47:49, jar wrote:
> This is not multi-thread safe.  At first, I thought all you'd lose is an
> occasional mis-match... but then I realized that once you had a collision
during
> the increment, you'd (probably) never re-align.  Have you looked at the cost
of
> an atomic increment in this scenario?

Done.

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.h#ne...
base/debug/trace_event.h:59: //     TRACE_EVENT_FINISH0("memory", "malloc",
ptr);
On 2011/12/01 02:55:26, nduca wrote:
> I suggest using an example closer to that ReadTransaction class where you put
> the START/FINISH in the constructor destructor to avoid triggering malloc/free
> type debates.

Done.

http://codereview.chromium.org/8590015/diff/15001/base/debug/trace_event.h#ne...
base/debug/trace_event.h:856: uint64 GetIntraProcessID(uint64 id) const { return
id ^ process_id_hash_; }
On 2011/12/01 02:55:26, nduca wrote:
> Why this versus just tracking id and a bool flag saying "you need to put the
> pid", then making the id a string in the json? 

Sounds good, but sadly I think I would have to double the size of TraceID to do
that :(. With a 64-bit hash, a collision is extremely unlikely. The collision
would have to happen within a set of START/FINISH events of the same
category/name. Seems OK considering there's not much risk?

http://codereview.chromium.org/8590015/diff/15001/chrome/browser/resources/tr...
File chrome/browser/resources/tracing/tests/start_finish.json (right):

http://codereview.chromium.org/8590015/diff/15001/chrome/browser/resources/tr...
chrome/browser/resources/tracing/tests/start_finish.json:1:
[{"cat":"renderer","pid":1,"tid":1,"ts":50,"ph":"S","name":"Long","args":{},"ext","1a"},{"cat":"renderer","pid":1,"tid":1,"ts":100,"ph":"S","name":"Cat","args":{},"ext","1"},{"cat":"renderer","pid":1,"tid":1,"ts":120,"ph":"B","name":"Scoped","args":{}},{"cat":"renderer","pid":1,"tid":1,"ts":150,"ph":"F","name":"Mismatch","args":{},"ext","beef1"},{"cat":"renderer","pid":1,"tid":1,"ts":170,"ph":"E","name":"Scoped","args":{}},{"cat":"renderer","pid":1,"tid":1,"ts":200,"ph":"S","name":"Cat","args":{},"ext","2"},{"cat":"renderer","pid":1,"tid":1,"ts":220,"ph":"B","name":"Scoped","args":{}},{"cat":"renderer","pid":1,"tid":1,"ts":230,"ph":"B","name":"SubScoped","args":{}},{"cat":"renderer","pid":1,"tid":1,"ts":250,"ph":"S","name":"Long","args":{},"ext","2a"},{"cat":"renderer","pid":1,"tid":1,"ts":270,"ph":"E","name":"SubScoped","args":{}},{"cat":"renderer","pid":1,"tid":1,"ts":300,"ph":"F","name":"Cat","args":{},"ext","1"},{"cat":"renderer","pid":1,"tid":1,"ts":350,"ph":"E","name":"Scoped","args":{}},{"cat":"renderer","pid":1,"tid":1,"ts":400,"ph":"F","name":"Cat","args":{},"ext","2"},{"cat":"renderer","pid":2,"tid":2,"ts":500,"ph":"S","name":"Dog","args":{},"ext","1"},{"cat":"renderer","pid":2,"tid":3,"ts":600,"ph":"S","name":"Dog","args":{},"ext","2"},{"cat":"renderer","pid":3,"tid":4,"ts":700,"ph":"F","name":"Dog","args":{},"ext","1"},{"cat":"renderer","pid":1,"tid":1,"ts":725,"ph":"S","name":"Mismatch","args":{},"ext","beef2"},{"cat":"renderer","pid":1,"tid":1,"ts":750,"ph":"F","name":"Long","args":{},"ext","2a"},{"cat":"renderer","pid":3,"tid":5,"ts":800,"ph":"F","name":"Dog","args":{},"ext","2"},{"cat":"renderer","pid":1,"tid":1,"ts":900,"ph":"F","name":"Long","args":{},"ext","1a"}]
On 2011/12/01 02:55:26, nduca wrote:
> 80cols, follow style of simple_trace.json
> 

Done.

> Are both mangled-pointers and regular IDs in here?

They both become hex IDs, so no difference here.

[nduca, 2011-12-02 00:00:47]

LGTM

[jar (doing other things), 2011-12-02 00:09:32]

LGTM with nit below.

Thanks

http://codereview.chromium.org/8590015/diff/21001/base/test/trace_event_analy...
File base/test/trace_event_analyzer.h (right):

http://codereview.chromium.org/8590015/diff/21001/base/test/trace_event_analy...
base/test/trace_event_analyzer.h:415: double min_us;
nit: Abbreviations are frowned on... IMO, *_microseconds would be simpler... and
not a big deal to type.

...yeah... I saw "us" was used in time.h.... but that was probably not a great
idea.  It gets worse when you look at:
mean_us

We're not that mean! ;-)

http://codereview.chromium.org/8590015/diff/21001/chrome/browser/resources/tr...
File chrome/browser/resources/tracing/tests/start_finish.json (right):

http://codereview.chromium.org/8590015/diff/21001/chrome/browser/resources/tr...
chrome/browser/resources/tracing/tests/start_finish.json:21:
{"cat":"r","pid":1,"tid":1,"ts":900,"ph":"F","name":"A","args":{},"id":"1a"}
+1  This is MUCH nicer ;-)