Add metrics to measure time elapsed between form load and form submission with or without Autofill.

Add metrics to measure time elapsed between form load and form submission with or without Autofill.

BUG=none
TEST=unit_tests --gtest_filter=AutofillMetricsTest.*

Committed: http://src.chromium.org/viewvc/chrome?view=rev&revision=99447

[Ilya Sherman, 2011-08-31 01:14:43]

Brett: Please take a look at the base/time.h changes.
Jim: Please take a look at the metrics changes.
David: Please take a look at the rest :)

[brettw, 2011-08-31 16:05:03]

time LGTM

[jar (doing other things), 2011-08-31 17:02:21]

The histogram usage LGTM, but ....

...drive by commentary on the rest:

The CL's use of time values seem confusing.  IMO, you should try hard to use the
standard basic types, such as TimeTicks(), which carry a clearly defined
meaning.  You should avoid conversions to "internal values" unless absolutely
necessary, such as when archiving, or passing though a webkit shim (where  our
types are unknown).

If you do use your own new flavor of time (commonly called "timestamp") then you
need to comment on what such a timestamp is.  Perhaps a better name might be
time_ticks_internal_value, if you don't want to comment.

As noted below, once you claim this is really just a serialized version of the
underlying type TimeTicks, I think you can't just assume that a 0 is the
serialization of TimeTicks() (null constructor).

I also didn't spot the place where you needed new serialization functionality
for TimeDelta.  If it is there... then fine... but if not, then it is better to
not augment the time.h file with this code.

http://codereview.chromium.org/7740070/diff/4001/chrome/browser/autofill/auto...
File chrome/browser/autofill/autofill_manager.cc (right):

http://codereview.chromium.org/7740070/diff/4001/chrome/browser/autofill/auto...
chrome/browser/autofill/autofill_manager.cc:798: initial_interaction_timestamp_
= TimeTicks::FromInternalValue(0);
This seems strange that you are supplying a specific "internal value" of 0, and
seemingly violating the privacy of that class.  IMO, you really intend to
provide a TimeTicks values that is_null(), and so you should call:
TimeTicks::TimeTicks().

http://codereview.chromium.org/7740070/diff/4001/chrome/browser/autofill/auto...
File chrome/browser/autofill/autofill_manager.h (right):

http://codereview.chromium.org/7740070/diff/4001/chrome/browser/autofill/auto...
chrome/browser/autofill/autofill_manager.h:118: int64 timestamp);
The name timestamp is is not defined.  You should at a minimimum have a comment
indicating what this argument is.  After reading a lot of this CL, I concluded
that it is probably the internal representation of a TimeTicks().   If possible,
it would be much nicer to consistently use TimeTicks(), and only serialize when
absolutely necessary, rather than defining interfaces which pass around the
internal value as some integral type.

It also was not clear why you needed to augment the time.h class to deserialize
TimeDelta values.  Is that being done in this CL somewhere?

http://codereview.chromium.org/7740070/diff/4001/chrome/browser/autofill/auto...
File chrome/browser/autofill/autofill_manager_unittest.cc (right):

http://codereview.chromium.org/7740070/diff/4001/chrome/browser/autofill/auto...
chrome/browser/autofill/autofill_manager_unittest.cc:519:
autofill_manager_->OnFormSubmitted(form, 0);
Here again, I suspect rather than 0, you should supply:
TimeTicks::TimeTicks().ToInternalValue()

http://codereview.chromium.org/7740070/diff/4001/chrome/browser/autofill/auto...
File chrome/browser/autofill/autofill_metrics_unittest.cc (right):

http://codereview.chromium.org/7740070/diff/4001/chrome/browser/autofill/auto...
chrome/browser/autofill/autofill_metrics_unittest.cc:406:
EXPECT_NO_FATAL_FAILURE(autofill_manager_->OnFormSubmitted(form, 0));
I don't think you should be passing in a zero.  That is probably an internal
representation of time time interval, and should be generated via that route.

Same comment applies below.

[Ilya Sherman, 2011-08-31 21:56:23]

http://codereview.chromium.org/7740070/diff/4001/chrome/browser/autofill/auto...
File chrome/browser/autofill/autofill_manager.cc (right):

