Update tracing framework to optionally use a ringbuffer.

Update tracing framework to optionally use a ringbuffer.

This updates the code to allow passing a continuous_tracing option into the trace framework. When enabled a ringbuffer will be used for event storage instead of a simple vector.

The continuous_tracing option will allow us to trace for longer periods of time without needing to worry that we'll stop tracing before hitting the event we're looking for.

BUG=156025
Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=188505

[nduca, 2013-02-01 21:39:19]

Woah, this is cool.

But, can you make it an option that you specify when you enable it? e.g.
eanble(categories, mode)

then plumb it all the way up through the controller....

[dsinclair, 2013-02-07 18:41:42]

PTAL.

This will function without any changes to the trace-viewer code, you just won't
be able to enable continuous mode until we update trace-viewer and do the DEPs
roll.

[nduca, 2013-02-12 19:42:22]

https://codereview.chromium.org/12096115/diff/24003/base/debug/trace_event_im...
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/12096115/diff/24003/base/debug/trace_event_im...
base/debug/trace_event_impl.h:211: void SetContinuousTracing(bool
continuous_tracing) {
I like it, but can we make it a mode and a required argument on the enable call?
That way we can correctly fail when two different callers enable the system but
in two different modes [which can happen]. And, correclty handle the case where
someone tries to mutate the logging mode when tracing is active.

https://codereview.chromium.org/12096115/diff/24003/base/debug/trace_event_im...
base/debug/trace_event_impl.h:381: bool continuous_tracing_;
Hm... can you factor out logged_events and logged_events_newest_/oldest_ to be a
class that is the Log object? I think it'd benefit us architecturally to have
this just be a log->AddEvent and then just have two log implementations.

[nduca, 2013-02-12 19:42:34]

Also, I think the cl descirption is a bit out of date.

[dsinclair, 2013-02-15 19:38:55]

Nat,

I've made the update to use a class for the buffer, the change is pushed up.

For the mode comment, do you want me to update the three SetEnabled methods in
trace_event_impl.h to take a final int flags parameter or were you thinking
something else?

Flags would be a bit mask which only has a CONTINUOUS option at the moment.

https://codereview.chromium.org/12096115/diff/24003/base/debug/trace_event_im...
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/12096115/diff/24003/base/debug/trace_event_im...
base/debug/trace_event_impl.h:381: bool continuous_tracing_;
On 2013/02/12 19:42:22, nduca wrote:
> Hm... can you factor out logged_events and logged_events_newest_/oldest_ to be
a
> class that is the Log object? I think it'd benefit us architecturally to have
> this just be a log->AddEvent and then just have two log implementations.

Done.

[nduca, 2013-02-16 00:59:07]

Actually, I think less typed than flags, more like Only for Options:

TracingMode {
  UNTIL_FULL,
  CONTINUOUS
}

There actually are others that we might add later.

[dsinclair, 2013-02-25 19:04:34]

PTAL. Converted to using the options to SetEnabled to determine if we're
continuous or not.

https://codereview.chromium.org/12096115/diff/24003/base/debug/trace_event_im...
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/12096115/diff/24003/base/debug/trace_event_im...
base/debug/trace_event_impl.h:211: void SetContinuousTracing(bool
continuous_tracing) {
On 2013/02/12 19:42:22, nduca wrote:
> I like it, but can we make it a mode and a required argument on the enable
call?
> That way we can correctly fail when two different callers enable the system
but
> in two different modes [which can happen]. And, correclty handle the case
where
> someone tries to mutate the logging mode when tracing is active.

Done.

[dsinclair, 2013-03-04 14:49:37]

On 2013/02/25 19:04:34, dsinclair wrote:
> PTAL. Converted to using the options to SetEnabled to determine if we're
> continuous or not.
> 
>
https://codereview.chromium.org/12096115/diff/24003/base/debug/trace_event_im...
> File base/debug/trace_event_impl.h (right):
> 
>
https://codereview.chromium.org/12096115/diff/24003/base/debug/trace_event_im...
> base/debug/trace_event_impl.h:211: void SetContinuousTracing(bool
> continuous_tracing) {
> On 2013/02/12 19:42:22, nduca wrote:
> > I like it, but can we make it a mode and a required argument on the enable
> call?
> > That way we can correctly fail when two different callers enable the system
> but
> > in two different modes [which can happen]. And, correclty handle the case
> where
> > someone tries to mutate the logging mode when tracing is active.
> 
> Done.

Ping.

[nduca, 2013-03-12 19:15:42]

few small nits

lets also not malloc all the time as noted on chat

https://codereview.chromium.org/12096115/diff/51001/base/debug/trace_event_im...
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/12096115/diff/51001/base/debug/trace_event_im...
base/debug/trace_event_impl.h:445: TraceBuffer* GetTraceBuffer();
Is this a test only hook? If so, clarify. If not, why?

[dsinclair, 2013-03-13 13:49:59]

PTAL, mallocs should be fixed up.

https://codereview.chromium.org/12096115/diff/51001/base/debug/trace_event_im...
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/12096115/diff/51001/base/debug/trace_event_im...
base/debug/trace_event_impl.h:445: TraceBuffer* GetTraceBuffer();
On 2013/03/12 19:15:42, nduca wrote:
> Is this a test only hook? If so, clarify. If not, why?

It's used internally. I use it to create the trace buffer on startup, and to
create the new one if you change the type when doing a SetEnabled. It's also
used in the flush when we do the swap.

[nduca, 2013-03-13 17:04:40]

lgtm thank you

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
File base/debug/trace_event_impl.cc (right):

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1154:
logged_events_->AddEvent(TraceEvent(it->first,
a nice followup would maybe be to initialize inplace, e.g. tmp =
logged_events_->AddEvent()
tmp.init(constructor args)

but since we did this before, its not a regression to land as is.

[dsinclair, 2013-03-13 17:53:25]

jar@ can you please take a look for base/ OWNERS.

pfeldman@ can you please take a look for content/browser/devtools OWNERS.

Thanks,
dan

[jar (doing other things), 2013-03-13 18:42:30]

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
File base/debug/trace_event_impl.cc (right):

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:120: int cur = logged_events_oldest_;
nit: avoid abreviations such as |cur| which I'm guessing is meant to mean
"current".  Better might |next|.

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:137: break;
nit: How about replacing last three lines with:
while(idx != logged_events_newest_)

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:152: uint32 logged_events_newest_;
nit: This is not really the index of the newest, but rather the first unused
entry in the circular buffer.  Possibly a better name would be:

unused_event_index_

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:153: uint32 logged_events_oldest_;
nit: Since this points to a singular event, better might be:

oldest_event_index_

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:168: // will do an AddEvent, if the buffer is
full we'd lose the metadata.
nit: "AddEvent, if the" --> "AddEvent.  If the"

I also don't understand the assertion about losing metadata.  This sure looks
like it will keep pushing, and growing the vector in any case, which may be
undesirable.  Perhaps at least a DCHECK(!IsFull()) would be nice.

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:182: return Size() == kTraceEventBufferSize;
I'm not clear on the meaning, given that you push without checking... but
suspect it woul be much safer to use:
return Size() >= kTraceEventBufferSize

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:188: for (size_t idx = 0; idx <
logged_events_.size(); idx++) {
nit: Rather than abbreviate |idx|, use |index|, or acceptable is |i| for such a
simple counter.  For complicated iterators, it is common to use |it|, but that
is about the only common abbreviation I've seen.

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:967: if
(!previous_logged_events->HasMoreEvents())
nit: again, why not put test into while()

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.h:141: std::vector<TraceEvent> logged_events_;
Data members should be private.  Methods can be made protected  when necessary.

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.h:143: DISALLOW_COPY_AND_ASSIGN(TraceBuffer);
nit: this should be in a private section.

[pfeldman, 2013-03-13 18:46:35]

devtools lgtm

[dsinclair, 2013-03-13 19:27:27]

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
File base/debug/trace_event_impl.cc (right):

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:120: int cur = logged_events_oldest_;
On 2013/03/13 18:42:30, jar wrote:
> nit: avoid abreviations such as |cur| which I'm guessing is meant to mean
> "current".  Better might |next|.

Done.

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:137: break;
On 2013/03/13 18:42:30, jar wrote:
> nit: How about replacing last three lines with:
> while(idx != logged_events_newest_)

Done.

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:152: uint32 logged_events_newest_;
On 2013/03/13 18:42:30, jar wrote:
> nit: This is not really the index of the newest, but rather the first unused
> entry in the circular buffer.  Possibly a better name would be:
> 
> unused_event_index_

Done.

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:153: uint32 logged_events_oldest_;
On 2013/03/13 18:42:30, jar wrote:
> nit: Since this points to a singular event, better might be:
> 
> oldest_event_index_

Done.

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:168: // will do an AddEvent, if the buffer is
full we'd lose the metadata.
On 2013/03/13 18:42:30, jar wrote:
> nit: "AddEvent, if the" --> "AddEvent.  If the"
> 
> I also don't understand the assertion about losing metadata.  This sure looks
> like it will keep pushing, and growing the vector in any case, which may be
> undesirable.  Perhaps at least a DCHECK(!IsFull()) would be nice.

Clarified the comment.

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:182: return Size() == kTraceEventBufferSize;
On 2013/03/13 18:42:30, jar wrote:
> I'm not clear on the meaning, given that you push without checking... but
> suspect it woul be much safer to use:
> return Size() >= kTraceEventBufferSize

Done.

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:188: for (size_t idx = 0; idx <
logged_events_.size(); idx++) {
On 2013/03/13 18:42:30, jar wrote:
> nit: Rather than abbreviate |idx|, use |index|, or acceptable is |i| for such
a
> simple counter.  For complicated iterators, it is common to use |it|, but that
> is about the only common abbreviation I've seen.

Done.

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:967: if
(!previous_logged_events->HasMoreEvents())
On 2013/03/13 18:42:30, jar wrote:
> nit: again, why not put test into while()

Done.

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:1154:
logged_events_->AddEvent(TraceEvent(it->first,
On 2013/03/13 17:04:40, nduca wrote:
> a nice followup would maybe be to initialize inplace, e.g. tmp =
> logged_events_->AddEvent()
> tmp.init(constructor args)
> 
> but since we did this before, its not a regression to land as is.

Ack.

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.h:141: std::vector<TraceEvent> logged_events_;
On 2013/03/13 18:42:30, jar wrote:
> Data members should be private.  Methods can be made protected  when
necessary.

Done.

https://codereview.chromium.org/12096115/diff/62001/base/debug/trace_event_im...
base/debug/trace_event_impl.h:143: DISALLOW_COPY_AND_ASSIGN(TraceBuffer);
On 2013/03/13 18:42:30, jar wrote:
> nit: this should be in a private section.

Done.

[jar (doing other things), 2013-03-15 19:13:30]

Much better....  Please help me understand your comment below.

https://codereview.chromium.org/12096115/diff/89001/base/debug/trace_event_im...
File base/debug/trace_event_impl.cc (right):

https://codereview.chromium.org/12096115/diff/89001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:126: oldest_event_index_ = 0;
nit: This three line snippet could be pulled into a helper function (static
method?) nicely.  It seems sad to see it repeated four times at line 145, 124,
109, and 105 (and have to read it each time).

void IncrementIndex(size_t *index) {...}

or

size_t NextIndex(size_t index) {...}

The latter is perhaps a tad messier... but I don't like taking addresses of
stuff when I don't have to (compilers are confused too commonly).

https://codereview.chromium.org/12096115/diff/89001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:172: : current_iteration_index_(0) {
nit: no need to wrap.. this will fit on previous line.

https://codereview.chromium.org/12096115/diff/89001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:173: logged_events_.reserve(1024);
nit: Please use a named constant here, and in the sibling class:

kInitialEventBufferSize

Why bother reserving here? If the buffer is used, it will grow towards 50K.  Is
this a performance optimization to avoid a bunch of little allocations, since
you know it will grow large?

https://codereview.chromium.org/12096115/diff/89001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:182: // the metadata does an AddEvent, if we had
the DCHECK we would fail
nit: this is a run-on sentence.  Please change the comma to a period.

That said, I don't understand the comment.  If you claim that a DCHECK would
fail here (if we had it), then the calling code sounds problematic.

Also, I *think* perhaps there is a typo on line 181 as you say "...does an
AddEvent."  I'm confused, because this code *is* AddEvent.  Did you mean to
mention a different function???

[dsinclair, 2013-03-15 19:39:55]

PTAL.

https://codereview.chromium.org/12096115/diff/89001/base/debug/trace_event_im...
File base/debug/trace_event_impl.cc (right):

https://codereview.chromium.org/12096115/diff/89001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:126: oldest_event_index_ = 0;
On 2013/03/15 19:13:30, jar wrote:
> nit: This three line snippet could be pulled into a helper function (static
> method?) nicely.  It seems sad to see it repeated four times at line 145, 124,
> 109, and 105 (and have to read it each time).
> 
> void IncrementIndex(size_t *index) {...}
> 
> or
> 
> size_t NextIndex(size_t index) {...}
> 
> The latter is perhaps a tad messier... but I don't like taking addresses of
> stuff when I don't have to (compilers are confused too commonly).

Done.

https://codereview.chromium.org/12096115/diff/89001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:172: : current_iteration_index_(0) {
On 2013/03/15 19:13:30, jar wrote:
> nit: no need to wrap.. this will fit on previous line.

Done.

https://codereview.chromium.org/12096115/diff/89001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:173: logged_events_.reserve(1024);
On 2013/03/15 19:13:30, jar wrote:
> nit: Please use a named constant here, and in the sibling class:
> 
> kInitialEventBufferSize
> 
> Why bother reserving here? If the buffer is used, it will grow towards 50K. 
Is
> this a performance optimization to avoid a bunch of little allocations, since
> you know it will grow large?

Done. It's a performance optimization as we know the buffer will get large once
it's turned on.

https://codereview.chromium.org/12096115/diff/89001/base/debug/trace_event_im...
base/debug/trace_event_impl.cc:182: // the metadata does an AddEvent, if we had
the DCHECK we would fail
On 2013/03/15 19:13:30, jar wrote:
> nit: this is a run-on sentence.  Please change the comma to a period.
> 
> That said, I don't understand the comment.  If you claim that a DCHECK would
> fail here (if we had it), then the calling code sounds problematic.
> 
> Also, I *think* perhaps there is a typo on line 181 as you say "...does an
> AddEvent."  I'm confused, because this code *is* AddEvent.  Did you mean to
> mention a different function???

Done. Hopefully with more clarity this time.

[jar (doing other things), 2013-03-15 19:43:06]

lgtm

[commit-bot: I haz the power, 2013-03-15 19:45:24]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/dsinclair@chromium.org/12096115/96001

[commit-bot: I haz the power, 2013-03-15 20:57:56]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/dsinclair@chromium.org/12096115/106004

[commit-bot: I haz the power, 2013-03-15 23:28:49]

Change committed as 188505

[jamesr, 2013-03-18 00:55:50]

I think this made the Linux 64 bit builder red:

http://build.chromium.org/p/chromium/builders/Linux%20x64/builds/46911

sizes sizes
PERF_REGRESS: nacl_helper-text/text (0.08%), nacl_helper-text/text (0.08%)