Add a command line flag for dumping trace events to VLOG

Add a command line flag for dumping trace events to VLOG

Only affects cc_unittests at the moment.

BUG=None
R=danakj@chromium.org, jar@chromium.org, nduca@chromium.org

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

[Ian Vollick, 2013-04-24 16:15:08]

On 2013/04/24 16:12:24, vollick wrote:

Actually, please hold off on reviewing this, Nat. I'm going to post a patch that
spits to stderr when the scoped objects get destroyed so we can see durations in
the spew.

[Ian Vollick, 2013-04-24 18:33:40]

Nat, I think this is ready. PTAL.

It's quite pretty. If you run with --cc-unittests-trace-events-to-stderr you get
output like this:
TraceLog (412267720647) Main:| | 'E', LayerTreeHost::UpdateLayers::CalcDrawProps
(0.122 ms)
TraceLog (412267720763) Main:| | 'B',
PrioritizedResourceManager::PrioritizeTextures
TraceLog (412267720851) Main:| | 'E',
PrioritizedResourceManager::PrioritizeTextures (0.088 ms)
TraceLog (412267720977) Main:| 'E', LayerTreeHost::UpdateLayers (0.516 ms)
TraceLog (412267721060) Main:| 'B', commit
TraceLog (412267721178) Compositor:'B',
ThreadProxy::BeginFrameCompleteOnImplThread
TraceLog (412267721252) Compositor:| 'B',
PrioritizedResourceManager::PushTexturePrioritiesToBackings
TraceLog (412267721325) Compositor:| | 'B',
PrioritizedResourceManager::SortBackings
TraceLog (412267721393) Compositor:| | 'E',
PrioritizedResourceManager::SortBackings (0.068 ms)
TraceLog (412267721503) Compositor:| 'E',
PrioritizedResourceManager::PushTexturePrioritiesToBackings (0.251 ms)
TraceLog (412267721585) Compositor:| 'C', EstimatedTexturesPerSecond
TraceLog (412267721676) Compositor:'E',
ThreadProxy::BeginFrameCompleteOnImplThread (0.498 ms)
TraceLog (412267721776) Compositor:'B', Scheduler::BeginFrameComplete
TraceLog (412267721833) Compositor:| 'B', Scheduler::ProcessScheduledActions()

On Dana's suggestion, I've even color-coded the output for different threads!

On 2013/04/24 16:15:08, vollick wrote:
> On 2013/04/24 16:12:24, vollick wrote:
> 
> Actually, please hold off on reviewing this, Nat. I'm going to post a patch
that
> spits to stderr when the scoped objects get destroyed so we can see durations
in
> the spew.

[danakj, 2013-04-24 20:07:41]

cc/ LGTM with a couple nits

https://codereview.chromium.org/14474006/diff/3001/cc/base/switches.cc
File cc/base/switches.cc (right):

https://codereview.chromium.org/14474006/diff/3001/cc/base/switches.cc#newcod...
cc/base/switches.cc:144: // Trace events get dumped to stderr for debugging
purposes.
Comment is on the wrong variable. Maybe add one for the tree flag too?

https://codereview.chromium.org/14474006/diff/3001/cc/test/cc_test_suite.cc
File cc/test/cc_test_suite.cc (right):

https://codereview.chromium.org/14474006/diff/3001/cc/test/cc_test_suite.cc#n...
cc/test/cc_test_suite.cc:29: base::debug::TraceLog::ECHO_TO_STDERR);
Do you want RECORD_CONTINUOUSLY in the options as well? Seems like you want
CONTINUOUSLY or UNTIL_FULL, and the former seems appropriate.

[danakj, 2013-04-24 20:10:12]

https://codereview.chromium.org/14474006/diff/3001/base/debug/trace_event_impl.h
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/14474006/diff/3001/base/debug/trace_event_imp...
base/debug/trace_event_impl.h:521: base::hash_map<int, std::vector<TimeTicks> >
thread_event_start_times_;
I think you're looking for std::stack for this instead of vector?

[jbates1, 2013-04-24 21:10:51]

Only concern I have would be performance. It looks heavy. Otherwise, leaving it
up to the chrome team for review.

[Ian Vollick, 2013-04-24 22:57:11]

Dana, thanks for the reviews!

