Enable Activity Logging by default

Enable Activity Logging by default

Previously, the Activity Log was disabled by default unless a flag was set or a specific app was installed.

With this CL, events will be logged for everyone. However, we will only write to the database or stream to the API if the flag is set or the app is installed.

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

[felt, 2013-08-29 15:01:42]

Hi Matt,

Can you please review this CL?

Adrienne

[karenlees, 2013-08-29 17:09:08]

https://codereview.chromium.org/23729005/diff/14001/chrome/browser/extensions...
File chrome/browser/extensions/activity_log/activity_log.cc (right):

https://codereview.chromium.org/23729005/diff/14001/chrome/browser/extensions...
chrome/browser/extensions/activity_log/activity_log.cc:437: if (!policy_)
We could also add check for IsDatabaseEnabled before trying to remove the URLs
but I guess it's possible it was previously enabled and there could be things to
clean up.  Just wanted to make sure I understood the logic.  Also if a user
disables the app/flag do we delete the entire DB or just let it auto clean?

https://codereview.chromium.org/23729005/diff/14001/chrome/browser/extensions...
File chrome/browser/extensions/activity_log/activity_log.h (right):

https://codereview.chromium.org/23729005/diff/14001/chrome/browser/extensions...
chrome/browser/extensions/activity_log/activity_log.h:138: // the database. This
is true if the Watchdog app is active *or* the
When you "active", do you mean actively being used or just installed?

[felt, 2013-08-29 17:35:35]

https://codereview.chromium.org/23729005/diff/14001/chrome/browser/extensions...
File chrome/browser/extensions/activity_log/activity_log.cc (right):

https://codereview.chromium.org/23729005/diff/14001/chrome/browser/extensions...
chrome/browser/extensions/activity_log/activity_log.cc:437: if (!policy_)
On 2013/08/29 17:09:08, karenlees wrote:
> We could also add check for IsDatabaseEnabled before trying to remove the URLs
> but I guess it's possible it was previously enabled and there could be things
to
> clean up.  Just wanted to make sure I understood the logic.  Also if a user
> disables the app/flag do we delete the entire DB or just let it auto clean?

Yes, I think we should let removal work even if it's currently disabled.
At the moment if a user disables the app/flag we don't do anything explicit, but
this is a good point.  I think for disabling we should leave the data alone
because it might be temporary; for uninstalling we should nuke the whole DB.
I'll file a bug for this.

https://codereview.chromium.org/23729005/diff/14001/chrome/browser/extensions...
File chrome/browser/extensions/activity_log/activity_log.h (right):

https://codereview.chromium.org/23729005/diff/14001/chrome/browser/extensions...
chrome/browser/extensions/activity_log/activity_log.h:138: // the database. This
is true if the Watchdog app is active *or* the
On 2013/08/29 17:09:08, karenlees wrote:
> When you "active", do you mean actively being used or just installed?

we're using "active" here to mean installed & enabled. i'll update the comment

[Matt Perry, 2013-08-29 23:51:35]

Have you done any measuring to see how the activity log affects performance and
memory usage?

[felt, 2013-08-29 23:57:46]

On 2013/08/29 23:51:35, Matt Perry wrote:
> Have you done any measuring to see how the activity log affects performance
and
> memory usage?

No. I've mostly focused on the database size and queued actions, but this
doesn't enable either for most users.

Are there any benchmarks etc. you recommend I use? I'm not sure what to do to
measure extension API call performance.

[Matt Perry, 2013-08-30 00:11:28]

On 2013/08/29 23:57:46, felt wrote:
> On 2013/08/29 23:51:35, Matt Perry wrote:
> > Have you done any measuring to see how the activity log affects performance
> and
> > memory usage?
> 
> No. I've mostly focused on the database size and queued actions, but this
> doesn't enable either for most users.

What's the eventual goal with this? Currently it looks like it ends up calling
LogAction, which is mostly a no-op if (!IsDatabaseEnabled() &&
!IsWatchdogAppEnabled()).

> Are there any benchmarks etc. you recommend I use? I'm not sure what to do to
> measure extension API call performance.

You could try using PerfTimer to time all the calls to LogExtensionActivity,
etc. Then just browse around manually with a bunch of extensions installed, and
keep track of:
- total time from all your PerfTimers
- total number of calls to activity log
- average time of call to activity log.

Unfortunately we don't have a good way of adding automated tests for this.
page_cycler might work, but it would give you noisy data (and you'd have to
compare before/after this patch).

[felt, 2013-08-30 00:16:48]

On 2013/08/30 00:11:28, Matt Perry wrote:
> On 2013/08/29 23:57:46, felt wrote:
> > On 2013/08/29 23:51:35, Matt Perry wrote:
> > > Have you done any measuring to see how the activity log affects
performance
> > and
> > > memory usage?
> > 
> > No. I've mostly focused on the database size and queued actions, but this
> > doesn't enable either for most users.
> 
> What's the eventual goal with this? Currently it looks like it ends up calling
> LogAction, which is mostly a no-op if (!IsDatabaseEnabled() &&
> !IsWatchdogAppEnabled()).

