Bug 45664 - Web Inspector: [Resources panel] Timing accuracy.
Summary: Web Inspector: [Resources panel] Timing accuracy.
Status: RESOLVED FIXED
Alias: None
Product: WebKit
Classification: Unclassified
Component: Web Inspector (Deprecated) (show other bugs)
Version: 528+ (Nightly build)
Hardware: All All
: P2 Normal
Assignee: Pavel Feldman
URL:
Keywords:
Depends on: 45816
Blocks:
  Show dependency treegraph
 
Reported: 2010-09-13 06:10 PDT by Pavel Feldman
Modified: 2010-09-16 02:31 PDT (History)
17 users (show)

See Also:


Attachments
[PATCH] Proposed change. (27.79 KB, patch)
2010-09-14 09:11 PDT, Pavel Feldman
no flags Details | Formatted Diff | Diff
[PATCH] Same with the chromium agent call fixed. (28.62 KB, patch)
2010-09-14 09:14 PDT, Pavel Feldman
no flags Details | Formatted Diff | Diff
[PATCH] More work for bots, no default values this time. (33.83 KB, patch)
2010-09-14 10:08 PDT, Pavel Feldman
no flags Details | Formatted Diff | Diff
[PATCH] Rebaselined. Bots, jump in. (34.08 KB, patch)
2010-09-15 01:11 PDT, Pavel Feldman
yurys: review+
Details | Formatted Diff | Diff
[PATCH] Review comments addressed (for try bots). (36.85 KB, patch)
2010-09-15 02:06 PDT, Pavel Feldman
no flags Details | Formatted Diff | Diff
[PATCH] More rebaselines. (36.85 KB, patch)
2010-09-15 02:48 PDT, Pavel Feldman
no flags Details | Formatted Diff | Diff
[PATCH] More rebaselines. (44.07 KB, patch)
2010-09-15 03:05 PDT, Pavel Feldman
no flags Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Pavel Feldman 2010-09-13 06:10:23 PDT
I set up a test page with two images followed by a JavaScript block which executes a script for 5 seconds in a tight loop. In Firebug, the images are correctly shown loading in parallel. In Chrome, the first image stop load time and the second image start show as after the tight loop finishes. It seems that long-running JavaScript code makes the timings in the resources panel inaccurate. Firebug used to have similar problems, but they were fixed. See this blog post for more information: http://www.softwareishard.com/blog/firebug/firebug-http-time-monitor/.

See images attached.
Comment 1 Pavel Feldman 2010-09-13 08:09:39 PDT
<< Previous post was a report from user >>

<< Below is a clarification note from Steve >>

A note from Steve with A more complete description of the problem:

Web Inspector appears to be displaying incorrect network timing info that's thrown off by JS execution in the page. Here's an example page:

    http://stevesouders.com/cuzillion/?c0=bj2hfff1_5_f&c1=bi2hfff2_0_f

There are two resources. Both start downloading at about the same time. The script finishes downloading around 1 second. The image finishes downloading around 2 seconds. This is in fact the behavior shown by HttpWatch and Firebug Net Panel. 

However, when viewed in Web Inspector in Chrome the image is shown as taking ~6 seconds to download. That's because the script has a 5 second tight loop. This is likely blocking the Web Inspector from determining the correct timing for the image download. (I verified the true image download time by watching my server logs.)
Comment 2 Pavel Feldman 2010-09-13 08:11:16 PDT
The reason is that we mark resource finish time after the JS execution callback. I'll look into it.
Comment 3 Pavel Feldman 2010-09-13 09:28:31 PDT
Investigation note:

To problems here:

1) Sync script processing is happening before we measure resource finish time (easy to fix)

2) Resource timing is measured from within WebCore dispatch events that are by definition synchronous. As a result, async network events are serialized and then measured (and hence are bogus). The way to fix it is to rely upon the network stack timers reported as a part of ResourceLoadTiming struct. Two missing pieces here:
 - resource finish time is currently not a part of load timing, need to extend it
 - not all of the WebKit platforms will be able to provide resource load timing, hence we will need to fall back to the existing behavior.
