Tracing: Added necessary plumbing to make sure clocksync metadata events are always included.

Tracing: Added necessary plumbing to make sure clocksync metadata events are always included.

Before this, they would only be included if the "__metadata" category was enabled. This
category should never be checked.

BUG=catapult:#2341

R=primiano@chromium.org
CC=charliea@chromium.org

[charliea (OOO until 10-5), 2016-06-06 14:22:23]

Description was changed from

==========
Tracing: Added necessary plumbing to make sure clocksync metadata events are
always included.

Before this, they would only be included if the "__metadata" category was
enabled. This
category should never be checked.

BUG=catapult:#2341

R=primiano@chromium.org
CC=charliea@chromium.org
==========

to

==========
Tracing: Added necessary plumbing to make sure clocksync metadata events are
always included.

Before this, they would only be included if the "__metadata" category was
enabled. This
category should never be checked.

BUG=catapult:#2341

R=primiano@chromium.org
CC=charliea@chromium.org
==========

[oystein (OOO til 10th of July), 2016-06-06 16:36:58]

whoops, forgot to send this out on Monday. ptal :)

[Primiano Tucci (use gerrit), 2016-06-06 18:48:04]

On 2016/06/06 16:36:58, Oystein wrote:
> whoops, forgot to send this out on Monday. ptal :)

Instea of adding the FORCED/NONFORCED api, isn't this a matter of saying:
__metadata is always enabled, regardless of the trace config (we could do this
either in TraceLog::UpdateCategoryGroupEnabledFlag or
TraceConfig::IsCategoryGroupEnabled)
If I am understanding everything correctly the use case here seems to be:
- if you  TRACE_EVENT_API_ADD_METADATA_EVENT("some category") we want that
metadata event to be emitted only if the category is enabled
- TRACE_EVENT_API_ADD_METADATA_EVENT("__metadata") we want that always, even if
traceconfig says -*

In other words, it seems to me that the deal here is: we want __metadata to be
"really" always on, even in presence of -*. ALso that should be a smaller CL.

[fmeawad, 2016-06-06 19:21:15]

On 2016/06/06 18:48:04, Primiano Tucci wrote:
> On 2016/06/06 16:36:58, Oystein wrote:
> > whoops, forgot to send this out on Monday. ptal :)
> 
> Instea of adding the FORCED/NONFORCED api, isn't this a matter of saying:
> __metadata is always enabled, regardless of the trace config (we could do this
> either in TraceLog::UpdateCategoryGroupEnabledFlag or
> TraceConfig::IsCategoryGroupEnabled)
> If I am understanding everything correctly the use case here seems to be:
> - if you  TRACE_EVENT_API_ADD_METADATA_EVENT("some category") we want that
> metadata event to be emitted only if the category is enabled
> - TRACE_EVENT_API_ADD_METADATA_EVENT("__metadata") we want that always, even
if
> traceconfig says -*
> 
> In other words, it seems to me that the deal here is: we want __metadata to be
> "really" always on, even in presence of -*. ALso that should be a smaller CL.

I agree with primiano here.

[oystein (OOO til 10th of July), 2016-06-06 19:51:53]

On 2016/06/06 18:48:04, Primiano Tucci wrote:
> On 2016/06/06 16:36:58, Oystein wrote:
> > whoops, forgot to send this out on Monday. ptal :)
> 
> Instea of adding the FORCED/NONFORCED api, isn't this a matter of saying:
> __metadata is always enabled, regardless of the trace config (we could do this
> either in TraceLog::UpdateCategoryGroupEnabledFlag or
> TraceConfig::IsCategoryGroupEnabled)
> If I am understanding everything correctly the use case here seems to be:
> - if you  TRACE_EVENT_API_ADD_METADATA_EVENT("some category") we want that
> metadata event to be emitted only if the category is enabled
> - TRACE_EVENT_API_ADD_METADATA_EVENT("__metadata") we want that always, even
if
> traceconfig says -*
> 
> In other words, it seems to me that the deal here is: we want __metadata to be
> "really" always on, even in presence of -*. ALso that should be a smaller CL.

