tracing: simplify lifetime of TraceEventFilter(s)

tracing: simplify lifetime of TraceEventFilter(s)

Two major changes introduced by this CL, both aimed at reducing the
complexity of TraceLog:
1) Simplify the lifetime of TraceEventFilters. Now they are kept alive
   until the very last moment when there is no space left for other
   filters.
2) Don't cache the full TraceConfig::EventFilters in the TraceLog.
   Instead make each filter keep its own copy of its config.

Background: TraceLog modes (recording, filtering, both)
-------------------------------------------------------
Recent changes (crrev.com/{2323483005,2316403002,2259493003) added the
ability to have two modes for TraceLog: recording, filtering or both.
"Recording" is the conventional mode where the macros
TRACE_EVENT*(category, event, args...) directly inject events into the
trace buffer when the corresponding category is enabled.
"Filtering" alone turns on the macros without recording events in
the buffer, but allows filters to snoop the events. A concrete
use case for this mode is the --enable-heap-profiling mode which
wants to see all the TRACE_EVENTs to reconstruct the pseudo stack
but doesn't want them to fill the trace buffer.
It is also possible to combine the two modes (filtering + recording).
In this case the filters have also the power of preventing an event
to be added to the buffer. The use case here (not there yet in the code)
are the cases where we want to collect traces form the field but want
to limit the size of the trace by doing some fine grained stripping.
Side note: there is a further level of filtering in TraceLog called
ArgumentFilterPredicate. Today this is used for post-processing the
buffer before flushing to filter out PII-sensitive events. Perhaps
in the near future this could be merged with the filtering mode.
However this is out of scope from this CL.

Problem: duplication of TraceConfig in TraceLog
-----------------------------------------------
The way TraceLog today handles multiple modes is quite hard to follow.
TraceLog today has one copy of the TraceConfig (which can contain config
for both modes) but two states (recording and filtering).
To overcome this, TraceLog keeps also a cached copy of the parts of
TraceConfig relevant for filters in the |enabled_event_filters_| field
and strives to keep that in sync with the indexed in the bitmaps of the
TraceCategory classes.

Solution introduced by this CL:
TraceLog stops keeping a cached copy of the TraceConfig. Instead
when creating and registering a filter, it attaches the config of the
specific filter to the filter instance itself. This can be obtained
without coupling TraceEventFilter and TraceConfig by using a tiny
interface with one virtual method (see TraceEventFilter::Config).
Overall this makes TraceLog simpler and easier to reason about filters.

Problem: lifetime of TraceEventFilter(s)
----------------------------------------
When is it safe to destroy a TraceEventFilter? They can be *disabled*
but not *destroyed* immediately after TraceLog::SetDisabled(FILTERING).
This is because of the multi-threading nature of tracing: other threads
might still be referencing the filters while tracing is being disabled.
Using a lock is a no-go as we don't want tracing to serialize the various
threads around a lock.
The current approach destroys them when tracing is re-enabled. This
can still causes races though if tracing is disabled and immediately
re-enabled. Also this makes the TraceLog code hard to follow.

Solution introduced by this CL:
When a new filter is registered, The EventFilterRegistry (EFR) adds it
to the set of filters (or crashes if there are no slots left).
The filter can be referred to via a numeric index which is guaranteed to
be stable for all the lifetime of the filter. This index is used by the
TraceCategory.enabled_filters_ bitmap.
When a filter is not needed anymore TraceLog simply unregisters it and
stops caring about its lifetime. The EFT will NOT destroy it immediately.
Instead it will mark it as free-able and defer the destruction until the
very last moment, that is, after unregistering all filters and adding other
32 of them. This makes the race extremely unrealistic at this point. The
only case when a thread can still refer to a destroyed filter becomes the
interval between starting the execution of a TRACE_EVENTx macro (when
the enabled_filters_ bitmap is read) and the invocation of the filter
(few instructions afterwards). In this tiny interval tracing needs to
be stopped and started enough times to add other 32 filters in order to
hit the race. Which is technically still possible but becomes
extremely unlikely from a practical viewpoint.

BUG=659689

[Primiano Tucci (use gerrit), 2016-12-06 12:26:50]

The CQ bit was checked by primiano@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-12-06 12:26:59]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-12-06 12:42:49]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-12-06 12:42:51]

Dry run: Try jobs failed on following builders:
  cast_shell_linux on master.tryserver.chromium.linux (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/cast_shell_linu...)

[Primiano Tucci (use gerrit), 2016-12-06 12:47:02]

The CQ bit was checked by primiano@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-12-06 12:47:19]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-12-06 13:03:56]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-12-06 13:03:57]