John, you're right -- this will incur some overhead, but there should be no hit
if you're not using the flag, and you should only use the flag for debugging,
what's-going-on-in-the-compositor purposes.

https://codereview.chromium.org/14474006/diff/3001/base/debug/trace_event_impl.h
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/14474006/diff/3001/base/debug/trace_event_imp...
base/debug/trace_event_impl.h:521: base::hash_map<int, std::vector<TimeTicks> >
thread_event_start_times_;
On 2013/04/24 20:10:12, danakj wrote:
> I think you're looking for std::stack for this instead of vector?

Done.

https://codereview.chromium.org/14474006/diff/3001/cc/base/switches.cc
File cc/base/switches.cc (right):

https://codereview.chromium.org/14474006/diff/3001/cc/base/switches.cc#newcod...
cc/base/switches.cc:144: // Trace events get dumped to stderr for debugging
purposes.
On 2013/04/24 20:07:41, danakj wrote:
> Comment is on the wrong variable. Maybe add one for the tree flag too?

Done.

https://codereview.chromium.org/14474006/diff/3001/cc/test/cc_test_suite.cc
File cc/test/cc_test_suite.cc (right):

https://codereview.chromium.org/14474006/diff/3001/cc/test/cc_test_suite.cc#n...
cc/test/cc_test_suite.cc:29: base::debug::TraceLog::ECHO_TO_STDERR);
On 2013/04/24 20:07:41, danakj wrote:
> Do you want RECORD_CONTINUOUSLY in the options as well? Seems like you want
> CONTINUOUSLY or UNTIL_FULL, and the former seems appropriate.

Good call! Done.

[Ian Vollick, 2013-04-25 01:15:07]

+jar for base/ OWNERS

[jar (doing other things), 2013-04-25 02:14:06]

lgtm

https://codereview.chromium.org/14474006/diff/8001/base/debug/trace_event_imp...
File base/debug/trace_event_impl.cc (right):

https://codereview.chromium.org/14474006/diff/8001/base/debug/trace_event_imp...
base/debug/trace_event_impl.cc:1135: thread_event_start_times_.end())
nit: undent-2 spaces.

You only need to indent 4 from previous line on a wrap... which ends up aligning
with the same name just after the paren.

[nduca, 2013-04-25 02:32:35]

any reason to make this a cc option rather than something else? And, why enable
cc only? Should we enable all? Or maybe enable cc*?

https://codereview.chromium.org/14474006/diff/8001/base/debug/trace_event_imp...
File base/debug/trace_event_impl.cc (right):

https://codereview.chromium.org/14474006/diff/8001/base/debug/trace_event_imp...
base/debug/trace_event_impl.cc:1120: if (trace_options_ & ECHO_TO_STDERR) {
if you just used a echoing trace log, you might be able to make this just be a
mode for recording...

https://codereview.chromium.org/14474006/diff/8001/cc/test/cc_test_suite.cc
File cc/test/cc_test_suite.cc (right):

https://codereview.chromium.org/14474006/diff/8001/cc/test/cc_test_suite.cc#n...
cc/test/cc_test_suite.cc:30: base::debug::TraceLog::RECORD_CONTINUOUSLY);
not sure i get this bit. Why not turn on a non-recording tracelog in this case?

[Ian Vollick, 2013-04-25 04:11:54]

On 2013/04/25 02:32:35, nduca wrote:
> any reason to make this a cc option rather than something else? And, why
enable
> cc only? Should we enable all? Or maybe enable cc*?

I wanted to give this a try for the cc_unittests first. If people like it, I'd
be happy to enable this more broadly. The base/ changes should still be
applicable. I'd originally enabled "*", but since this is only for the
cc_unittests, and since we only use the "cc" category in src/cc, this seemed
like a good default (cuts down on a lot of MessageLoop noise). In any case, I've
made it possible to specify the category string using the new flag, so if we
want to see all events, it's definitely possible.

