Inject timestamps to resource messages.

Inject renderer receive message time into resource notifications.

Previously time calculations based on "now"-time taken when renderer processed resource notification messages.

Renderer time is calculated by interpolation based on taken values. Because of long JS evaluation or heavy rendering, "renderer" time range might be skewed.

To fix situation, "renderer" time should be taken when IPC messages are processed by renderer IO thread.

This patch adds message filter that supplies aforementioned messages with timestamps.


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

[eustas, 2013-04-30 14:17:44]

Preview: injection code moved to DevToolsAgentFilter

[eustas, 2013-05-17 09:10:52]

On 2013/04/30 14:17:44, eustas.ru wrote:
> Preview: injection code moved to DevToolsAgentFilter

to Charlie: John is OOO till end of May. Do you know someone else who could
review this?

[Charlie Reis, 2013-05-17 19:16:04]

On 2013/05/17 09:10:52, eustas.ru wrote:
> On 2013/04/30 14:17:44, eustas.ru wrote:
> > Preview: injection code moved to DevToolsAgentFilter
> 
> to Charlie: John is OOO till end of May. Do you know someone else who could
> review this?

If you're just looking for a content owner review, I'm happy to take a look when
the other reviewers have approved it.  Sounds like simonjam and pfeldman should
look first, though.

[eustas, 2013-05-23 08:06:14]

to Charlie: Actually James had given lgtm for draft of this patch
https://codereview.chromium.org/14359004/ and Pavel advised to move logic to
devtools_agent_filter.

to James and Pavel: PTAL.

[James Simonsen, 2013-05-23 18:39:20]

still lgtm

[Charlie Reis, 2013-05-23 20:13:11]

I don't understand why this is in the DevToolsAgentFilter.  That's a strange
dependency to have if it is supposed to happen for all messages.

https://codereview.chromium.org/14646006/diff/13001/content/common/resource_d...
File content/common/resource_dispatcher.cc (right):

https://codereview.chromium.org/14646006/diff/13001/content/common/resource_d...
content/common/resource_dispatcher.cc:510: }
Please abstract this into a helper method rather than copy/pasting it 3 times.

https://codereview.chromium.org/14646006/diff/13001/content/common/resource_d...
File content/common/resource_dispatcher.h (right):

https://codereview.chromium.org/14646006/diff/13001/content/common/resource_d...
content/common/resource_dispatcher.h:188: base::TimeTicks io_timestamp_;
Please add a comment here.

[eustas, 2013-05-24 15:22:28]

Only "renderer" child threads could benefit on "patching" resource messages.
 So adding it to DevToolsAgentFilter is a minimal-overhead solution (this filter
is attached only to renderer thread, and reusing it we avoid adding new filter
to filter-chain).

 If you have no objections, I could turn back to distinct filter attached to
renderer thread.

https://codereview.chromium.org/14646006/diff/13001/content/common/resource_d...
File content/common/resource_dispatcher.cc (right):

https://codereview.chromium.org/14646006/diff/13001/content/common/resource_d...
content/common/resource_dispatcher.cc:510: }
On 2013/05/23 20:13:11, creis wrote:
> Please abstract this into a helper method rather than copy/pasting it 3 times.

Done.

https://codereview.chromium.org/14646006/diff/13001/content/common/resource_d...
File content/common/resource_dispatcher.h (right):

https://codereview.chromium.org/14646006/diff/13001/content/common/resource_d...
content/common/resource_dispatcher.h:188: base::TimeTicks io_timestamp_;
On 2013/05/23 20:13:11, creis wrote:
> Please add a comment here.

Done.

[Charlie Reis, 2013-05-24 16:17:08]

Darin, can I get your thoughts on this?  Seems like we might want it in a
separate MessageFilter rather than piggy-backing on DevToolsAgentFilter, but I'm
not sure what the impact would be.

https://codereview.chromium.org/14646006/diff/23001/content/common/resource_d...
File content/common/resource_dispatcher.cc (right):