Dry run: Try jobs failed on following builders:
  android_compile_dbg on master.tryserver.chromium.android (JOB_FAILED,
https://build.chromium.org/p/tryserver.chromium.android/builders/android_comp...)

[Primiano Tucci (use gerrit), 2016-12-06 14:48:51]

The CQ bit was checked by primiano@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-12-06 14:49:02]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[Primiano Tucci (use gerrit), 2016-12-06 14:55:29]

Description was changed from

==========
tracing: simplify lifetime of TraceEventFilter(s)

Two major changes introduced by this CL, both aimed at reducing the
complexity of TraceLog:
1) Simplify the lifetime of TraceEventFilters. Now they are kept alive
   until the very last moment when there is no space left for other
   filters.
2) Don't cache the full TraceConfig::EventFilters in the TraceLog.
   Instead make each filter keep its own copy of its config.

Background: TraceLog modes (recording, filtering, both)
-------------------------------------------------------
Recent changes (crrev.com/{2323483005,2316403002,2259493003) added the
ability to have two modes for TraceLog: recording, filtering (or both).
"Recording" is the conventional mode where the macros
TRACE_EVENT*(category, event, args...) directly inject events into the
trace buffer when the corresponding category is enabled.
"Filtering" alone turns on the macros without recording events in
the buffer, but allows filters to snoop the events. A concrete
use case for this mode is the --enable-heap-profiling mode which
wants to see all the TRACE_EVENTs to reconstruct the pseudo stack
but doesn't want them to fill the trace buffer.
It is also possible to combine the two modes (filtering + recording).
In this case the filters have also the power of preventing an event
to be added to the buffer. The use case here (not there yet in the code)
are the cases where we want to collect traces form the field but want
to limit the size of the trace by doing some fine grained stripping.
Side note: there is a further level of filtering in TraceLog called
ArgumentFilterPredicate. Today this is used for post-processing the
buffer before flushing to filter out PII-sensitive events. Perhaps
in the near future this could be merged with the filtering mode.
However this is out of scope from this CL.

Problem: duplication of TraceConfig in TraceLog
-----------------------------------------------
The way TraceLog today handles multiple modes is quite hard to follow.
TraceLog today has one copy of the TraceConfig (which can contain config
for both modes) but two states (recording and filtering).
To overcome this, TraceLog keeps also a cached copy of the parts of
TraceConfig relevant for filters in the |enabled_event_filters_| field
and strives to keep that in sync with the indexed in the bitmaps of the
TraceCategory classes.

Solution introduced by this CL:
TraceLog stops keeping a cached copy of the TraceConfig. Instead
when creating and registering a filter, it attaches the config of the
specific filter to the filter instance itself. This can be obtained
without coupling TraceEventFilter and TraceConfig by using a tiny
interface with one virtual method (see TraceEventFilter::Config).
Overall this makes TraceLog simpler and easier to reason about filters.

Problem: lifetime of TraceEventFilter(s)
----------------------------------------
When is it safe to destroy a TraceEventFilter? They can be *disabled*
but not *destroyed* immediately after TraceLog::SetDisabled(filtering).
This is because of the multi-threading nature of tracing: other threads
might still be referencing the filters while tracing is being disabled.
Using a lock is a no-go as we don't want tracing to serialize the various
threads around a lock.
The current approach destroys them when tracing is re-enabled. This
can still causes races though if tracing is disabled and immediately
re-enabled. Also this makes the TraceLog code hard to follow.

Solution introduced by this CL:
When a new filter is registered, TEFR adds it to the set of filters
or crashes if there are no slots left (this behavior is already there).
The filter can be referred to via a numeric index which is guaranteed to
be stable for all the lifetime of the filter. This index will be used
by the TraceCategory.enabled_filters_ bitmap.
When a filter is not anymore needed TraceLog simply unregisters it and
stops caring about the lifetime. The TEFR will NOT destroy it immediately.
Instead it will mark it as freeable and defer the destruction until the
very last moment, that is, after unregistering all filters and adding other
32 of them. This makes the race extremely unrealistic at this point. The
only case when a thread can still refer to a destroyed filter becomes the
interval between starting the execution of a TRACE_EVENTx macro (when
the enabled_filters_ bitmap is read) and the invocation of the filter
(few instructions afterwards). In this tiny interval tracing needs to
be stopped and started enough times to add other 32 filters in order to
hit the race. Which is technically still possible but extremely unlikely

BUG=659689
==========

to

==========
tracing: simplify lifetime of TraceEventFilter(s)

Two major changes introduced by this CL, both aimed at reducing the
complexity of TraceLog:
1) Simplify the lifetime of TraceEventFilters. Now they are kept alive
   until the very last moment when there is no space left for other
   filters.