Yep, that's basically it. I don't think we should expose "__metadata" to the API
users though, it smells like an implementation detail. Most of the CL size in
that case is to make the usages of this go through the proper macros rather than
calling into TraceLog directly, so adding some special-casing for always
enabling "__metadata" rather than skipping the category enabled check wouldn't
affect the CL size much, I think. It would just remove some (most?) of the
trace_event.h stuff and add to trace_log.cc. Note that all of the existing uses
of __metadata (except the clocksync ones) were already skipping the category
check (the ones in memory infra and the tracing controller), this just wraps
that logic in the API.

[Primiano Tucci (use gerrit), 2016-06-07 15:29:26]

On 2016/06/06 19:51:53, Oystein wrote:
> On 2016/06/06 18:48:04, Primiano Tucci wrote:
> > On 2016/06/06 16:36:58, Oystein wrote:
> > > whoops, forgot to send this out on Monday. ptal :)
> > 
> > Instea of adding the FORCED/NONFORCED api, isn't this a matter of saying:
> > __metadata is always enabled, regardless of the trace config (we could do
this
> > either in TraceLog::UpdateCategoryGroupEnabledFlag or
> > TraceConfig::IsCategoryGroupEnabled)
> > If I am understanding everything correctly the use case here seems to be:
> > - if you  TRACE_EVENT_API_ADD_METADATA_EVENT("some category") we want that
> > metadata event to be emitted only if the category is enabled
> > - TRACE_EVENT_API_ADD_METADATA_EVENT("__metadata") we want that always, even
> if
> > traceconfig says -*
> > 
> > In other words, it seems to me that the deal here is: we want __metadata to
be
> > "really" always on, even in presence of -*. ALso that should be a smaller
CL.
> 
> Yep, that's basically it. I don't think we should expose "__metadata" to the
API
> users though, it smells like an implementation detail. Most of the CL size in
> that case is to make the usages of this go through the proper macros rather
than
> calling into TraceLog directly, so adding some special-casing for always
> enabling "__metadata" rather than skipping the category enabled check wouldn't
> affect the CL size much, I think. It would just remove some (most?) of the
> trace_event.h stuff and add to trace_log.cc. 

My main concern is not really CL size itself, but keeping the API easier to
reason about.
I am a bit scared about creating precedent for the set of TRACE_EVENT*_FORCED
APIs.
Good point about not exposing metadata, but I think that boils down to have a 
#define TRACE_METADATA_CATEGORY_ALWAYS_ON "__metadata"
and having code doing
TRACE_EVENT_METADATA1(TRACE_METADATA_CATEGORY_ALWAYS_ON, "foo", "bar").

> Note that all of the existing uses
> of __metadata (except the clocksync ones) were already skipping the category
> check (the ones in memory infra and the tracing controller)
Uh? I think that at least for memory-infra it is not intentional.
Today it does 
TRACE_EVENT_API_ADD_METADATA_EVENT(TraceLog::GetCategoryGroupEnabled("__metadata"),...)
which really today could be replaced with
TRACE_EVENT_METADATA1(kMemoryInfraCategory, ...). Just back then there was no
TRACE_EVENT_METADATA1 because that seemed to be an internal impl detail not
going to be exposed.

The main problem with TRACE_EVENT_METADATA_FORCED1 is that is implicitly
assigning the category "__metadata" which IMHO a bit obscure.

Going back to the original problem (Charlie's events getting dropped on the
floor) I think the immediate concern could be fixed with a 2 line if in 
TraceLog::UpdateCategoryGroupEnabledFlag of the form

if (mode_ == RECORDING_MODE && !strcmp(category_group, "__metadata"))
  enabled_flag |= ENABLED_FOR_RECORDING;

or is there something I'm missing?