Comment 4 Pavel Feldman 2010-09-14 09:11:55 PDT
Created attachment 67561 [details]
[PATCH] Proposed change.

With this change, platforms have a way to report proper resource load finish time to the WebCore. Rest of the timers can already be pushed by means of ResourceLoadTiming. Resource finish is a bit different since it is not available on didReceiveResponse. Hence it should be reported as a part of didFinishLoad.
Comment 5 Pavel Feldman 2010-09-14 09:14:28 PDT
Created attachment 67563 [details]
[PATCH] Same with the chromium agent call fixed.

Chromium bots will still fail compile since they need coordinated landing.
Comment 6 Eric Seidel (no email) 2010-09-14 09:28:37 PDT
Attachment 67561 [details] did not build on mac:
Build output: http://queues.webkit.org/results/4047007
Comment 7 WebKit Review Bot 2010-09-14 09:30:36 PDT
Attachment 67561 [details] did not build on gtk:
Build output: http://queues.webkit.org/results/4004010
Comment 8 WebKit Review Bot 2010-09-14 09:39:47 PDT
Attachment 67561 [details] did not build on chromium:
Build output: http://queues.webkit.org/results/3996012
Comment 9 Eric Seidel (no email) 2010-09-14 09:42:07 PDT
Attachment 67563 [details] did not build on mac:
Build output: http://queues.webkit.org/results/4054006
Comment 10 WebKit Review Bot 2010-09-14 09:47:42 PDT
Attachment 67563 [details] did not build on gtk:
Build output: http://queues.webkit.org/results/4005011
Comment 11 WebKit Review Bot 2010-09-14 09:54:31 PDT
Attachment 67563 [details] did not build on chromium:
Build output: http://queues.webkit.org/results/4070005
Comment 12 Pavel Feldman 2010-09-14 10:08:07 PDT
Created attachment 67572 [details]
[PATCH] More work for bots, no default values this time.
Comment 13 Early Warning System Bot 2010-09-14 10:21:48 PDT
Attachment 67572 [details] did not build on qt:
Build output: http://queues.webkit.org/results/4063009
Comment 14 Eric Seidel (no email) 2010-09-14 10:28:11 PDT
Attachment 67572 [details] did not build on mac:
Build output: http://queues.webkit.org/results/4071008
Comment 15 WebKit Review Bot 2010-09-14 10:33:40 PDT
Attachment 67572 [details] did not build on gtk:
Build output: http://queues.webkit.org/results/4001010
Comment 16 WebKit Review Bot 2010-09-14 10:45:26 PDT
Attachment 67572 [details] did not build on chromium:
Build output: http://queues.webkit.org/results/4051011
Comment 17 WebKit Review Bot 2010-09-14 11:47:27 PDT
Attachment 67572 [details] did not build on win:
Build output: http://queues.webkit.org/results/4026010
Comment 18 Pavel Feldman 2010-09-15 01:11:30 PDT
Created attachment 67653 [details]
[PATCH] Rebaselined. Bots, jump in.
Comment 19 Yury Semikhatsky 2010-09-15 01:38:10 PDT
Comment on attachment 67653 [details]
[PATCH] Rebaselined. Bots, jump in.

Please address the comments before landing.


View in context: https://bugs.webkit.org/attachment.cgi?id=67653&action=prettypatch

> WebCore/inspector/InspectorController.cpp:1060
> +    resource->endTiming(0);
It might make sense to pass real time here. The timing may be useful in a scenario where the user checks whether the resource is available and takes further decision based on its availability.

> WebCore/platform/network/ResourceHandleClient.h:76
> +        virtual void didFinishLoading(ResourceHandle*, double) { }
Please specify name for the second parameter.

> WebKit/chromium/public/WebURLLoaderClient.h:67
> +    virtual void didFinishLoading(WebURLLoader*, double finishTime) { }
You will get "unused parameter" warning here.