2) Don't cache the full TraceConfig::EventFilters in the TraceLog.
   Instead make each filter keep its own copy of its config.

Background: TraceLog modes (recording, filtering, both)
-------------------------------------------------------
Recent changes (crrev.com/{2323483005,2316403002,2259493003) added the
ability to have two modes for TraceLog: recording, filtering or both.
"Recording" is the conventional mode where the macros
TRACE_EVENT*(category, event, args...) directly inject events into the
trace buffer when the corresponding category is enabled.
"Filtering" alone turns on the macros without recording events in
the buffer, but allows filters to snoop the events. A concrete
use case for this mode is the --enable-heap-profiling mode which
wants to see all the TRACE_EVENTs to reconstruct the pseudo stack
but doesn't want them to fill the trace buffer.
It is also possible to combine the two modes (filtering + recording).
In this case the filters have also the power of preventing an event
to be added to the buffer. The use case here (not there yet in the code)
are the cases where we want to collect traces form the field but want
to limit the size of the trace by doing some fine grained stripping.
Side note: there is a further level of filtering in TraceLog called
ArgumentFilterPredicate. Today this is used for post-processing the
buffer before flushing to filter out PII-sensitive events. Perhaps
in the near future this could be merged with the filtering mode.
However this is out of scope from this CL.

Problem: duplication of TraceConfig in TraceLog
-----------------------------------------------
The way TraceLog today handles multiple modes is quite hard to follow.
TraceLog today has one copy of the TraceConfig (which can contain config
for both modes) but two states (recording and filtering).
To overcome this, TraceLog keeps also a cached copy of the parts of
TraceConfig relevant for filters in the |enabled_event_filters_| field
and strives to keep that in sync with the indexed in the bitmaps of the
TraceCategory classes.

Solution introduced by this CL:
TraceLog stops keeping a cached copy of the TraceConfig. Instead
when creating and registering a filter, it attaches the config of the
specific filter to the filter instance itself. This can be obtained
without coupling TraceEventFilter and TraceConfig by using a tiny
interface with one virtual method (see TraceEventFilter::Config).
Overall this makes TraceLog simpler and easier to reason about filters.

Problem: lifetime of TraceEventFilter(s)
----------------------------------------
When is it safe to destroy a TraceEventFilter? They can be *disabled*
but not *destroyed* immediately after TraceLog::SetDisabled(FILTERING).
This is because of the multi-threading nature of tracing: other threads
might still be referencing the filters while tracing is being disabled.
Using a lock is a no-go as we don't want tracing to serialize the various
threads around a lock.
The current approach destroys them when tracing is re-enabled. This
can still causes races though if tracing is disabled and immediately
re-enabled. Also this makes the TraceLog code hard to follow.

Solution introduced by this CL:
When a new filter is registered, The EventFilterRegistry (EFR) adds it
to the set of filters (or crashes if there are no slots left).
The filter can be referred to via a numeric index which is guaranteed to
be stable for all the lifetime of the filter. This index is used by the
TraceCategory.enabled_filters_ bitmap.
When a filter is not needed anymore TraceLog simply unregisters it and
stops caring about its lifetime. The EFT will NOT destroy it immediately.
Instead it will mark it as free-able and defer the destruction until the
very last moment, that is, after unregistering all filters and adding other
32 of them. This makes the race extremely unrealistic at this point. The
only case when a thread can still refer to a destroyed filter becomes the
interval between starting the execution of a TRACE_EVENTx macro (when
the enabled_filters_ bitmap is read) and the invocation of the filter
(few instructions afterwards). In this tiny interval tracing needs to
be stopped and started enough times to add other 32 filters in order to
hit the race. Which is technically still possible but becomes
extremely unlikely from a practical viewpoint.

BUG=659689
==========

[Primiano Tucci (use gerrit), 2016-12-06 14:55:29]

primiano@chromium.org changed reviewers:
+ oysteine@chromium.org, ssid@chromium.org

[Primiano Tucci (use gerrit), 2016-12-06 14:57:45]

This follows the pure-refactoring in https://codereview.chromium.org/2549103003.

This is the "Tock" part.
Essentially I'm aiming at gradually remove pieces from TraceLog so that:
1) TraceLog becomes less scary
2) We can reuse those pieces in the planned "common" folder reused outside of
base. if you notice I'm carefully avoiding any non-trivial base/ dependency
(e.g. base/macros.h or base/export.h) in all these new classes.

[commit-bot: I haz the power, 2016-12-06 15:32:10]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-12-06 15:32:11]

Dry run: Try jobs failed on following builders:
  win_chromium_x64_rel_ng on master.tryserver.chromium.win (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.win/builders/win_chromium_x64_...)