https://codereview.chromium.org/14646006/diff/23001/content/common/resource_d...
content/common/resource_dispatcher.cc:709: else {
nit: No else needed, since you return in the first branch.

https://codereview.chromium.org/14646006/diff/23001/content/renderer/devtools...
File content/renderer/devtools/devtools_agent_filter.h (right):

https://codereview.chromium.org/14646006/diff/23001/content/renderer/devtools...
content/renderer/devtools/devtools_agent_filter.h:31: // is posted to main
thread. It is served just before resource message.
Again, this seems unrelated to DevTools.  I could imagine DevTools becoming a
component that isn't always guaranteed to be present, in which case you'd
accidentally lose this logic.

I don't know what the overhead of adding a new MessageFilter is, though, so I'll
defer to Darin.

[eustas, 2013-05-27 12:03:57]

Added distinct ChildResourceFilter back. So both ways to inject timestamps could
be seen in different patchsets.

https://codereview.chromium.org/14646006/diff/23001/content/renderer/devtools...
File content/renderer/devtools/devtools_agent_filter.h (right):

https://codereview.chromium.org/14646006/diff/23001/content/renderer/devtools...
content/renderer/devtools/devtools_agent_filter.h:31: // is posted to main
thread. It is served just before resource message.
On 2013/05/24 16:17:08, creis wrote:
> Again, this seems unrelated to DevTools.  I could imagine DevTools becoming a
> component that isn't always guaranteed to be present, in which case you'd
> accidentally lose this logic.
> 
> I don't know what the overhead of adding a new MessageFilter is, though, so
I'll
> defer to Darin.

Done.

[jam, 2013-05-28 15:59:24]

On 2013/05/24 16:17:08, creis wrote:
> Darin, can I get your thoughts on this?  Seems like we might want it in a
> separate MessageFilter rather than piggy-backing on DevToolsAgentFilter, but
I'm
> not sure what the impact would be.

We add separate message filters (in the browser and child processe) per feature
to make things clearer. The impact is minimal.

[jam, 2013-05-28 16:02:28]

looking at the whole change: why are you adding a new filter instead of
dispatching this IPC in ResourceDispatcher::OnMessageReceived?

[jam, 2013-05-28 16:06:44]

ok looked through the bug and see why you're doing stuff on the IO thread.

however this change doesn't look like it'll always work since the timestamp is
basically a global. So it only works if the main message loop always dispatches
a ResourceDispatcher IPC message before the next one comes in (or else the
earlier queued message will use the newer IPC message's time).

[eustas, 2013-05-28 16:20:32]

"set_io_timestamp" tasks are dispatched in the same message loop as
ResourceDispatcher IPC messages. So tasks will be properly interleaved and each
timestamp will correspond it's resource message.


On 2013/05/28 16:06:44, jam wrote:
> however this change doesn't look like it'll always work since the timestamp is
> basically a global. So it only works if the main message loop always
dispatches
> a ResourceDispatcher IPC message before the next one comes in (or else the
> earlier queued message will use the newer IPC message's time).

[jam, 2013-05-28 17:54:50]

On 2013/05/28 16:20:32, eustas.ru wrote:
> "set_io_timestamp" tasks are dispatched in the same message loop as
> ResourceDispatcher IPC messages. So tasks will be properly interleaved and
each
> timestamp will correspond it's resource message.

ah, I misread that code, sorry.

per bug 223836, it says the network time should be used. so i'm wondering why
you're doing this in the renderer IO thread, instead of just having the browser
generate this time in ResourceDispatcherHost and add this time to the relevant
IPC messages?

[eustas, 2013-05-28 18:23:35]

Oh, bug title is the first reporter impression.

Actually browser timing for both request start and response start browser
timestamps are reported to renderer. And then they are converted to achieve
coherence with other renderer timestamps.

Previously for conversion we used renderer main thread timestamps
when messages were processed by ResourceDispatcher.
But this leads to skewed results in case main thread is under heavy load. Those
skewed results look like we don't use browser timing at all.

So we decided to improve conversion precision by taking timestamps
on IO thread.
It works in more predictable manner, because there are no user-specified or
computing-extensive tasks.


On 2013/05/28 17:54:50, jam wrote:
> per bug 223836, it says the network time should be used. so i'm wondering why
> you're doing this in the renderer IO thread, instead of just having the
browser
> generate this time in ResourceDispatcherHost and add this time to the relevant
> IPC messages?

[jam, 2013-05-28 18:31:53]

On 2013/05/28 18:23:35, eustas.ru wrote:
> Oh, bug title is the first reporter impression.
> 
> Actually browser timing for both request start and response start browser
> timestamps are reported to renderer. And then they are converted to achieve
> coherence with other renderer timestamps.

I don't understand this last sentence. Can you expand on this? i.e. what/why is
it converted, and what coherence are you referring to? Basically I'm wondering
why the browser-side time isn't enough.

> 
> Previously for conversion we used renderer main thread timestamps
> when messages were processed by ResourceDispatcher.
> But this leads to skewed results in case main thread is under heavy load.
Those
> skewed results look like we don't use browser timing at all.
> 
> So we decided to improve conversion precision by taking timestamps
> on IO thread.
> It works in more predictable manner, because there are no user-specified or
> computing-extensive tasks.
> 
> 
> On 2013/05/28 17:54:50, jam wrote:
> > per bug 223836, it says the network time should be used. so i'm wondering
why
> > you're doing this in the renderer IO thread, instead of just having the
> browser
> > generate this time in ResourceDispatcherHost and add this time to the
relevant
> > IPC messages?

[eustas, 2013-05-28 19:25:41]

1) Coherence. Historically, series of "synchronously" taken timestamps taken on
different processes could be shifted by some offset. This offset is not a fixed
value and could change sometimes.

So if we take timestamps on two processes and then put them all on one timeline,
then we will see that some events arrive out of order. That is incoherence.

To fix this we have a trick - for a sequence of timestamps on process A we find
take timestamps on process B that correspond first and last timestamps. Then we
lineary transform all intermediate timestamps. Thus we eliminate parasite offset
and events from different processes are shown on timeline arrive in correct
order.

I think James Simonsen could tell you about this in more details.

2) Skewing. As I mentioned, we take two timestamps on renderer thread that
"correspond" two timestamps on browser thread to interpolate other timing.

But imagine, if main renderer thread got stuck with rendering/compositing, or
user JS runs too long...
Then IPC messages sent by browser will not be processed in time.
So, when we process IPC message it could be too late.

On the other hand io thread is very lightweight in terms of CPU loads.
So if we take timestamps from io thread (which resides in the same process as
main thread) we can assume that they are taken at right moment.

I hope this explanation made things a little more clear ;-)


