Add time from navigation_start to NTP LogEvent

Add time from navigation_start to NTP LogEvent

BUG=467633
Committed: https://crrev.com/68e665768e2e4a905bb932bf24428d140b28d858
Cr-Commit-Position: refs/heads/master@{#321439}

[fserb, 2015-03-16 17:17:44]

fserb@chromium.org changed reviewers:
+ dbeam@chromium.org, kmadhusu@chromium.org, wfh@chromium.org

[fserb, 2015-03-16 17:17:44]

fserb@chromium.org changed required reviewers:
+ dbeam@chromium.org, kmadhusu@chromium.org, wfh@chromium.org

[Will Harris, 2015-03-16 17:39:03]

https://codereview.chromium.org/1006753003/diff/20001/chrome/common/render_me...
File chrome/common/render_messages.h (right):

https://codereview.chromium.org/1006753003/diff/20001/chrome/common/render_me...
chrome/common/render_messages.h:597: int64 /* time */)
delta should always be positive, can this be a uint64

https://codereview.chromium.org/1006753003/diff/20001/chrome/renderer/searchb...
File chrome/renderer/searchbox/searchbox.cc (right):

https://codereview.chromium.org/1006753003/diff/20001/chrome/renderer/searchb...
chrome/renderer/searchbox/searchbox.cc:172: int64 delta = now - start;
add DCHECK that now > start

[fserb, 2015-03-16 17:49:39]

Thanks for the comments. Done.

https://codereview.chromium.org/1006753003/diff/20001/chrome/common/render_me...
File chrome/common/render_messages.h (right):

https://codereview.chromium.org/1006753003/diff/20001/chrome/common/render_me...
chrome/common/render_messages.h:597: int64 /* time */)
On 2015/03/16 17:39:03, Will Harris wrote:
> delta should always be positive, can this be a uint64

Done.

https://codereview.chromium.org/1006753003/diff/20001/chrome/renderer/searchb...
File chrome/renderer/searchbox/searchbox.cc (right):

https://codereview.chromium.org/1006753003/diff/20001/chrome/renderer/searchb...
chrome/renderer/searchbox/searchbox.cc:172: int64 delta = now - start;
On 2015/03/16 17:39:03, Will Harris wrote:
> add DCHECK that now > start

Done.

[Will Harris, 2015-03-16 18:08:54]

chrome/common/render_messages.h lgtm

[kmadhusu, 2015-03-16 21:35:30]

https://codereview.chromium.org/1006753003/diff/80001/chrome/renderer/searchb...
File chrome/renderer/searchbox/searchbox.cc (right):

https://codereview.chromium.org/1006753003/diff/80001/chrome/renderer/searchb...
chrome/renderer/searchbox/searchbox.cc:169: .navigationStart();
style nit: Can you rewrite this line as follows:
uint64 start =
    1000 *
(render_view()->GetMainRenderFrame()->GetWebFrame()->performance().navigationStart());

https://codereview.chromium.org/1006753003/diff/80001/chrome/renderer/searchb...
chrome/renderer/searchbox/searchbox.cc:171: (base::TimeTicks::Now() -
base::TimeTicks::UnixEpoch()).InMilliseconds();
Is there any specific reason to use base::TimeTicks functions instead of
base::Time functions?

[fserb, 2015-03-16 21:45:50]

thanks.

https://codereview.chromium.org/1006753003/diff/80001/chrome/renderer/searchb...
File chrome/renderer/searchbox/searchbox.cc (right):

https://codereview.chromium.org/1006753003/diff/80001/chrome/renderer/searchb...
chrome/renderer/searchbox/searchbox.cc:169: .navigationStart();
On 2015/03/16 21:35:30, kmadhusu wrote:
> style nit: Can you rewrite this line as follows:
> uint64 start =
>     1000 *
>
(render_view()->GetMainRenderFrame()->GetWebFrame()->performance().navigationStart());

I can, but it doesn't fit in 80chars and the "git cl format" changes it back.

https://codereview.chromium.org/1006753003/diff/80001/chrome/renderer/searchb...
chrome/renderer/searchbox/searchbox.cc:171: (base::TimeTicks::Now() -
base::TimeTicks::UnixEpoch()).InMilliseconds();
On 2015/03/16 21:35:30, kmadhusu wrote:
> Is there any specific reason to use base::TimeTicks functions instead of
> base::Time functions? 