http://codereview.chromium.org/7740070/diff/4001/chrome/browser/autofill/auto...
chrome/browser/autofill/autofill_manager.cc:798: initial_interaction_timestamp_
= TimeTicks::FromInternalValue(0);
On 2011/08/31 17:02:21, jar wrote:
> This seems strange that you are supplying a specific "internal value" of 0,
and
> seemingly violating the privacy of that class.  IMO, you really intend to
> provide a TimeTicks values that is_null(), and so you should call:
> TimeTicks::TimeTicks().

Done.

http://codereview.chromium.org/7740070/diff/4001/chrome/browser/autofill/auto...
File chrome/browser/autofill/autofill_manager.h (right):

http://codereview.chromium.org/7740070/diff/4001/chrome/browser/autofill/auto...
chrome/browser/autofill/autofill_manager.h:118: int64 timestamp);
On 2011/08/31 17:02:21, jar wrote:
> The name timestamp is is not defined.  You should at a minimimum have a
comment
> indicating what this argument is.  After reading a lot of this CL, I concluded
> that it is probably the internal representation of a TimeTicks().   If
possible,
> it would be much nicer to consistently use TimeTicks(), and only serialize
when
> absolutely necessary, rather than defining interfaces which pass around the
> internal value as some integral type.

The timestamp is being serialized for IPC communication, but you're right that
there's a better place to do that serialization.  Done.

> It also was not clear why you needed to augment the time.h class to
deserialize
> TimeDelta values.  Is that being done in this CL somewhere?

It's being used to set mock expectations in the unit tests.  I've also updated
the IPC serialization code to use this.

http://codereview.chromium.org/7740070/diff/4001/chrome/browser/autofill/auto...
File chrome/browser/autofill/autofill_manager_unittest.cc (right):

http://codereview.chromium.org/7740070/diff/4001/chrome/browser/autofill/auto...
chrome/browser/autofill/autofill_manager_unittest.cc:519:
autofill_manager_->OnFormSubmitted(form, 0);
On 2011/08/31 17:02:21, jar wrote:
> Here again, I suspect rather than 0, you should supply:
> TimeTicks::TimeTicks().ToInternalValue()

This is actually just a filler value to make the code compile -- it doesn't
matter what the value is.  But, with the updated API, the argument is now the
more abstract type.

http://codereview.chromium.org/7740070/diff/4001/chrome/browser/autofill/auto...
File chrome/browser/autofill/autofill_metrics_unittest.cc (right):

http://codereview.chromium.org/7740070/diff/4001/chrome/browser/autofill/auto...
chrome/browser/autofill/autofill_metrics_unittest.cc:406:
EXPECT_NO_FATAL_FAILURE(autofill_manager_->OnFormSubmitted(form, 0));
On 2011/08/31 17:02:21, jar wrote:
> I don't think you should be passing in a zero.  That is probably an internal
> representation of time time interval, and should be generated via that route.
> 
> Same comment applies below.

Done.

[Ilya Sherman, 2011-08-31 21:56:45]

+jam for content/ changes

[Ilya Sherman, 2011-08-31 21:57:10]

On 2011/08/31 21:56:45, Ilya Sherman wrote:
> +jam for content/ changes

Erm, that is, for ipc/ changes.

[dhollowa, 2011-08-31 22:40:52]

http://codereview.chromium.org/7740070/diff/6001/chrome/browser/autofill/auto...
File chrome/browser/autofill/autofill_manager.cc (right):

http://codereview.chromium.org/7740070/diff/6001/chrome/browser/autofill/auto...
chrome/browser/autofill/autofill_manager.cc:392: // Messages might arrive out of
order, so always remember the earliest
This code repeats below.  Pull out into utility function please.

http://codereview.chromium.org/7740070/diff/6001/chrome/browser/autofill/form...
File chrome/browser/autofill/form_structure.cc (right):