> 
>
https://codereview.chromium.org/14474006/diff/8001/base/debug/trace_event_imp...
> File base/debug/trace_event_impl.cc (right):
> 
>
https://codereview.chromium.org/14474006/diff/8001/base/debug/trace_event_imp...
> base/debug/trace_event_impl.cc:1120: if (trace_options_ & ECHO_TO_STDERR) {
> if you just used a echoing trace log, you might be able to make this just be a
> mode for recording...

I'd looked at putting all the logic in a subclass of TraceBuffer, but it doesn't
have convenient access to the data I wanted for pretty printing (like thread
names). I could possibly plumb these as extra arguments to TraceBuffer::AddEvent
if you think that would be better.

> 
> https://codereview.chromium.org/14474006/diff/8001/cc/test/cc_test_suite.cc
> File cc/test/cc_test_suite.cc (right):
> 
>
https://codereview.chromium.org/14474006/diff/8001/cc/test/cc_test_suite.cc#n...
> cc/test/cc_test_suite.cc:30: base::debug::TraceLog::RECORD_CONTINUOUSLY);
> not sure i get this bit. Why not turn on a non-recording tracelog in this
case?

I've created a new TraceBuffer that just discards events it receives. We use
this when we're in ECHO_TO_STDERR mode. This let me get rid of the
RECORD_CONTINUOUSLY business.

[Ian Vollick, 2013-04-26 01:21:29]

jamesr pointed out that VLOG is probably better than stderr. I've updated the
patch accordingly. PTAL.

On 2013/04/25 04:11:54, vollick wrote:
> On 2013/04/25 02:32:35, nduca wrote:
> > any reason to make this a cc option rather than something else? And, why
> enable
> > cc only? Should we enable all? Or maybe enable cc*?
> 
> I wanted to give this a try for the cc_unittests first. If people like it, I'd
> be happy to enable this more broadly. The base/ changes should still be
> applicable. I'd originally enabled "*", but since this is only for the
> cc_unittests, and since we only use the "cc" category in src/cc, this seemed
> like a good default (cuts down on a lot of MessageLoop noise). In any case,
I've
> made it possible to specify the category string using the new flag, so if we
> want to see all events, it's definitely possible.
> 
> > 
> >
>
https://codereview.chromium.org/14474006/diff/8001/base/debug/trace_event_imp...
> > File base/debug/trace_event_impl.cc (right):
> > 
> >
>
https://codereview.chromium.org/14474006/diff/8001/base/debug/trace_event_imp...
> > base/debug/trace_event_impl.cc:1120: if (trace_options_ & ECHO_TO_STDERR) {
> > if you just used a echoing trace log, you might be able to make this just be
a
> > mode for recording...
> 
> I'd looked at putting all the logic in a subclass of TraceBuffer, but it
doesn't
> have convenient access to the data I wanted for pretty printing (like thread
> names). I could possibly plumb these as extra arguments to
TraceBuffer::AddEvent
> if you think that would be better.
> 
> > 
> > https://codereview.chromium.org/14474006/diff/8001/cc/test/cc_test_suite.cc
> > File cc/test/cc_test_suite.cc (right):
> > 
> >
>
https://codereview.chromium.org/14474006/diff/8001/cc/test/cc_test_suite.cc#n...
> > cc/test/cc_test_suite.cc:30: base::debug::TraceLog::RECORD_CONTINUOUSLY);
> > not sure i get this bit. Why not turn on a non-recording tracelog in this
> case?
> 
> I've created a new TraceBuffer that just discards events it receives. We use
> this when we're in ECHO_TO_STDERR mode. This let me get rid of the
> RECORD_CONTINUOUSLY business.

[nduca, 2013-04-26 17:43:36]

LGTM

[nduca, 2013-04-26 17:44:14]

You should email parts of the internet when you land this :)

[commit-bot: I haz the power, 2013-04-26 18:58:15]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/vollick@chromium.org/14474006/21001

[commit-bot: I haz the power, 2013-04-26 19:21:55]

Sorry for I got bad news for ya.
Compile failed with a clobber build on win_rel.
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=win_rel&nu...
Your code is likely broken or HEAD is junk. Please ensure your
code is not broken then alert the build sheriffs.
Look at the try server FAQ for more details.

[commit-bot: I haz the power, 2013-04-26 19:25:36]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/vollick@chromium.org/14474006/21001

[commit-bot: I haz the power, 2013-04-26 19:32:01]

Sorry for I got bad news for ya.
Compile failed with a clobber build on win7_aura.
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=win7_aura&...
Your code is likely broken or HEAD is junk. Please ensure your
code is not broken then alert the build sheriffs.
Look at the try server FAQ for more details.

[Ian Vollick, 2013-04-29 13:37:54]

Committed patchset #8 manually as r197024 (presubmit successful).