Done.

[kmadhusu, 2015-03-16 21:58:48]

https://codereview.chromium.org/1006753003/diff/80001/chrome/renderer/searchb...
File chrome/renderer/searchbox/searchbox.cc (right):

https://codereview.chromium.org/1006753003/diff/80001/chrome/renderer/searchb...
chrome/renderer/searchbox/searchbox.cc:169: .navigationStart();
On 2015/03/16 21:45:49, fserb wrote:
> On 2015/03/16 21:35:30, kmadhusu wrote:
> > style nit: Can you rewrite this line as follows:
> > uint64 start =
> >     1000 *
> >
>
(render_view()->GetMainRenderFrame()->GetWebFrame()->performance().navigationStart());
> 
> I can, but it doesn't fit in 80chars and the "git cl format" changes it back.

You can break the line. I prefer to see 2 lines instead of 4 lines.

https://codereview.chromium.org/1006753003/diff/120001/chrome/renderer/search...
File chrome/renderer/searchbox/searchbox.cc (right):

https://codereview.chromium.org/1006753003/diff/120001/chrome/renderer/search...
chrome/renderer/searchbox/searchbox.cc:170: uint64 now = (base::Time::Now() -
base::Time::UnixEpoch()).InMilliseconds();
I am not an expert to decide which function to use here. Based on the header
comments specified in
https://code.google.com/p/chromium/codesearch#chromium/src/base/time/time.h&t...,
"TimeTicks"  is guaranteed not to decrease whereas "Time" may actually decrease
or jump. I just wanted to make sure that you thought about it before using it
here.

[fserb, 2015-03-16 22:05:32]

https://codereview.chromium.org/1006753003/diff/80001/chrome/renderer/searchb...
File chrome/renderer/searchbox/searchbox.cc (right):

https://codereview.chromium.org/1006753003/diff/80001/chrome/renderer/searchb...
chrome/renderer/searchbox/searchbox.cc:169: .navigationStart();
On 2015/03/16 21:58:48, kmadhusu wrote:
> On 2015/03/16 21:45:49, fserb wrote:
> > On 2015/03/16 21:35:30, kmadhusu wrote:
> > > style nit: Can you rewrite this line as follows:
> > > uint64 start =
> > >     1000 *
> > >
> >
>
(render_view()->GetMainRenderFrame()->GetWebFrame()->performance().navigationStart());
> > 
> > I can, but it doesn't fit in 80chars and the "git cl format" changes it
back.
> 
> You can break the line. I prefer to see 2 lines instead of 4 lines.

I changed it a bit, but if I run "git cl format" it reverts it back.

https://codereview.chromium.org/1006753003/diff/120001/chrome/renderer/search...
File chrome/renderer/searchbox/searchbox.cc (right):

https://codereview.chromium.org/1006753003/diff/120001/chrome/renderer/search...
chrome/renderer/searchbox/searchbox.cc:170: uint64 now = (base::Time::Now() -
base::Time::UnixEpoch()).InMilliseconds();
On 2015/03/16 21:58:48, kmadhusu wrote:
> I am not an expert to decide which function to use here. Based on the header
> comments specified in
>
https://code.google.com/p/chromium/codesearch#chromium/src/base/time/time.h&t...,
> "TimeTicks"  is guaranteed not to decrease whereas "Time" may actually
decrease
> or jump. I just wanted to make sure that you thought about it before using it
> here. 

yeah, I saw that. But since I'm always using (now - epoch), it's pretty safe
either way. The reason I used TimeTicks (and maybe I should keep it) is because
navigationStart uses it too.

[kmadhusu, 2015-03-17 00:10:40]

Thanks.

https://codereview.chromium.org/1006753003/diff/80001/chrome/renderer/searchb...
File chrome/renderer/searchbox/searchbox.cc (right):