> WebKit/chromium/public/WebURLLoaderClient.h:70
> +    void didFinishLoading(WebURLLoader* loader) { didFinishLoading(loader, 0); }
This should be virtual, otherwise Chromium may break.
Comment 20 Pavel Feldman 2010-09-15 02:06:55 PDT
Created attachment 67658 [details]
[PATCH] Review comments addressed (for try bots).
Comment 21 Eric Seidel (no email) 2010-09-15 02:28:41 PDT
Attachment 67658 [details] did not build on mac:
Build output: http://queues.webkit.org/results/4021024
Comment 22 Pavel Feldman 2010-09-15 02:48:06 PDT
Created attachment 67660 [details]
[PATCH] More rebaselines.
Comment 23 Pavel Feldman 2010-09-15 03:05:59 PDT
Created attachment 67661 [details]
[PATCH] More rebaselines.
Comment 24 Pavel Feldman 2010-09-15 05:13:40 PDT
        M       WebCore/ChangeLog
        M       WebCore/inspector/InspectorController.cpp
        M       WebCore/inspector/InspectorController.h
        M       WebCore/inspector/InspectorResource.cpp
        M       WebCore/inspector/InspectorResource.h
        M       WebCore/loader/DocumentLoader.cpp
        M       WebCore/loader/MainResourceLoader.cpp
        M       WebCore/loader/MainResourceLoader.h
        M       WebCore/loader/NetscapePlugInStreamLoader.cpp
        M       WebCore/loader/PingLoader.h
        M       WebCore/loader/ResourceLoadNotifier.cpp
        M       WebCore/loader/ResourceLoadNotifier.h
        M       WebCore/loader/ResourceLoader.cpp
        M       WebCore/loader/ResourceLoader.h
        M       WebCore/loader/SubresourceLoader.cpp
        M       WebCore/loader/SubresourceLoader.h
        M       WebCore/loader/appcache/ApplicationCacheGroup.cpp
        M       WebCore/loader/appcache/ApplicationCacheGroup.h
        M       WebCore/loader/icon/IconFetcher.cpp
        M       WebCore/loader/icon/IconFetcher.h
        M       WebCore/platform/graphics/gstreamer/WebKitWebSourceGStreamer.cpp
        M       WebCore/platform/network/BlobResourceHandle.cpp
        M       WebCore/platform/network/ResourceHandleClient.h
        M       WebCore/platform/network/cf/ResourceHandleCFNet.cpp
        M       WebCore/platform/network/curl/ResourceHandleCurl.cpp
        M       WebCore/platform/network/curl/ResourceHandleManager.cpp
        M       WebCore/platform/network/mac/ResourceHandleMac.mm
        M       WebCore/platform/network/qt/QNetworkReplyHandler.cpp
        M       WebCore/platform/network/qt/ResourceHandleQt.cpp
        M       WebCore/platform/network/soup/ResourceHandleSoup.cpp
        M       WebCore/platform/network/win/ResourceHandleWin.cpp
        M       WebKit/chromium/ChangeLog
        M       WebKit/chromium/public/WebURLLoaderClient.h
        M       WebKit/chromium/src/ResourceHandle.cpp
        M       WebKit/chromium/src/WebDevToolsAgentImpl.cpp
        M       WebKit/gtk/ChangeLog
        M       WebKit/gtk/webkit/webkitdownload.cpp
Committed r67551
Comment 25 WebKit Review Bot 2010-09-15 05:29:28 PDT
http://trac.webkit.org/changeset/67551 might have broken Qt Linux Release
Comment 26 Eric Seidel (no email) 2010-09-16 01:24:54 PDT
Could this be causing the image load failure seen in bug 45875?
Comment 27 Pavel Feldman 2010-09-16 02:31:08 PDT
(In reply to comment #26)
> Could this be causing the image load failure seen in bug 45875?

I don't think so. This change only added parameter to the didFinishLoading. Did not change behavior.