[dsinclair, 2016-06-07 19:31:50]

On 2016/06/07 15:29:26, Primiano Tucci wrote:
> On 2016/06/06 19:51:53, Oystein wrote:
> > On 2016/06/06 18:48:04, Primiano Tucci wrote:
> > > On 2016/06/06 16:36:58, Oystein wrote:
> > > > whoops, forgot to send this out on Monday. ptal :)
> > > 
> > > Instea of adding the FORCED/NONFORCED api, isn't this a matter of saying:
> > > __metadata is always enabled, regardless of the trace config (we could do
> this
> > > either in TraceLog::UpdateCategoryGroupEnabledFlag or
> > > TraceConfig::IsCategoryGroupEnabled)
> > > If I am understanding everything correctly the use case here seems to be:
> > > - if you  TRACE_EVENT_API_ADD_METADATA_EVENT("some category") we want that
> > > metadata event to be emitted only if the category is enabled
> > > - TRACE_EVENT_API_ADD_METADATA_EVENT("__metadata") we want that always,
even
> > if
> > > traceconfig says -*
> > > 
> > > In other words, it seems to me that the deal here is: we want __metadata
to
> be
> > > "really" always on, even in presence of -*. ALso that should be a smaller
> CL.
> > 
> > Yep, that's basically it. I don't think we should expose "__metadata" to the
> API
> > users though, it smells like an implementation detail. Most of the CL size
in
> > that case is to make the usages of this go through the proper macros rather
> than
> > calling into TraceLog directly, so adding some special-casing for always
> > enabling "__metadata" rather than skipping the category enabled check
wouldn't
> > affect the CL size much, I think. It would just remove some (most?) of the
> > trace_event.h stuff and add to trace_log.cc. 
> 
> My main concern is not really CL size itself, but keeping the API easier to
> reason about.
> I am a bit scared about creating precedent for the set of TRACE_EVENT*_FORCED
> APIs.
> Good point about not exposing metadata, but I think that boils down to have a 
> #define TRACE_METADATA_CATEGORY_ALWAYS_ON "__metadata"
> and having code doing
> TRACE_EVENT_METADATA1(TRACE_METADATA_CATEGORY_ALWAYS_ON, "foo", "bar").
> 
> > Note that all of the existing uses
> > of __metadata (except the clocksync ones) were already skipping the category
> > check (the ones in memory infra and the tracing controller)
> Uh? I think that at least for memory-infra it is not intentional.
> Today it does 
>
TRACE_EVENT_API_ADD_METADATA_EVENT(TraceLog::GetCategoryGroupEnabled("__metadata"),...)
> which really today could be replaced with
> TRACE_EVENT_METADATA1(kMemoryInfraCategory, ...). Just back then there was no
> TRACE_EVENT_METADATA1 because that seemed to be an internal impl detail not
> going to be exposed.
> 
> The main problem with TRACE_EVENT_METADATA_FORCED1 is that is implicitly
> assigning the category "__metadata" which IMHO a bit obscure.
> 
> Going back to the original problem (Charlie's events getting dropped on the
> floor) I think the immediate concern could be fixed with a 2 line if in 
> TraceLog::UpdateCategoryGroupEnabledFlag of the form
> 
> if (mode_ == RECORDING_MODE && !strcmp(category_group, "__metadata"))
>   enabled_flag |= ENABLED_FOR_RECORDING;
> 
> or is there something I'm missing?



Aren't the metadata events already pushed onto their own queue, through their
own addition methods which ignore the category filters all together? If that's
the case, they should be getting emitted now, and if they aren't that's a
different bug.

[Primiano Tucci (use gerrit), 2016-06-07 19:33:36]