http://codereview.chromium.org/7740070/diff/6001/chrome/browser/autofill/form...
chrome/browser/autofill/form_structure.cc:797: if (!interaction_time.is_null()
&& !submission_time.is_null() &&
Could you explain why this is needed.  It seems like this could mask bugs.

http://codereview.chromium.org/7740070/diff/6001/chrome/renderer/autofill/aut...
File chrome/renderer/autofill/autofill_agent.cc (right):

http://codereview.chromium.org/7740070/diff/6001/chrome/renderer/autofill/aut...
chrome/renderer/autofill/autofill_agent.cc:105: base::TimeTicks::Now()));
Wouldn't it be simpler to just track the time on the browser side in the
AutofillManager code?

http://codereview.chromium.org/7740070/diff/6001/chrome/renderer/autofill/aut...
chrome/renderer/autofill/autofill_agent.cc:207: Send(new
AutofillHostMsg_TextFieldDidChange(routing_id(), form, field,
I would think it is just as telling to track the delta between form load and
submit.    Do we really need to start at the first interaction?

[Ilya Sherman, 2011-08-31 23:21:32]

http://codereview.chromium.org/7740070/diff/6001/chrome/browser/autofill/auto...
File chrome/browser/autofill/autofill_manager.cc (right):

http://codereview.chromium.org/7740070/diff/6001/chrome/browser/autofill/auto...
chrome/browser/autofill/autofill_manager.cc:392: // Messages might arrive out of
order, so always remember the earliest
On 2011/08/31 22:40:52, dhollowa wrote:
> This code repeats below.  Pull out into utility function please.

Done.

http://codereview.chromium.org/7740070/diff/6001/chrome/browser/autofill/form...
File chrome/browser/autofill/form_structure.cc (right):

http://codereview.chromium.org/7740070/diff/6001/chrome/browser/autofill/form...
chrome/browser/autofill/form_structure.cc:797: if (!interaction_time.is_null()
&& !submission_time.is_null() &&
On 2011/08/31 22:40:52, dhollowa wrote:
> Could you explain why this is needed.  It seems like this could mask bugs.

Done.

http://codereview.chromium.org/7740070/diff/6001/chrome/renderer/autofill/aut...
File chrome/renderer/autofill/autofill_agent.cc (right):

http://codereview.chromium.org/7740070/diff/6001/chrome/renderer/autofill/aut...
chrome/renderer/autofill/autofill_agent.cc:105: base::TimeTicks::Now()));
On 2011/08/31 22:40:52, dhollowa wrote:
> Wouldn't it be simpler to just track the time on the browser side in the
> AutofillManager code?

Yes, but it would be somewhat less accurate, since IPC calls have no latency
guarantees.

http://codereview.chromium.org/7740070/diff/6001/chrome/renderer/autofill/aut...
chrome/renderer/autofill/autofill_agent.cc:207: Send(new
AutofillHostMsg_TextFieldDidChange(routing_id(), form, field,
On 2011/08/31 22:40:52, dhollowa wrote:
> I would think it is just as telling to track the delta between form load and
> submit.    Do we really need to start at the first interaction?

I considered that, but a <form> element being loaded into the DOM does not mean
that it is user visible.  We've seen a number of websites that dynamically
manipulate form visibility.  Moreover, Autofill currently triggers less often
for these forms, because we've really optimized for the case of static forms. 
So, measuring from form load time would bias the metrics in favor of Autofill.

For dynamically shown forms, measuring from the initial interaction time also
better maps on to the number we actually want to measure:  How long does it take
a user to fill a form, with or without Autofill.  If we measure the delta from
form load, all of the metrics will be somewhat inflated.

[dhollowa, 2011-08-31 23:42:20]

http://codereview.chromium.org/7740070/diff/6001/chrome/browser/autofill/form...
File chrome/browser/autofill/form_structure.cc (right):

http://codereview.chromium.org/7740070/diff/6001/chrome/browser/autofill/form...
chrome/browser/autofill/form_structure.cc:797: if (!interaction_time.is_null()
&& !submission_time.is_null() &&
On 2011/08/31 23:21:32, Ilya Sherman wrote:
> On 2011/08/31 22:40:52, dhollowa wrote:
> > Could you explain why this is needed.  It seems like this could mask bugs.
> 
> Done.

Sorry, my thinking was to let the bad data propagate through to the metrics so
we could actually detect bugs in the data.

http://codereview.chromium.org/7740070/diff/6001/chrome/renderer/autofill/aut...
File chrome/renderer/autofill/autofill_agent.cc (right):

http://codereview.chromium.org/7740070/diff/6001/chrome/renderer/autofill/aut...
chrome/renderer/autofill/autofill_agent.cc:105: base::TimeTicks::Now()));
On 2011/08/31 23:21:32, Ilya Sherman wrote:
> On 2011/08/31 22:40:52, dhollowa wrote:
> > Wouldn't it be simpler to just track the time on the browser side in the
> > AutofillManager code?
> 
> Yes, but it would be somewhat less accurate, since IPC calls have no latency
> guarantees.

We're measuring user-time at a many-seconds possibly minutes magnitude.  IPC
latency is tens of milliseconds at worst I'd wager.  So the complexity of
computing it here and plumbing through IPC versus computing Now() in the browser
seems unnecessary.

http://codereview.chromium.org/7740070/diff/6001/chrome/renderer/autofill/aut...
chrome/renderer/autofill/autofill_agent.cc:207: Send(new
AutofillHostMsg_TextFieldDidChange(routing_id(), form, field,
On 2011/08/31 23:21:32, Ilya Sherman wrote:
> On 2011/08/31 22:40:52, dhollowa wrote:
> > I would think it is just as telling to track the delta between form load and
> > submit.    Do we really need to start at the first interaction?
> 
> I considered that, but a <form> element being loaded into the DOM does not
mean
> that it is user visible.  We've seen a number of websites that dynamically
> manipulate form visibility.  Moreover, Autofill currently triggers less often
> for these forms, because we've really optimized for the case of static forms. 
> So, measuring from form load time would bias the metrics in favor of Autofill.
> 
> For dynamically shown forms, measuring from the initial interaction time also
> better maps on to the number we actually want to measure:  How long does it
take
> a user to fill a form, with or without Autofill.  If we measure the delta from
> form load, all of the metrics will be somewhat inflated.

But for the dynamic case, we don't flag it as fillable.  So the bias would not
apply.  Also, the first interaction with the form might be with a select-menu so
I'm not sure we're really capturing the first interaction accurately.  Form load
gives a nice predictable start point.

[jam, 2011-09-01 01:40:29]

ipc lgtm

[dhollowa, 2011-09-01 03:52:50]

LGTM.  Thanks Ilya.

[commit-bot: I haz the power, 2011-09-02 01:03:39]

Try job failure for 7740070-20004 (retry) on win for steps "update_scripts,
update".
It's a second try, previously, step "interactive_ui_tests" failed.
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=win&number...

Step "update" is always a major failure.
Look at the try server FAQ for more details.

[jar (doing other things), 2011-09-02 01:48:32]

http://codereview.chromium.org/7740070/diff/20004/chrome/browser/autofill/aut...
File chrome/browser/autofill/autofill_metrics.cc (right):

http://codereview.chromium.org/7740070/diff/20004/chrome/browser/autofill/aut...
chrome/browser/autofill/autofill_metrics.cc:315:
UMA_HISTOGRAM_TIMES("Autofill.FillDuration.FromInteraction.WithAutofill",
What is the dynamic range you're expecting for this?  UMA_HISTOGRAM_TIMES has
its overflow bucket start at 10seconds.  Is that too short?  
For instance, UMA_HISTOGRAM_MEDIUM_TIME() runs from 10ms to 3 minutes (and
you'll hopefully make very little use of that tail).

http://codereview.chromium.org/7740070/diff/20004/chrome/browser/autofill/for...
File chrome/browser/autofill/form_structure.cc (right):

http://codereview.chromium.org/7740070/diff/20004/chrome/browser/autofill/for...
chrome/browser/autofill/form_structure.cc:814: if (!interaction_time.is_null())
{
(optional) personal style nit: I really like early return when possible, so that
the remainder of the code is not indented, and the reader doesn't have to look
to see what else can happen.  For example:

if (interaction_time.is_null())
  return;

http://codereview.chromium.org/7740070/diff/20004/chrome/common/autofill_mess...
File chrome/common/autofill_messages.h (right):

http://codereview.chromium.org/7740070/diff/20004/chrome/common/autofill_mess...
chrome/common/autofill_messages.h:97: base::TimeTicks /* timestamp */)
I didn't watch the flow carefully... but be certain to only compare TimeTicks
values obtained in the the same process.  Each process has a different baseline,
so times in different processes are not comparable.

If this is a problem, you can normalize them during transit by changing them to
a TimeDelta at this boundary (and optionally translating them back to a
TimeTicks in the other process).

[Ilya Sherman, 2011-09-02 06:57:53]

http://codereview.chromium.org/7740070/diff/20004/chrome/browser/autofill/aut...
File chrome/browser/autofill/autofill_metrics.cc (right):

http://codereview.chromium.org/7740070/diff/20004/chrome/browser/autofill/aut...
chrome/browser/autofill/autofill_metrics.cc:315:
UMA_HISTOGRAM_TIMES("Autofill.FillDuration.FromInteraction.WithAutofill",
On 2011/09/02 01:48:33, jar wrote:
> What is the dynamic range you're expecting for this?  UMA_HISTOGRAM_TIMES has
> its overflow bucket start at 10seconds.  Is that too short?  
> For instance, UMA_HISTOGRAM_MEDIUM_TIME() runs from 10ms to 3 minutes (and
> you'll hopefully make very little use of that tail).

Oh, wow, good catch!  I think 100ms to 10 minutes is probably a reasonable
dynamic range for this metric -- does my change look correct for that?

http://codereview.chromium.org/7740070/diff/20004/chrome/browser/autofill/for...
File chrome/browser/autofill/form_structure.cc (right):

http://codereview.chromium.org/7740070/diff/20004/chrome/browser/autofill/for...
chrome/browser/autofill/form_structure.cc:814: if (!interaction_time.is_null())
{
On 2011/09/02 01:48:33, jar wrote:
> (optional) personal style nit: I really like early return when possible, so
that
> the remainder of the code is not indented, and the reader doesn't have to look
> to see what else can happen.  For example:
> 
> if (interaction_time.is_null())
>   return;

I generally agree with you.  I decided on the nested style here, however, to
match the if-stmt immediately above this one.

http://codereview.chromium.org/7740070/diff/20004/chrome/common/autofill_mess...
File chrome/common/autofill_messages.h (right):

http://codereview.chromium.org/7740070/diff/20004/chrome/common/autofill_mess...
chrome/common/autofill_messages.h:97: base::TimeTicks /* timestamp */)
On 2011/09/02 01:48:33, jar wrote:
> I didn't watch the flow carefully... but be certain to only compare TimeTicks
> values obtained in the the same process.  Each process has a different
baseline,
> so times in different processes are not comparable.
> 
> If this is a problem, you can normalize them during transit by changing them
to
> a TimeDelta at this boundary (and optionally translating them back to a
> TimeTicks in the other process).

Yes, all of the TimeTicks values are being collected in the renderer process,
which is where the user interaction occurs.  Thanks for the warning though!  :)

[jar (doing other things), 2011-09-02 20:09:26]

LGTM

http://codereview.chromium.org/7740070/diff/20004/chrome/browser/autofill/aut...
File chrome/browser/autofill/autofill_metrics.cc (right):

http://codereview.chromium.org/7740070/diff/20004/chrome/browser/autofill/aut...
chrome/browser/autofill/autofill_metrics.cc:315:
UMA_HISTOGRAM_TIMES("Autofill.FillDuration.FromInteraction.WithAutofill",
On 2011/09/02 06:57:54, Ilya Sherman wrote:
> On 2011/09/02 01:48:33, jar wrote:
> > What is the dynamic range you're expecting for this?  UMA_HISTOGRAM_TIMES
has
> > its overflow bucket start at 10seconds.  Is that too short?  
> > For instance, UMA_HISTOGRAM_MEDIUM_TIME() runs from 10ms to 3 minutes (and
> > you'll hopefully make very little use of that tail).
> 
> Oh, wow, good catch!  I think 100ms to 10 minutes is probably a reasonable
> dynamic range for this metric -- does my change look correct for that?

Your change to 100ms through 10 minutes looks great.  Thanks.