[Primiano Tucci (use gerrit), 2016-12-07 11:33:11]

The CQ bit was checked by primiano@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-12-07 11:33:25]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-12-07 13:07:18]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-12-07 13:07:19]

Dry run: Try jobs failed on following builders:
  win_chromium_compile_dbg_ng on master.tryserver.chromium.win (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.win/builders/win_chromium_comp...)

[Primiano Tucci (use gerrit), 2016-12-08 12:18:30]

The CQ bit was checked by primiano@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-12-08 12:18:41]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-12-08 13:20:17]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-12-08 13:20:18]

Dry run: Try jobs failed on following builders:
  win_chromium_compile_dbg_ng on master.tryserver.chromium.win (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.win/builders/win_chromium_comp...)

[Primiano Tucci (use gerrit), 2016-12-09 11:55:27]

The CQ bit was checked by primiano@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-12-09 11:55:35]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-12-09 13:24:16]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-12-09 13:24:17]

Dry run: Try jobs failed on following builders:
  linux_chromium_asan_rel_ng on master.tryserver.chromium.linux (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/linux_chromium_...)

[Primiano Tucci (use gerrit), 2016-12-09 14:49:20]

Ping on this. 
(the red bots look sadly all flakes, see crbug.com/{672841,672831,672838})

[ssid, 2016-12-12 04:50:18]

Description says:
1) Simplify the lifetime of TraceEventFilters. Now they are kept alive
   until the very last moment when there is no space left for other
   filters.
But, the filters are kept alive only till next tracing session. the limit on
number of filters is 32 irrespective of it's lifetime.

Description says:
In this tiny interval tracing needs to
be stopped and started enough times to add other 32 filters in order to
hit the race. Which is technically still possible but becomes
extremely unlikely from a practical viewpoint.

But, each tracing session can add 32 filters. Each EventNameFilter can be
different and there could be use case in future that might require adding lot of
filters. In this case starting tracing next time could cause a race since all
filters will be cleared.

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
File base/trace_event/event_filter_registry.cc (right):

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
base/trace_event/event_filter_registry.cc:34: for (uint32_t i = 0; i <
kMaxFilters; i++) {
Why do you need a loop here?
Can you just do
CHECK(!filters_[filters_index_].active);
And execute for i=0 case?

The only case where filters_[filters_index_].active is true is when you add 33
filters in the same session or there's a race in registering and unregistering

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
File base/trace_event/event_filter_registry.h (right):

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
base/trace_event/event_filter_registry.h:40: // destruction until the very last
moment.
When I proposed the model of leaking filters to Oystein, he was strongly against
leaking / keeping alive 32 filter objects that can contain list of strings and
now it also contains the config. This could use a bit of memory. That is the
reason we went for a model where filters are destroyed when next session starts.
Each EventNameFilter object has EventNamesWhitelist. We might be whitelisting
lot of events.
New filters can be added that are big objects.

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
base/trace_event/event_filter_registry.h:99: static FilterEntry
filters_[kMaxFilters];
Should you annotate this object as leaked, or the sanitizers will complain?
ANNOTATE_LEAKING_OBJECT_PTR

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
File base/trace_event/event_name_filter.h (right):

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
base/trace_event/event_name_filter.h:32: std::unique_ptr<EventNamesWhitelist>);
I don't think this argument is needed anymore. the whitelist is taken from the
args in the config.
Maybe TraceEventFilter::Config::GetArgAsSet() should be part of the interface?

event_names_whitelist = filter_config.GetArgAsSet("event_name_whitelist",
&*whitelist)

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
base/trace_event/event_name_filter.h:39: std::unique_ptr<const
EventNamesWhitelist> event_names_whitelist_;
Also this can store just one list instead of 2, if GetArgAsSet returns a
reference to the existing args?

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/trace...
File base/trace_event/trace_log.cc (right):

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/trace...
base/trace_event/trace_log.cc:580: std::unique_ptr<TraceConfig::EventFilters>
saved_filters_config;
I do not think this is required anymore. The TraceConfig::Merge should take care
of this.
Previously this was added because there could be a case where someone passes a
trace config with filters and not enable FILTERING_MODE. Instead of failing
here, we just ignored the filters. Now there are CHECKs for both the cases where
filter configs are passed without enabling FILTERING_MODE and filter configs are
passed when filters are enabled already. There is no other way the filter config
here can be inconsistent with the active filters now.

But, if we decide to remove tone of the CHECK below, see comment, then this is
required.

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/trace...
base/trace_event/trace_log.cc:610: CHECK(trace_config.event_filters().empty())
Crashes in case of --enable-heap-profiling:
TracingControllerImpl::AddTraceMessageFilter sends a "begin tracing" message to
a new process that has started after tracing starts. This uses the
GetCurrentTraceConfig() method.
Now the child process will crash because FILTERING_MODE will not be enabled by
ChildTraceMessageFilter::OnBeginTracing, but the trace config passed will have
filters.

