Bug 45664 – Web Inspector: [Resources panel] Timing accuracy.

• Status: RESOLVED
• Resolution: FIXED
• Component: Web Inspector (Deprecated)

[Pavel Feldman]

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.

[Pavel Feldman]

<< 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.)

[Pavel Feldman]

The reason is that we mark resource finish time after the JS execution callback. I'll look into it.

[Pavel Feldman]

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.

[Pavel Feldman]

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.

[Pavel Feldman]

Created attachment 67563 [details]
[PATCH] Same with the chromium agent call fixed.

Chromium bots will still fail compile since they need coordinated landing.

[Eric Seidel (no email)]

Attachment 67561 [details] did not build on mac:
Build output: http://queues.webkit.org/results/4047007

[WebKit Review Bot]

Attachment 67561 [details] did not build on gtk:
Build output: http://queues.webkit.org/results/4004010

[WebKit Review Bot]

Attachment 67561 [details] did not build on chromium:
Build output: http://queues.webkit.org/results/3996012

[Eric Seidel (no email)]

Attachment 67563 [details] did not build on mac:
Build output: http://queues.webkit.org/results/4054006

[WebKit Review Bot]

Attachment 67563 [details] did not build on gtk:
Build output: http://queues.webkit.org/results/4005011

[WebKit Review Bot]

Attachment 67563 [details] did not build on chromium:
Build output: http://queues.webkit.org/results/4070005

[Pavel Feldman]

Created attachment 67572 [details]
[PATCH] More work for bots, no default values this time.

[Early Warning System Bot]

Attachment 67572 [details] did not build on qt:
Build output: http://queues.webkit.org/results/4063009

[Eric Seidel (no email)]

Attachment 67572 [details] did not build on mac:
Build output: http://queues.webkit.org/results/4071008

[WebKit Review Bot]

Attachment 67572 [details] did not build on gtk:
Build output: http://queues.webkit.org/results/4001010

[WebKit Review Bot]

Attachment 67572 [details] did not build on chromium:
Build output: http://queues.webkit.org/results/4051011

[WebKit Review Bot]

Attachment 67572 [details] did not build on win:
Build output: http://queues.webkit.org/results/4026010

[Pavel Feldman]

Created attachment 67653 [details]
[PATCH] Rebaselined. Bots, jump in.

[Yury Semikhatsky]

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.

[Pavel Feldman]

Created attachment 67658 [details]
[PATCH] Review comments addressed (for try bots).

[Eric Seidel (no email)]

Attachment 67658 [details] did not build on mac:
Build output: http://queues.webkit.org/results/4021024

[Pavel Feldman]

Created attachment 67660 [details]
[PATCH] More rebaselines.

[Pavel Feldman]

Created attachment 67661 [details]
[PATCH] More rebaselines.

[Pavel Feldman]

        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

[WebKit Review Bot]

http://trac.webkit.org/changeset/67551 might have broken Qt Linux Release

[Eric Seidel (no email)]

Could this be causing the image load failure seen in bug 45875?

[Pavel Feldman]

(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.