Coming soon in LogAction:
* UMA stats to tell us how often extensions do certain things to websites
* Erik wants the AL to support a new piece of UI that will ping a tab whenever
an extension does a certain operation in that tab

Both features will be on for all users. I want to enable the AL first in this
standalone CL so that I can see if just the logging enabled everywhere causes
any kinds of performance problems or regressions.

> 
> > Are there any benchmarks etc. you recommend I use? I'm not sure what to do
to
> > measure extension API call performance.
> 
> You could try using PerfTimer to time all the calls to LogExtensionActivity,
> etc. Then just browse around manually with a bunch of extensions installed,
and
> keep track of:
> - total time from all your PerfTimers
> - total number of calls to activity log
> - average time of call to activity log.
> 
> Unfortunately we don't have a good way of adding automated tests for this.
> page_cycler might work, but it would give you noisy data (and you'd have to
> compare before/after this patch).

OK, I'll try this out and let you know how it goes.

[felt, 2013-08-30 19:53:59]

> > You could try using PerfTimer to time all the calls to LogExtensionActivity,
> > etc. Then just browse around manually with a bunch of extensions installed,
> and
> > keep track of:
> > - total time from all your PerfTimers
> > - total number of calls to activity log
> > - average time of call to activity log.
> > 
> > Unfortunately we don't have a good way of adding automated tests for this.
> > page_cycler might work, but it would give you noisy data (and you'd have to
> > compare before/after this patch).
> 
> OK, I'll try this out and let you know how it goes.

I browsed around for 10min with a bunch of different extensions installed. I
timed how much time was spent inside LogAction, as well as how much time was
spent in OnScriptsExecuted (which is a superset of LogAction, but called less
often).

-- OnScriptsExecuted triggered 190 times: min 0.004ms, max 0.217ms, avg 0.081ms,
median 0.093ms
-- LogAction triggered 7282 times: min 0.000ms, max 0.108ms, avg 0.005ms, median
0.004ms

During that 10min, a total of 38ms was spent inside LogAction and 15ms was spent
inside OnScriptsExecuted.

This seems acceptable to me, but I don't have a good reference point. What do
you think?

[Matt Perry, 2013-08-30 20:38:08]

On 2013/08/30 19:53:59, felt wrote:
> > > You could try using PerfTimer to time all the calls to
LogExtensionActivity,
> > > etc. Then just browse around manually with a bunch of extensions
installed,
> > and
> > > keep track of:
> > > - total time from all your PerfTimers
> > > - total number of calls to activity log
> > > - average time of call to activity log.
> > > 
> > > Unfortunately we don't have a good way of adding automated tests for this.
> > > page_cycler might work, but it would give you noisy data (and you'd have
to
> > > compare before/after this patch).
> > 
> > OK, I'll try this out and let you know how it goes.
> 
> I browsed around for 10min with a bunch of different extensions installed. I
> timed how much time was spent inside LogAction, as well as how much time was
> spent in OnScriptsExecuted (which is a superset of LogAction, but called less
> often).
> 
> -- OnScriptsExecuted triggered 190 times: min 0.004ms, max 0.217ms, avg
0.081ms,
> median 0.093ms
> -- LogAction triggered 7282 times: min 0.000ms, max 0.108ms, avg 0.005ms,
median
> 0.004ms
> 
> During that 10min, a total of 38ms was spent inside LogAction and 15ms was
spent
> inside OnScriptsExecuted.
> 
> This seems acceptable to me, but I don't have a good reference point. What do
> you think?

OK great, that sounds good! Thanks for testing it out.

LGTM

[commit-bot: I haz the power, 2013-08-30 20:41:36]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/felt@chromium.org/23729005/20001

[Matt Perry, 2013-08-30 20:49:20]

Still LGTM, but a request for more measuring.

https://codereview.chromium.org/23729005/diff/20001/chrome/browser/extensions...
File chrome/browser/extensions/api/web_request/web_request_api.cc (right):

https://codereview.chromium.org/23729005/diff/20001/chrome/browser/extensions...
chrome/browser/extensions/api/web_request/web_request_api.cc:1679:
LogExtensionActivity(profile,
Actually, I just realized that LogAction is not the interesting call to measure.
I'd be interested to measure calls like this (and all the other ones that used
to be gated on ActivityLog::IsEnabled()), because that's where the extra
processing is done to create the args details object. Would you mind doing the
test again measuring those? For the webRequest one, make sure Adblock is
installed.

[felt, 2013-08-30 22:09:46]

On 2013/08/30 20:49:20, Matt Perry wrote:
> Still LGTM, but a request for more measuring.
> 
>
https://codereview.chromium.org/23729005/diff/20001/chrome/browser/extensions...
> File chrome/browser/extensions/api/web_request/web_request_api.cc (right):
> 
>
https://codereview.chromium.org/23729005/diff/20001/chrome/browser/extensions...
> chrome/browser/extensions/api/web_request/web_request_api.cc:1679:
> LogExtensionActivity(profile,
> Actually, I just realized that LogAction is not the interesting call to
measure.
> I'd be interested to measure calls like this (and all the other ones that used
> to be gated on ActivityLog::IsEnabled()), because that's where the extra
> processing is done to create the args details object. Would you mind doing the
> test again measuring those? For the webRequest one, make sure Adblock is
> installed.