The FILTERING_MODE in child process will be enabled by
MemoryDumpManager::Initialize much before the tracing is started, which is
better. Currently we just ignore the filters given by the config since filtering
is already enabled (by command line flag).

This CL first tries to fixes the issue of child process not passing the
FILTERING_MODE flag:
https://codereview.chromium.org/2466873002/
But, it is waiting on the discussion thread with you ("Filtering mode
discussion").

I cannot think of any better solution than to ignore new filters in case of heap
profiler filter being enabled by both MDM and trace message filter. Or we can
check for heap_profiler_filter as special case and ignore multiple
registrations.
We cannot avoid sending filter config along with begin tracing message since for
slow reports, only browser will set the event_name_filter and it has to be sent
through the ipc.

[ssid, 2016-12-12 04:57:37]

I feel there are too many constraints on the definition of "filtering" just when
using two filters and causes all complexity in TraceLog. I strongly feel the
need for heap profiler to not use the filters and just somehow instrument the
TRACE_EVENT macros to get the trace event names. something like
https://codereview.chromium.org/1837013003/diff/120001/base/trace_event/trace...
This would also avoid problems like grabbing screenshot like TRACE_EVENT1("x",
"y", "obj", take_screenshot());. If we instrument macro we wont need to call the
arg methods.

[Primiano Tucci (use gerrit), 2016-12-12 14:38:55]

Thanks a lot ssid for all the comments, they are really helpful. I know this is
being a pain, but I prefer being a pain and fixing this situation once per all,
instead of having to keep in mind special cases when we touch tracing code.
My intended outcome is to make all this more robust and less problematic, and I
need you pointing out all this to make it happen.
Thanks in advance for all the patience :)

Some replies below. I have seen but still haven't answered to your questions
about Tracing being enabled in child processes vs --enable-heap-profiling. Let
me think a bit more and I will get to that point soon.

On 2016/12/12 04:50:18, ssid wrote:
> I feel there are too many constraints on the definition of "filtering" just
when
> using two filters and causes all complexity in TraceLog. I strongly feel the
> need for heap profiler to not use the filters and just somehow instrument the
> TRACE_EVENT macros to get the trace event names. something like
>
https://codereview.chromium.org/1837013003/diff/120001/base/trace_event/trace...
> This would also avoid problems like grabbing screenshot like TRACE_EVENT1("x",
> "y", "obj", take_screenshot());. If we instrument macro we wont need to call
the
> arg methods.

Hmm honestly don't agree. If we have to add something to the macros, I prefer to
go to the effort of that once, even if it's a pain, and create a robust building
block on top of which we can build things like the heap profiler, filtering and
whitelisting.
We can't go through this all the times for each use case.

I think that filtering is the right level of abstraction, we just need to get
this right. Thankfully we seem to have the right people here to make this
happen, so let's just have a bit of patience and we'll make all this clean and
sorted. 


> Description says:
> 1) Simplify the lifetime of TraceEventFilters. Now they are kept alive
>    until the very last moment when there is no space left for other
>    filters.
> But, the filters are kept alive only till next tracing session. the limit on
> number of filters is 32 irrespective of it's lifetime.
Hmm not sure I understand this.

 
> Description says:
> In this tiny interval tracing needs to
> be stopped and started enough times to add other 32 filters in order to
> hit the race. Which is technically still possible but becomes
> extremely unlikely from a practical viewpoint.
> 
> But, each tracing session can add 32 filters. Each EventNameFilter can be
> different and there could be use case in future that might require adding lot
of
> filters. In this case starting tracing next time could cause a race since all
> filters will be cleared.

To be clear. The case you are describing is not different from the current
state. In this implementation filters are unregistered when trace ends and
destroyed *at earliest* (this is the change) when tracing is re-started.
If the traceconfig uses all filters, the only possible race is the current one
mentioned here, i.e. if tracing is re-started too quickly.