https://codereview.chromium.org/1006753003/diff/80001/chrome/renderer/searchb...
chrome/renderer/searchbox/searchbox.cc:169: .navigationStart();
On 2015/03/16 22:05:32, fserb wrote:
> On 2015/03/16 21:58:48, kmadhusu wrote:
> > On 2015/03/16 21:45:49, fserb wrote:
> > > On 2015/03/16 21:35:30, kmadhusu wrote:
> > > > style nit: Can you rewrite this line as follows:
> > > > uint64 start =
> > > >     1000 *
> > > >
> > >
> >
>
(render_view()->GetMainRenderFrame()->GetWebFrame()->performance().navigationStart());
> > > 
> > > I can, but it doesn't fit in 80chars and the "git cl format" changes it
> back.
> > 
> > You can break the line. I prefer to see 2 lines instead of 4 lines.
> 
> I changed it a bit, but if I run "git cl format" it reverts it back.

I generally don't run "git cl format". 
Try this and see if it works:
uint64 start = 1000 * (render_view()->GetMainRenderFrame()->GetWebFrame()->
    performance().navigationStart());

https://codereview.chromium.org/1006753003/diff/120001/chrome/renderer/search...
File chrome/renderer/searchbox/searchbox.cc (right):

https://codereview.chromium.org/1006753003/diff/120001/chrome/renderer/search...
chrome/renderer/searchbox/searchbox.cc:170: uint64 now = (base::Time::Now() -
base::Time::UnixEpoch()).InMilliseconds();
On 2015/03/16 22:05:32, fserb wrote:
> On 2015/03/16 21:58:48, kmadhusu wrote:
> > I am not an expert to decide which function to use here. Based on the header
> > comments specified in
> >
>
https://code.google.com/p/chromium/codesearch#chromium/src/base/time/time.h&t...,
> > "TimeTicks"  is guaranteed not to decrease whereas "Time" may actually
> decrease
> > or jump. I just wanted to make sure that you thought about it before using
it
> > here. 
> 
> yeah, I saw that. But since I'm always using (now - epoch), it's pretty safe
> either way. The reason I used TimeTicks (and maybe I should keep it) is
because
> navigationStart uses it too.

Sure.

[fserb, 2015-03-17 15:54:49]

Done.

https://codereview.chromium.org/1006753003/diff/120001/chrome/renderer/search...
File chrome/renderer/searchbox/searchbox.cc (right):

https://codereview.chromium.org/1006753003/diff/120001/chrome/renderer/search...
chrome/renderer/searchbox/searchbox.cc:170: uint64 now = (base::Time::Now() -
base::Time::UnixEpoch()).InMilliseconds();
On 2015/03/17 00:10:40, kmadhusu wrote:
> On 2015/03/16 22:05:32, fserb wrote:
> > On 2015/03/16 21:58:48, kmadhusu wrote:
> > > I am not an expert to decide which function to use here. Based on the
header
> > > comments specified in
> > >
> >
>
https://code.google.com/p/chromium/codesearch#chromium/src/base/time/time.h&t...,
> > > "TimeTicks"  is guaranteed not to decrease whereas "Time" may actually
> > decrease
> > > or jump. I just wanted to make sure that you thought about it before using
> it
> > > here. 
> > 
> > yeah, I saw that. But since I'm always using (now - epoch), it's pretty safe
> > either way. The reason I used TimeTicks (and maybe I should keep it) is
> because
> > navigationStart uses it too.
> 
> Sure.

Acknowledged.

[kmadhusu, 2015-03-17 16:48:32]

lgtm

[Dan Beam, 2015-03-17 17:17:19]

https://codereview.chromium.org/1006753003/diff/140001/chrome/browser/ui/webu...
File chrome/browser/ui/webui/ntp/ntp_user_data_logger.cc (right):