On 2016/06/07 19:31:50, dsinclair wrote:
> On 2016/06/07 15:29:26, Primiano Tucci wrote:
> > On 2016/06/06 19:51:53, Oystein wrote:
> > > On 2016/06/06 18:48:04, Primiano Tucci wrote:
> > > > On 2016/06/06 16:36:58, Oystein wrote:
> > > > > whoops, forgot to send this out on Monday. ptal :)
> > > > 
> > > > Instea of adding the FORCED/NONFORCED api, isn't this a matter of
saying:
> > > > __metadata is always enabled, regardless of the trace config (we could
do
> > this
> > > > either in TraceLog::UpdateCategoryGroupEnabledFlag or
> > > > TraceConfig::IsCategoryGroupEnabled)
> > > > If I am understanding everything correctly the use case here seems to
be:
> > > > - if you  TRACE_EVENT_API_ADD_METADATA_EVENT("some category") we want
that
> > > > metadata event to be emitted only if the category is enabled
> > > > - TRACE_EVENT_API_ADD_METADATA_EVENT("__metadata") we want that always,
> even
> > > if
> > > > traceconfig says -*
> > > > 
> > > > In other words, it seems to me that the deal here is: we want __metadata
> to
> > be
> > > > "really" always on, even in presence of -*. ALso that should be a
smaller
> > CL.
> > > 
> > > Yep, that's basically it. I don't think we should expose "__metadata" to
the
> > API
> > > users though, it smells like an implementation detail. Most of the CL size
> in
> > > that case is to make the usages of this go through the proper macros
rather
> > than
> > > calling into TraceLog directly, so adding some special-casing for always
> > > enabling "__metadata" rather than skipping the category enabled check
> wouldn't
> > > affect the CL size much, I think. It would just remove some (most?) of the
> > > trace_event.h stuff and add to trace_log.cc. 
> > 
> > My main concern is not really CL size itself, but keeping the API easier to
> > reason about.
> > I am a bit scared about creating precedent for the set of
TRACE_EVENT*_FORCED
> > APIs.
> > Good point about not exposing metadata, but I think that boils down to have
a 
> > #define TRACE_METADATA_CATEGORY_ALWAYS_ON "__metadata"
> > and having code doing
> > TRACE_EVENT_METADATA1(TRACE_METADATA_CATEGORY_ALWAYS_ON, "foo", "bar").
> > 
> > > Note that all of the existing uses
> > > of __metadata (except the clocksync ones) were already skipping the
category
> > > check (the ones in memory infra and the tracing controller)
> > Uh? I think that at least for memory-infra it is not intentional.
> > Today it does 
> >
>
TRACE_EVENT_API_ADD_METADATA_EVENT(TraceLog::GetCategoryGroupEnabled("__metadata"),...)
> > which really today could be replaced with
> > TRACE_EVENT_METADATA1(kMemoryInfraCategory, ...). Just back then there was
no
> > TRACE_EVENT_METADATA1 because that seemed to be an internal impl detail not
> > going to be exposed.
> > 
> > The main problem with TRACE_EVENT_METADATA_FORCED1 is that is implicitly
> > assigning the category "__metadata" which IMHO a bit obscure.
> > 
> > Going back to the original problem (Charlie's events getting dropped on the
> > floor) I think the immediate concern could be fixed with a 2 line if in 
> > TraceLog::UpdateCategoryGroupEnabledFlag of the form
> > 
> > if (mode_ == RECORDING_MODE && !strcmp(category_group, "__metadata"))
> >   enabled_flag |= ENABLED_FOR_RECORDING;
> > 
> > or is there something I'm missing?
> 
> 
> 
> Aren't the metadata events already pushed onto their own queue, through their
> own addition methods which ignore the category filters all together? If that's
> the case, they should be getting emitted now, and if they aren't that's a
> different bug.

See crbug.com/618054 metadata events right now are just a mess.
I did chat with oysteine@ offline. The thing I'm going to do right now is to
send a two line patch to make sure that __metadata category is considered always
on. This will solve the problem that is blocking charlie which is -* preventing
the clock sync markers to be added.
Than we'll figure out a proper solution to that bug, eventually reverting my fix
in favor of something consistent and civilized.