On 2013/05/28 18:31:53, jam wrote:
> I don't understand this last sentence. Can you expand on this? i.e. what/why
is
> it converted, and what coherence are you referring to? Basically I'm wondering
> why the browser-side time isn't enough.

[jam, 2013-05-28 23:00:15]

lgtm, thanks for the explanation and for bearing through all my questions!

https://codereview.chromium.org/14646006/diff/29001/content/common/resource_d...
File content/common/resource_dispatcher.h (right):

https://codereview.chromium.org/14646006/diff/29001/content/common/resource_d...
content/common/resource_dispatcher.h:166: // then current time is returned.
Saved timestamp is reset, so follofing
nit: spelling

https://codereview.chromium.org/14646006/diff/29001/content/common/resource_d...
content/common/resource_dispatcher.h:168: base::TimeTicks
consume_io_timestamp();
nit: per style guide, since this isn't implemented inline it should be
ConsumeIOTimestamp()

[eustas, 2013-05-29 08:31:25]

https://codereview.chromium.org/14646006/diff/29001/content/common/resource_d...
File content/common/resource_dispatcher.h (right):

https://codereview.chromium.org/14646006/diff/29001/content/common/resource_d...
content/common/resource_dispatcher.h:166: // then current time is returned.
Saved timestamp is reset, so follofing
On 2013/05/28 23:00:15, jam wrote:
> nit: spelling

Done.

https://codereview.chromium.org/14646006/diff/29001/content/common/resource_d...
content/common/resource_dispatcher.h:168: base::TimeTicks
consume_io_timestamp();
On 2013/05/28 23:00:15, jam wrote:
> nit: per style guide, since this isn't implemented inline it should be
> ConsumeIOTimestamp()

Done.

[commit-bot: I haz the power, 2013-05-29 11:44:36]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/eustas@chromium.org/14646006/41001

[commit-bot: I haz the power, 2013-05-29 14:47:19]

Change committed as 202870