https://codereview.chromium.org/1006753003/diff/140001/chrome/browser/ui/webu...
chrome/browser/ui/webui/ntp/ntp_user_data_logger.cc:130: void
NTPUserDataLogger::LogEvent(NTPLoggingEventType event, uint64 time) {
why do you ask for this if it's not used...?

https://codereview.chromium.org/1006753003/diff/140001/chrome/browser/ui/webu...
File chrome/browser/ui/webui/ntp/ntp_user_data_logger.h (right):

https://codereview.chromium.org/1006753003/diff/140001/chrome/browser/ui/webu...
chrome/browser/ui/webui/ntp/ntp_user_data_logger.h:45: // incremented. The time
parameters contains the time when this event occured
occurred

https://codereview.chromium.org/1006753003/diff/140001/chrome/renderer/search...
File chrome/renderer/searchbox/searchbox.cc (right):

https://codereview.chromium.org/1006753003/diff/140001/chrome/renderer/search...
chrome/renderer/searchbox/searchbox.cc:169: uint64 delta = now - start;
i'm really confused as to what everything here is doing...

why aren't you just doing

  Time::Now() - Time(navigationStart())

(or TimeTicks::Now() - TimeTicks(navigationStart()))?

https://codereview.chromium.org/1006753003/diff/140001/chrome/renderer/search...
chrome/renderer/searchbox/searchbox.cc:170: DVLOG(1) << now << " - " << start <<
" = " << delta;
remove debug logging... unless there's some purpose?

[fserb, 2015-03-17 17:41:32]

https://codereview.chromium.org/1006753003/diff/140001/chrome/browser/ui/webu...
File chrome/browser/ui/webui/ntp/ntp_user_data_logger.cc (right):

https://codereview.chromium.org/1006753003/diff/140001/chrome/browser/ui/webu...
chrome/browser/ui/webui/ntp/ntp_user_data_logger.cc:130: void
NTPUserDataLogger::LogEvent(NTPLoggingEventType event, uint64 time) {
On 2015/03/17 17:17:19, Dan Beam wrote:
> why do you ask for this if it's not used...?

I've split the change in two:
https://codereview.chromium.org/1007383003/

https://codereview.chromium.org/1006753003/diff/140001/chrome/browser/ui/webu...
File chrome/browser/ui/webui/ntp/ntp_user_data_logger.h (right):

https://codereview.chromium.org/1006753003/diff/140001/chrome/browser/ui/webu...
chrome/browser/ui/webui/ntp/ntp_user_data_logger.h:45: // incremented. The time
parameters contains the time when this event occured
On 2015/03/17 17:17:19, Dan Beam wrote:
> occurred

Done.

https://codereview.chromium.org/1006753003/diff/140001/chrome/renderer/search...
File chrome/renderer/searchbox/searchbox.cc (right):

https://codereview.chromium.org/1006753003/diff/140001/chrome/renderer/search...
chrome/renderer/searchbox/searchbox.cc:169: uint64 delta = now - start;
On 2015/03/17 17:17:19, Dan Beam wrote:
> i'm really confused as to what everything here is doing...
> 
> why aren't you just doing
> 
>   Time::Now() - Time(navigationStart())
> 
> (or TimeTicks::Now() - TimeTicks(navigationStart()))?

I've tried my best to do it this way before, which would be the sanner way.

Except that Time/TimeTicks don't have constructors (nor static functions) that
receive timestamp as input. The closest thing it has is a function that gets an
int64 InternalValue, but navigationStart is not a proper internalValue.

Since navigationStart is a timestamp since epoch (converted from a TimeTicks), I
got the delta by getting the timestamp now (Now - UnixEpoch) and subtracting
from the navigationStart.

An alternative would be to ADD UnixEpoch to navigationStart, and use that as an
InternalValue, but it seems hackier to me, since I'm just guessing what the
InternalValue is supposed to be.

But maybe I missed something on base::TimeTicks? If I do what you suggest, I get
a huge number as output from the subtraction (like 1765681612ms).

https://codereview.chromium.org/1006753003/diff/140001/chrome/renderer/search...
chrome/renderer/searchbox/searchbox.cc:170: DVLOG(1) << now << " - " << start <<
" = " << delta;
On 2015/03/17 17:17:19, Dan Beam wrote:
> remove debug logging... unless there's some purpose?

Done.

[fserb, 2015-03-18 21:14:19]

PTAL

[fserb, 2015-03-19 19:35:30]

fserb@chromium.org changed reviewers:
+ jhawkins@chromium.org

[fserb, 2015-03-19 19:35:30]

fserb@chromium.org changed required reviewers:
+ jhawkins@chromium.org

[James Hawkins, 2015-03-19 19:49:00]

On 2015/03/19 19:35:31, fserb wrote:

Which files are you asking me to review?

[chromium-reviews, 2015-03-19 19:50:15]

chrome/browser/ui/webui/...

On Thu, Mar 19, 2015 at 3:49 PM <jhawkins@chromium.org> wrote:

> On 2015/03/19 19:35:31, fserb wrote:
>
> Which files are you asking me to review?
>
> https://codereview.chromium.org/1006753003/
>

To unsubscribe from this group and stop receiving emails from it, send an email
to chromium-reviews+unsubscribe@chromium.org.

[James Hawkins, 2015-03-19 19:59:59]

https://codereview.chromium.org/1006753003/diff/180001/chrome/browser/ui/webu...
File chrome/browser/ui/webui/metrics_handler.cc (left):

https://codereview.chromium.org/1006753003/diff/180001/chrome/browser/ui/webu...
chrome/browser/ui/webui/metrics_handler.cc:112:
NTPUserDataLogger::GetOrCreateFromWebContents(
Please don't change the styling, i.e., leave the newline.

https://codereview.chromium.org/1006753003/diff/180001/chrome/browser/ui/webu...
File chrome/browser/ui/webui/ntp/ntp_user_data_logger.h (right):

https://codereview.chromium.org/1006753003/diff/180001/chrome/browser/ui/webu...
chrome/browser/ui/webui/ntp/ntp_user_data_logger.h:45: // incremented. The time
parameters contains the time when this event occurred
nit: s/parameters/parameter/

https://codereview.chromium.org/1006753003/diff/180001/chrome/browser/ui/webu...
chrome/browser/ui/webui/ntp/ntp_user_data_logger.h:45: // incremented. The time
parameters contains the time when this event occurred
Optional nit: You can just simply say "|time| contains the..."

https://codereview.chromium.org/1006753003/diff/180001/chrome/browser/ui/webu...
chrome/browser/ui/webui/ntp/ntp_user_data_logger.h:45: // incremented. The time
parameters contains the time when this event occurred
I don't understand what this parameter is supposed to be based on the comment. 
Is this a time delta?

[fserb, 2015-03-19 20:07:49]

Done. thanks.

https://codereview.chromium.org/1006753003/diff/180001/chrome/browser/ui/webu...
File chrome/browser/ui/webui/metrics_handler.cc (left):

https://codereview.chromium.org/1006753003/diff/180001/chrome/browser/ui/webu...
chrome/browser/ui/webui/metrics_handler.cc:112:
NTPUserDataLogger::GetOrCreateFromWebContents(
On 2015/03/19 19:59:59, James Hawkins wrote:
> Please don't change the styling, i.e., leave the newline.

I think it was 'git cl format', reverted.

https://codereview.chromium.org/1006753003/diff/180001/chrome/browser/ui/webu...
File chrome/browser/ui/webui/ntp/ntp_user_data_logger.h (right):

https://codereview.chromium.org/1006753003/diff/180001/chrome/browser/ui/webu...
chrome/browser/ui/webui/ntp/ntp_user_data_logger.h:45: // incremented. The time
parameters contains the time when this event occurred
On 2015/03/19 19:59:59, James Hawkins wrote:
> Optional nit: You can just simply say "|time| contains the..."

Done.

https://codereview.chromium.org/1006753003/diff/180001/chrome/browser/ui/webu...
chrome/browser/ui/webui/ntp/ntp_user_data_logger.h:45: // incremented. The time
parameters contains the time when this event occurred
On 2015/03/19 19:59:59, James Hawkins wrote:
> nit: s/parameters/parameter/

Done.

https://codereview.chromium.org/1006753003/diff/180001/chrome/browser/ui/webu...
chrome/browser/ui/webui/ntp/ntp_user_data_logger.h:45: // incremented. The time
parameters contains the time when this event occurred
On 2015/03/19 19:59:59, James Hawkins wrote:
> I don't understand what this parameter is supposed to be based on the comment.

> Is this a time delta?

Yes. Made it clearer.

[James Hawkins, 2015-03-19 20:10:07]

https://codereview.chromium.org/1006753003/diff/200001/chrome/browser/ui/webu...
File chrome/browser/ui/webui/ntp/ntp_user_data_logger.h (right):

https://codereview.chromium.org/1006753003/diff/200001/chrome/browser/ui/webu...
chrome/browser/ui/webui/ntp/ntp_user_data_logger.h:47: void
LogEvent(NTPLoggingEventType event, uint64 time);
Why not use TimeDelta?

https://code.google.com/p/chromium/codesearch#chromium/src/base/time/time.h&q...

[fserb, 2015-03-19 20:15:31]

https://codereview.chromium.org/1006753003/diff/200001/chrome/browser/ui/webu...
File chrome/browser/ui/webui/ntp/ntp_user_data_logger.h (right):

https://codereview.chromium.org/1006753003/diff/200001/chrome/browser/ui/webu...
chrome/browser/ui/webui/ntp/ntp_user_data_logger.h:47: void
LogEvent(NTPLoggingEventType event, uint64 time);
On 2015/03/19 20:10:07, James Hawkins wrote:
> Why not use TimeDelta?
> 
>
https://code.google.com/p/chromium/codesearch#chromium/src/base/time/time.h&q...

so... the problem is we are constructing this time from the difference from
NavigationStart which is created as a TimeDelta, but then saved as an int64
since epoch on the renderer. And it's not trivial to do the reverse operation
without some weird hacking. If you look at searchbox.cc on this CL you will see
what I mean.

I can still convert the timestamp that I generate with
TimeDelta.fromMilliseconds(...) if you'd prefer like that.

[James Hawkins, 2015-03-19 20:18:22]

On 2015/03/19 20:15:31, fserb wrote:
>
https://codereview.chromium.org/1006753003/diff/200001/chrome/browser/ui/webu...
> File chrome/browser/ui/webui/ntp/ntp_user_data_logger.h (right):
> 
>
https://codereview.chromium.org/1006753003/diff/200001/chrome/browser/ui/webu...
> chrome/browser/ui/webui/ntp/ntp_user_data_logger.h:47: void
> LogEvent(NTPLoggingEventType event, uint64 time);
> On 2015/03/19 20:10:07, James Hawkins wrote:
> > Why not use TimeDelta?
> > 
> >
>
https://code.google.com/p/chromium/codesearch#chromium/src/base/time/time.h&q...
> 
> so... the problem is we are constructing this time from the difference from
> NavigationStart which is created as a TimeDelta, but then saved as an int64
> since epoch on the renderer. And it's not trivial to do the reverse operation
> without some weird hacking. If you look at searchbox.cc on this CL you will
see
> what I mean.
> 
> I can still convert the timestamp that I generate with
> TimeDelta.fromMilliseconds(...) if you'd prefer like that.

Bummer.  Yeah, let's use TimeDelta where possible.

[fserb, 2015-03-19 20:37:41]

Ok. Converted them all to TimeDelta.

[James Hawkins, 2015-03-19 20:43:45]

lgtm

[fserb, 2015-03-19 20:45:12]

The CQ bit was checked by fserb@chromium.org

[fserb, 2015-03-19 20:45:12]

The patchset sent to the CQ was uploaded after l-g-t-m from wfh@chromium.org,
kmadhusu@chromium.org
Link to the patchset: https://codereview.chromium.org/1006753003/#ps220001
(title: " ")

[commit-bot: I haz the power, 2015-03-19 20:45:58]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1006753003/220001

[commit-bot: I haz the power, 2015-03-19 20:46:02]

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

[commit-bot: I haz the power, 2015-03-19 20:46:04]

All required reviewers (with asterisk prefixes) have not yet approved this CL.

No LGTM from a valid reviewer yet. Only full committers are accepted.
Even if an LGTM may have been provided, it was from a non-committer,
_not_ a full super star committer.
See http://www.chromium.org/getting-involved/become-a-committer
Note that this has nothing to do with OWNERS files.

[fserb, 2015-03-19 20:46:53]

fserb@chromium.org changed reviewers:
- dbeam@chromium.org

[fserb, 2015-03-19 20:46:53]

fserb@chromium.org changed required reviewers:
- dbeam@chromium.org

[fserb, 2015-03-19 20:47:06]

The CQ bit was checked by fserb@chromium.org

[commit-bot: I haz the power, 2015-03-19 20:47:51]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1006753003/220001

[commit-bot: I haz the power, 2015-03-19 21:48:50]

Committed patchset #12 (id:220001)

[commit-bot: I haz the power, 2015-03-19 21:49:53]

Patchset 12 (id:??) landed as
https://crrev.com/68e665768e2e4a905bb932bf24428d140b28d858
Cr-Commit-Position: refs/heads/master@{#321439}