OK, ran it for 10 minutes again and got more aggressive with the number of page
loads & collected more data.

LogAction: 18,402 counts, total of 83ms, max 0.247ms, avg 0.004ms

LogExtensionEventMessage: 4,078 counts, total of 89ms, max 0.177ms, avg 0.022ms
*Note that these calls include cost of LogAction

LogExtensionActivity: 3,360 counts, total of 52ms, max 0.257ms, avg 0.015ms
*Note that these calls include cost of LogAction

OuterLogExtensionActivity: 3,360 counts, total of 123ms, max 0.256ms, avg
0.037ms
*This is the prep work that happens before each LogExtensionActivity call (on a
different thread)

DOMActivityLogger: 2,805 counts, total of 134ms, max 0.187ms, avg 0.048ms
* There's also an asynchronous IPC between the renderer and the browser threads
(for logging DOM API calls) that I'm not sure how to time. Is the cost of an IPC
message between those two processes well known? If so, that would have to be
added to these events.

[felt, 2013-08-30 22:16:31]

Hi Chris & James, can I get OWNERS reviews for two files:

cevans: chrome/common/render_messages.h
jhawkins: chrome/renderer/chrome_render_process_observer.[cc|h]

Strictly code deletions in those files.

Thanks,
Adrienne

[Matt Perry, 2013-08-30 22:18:47]

On 2013/08/30 22:09:46, felt wrote:
> On 2013/08/30 20:49:20, Matt Perry wrote:
> > Still LGTM, but a request for more measuring.
> > 
> >
>
https://codereview.chromium.org/23729005/diff/20001/chrome/browser/extensions...
> > File chrome/browser/extensions/api/web_request/web_request_api.cc (right):
> > 
> >
>
https://codereview.chromium.org/23729005/diff/20001/chrome/browser/extensions...
> > chrome/browser/extensions/api/web_request/web_request_api.cc:1679:
> > LogExtensionActivity(profile,
> > Actually, I just realized that LogAction is not the interesting call to
> measure.
> > I'd be interested to measure calls like this (and all the other ones that
used
> > to be gated on ActivityLog::IsEnabled()), because that's where the extra
> > processing is done to create the args details object. Would you mind doing
the
> > test again measuring those? For the webRequest one, make sure Adblock is
> > installed.
> 
> OK, ran it for 10 minutes again and got more aggressive with the number of
page
> loads & collected more data.
> 
> LogAction: 18,402 counts, total of 83ms, max 0.247ms, avg 0.004ms
> 
> LogExtensionEventMessage: 4,078 counts, total of 89ms, max 0.177ms, avg
0.022ms
> *Note that these calls include cost of LogAction
> 
> LogExtensionActivity: 3,360 counts, total of 52ms, max 0.257ms, avg 0.015ms
> *Note that these calls include cost of LogAction
> 
> OuterLogExtensionActivity: 3,360 counts, total of 123ms, max 0.256ms, avg
> 0.037ms
> *This is the prep work that happens before each LogExtensionActivity call (on
a
> different thread)
> 
> DOMActivityLogger: 2,805 counts, total of 134ms, max 0.187ms, avg 0.048ms
> * There's also an asynchronous IPC between the renderer and the browser
threads
> (for logging DOM API calls) that I'm not sure how to time. Is the cost of an
IPC
> message between those two processes well known? If so, that would have to be
> added to these events.

OK, those numbers look good as well. Let's not worry about the cost of IPC for
now. I don't think 2805 counts over 600 seconds is enough to be a concern.

Thanks again!

[James Hawkins, 2013-08-30 23:34:57]

lgtm

[felt, 2013-09-03 15:58:38]

On 2013/08/30 22:16:31, felt wrote:
> Hi Chris & James, can I get OWNERS reviews for two files:
> 
> cevans: chrome/common/render_messages.h
> jhawkins: chrome/renderer/chrome_render_process_observer.[cc|h]
> 
> Strictly code deletions in those files.
> 
> Thanks,
> Adrienne

hey chris, quick ping so this doesn't get lost in the shuffle of long weekend
emails

[felt, 2013-09-04 19:44:07]

palmer- cevans said you'd review this for me. I need OWNERS for
chrome/common/render_messages.h. It should take 2 seconds, it's a deletion of a
few lines of code.

[palmer, 2013-09-04 20:36:24]

lgtm

[commit-bot: I haz the power, 2013-09-04 20:38:03]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/felt@chromium.org/23729005/20001

[felt, 2013-09-04 20:38:03]

On 2013/09/04 20:36:24, Chromium Palmer wrote:
> lgtm

thanks!

[commit-bot: I haz the power, 2013-09-04 21:14:56]

Retried try job too often on android_aosp for step(s) compile
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=android_ao...

[commit-bot: I haz the power, 2013-09-05 00:02:35]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/felt@chromium.org/23729005/20001

[commit-bot: I haz the power, 2013-09-05 00:40:48]

Change committed as 221319