I wrote this assuming that we'd use << 32 filters per trace session. However,
thinking twice we should make our code robust even for this case. This can be
easily solved either asserting that we don't even register more than
(kMaxFilters / 2) or keeping a parallel list of kMaxFilter unregistered filters.
Let me see which one is cleaner and I will fix this problem.

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
File base/trace_event/event_filter_registry.cc (right):

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
base/trace_event/event_filter_registry.cc:34: for (uint32_t i = 0; i <
kMaxFilters; i++) {
On 2016/12/12 04:50:18, ssid wrote:
> Why do you need a loop here?
> Can you just do
> CHECK(!filters_[filters_index_].active);
> And execute for i=0 case?
> 
> The only case where filters_[filters_index_].active is true is when you add 33
> filters in the same session or there's a race in registering and unregistering

Right I wrote this when I wanted to support unregistration of individual  (so to
support having holes in the sequence) but then realized that right now we don't
need it, and forgot to simplify this code.
So the principle of keeping it simple unless you need complexity wins, doing
your way.

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
File base/trace_event/event_filter_registry.h (right):

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
base/trace_event/event_filter_registry.h:40: // destruction until the very last
moment.
On 2016/12/12 04:50:18, ssid wrote:
> When I proposed the model of leaking filters to Oystein, he was strongly
against
> leaking / keeping alive 32 filter objects that can contain list of strings and
> now it also contains the config. This could use a bit of memory. That is the
> reason we went for a model where filters are destroyed when next session
starts.
> Each EventNameFilter object has EventNamesWhitelist. We might be whitelisting
> lot of events.
> New filters can be added that are big objects.

Even if each filter contains a whitelist of 100 strings of 10 chars each, it
would be ~1K per filter -> 32k for the 32 filters. 
If we really want to free this memory as soon as possible, but not too soon, I
think the best way is to:
- Add a method: DestroyUnregisteredFilters() here, which deletes all the !active
filters.
- Post a call to that method at some point after tracing has been disabled.


We have to just come up with a reasonable approach here. The race window is
quite tiny if you think about that: is between the read of the bitmap and the
actual dereferencign of the filter.
In theory we could PostDelayedTask(one second,  DestroyUnregisteredFilters)
after tracing has been disabled and that would sovle all the problems.
The only thing that that "one second" sucks. Is not the 1s itself, is any
arbitrary amount of time really.
But I cannot think to any other option (without start making the use of filters
locked, which is a no-go)

WDYT?

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
base/trace_event/event_filter_registry.h:99: static FilterEntry
filters_[kMaxFilters];
On 2016/12/12 04:50:18, ssid wrote:
> Should you annotate this object as leaked, or the sanitizers will complain?
> ANNOTATE_LEAKING_OBJECT_PTR

I discovered recently that ASan doesn't complain about memory still reachable by
global objects.
In other words, for Asan this is NOT a leak:

char* g_var;

function() {
 g_var = malloc(...)
}

if you call function() only once.

However, if you call function() twice or more, it becomes a leak (and asan will
complain) becuase now you have allocated memory which is not reachable by
anything else.

In our case, all the newly allocated objects are referenced from filters_, so
there is no need for an annotation

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
File base/trace_event/event_name_filter.h (right):

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
base/trace_event/event_name_filter.h:32: std::unique_ptr<EventNamesWhitelist>);
On 2016/12/12 04:50:18, ssid wrote:
> I don't think this argument is needed anymore. the whitelist is taken from the
> args in the config.
> Maybe TraceEventFilter::Config::GetArgAsSet() should be part of the interface?
> 
> event_names_whitelist = filter_config.GetArgAsSet("event_name_whitelist",
> &*whitelist)

Nope I don't want for filters to depend on TraceConfig.
This is more about the split between the common part of tracing and the
chromium-specific. I have not clear yet where TraceConfig will end up, and in
doubt I don't want anything % TraceLog to depend on TraceConfig. This makes the
overall code easier to reason about.

From a concrete viewpoint also, we need a hashtable here, so we need to turn the
traceconfig into an unordered_dict at least once. I prefer then doing that into
TraceLog instead, to keep dependencies cleaner.

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
base/trace_event/event_name_filter.h:39: std::unique_ptr<const
EventNamesWhitelist> event_names_whitelist_;
On 2016/12/12 04:50:18, ssid wrote:
> Also this can store just one list instead of 2, if GetArgAsSet returns a
> reference to the existing args?

From a practical viewpoint:
TraceConfig wraps a base::Value. The whitelist there is a list, which would be
too expensive to query: it's O(n), and on top of that base::Value has quite some
boilerplate and checks around any operation.

From a dependency viewpoint:
The major motivation to all this is to isolate and clean up our dependencies
from the rest of //base.
So the event filtering mechanism can stay generic and not depend on chromium,
while we can leave the TraceConfig on the chromium side (See
bit.ly/tracing-unbundling).
So I'd really want TraceLog to be the only one depending on TraceConfig, and not
the rest.

I think you have a valid point though: the only bit of the config we need is the
category logic.
Maybe I can come up with a way to keep only that and drop the args, so we don't
keep a double copy here. Lemme have a look.

[ssid, 2016-12-12 21:25:53]

> Some replies below. I have seen but still haven't answered to your questions
> about Tracing being enabled in child processes vs --enable-heap-profiling. Let
> me think a bit more and I will get to that point soon.

