Add NESTABLE_ASYNC APIs to Tracing

This CL adds NESTABLE_ASYNC APIs to tracing.
This is a part of the effort to get NetLog data into
tracing. The reason to add these new APIs for logging 
NetLog events is that NetLog events are logged
asynchronously and can have multiple nested levels of
inner events. The current ASYNC_STEP APIs only allow
one level of nested events. 

In general, it would be useful if we could can have an
async event broken into sub steps, each sub step has an 
explicitly defined beginning and end within that overall 
event, with additional arguments.

Design Doc: 
https://docs.google.com/document/d/1Z2uqj59UEts5IiXX78mkdU4kd6e7kE3JUKPoDK97bVs/edit?usp=sharing
BUG=399701
Committed: https://crrev.com/039bf813a96ec7284af2fb85926769714cb5eb05
Cr-Commit-Position: refs/heads/master@{#293940}

[xunjieli, 2014-09-02 20:21:46]

xunjieli@chromium.org changed reviewers:
+ dsinclair@chromium.org, nduca@chromium.org

[xunjieli, 2014-09-02 20:21:46]

Hi dsinclair and nduca,

I have separated out trace specific changes. PTAL. Thanks!

Helen

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

https://codereview.chromium.org/536503002/diff/1/base/debug/trace_event.h#new...
base/debug/trace_event.h:1008: #define TRACE_EVENT_PHASE_NET_LOG_BEGIN ('x')
Any letters that I can use? is x, y, z okay?

[dsinclair, 2014-09-02 20:31:17]

On 2014/09/02 20:22:26, xunjieli1 wrote:

Is there a reason to create NET_LOG_* events specifically? They don't seem to do
anything special from a quick glance. Is there an email chain or doc I can look
at to see the reasoning?

[mmenke, 2014-09-02 20:46:02]

On 2014/09/02 20:31:17, dsinclair wrote:
> On 2014/09/02 20:22:26, xunjieli1 wrote:
> 
> Is there a reason to create NET_LOG_* events specifically? They don't seem to
do
> anything special from a quick glance. Is there an email chain or doc I can
look
> at to see the reasoning?

They're nested.  No other events are.

[dsinclair, 2014-09-02 21:06:07]

> > Is there a reason to create NET_LOG_* events specifically? They don't seem
to
> do
> > anything special from a quick glance. Is there an email chain or doc I can
> look
> > at to see the reasoning?
> 
> They're nested.  No other events are.


I'm not sure if I understand. Events in tracing are nested already. If you call
BEGIN, BEGIN, END, END we'll nest them. Is it that this is an ASYNC type event
and those aren't nested?

[xunjieli, 2014-09-02 21:07:34]

On 2014/09/02 21:06:07, dsinclair wrote:
> > > Is there a reason to create NET_LOG_* events specifically? They don't seem
> to
> > do
> > > anything special from a quick glance. Is there an email chain or doc I can
> > look
> > > at to see the reasoning?
> > 
> > They're nested.  No other events are.
> 
> 
> I'm not sure if I understand. Events in tracing are nested already. If you
call
> BEGIN, BEGIN, END, END we'll nest them. Is it that this is an ASYNC type event
> and those aren't nested?

I believe we need the ASYNC type.

[xunjieli, 2014-09-02 23:45:58]

Patchset #2 (id:20001) has been deleted

[nduca, 2014-09-03 05:37:24]

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

https://codereview.chromium.org/536503002/diff/1/base/debug/trace_event.h#new...
base/debug/trace_event.h:639: // associated arguments. If the category is not
enabled, then this
not just 2

https://codereview.chromium.org/536503002/diff/1/base/debug/trace_event.h#new...
base/debug/trace_event.h:648: // NET_LOG_ events are supposed to be used for
logging NetLog events only.
Please retitle to nestable_async_*.

Tracing is neutral to all libraries that use it. We seek abstractions that allow
us to represent the behavior of complex systems like the network stack, or the
graphics stack. But we never create abstractions that are purely for one domain
only.

So, please update the naming accordingly so that its not that this is for
netlog, but rather that what the abstraction we're creating here allows us to
represent. Your docs should explain when to use this, and when to use the
async_begin/end/step_into/after apis.

And you should update the *old* apis [the regular async apis] to clarify when to
use those.

Finally, please explain the nesting semantics. E.g. what happens if you say end,
before a begin. Or if you say begin, end end. Etc. This should be in the docs.

https://codereview.chromium.org/536503002/diff/1/base/debug/trace_event.h#new...
base/debug/trace_event.h:1008: #define TRACE_EVENT_PHASE_NET_LOG_BEGIN ('x')
how about looking at the other ones and thinking a bit more carefully about it? 
i'd like to have a *reasoned* explanation of why the letters are chosen, not
just picking three letters.

you'll note async uses S/T/P, the flow uses s/t/f. Most of the letters are at
least somewhat related. Can you find something that makes sense?

[nduca, 2014-09-03 05:38:34]

Also please make your CL description more readable. The first line in the commit
should explain the high level goal of whats being done: add nestable async
events to tracing.

YOu should then have more details in the commit message that explain *why*, what
they're used for, why they're important vs the old events, and a link to the
design doc we've been working on.

[xunjieli, 2014-09-03 14:51:10]

Thanks Nat for the review! I have uploaded a new patch. PTAL

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

https://codereview.chromium.org/536503002/diff/1/base/debug/trace_event.h#new...
base/debug/trace_event.h:639: // associated arguments. If the category is not
enabled, then this
There are two associated arguments right? arg1 and arg2. Or should I count name
and id too? The other examples in this file only count arg1 and arg2. 
On 2014/09/03 05:37:23, nduca wrote:
> not just 2

https://codereview.chromium.org/536503002/diff/1/base/debug/trace_event.h#new...
base/debug/trace_event.h:648: // NET_LOG_ events are supposed to be used for
logging NetLog events only.
On 2014/09/03 05:37:24, nduca wrote:
> Please retitle to nestable_async_*.
> 
> Tracing is neutral to all libraries that use it. We seek abstractions that
allow
> us to represent the behavior of complex systems like the network stack, or the
> graphics stack. But we never create abstractions that are purely for one
domain
> only.
> 
> So, please update the naming accordingly so that its not that this is for
> netlog, but rather that what the abstraction we're creating here allows us to
> represent. Your docs should explain when to use this, and when to use the
> async_begin/end/step_into/after apis.
> 
> And you should update the *old* apis [the regular async apis] to clarify when
to
> use those.
> 
> Finally, please explain the nesting semantics. E.g. what happens if you say
end,
> before a begin. Or if you say begin, end end. Etc. This should be in the docs.
> 

Done. Since dsinclair mentioned that the existing non-async counterparts does
nesting as well, how does tracing handle unmatched begin and end there? Should
parsing these nestable_async begin and end be the same as that one?

https://codereview.chromium.org/536503002/diff/1/base/debug/trace_event.h#new...
base/debug/trace_event.h:1008: #define TRACE_EVENT_PHASE_NET_LOG_BEGIN ('x')
Done. 
On 2014/09/03 05:37:24, nduca wrote:
> how about looking at the other ones and thinking a bit more carefully about
it? 
> i'd like to have a *reasoned* explanation of why the letters are chosen, not
> just picking three letters.
> 
> you'll note async uses S/T/P, the flow uses s/t/f. Most of the letters are at
> least somewhat related. Can you find something that makes sense?

[dsinclair, 2014-09-03 15:02:47]

https://codereview.chromium.org/536503002/diff/40001/base/debug/trace_event.h
File base/debug/trace_event.h (right):

https://codereview.chromium.org/536503002/diff/40001/base/debug/trace_event.h...
base/debug/trace_event.h:1023: #define TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT
('n')
bikeshed: should these be ASYNC_NESTABLE (and the macros above) to keep them
consistent with the other ASYNC events? (And move them up with the other ASYNC_*
entries?

[xunjieli, 2014-09-03 15:09:15]

https://codereview.chromium.org/536503002/diff/40001/base/debug/trace_event.h
File base/debug/trace_event.h (right):

https://codereview.chromium.org/536503002/diff/40001/base/debug/trace_event.h...
base/debug/trace_event.h:1023: #define TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT
('n')
On 2014/09/03 15:02:47, dsinclair wrote:
> bikeshed: should these be ASYNC_NESTABLE (and the macros above) to keep them
> consistent with the other ASYNC events? (And move them up with the other
ASYNC_*
> entries?

Done. ASYNC_NESTABLE does sound better. Thanks!

[nduca, 2014-09-03 18:15:04]

nestable_async please.

[xunjieli, 2014-09-03 18:45:33]

On 2014/09/03 18:15:04, nduca wrote:
> nestable_async please.

I don't have a strong preference. Since there already exist async_* apis, I
think it will be good to follow the pattern. 
But I am fine with whichever you guys choose. Dan and Nat, is there an agreement
on the naming?

[nduca, 2014-09-03 19:35:35]

I talked to Dan offline, I think I pursuaded him to go with the nestable_async.
Sorry about the crossed wires. Some more comments. Please think critically as
you read your docstrings about how you would feel if you were brand new to this
codebase and you were trying to understand async vs nestable async. You want
this to be clear. The comments don't pass a clarity test yet.

[xunjieli, 2014-09-03 19:48:12]

Sure. Did you send the comments? I don't see them.

On 2014/09/03 19:35:35, nduca wrote:
> I talked to Dan offline, I think I pursuaded him to go with the
nestable_async.
> Sorry about the crossed wires. Some more comments. Please think critically as
> you read your docstrings about how you would feel if you were brand new to
this
> codebase and you were trying to understand async vs nestable async. You want
> this to be clear. The comments don't pass a clarity test yet.

[dsinclair, 2014-09-04 14:17:42]

On 2014/09/03 19:48:12, xunjieli1 wrote:
> Sure. Did you send the comments? I don't see them.
> 
> On 2014/09/03 19:35:35, nduca wrote:
> > I talked to Dan offline, I think I pursuaded him to go with the
> nestable_async.
> > Sorry about the crossed wires. Some more comments. Please think critically
as
> > you read your docstrings about how you would feel if you were brand new to
> this
> > codebase and you were trying to understand async vs nestable async. You want
> > this to be clear. The comments don't pass a clarity test yet.


When this lands, can you please update
https://docs.google.com/a/chromium.org/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYM...
?

[xunjieli, 2014-09-04 14:24:27]

On 2014/09/04 14:17:42, dsinclair wrote:
> On 2014/09/03 19:48:12, xunjieli1 wrote:
> > Sure. Did you send the comments? I don't see them.
> > 
> > On 2014/09/03 19:35:35, nduca wrote:
> > > I talked to Dan offline, I think I pursuaded him to go with the
> > nestable_async.
> > > Sorry about the crossed wires. Some more comments. Please think critically
> as
> > > you read your docstrings about how you would feel if you were brand new to
> > this
> > > codebase and you were trying to understand async vs nestable async. You
want
> > > this to be clear. The comments don't pass a clarity test yet.
> 
> 
> When this lands, can you please update
>
https://docs.google.com/a/chromium.org/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYM...
> ?

I only have view access. Should I do it somewhere else and maybe you or Nat and
review/copy over?

[xunjieli, 2014-09-05 17:08:52]

Pinging. PTAL. Thanks!

[dsinclair, 2014-09-08 16:43:28]

lgtm

[xunjieli, 2014-09-08 19:42:34]

Patchset #7 (id:140001) has been deleted

[nduca, 2014-09-08 22:21:14]

more comments, but lgtm assuming you can address them

https://codereview.chromium.org/536503002/diff/80001/base/debug/trace_event.h
File base/debug/trace_event.h (right):

https://codereview.chromium.org/536503002/diff/80001/base/debug/trace_event.h...
base/debug/trace_event.h:514: // Records a single ASYNC_BEGIN event called
"name" immediately, with 0, 1 or 2
I want to discourage people from using this api. please update the docs so that
people are steered to the nestable version. This should only be used by legacy
code and the comments should effectively say this.

https://codereview.chromium.org/536503002/diff/80001/base/debug/trace_event.h...
base/debug/trace_event.h:654: // - Unmatched ASYNC_NESTABLE_END event will be
parsed as an instant event,
Your docstrings here look like they're explaining the |id| argument. Can you
shuffle this around so its clear which is just explaining the general api vs the
arguments?

https://codereview.chromium.org/536503002/diff/80001/base/debug/trace_event.h...
base/debug/trace_event.h:659: //   ASYNC_NESTABLE_* APIs are used to capture
asynchronous operations which can
this seems like its better up top of this comment block? think about good
comments:


One line sentence.

General explanation paragraph, usually provides information on when to use it,
what scenarios make sense.

Detail paragraphs. Here's where to put semantic information.

Argument information.

https://codereview.chromium.org/536503002/diff/80001/base/debug/trace_event.h...
base/debug/trace_event.h:661: //   only has one level of sub-events, one should
consider using ASYNC_STEP_*.
I don't think we're intending people to point at async_step. We're probably
going to remove that, so I'd remove this If sentence.

https://codereview.chromium.org/536503002/diff/80001/base/debug/trace_event_i...
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/536503002/diff/80001/base/debug/trace_event_i...
base/debug/trace_event_impl.h:496: class BASE_EXPORT EnabledStateObserver {
why? this should be a separate CL

[xunjieli, 2014-09-09 13:24:26]

Patchset #7 (id:160001) has been deleted

[xunjieli, 2014-09-09 13:31:19]

Thanks for the review! I have uploaded a new patch to address the comments, and
moved trace_event_impl.h to another CL.

https://codereview.chromium.org/536503002/diff/80001/base/debug/trace_event.h
File base/debug/trace_event.h (right):

https://codereview.chromium.org/536503002/diff/80001/base/debug/trace_event.h...
base/debug/trace_event.h:514: // Records a single ASYNC_BEGIN event called
"name" immediately, with 0, 1 or 2
On 2014/09/08 22:21:13, nduca wrote:
> I want to discourage people from using this api. please update the docs so
that
> people are steered to the nestable version. This should only be used by legacy
> code and the comments should effectively say this.

Done.

https://codereview.chromium.org/536503002/diff/80001/base/debug/trace_event.h...
base/debug/trace_event.h:654: // - Unmatched ASYNC_NESTABLE_END event will be
parsed as an instant event,
On 2014/09/08 22:21:13, nduca wrote:
> Your docstrings here look like they're explaining the |id| argument. Can you
> shuffle this around so its clear which is just explaining the general api vs
the
> arguments?

Done.

https://codereview.chromium.org/536503002/diff/80001/base/debug/trace_event.h...
base/debug/trace_event.h:659: //   ASYNC_NESTABLE_* APIs are used to capture
asynchronous operations which can
On 2014/09/08 22:21:13, nduca wrote:
> this seems like its better up top of this comment block? think about good
> comments:
> 
> 
> One line sentence.
> 
> General explanation paragraph, usually provides information on when to use it,
> what scenarios make sense.
> 
> Detail paragraphs. Here's where to put semantic information.
> 
> Argument information.

Done. Thanks for the detailed explanation!

https://codereview.chromium.org/536503002/diff/80001/base/debug/trace_event.h...
base/debug/trace_event.h:661: //   only has one level of sub-events, one should
consider using ASYNC_STEP_*.
On 2014/09/08 22:21:13, nduca wrote:
> I don't think we're intending people to point at async_step. We're probably
> going to remove that, so I'd remove this If sentence.

Done.

https://codereview.chromium.org/536503002/diff/80001/base/debug/trace_event_i...
File base/debug/trace_event_impl.h (right):

https://codereview.chromium.org/536503002/diff/80001/base/debug/trace_event_i...
base/debug/trace_event_impl.h:496: class BASE_EXPORT EnabledStateObserver {
On 2014/09/08 22:21:13, nduca wrote:
> why? this should be a separate CL

Done.

[xunjieli, 2014-09-09 13:32:12]

The CQ bit was checked by xunjieli@chromium.org

[commit-bot: I haz the power, 2014-09-09 13:33:03]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/xunjieli@chromium.org/536503002/180001

[commit-bot: I haz the power, 2014-09-09 15:26:20]

Committed patchset #7 (id:180001) as efcfda133af95f4f579ba3f49b6243bdd57e4d0a

[commit-bot: I haz the power, 2014-09-10 03:53:25]

Patchset 7 (id:??) landed as
https://crrev.com/039bf813a96ec7284af2fb85926769714cb5eb05
Cr-Commit-Position: refs/heads/master@{#293940}