Yes, thanks for looking into this, has been an unsettling thing that keeps
getting push backs.

> On 2016/12/12 04:50:18, ssid wrote:
> > I feel there are too many constraints on the definition of "filtering" just
> when
> > using two filters and causes all complexity in TraceLog. I strongly feel the
> > need for heap profiler to not use the filters and just somehow instrument
the
> > TRACE_EVENT macros to get the trace event names. something like
> >
>
https://codereview.chromium.org/1837013003/diff/120001/base/trace_event/trace...
> > This would also avoid problems like grabbing screenshot like
TRACE_EVENT1("x",
> > "y", "obj", take_screenshot());. If we instrument macro we wont need to call
> the
> > arg methods.
> 
> Hmm honestly don't agree. If we have to add something to the macros, I prefer
to
> go to the effort of that once, even if it's a pain, and create a robust
building
> block on top of which we can build things like the heap profiler, filtering
and
> whitelisting.
> We can't go through this all the times for each use case.
> 
> I think that filtering is the right level of abstraction, we just need to get
> this right. Thankfully we seem to have the right people here to make this
> happen, so let's just have a bit of patience and we'll make all this clean and
> sorted. 

Okay sounds good. If you feel this is blocking your refactoring then I would
suggest add a todo for me to put the checks and i will work on it. I was just
waiting for this refactoring to clean up the issue.

> > Description says:
> > 1) Simplify the lifetime of TraceEventFilters. Now they are kept alive
> >    until the very last moment when there is no space left for other
> >    filters.
> > But, the filters are kept alive only till next tracing session. the limit on
> > number of filters is 32 irrespective of it's lifetime.
> Hmm not sure I understand this.
Sorry ignore this reply. I was misunderstanding your description.
 
> > Description says:
> > In this tiny interval tracing needs to
> > be stopped and started enough times to add other 32 filters in order to
> > hit the race. Which is technically still possible but becomes
> > extremely unlikely from a practical viewpoint.
> > 
> > But, each tracing session can add 32 filters. Each EventNameFilter can be
> > different and there could be use case in future that might require adding
lot
> of
> > filters. In this case starting tracing next time could cause a race since
all
> > filters will be cleared.
> 
> To be clear. The case you are describing is not different from the current
> state. In this implementation filters are unregistered when trace ends and
> destroyed *at earliest* (this is the change) when tracing is re-started.
> If the traceconfig uses all filters, the only possible race is the current one
> mentioned here, i.e. if tracing is re-started too quickly.

Yes, I was just pointing out there could still be other cases which can cause
issues, other than the one you described there.

> I wrote this assuming that we'd use << 32 filters per trace session. However,
> thinking twice we should make our code robust even for this case. This can be
> easily solved either asserting that we don't even register more than
> (kMaxFilters / 2) or keeping a parallel list of kMaxFilter unregistered
filters.
> Let me see which one is cleaner and I will fix this problem.

It is not really a big issue. I think it's better to have a /2 assertion than
having parallel list. Please update the description too. Thanks.

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
File base/trace_event/event_filter_registry.h (right):

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
base/trace_event/event_filter_registry.h:40: // destruction until the very last
moment.
On 2016/12/12 14:38:54, Primiano Tucci wrote:
> On 2016/12/12 04:50:18, ssid wrote:
> > When I proposed the model of leaking filters to Oystein, he was strongly
> against
> > leaking / keeping alive 32 filter objects that can contain list of strings
and
> > now it also contains the config. This could use a bit of memory. That is the
> > reason we went for a model where filters are destroyed when next session
> starts.
> > Each EventNameFilter object has EventNamesWhitelist. We might be
whitelisting
> > lot of events.
> > New filters can be added that are big objects.
> 
> Even if each filter contains a whitelist of 100 strings of 10 chars each, it
> would be ~1K per filter -> 32k for the 32 filters. 
> If we really want to free this memory as soon as possible, but not too soon, I
> think the best way is to:
> - Add a method: DestroyUnregisteredFilters() here, which deletes all the
!active
> filters.
> - Post a call to that method at some point after tracing has been disabled.
> 
> 
> We have to just come up with a reasonable approach here. The race window is
> quite tiny if you think about that: is between the read of the bitmap and the
> actual dereferencign of the filter.
> In theory we could PostDelayedTask(one second,  DestroyUnregisteredFilters)
> after tracing has been disabled and that would sovle all the problems.
> The only thing that that "one second" sucks. Is not the 1s itself, is any
> arbitrary amount of time really.
> But I cannot think to any other option (without start making the use of
filters
> locked, which is a no-go)
> 
> WDYT?

So, I think we could just destroy at SetEnabled. We have an assumption that we
do not have a race between SetEnabled and SetDisabled in lot of places like
memory-infra. the OnTracelogEnabled calls are made outside lock and if tracing
was enabled in that gap, then we would crash at MDM.
We also have a DCHECK(!flush_task_runner_); which means we will crash if enabled
just after disabling.

You should also note that we do a FlushCurrentThread call on all the threads on
the process after a SetDisabled call. The only case where the crash can happen
is that if a new thread which is not registered yet tried to access the filter.
So, the time difference here is not really small and it's safe.

But, in any case we will still be leaking some filters that were added in last
tracing session since we don't clear till next session. So, I am fine with the
existing code leaking filters. Just that we will be leaking more filters now
(from multiple sessions).

It was Oystein's opinion. Not sure what he thinks is better.

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
base/trace_event/event_filter_registry.h:99: static FilterEntry
filters_[kMaxFilters];
On 2016/12/12 14:38:54, Primiano Tucci wrote:
> On 2016/12/12 04:50:18, ssid wrote:
> > Should you annotate this object as leaked, or the sanitizers will complain?
> > ANNOTATE_LEAKING_OBJECT_PTR
> 
> I discovered recently that ASan doesn't complain about memory still reachable
by
> global objects.
> In other words, for Asan this is NOT a leak:
> 
> char* g_var;
> 
> function() {
>  g_var = malloc(...)
> }
> 
> if you call function() only once.
> 
> However, if you call function() twice or more, it becomes a leak (and asan
will
> complain) becuase now you have allocated memory which is not reachable by
> anything else.
> 
> In our case, all the newly allocated objects are referenced from filters_, so
> there is no need for an annotation

Okay thanks!

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
File base/trace_event/event_name_filter.h (right):

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
base/trace_event/event_name_filter.h:32: std::unique_ptr<EventNamesWhitelist>);
On 2016/12/12 14:38:55, Primiano Tucci wrote:
> On 2016/12/12 04:50:18, ssid wrote:
> > I don't think this argument is needed anymore. the whitelist is taken from
the
> > args in the config.
> > Maybe TraceEventFilter::Config::GetArgAsSet() should be part of the
interface?
> > 
> > event_names_whitelist = filter_config.GetArgAsSet("event_name_whitelist",
> > &*whitelist)
> 
> Nope I don't want for filters to depend on TraceConfig.
> This is more about the split between the common part of tracing and the
> chromium-specific. I have not clear yet where TraceConfig will end up, and in
> doubt I don't want anything % TraceLog to depend on TraceConfig. This makes
the
> overall code easier to reason about.
> 
> From a concrete viewpoint also, we need a hashtable here, so we need to turn
the
> traceconfig into an unordered_dict at least once. I prefer then doing that
into
> TraceLog instead, to keep dependencies cleaner.

Yes it makes that we need a hashtable here for the strings. We could keep the
table separate.

It's just a bit weird that you need to pass the config to filters in some other
way. But, yes, this looks good now.

https://codereview.chromium.org/2557743002/diff/100001/base/trace_event/event...
base/trace_event/event_name_filter.h:39: std::unique_ptr<const
EventNamesWhitelist> event_names_whitelist_;
On 2016/12/12 14:38:55, Primiano Tucci wrote:
> On 2016/12/12 04:50:18, ssid wrote:
> > Also this can store just one list instead of 2, if GetArgAsSet returns a
> > reference to the existing args?
> 
> From a practical viewpoint:
> TraceConfig wraps a base::Value. The whitelist there is a list, which would be
> too expensive to query: it's O(n), and on top of that base::Value has quite
some
> boilerplate and checks around any operation.
> 
> From a dependency viewpoint:
> The major motivation to all this is to isolate and clean up our dependencies
> from the rest of //base.
> So the event filtering mechanism can stay generic and not depend on chromium,
> while we can leave the TraceConfig on the chromium side (See
> bit.ly/tracing-unbundling).
> So I'd really want TraceLog to be the only one depending on TraceConfig, and
not
> the rest.
> 
> I think you have a valid point though: the only bit of the config we need is
the
> category logic.
> Maybe I can come up with a way to keep only that and drop the args, so we
don't
> keep a double copy here. Lemme have a look.

Acknowledged.

[ssid, 2017-01-12 05:46:23]

Are you planning to work on this one?
Do you want me to work on this CL and finish it?

[Primiano Tucci (use gerrit), 2017-01-12 11:20:30]

On 2017/01/12 05:46:23, ssid wrote:
> Are you planning to work on this one?
> Do you want me to work on this CL and finish it?

Yup sorry, just got delayed byt docs and postmortems. will be back on this CL
soon.