Dev tools network performance analysis gives incorrect time values

RESOLVED FIXED in Firefox 59

Status

defect
P3
normal
RESOLVED FIXED
2 years ago
Last year

People

(Reporter: dsmith, Assigned: vi.le)

Tracking

({dev-doc-needed})

56 Branch
Firefox 59
Dependency tree / graph

Firefox Tracking Flags

(firefox57 wontfix, firefox58 wontfix, firefox59 fixed)

Details

Attachments

(1 attachment)

User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:56.0) Gecko/20100101 Firefox/56.0
Build ID: 20170717030207

Steps to reproduce:

Loaded a page testing sprite loading times for bundled vs unbundled scenarios.

URL: http://jlwagner.net/tests/sprite-vs-nosprite/nosprite.html

Bring up dev tools, go to the Network tab, and run a performance analysis on the page load time.


Actual results:

The HTML shows (for example) a total time of 0.11 seconds, which is in line with expectations. However the total time given for loading the images is listed at 328.21 seconds, which is very much wrong.  The correct value might be 3.2821 seconds, based on a wall clock comparison.


Expected results:

The provided time should be accurate to the performance being measured.
Component: Untriaged → Developer Tools: Netmonitor
Status: UNCONFIRMED → NEW
Has STR: --- → yes
Ever confirmed: true
Hi, can I work on this? :-)
(In reply to Vincent Lequertier from comment #1)
> Hi, can I work on this? :-)
Sure, assigned to you!
Honza
Assignee: nobody → vi.le
Status: NEW → ASSIGNED
Here is a patch. I haven't found a test which looks for load times in the statistics panel.
(In reply to Vincent Lequertier from comment #4)
> Here is a patch. I haven't found a test which looks for load times in the
> statistics panel.
Hmm, this is weird. Why we should divide the time by 100 for images and not for other resource types?

Now, when I am looking at this again, I feel it isn't a bug, but a feature. I believe that the number in the report represents total load time of all resources of given type).
https://developer.mozilla.org/en-US/docs/Tools/Network_Monitor#Performance_analysis

So, in this case (STR from comment #0) total time needed to load all 223 images.

@Fred: can you please confirm this? Is this report a bug?

Honza
Flags: needinfo?(gasolin)
I can confirm that manually adding up all the individual .svg load times gave me a total of 323.872 seconds, while re-running the diagnostics gave a total of 333.81 seconds — within margin of variation from subsequent runs.

While that may be technically correct in a "these add up to that" way, I'd say it wasn't useful, since the vast majority of the time being counted is the 'blocked' total of each individual entry, which must necessarily be considered as acting in parallel with everything else.  Perhaps if it added up all non-blocked time for all entries?
Maybe we can have a better documentation on how those load times are calculated?
(In reply to David Smith from comment #6)
> I can confirm that manually adding up all the individual .svg load times
> gave me a total of 323.872 seconds, while re-running the diagnostics gave a
> total of 333.81 seconds — within margin of variation from subsequent runs.
Nice, thanks for verification!

> While that may be technically correct in a "these add up to that" way, I'd
> say it wasn't useful, since the vast majority of the time being counted is
> the 'blocked' total of each individual entry, which must necessarily be
> considered as acting in parallel with everything else.  Perhaps if it added
> up all non-blocked time for all entries?
Yes, good question.

I am not entirely sure whether the blocked time should be removed. It's part
of the loading process time too. Perhaps we could somehow display both times?
This is part of the "Performance Analysis" action and providing detailed 
timing info is expected (so, we shouldn't be afraid about providing more numbers)

(In reply to Vincent Lequertier from comment #7)
> Maybe we can have a better documentation on how those load times are
> calculated?
Agree! (we should at least properly document the current state)

Honza
Keywords: dev-doc-needed
Comment on attachment 8911591 [details]
Bug 1381648 - Add non blocking time to the statistics panel of netmonitor;

https://reviewboard.mozilla.org/r/183010/#review188760
Attachment #8911591 - Flags: review?(odvarko) → review-
The statistics page shows the summary of each img load time, which seems not useful and make the statistics report looks wrong.

The more accurate one would be filter the request's MIME type and check all time stamps to get the accurate load time.
Flags: needinfo?(gasolin)
Ok, I'll see if I can sum up the timestamps of images.

Vincent
This patch adds a new column for non-blocking time.
Comment on attachment 8911591 [details]
Bug 1381648 - Add non blocking time to the statistics panel of netmonitor;

https://reviewboard.mozilla.org/r/183010/#review193544

Thanks for the patch!

Please see my inline comments.

Honza

::: devtools/client/locales/en-US/netmonitor.properties:327
(Diff revision 2)
>  # This is the label displayed in the performance analysis view for the
>  # total requests time, in seconds.
>  charts.totalSeconds=Time: #1 second;Time: #1 seconds
>  
> +# LOCALIZATION NOTE (charts.totalSeconds): Semi-colon list of plural forms.
> +# See: http://developer.mozilla.org/en/docs/Localization_and_Plurals

Fix the string ID in the LOCALIZATION comment
=> charts.totalSecondsNonBlocking

::: devtools/client/locales/en-US/netmonitor.properties:358
(Diff revision 2)
>  # LOCALIZATION NOTE (charts.totalCount): This is the label displayed
>  # in the header column in the performance analysis view for time of request.
>  charts.time=Time
>  
> +# LOCALIZATION NOTE (charts.totalCount): This is the label displayed
> +# in the header column in the performance analysis view for non blocking

Again, please fix the string ID in the LOCALIZATION note.

Also, you should use this string ID:

charts.nonblockingtime => charts.nonBlockingTime

::: devtools/client/netmonitor/src/components/statistics-panel.js:124
(Diff revision 2)
>          count: "",
>          label: L10N.getStr("charts.type"),
>          size: L10N.getStr("charts.size"),
>          transferredSize: L10N.getStr("charts.transferred"),
>          time: L10N.getStr("charts.time"),
> +        nonblockingTime: L10N.getStr("charts.nonblockingtime"),

name of the variable should be `nonBlockingTime`
Attachment #8911591 - Flags: review?(odvarko) → review-
Thanks for the review!
Comment on attachment 8911591 [details]
Bug 1381648 - Add non blocking time to the statistics panel of netmonitor;

https://reviewboard.mozilla.org/r/183010/#review193960

::: devtools/client/locales/en-US/netmonitor.properties:330
(Diff revision 3)
>  
> +# LOCALIZATION NOTE (charts.totalSecondsNonBlocking): Semi-colon list of plural forms.
> +# See: http://developer.mozilla.org/en/docs/Localization_and_Plurals
> +# This is the label displayed in the performance analysis view for the
> +# total requests time (non-blocking), in seconds.
> +charts.totalSecondsNonBlocking=Non blocking time: #1 second;Non blocking time: #1 seconds

We can define variables with %1$S, and format it with L10N.getFormatStr, like

http://searchfox.org/mozilla-central/source/devtools/client/locales/en-US/netmonitor.properties#1002

::: devtools/client/netmonitor/src/components/statistics-panel.js:124
(Diff revision 3)
>          count: "",
>          label: L10N.getStr("charts.type"),
>          size: L10N.getStr("charts.size"),
>          transferredSize: L10N.getStr("charts.transferred"),
>          time: L10N.getStr("charts.time"),
> +        nonBlockingTime: L10N.getStr("charts.nonBlockingTime"),

please put params in alphabet order

::: devtools/client/netmonitor/src/components/statistics-panel.js:150
(Diff revision 3)
>              getSizeWithDecimals(total / 1024)),
>          time: (total) => {
>            let seconds = total / 1000;
>            let string = getTimeWithDecimals(seconds);
>            return PluralForm.get(seconds,
>              L10N.getStr("charts.totalSeconds")).replace("#1", string);

can be replaced with L10N.getFormatStr

::: devtools/client/netmonitor/src/components/statistics-panel.js:156
(Diff revision 3)
>          },
> +        nonBlockingTime: (total) => {
> +          let seconds = total / 1000;
> +          let string = getTimeWithDecimals(seconds);
> +          return PluralForm.get(seconds,
> +            L10N.getStr("charts.totalSecondsNonBlocking")).replace("#1", string);

can be replaced with L10N.getFormatStr

::: devtools/client/netmonitor/src/components/statistics-panel.js:188
(Diff revision 3)
>        count: 0,
>        label: type,
>        size: 0,
>        transferredSize: 0,
>        time: 0,
> +      nonBlockingTime: 0,

alphabet order
Comment on attachment 8911591 [details]
Bug 1381648 - Add non blocking time to the statistics panel of netmonitor;

https://reviewboard.mozilla.org/r/183010/#review193960

> please put params in alphabet order

The order of the params is the order in which the columns are displayed. Putting the params in alphabet order would change the columns order to be Type, Non blocking time, Size, Time, Transferred.

> alphabet order

The order here is the order in which the values are displayed.
Comment on attachment 8911591 [details]
Bug 1381648 - Add non blocking time to the statistics panel of netmonitor;

https://reviewboard.mozilla.org/r/183010/#review194672

::: devtools/client/locales/en-US/netmonitor.properties:330
(Diff revision 3)
>  
> +# LOCALIZATION NOTE (charts.totalSecondsNonBlocking): Semi-colon list of plural forms.
> +# See: http://developer.mozilla.org/en/docs/Localization_and_Plurals
> +# This is the label displayed in the performance analysis view for the
> +# total requests time (non-blocking), in seconds.
> +charts.totalSecondsNonBlocking=Non blocking time: #1 second;Non blocking time: #1 seconds

Thanks, cleaner that way
Comment on attachment 8911591 [details]
Bug 1381648 - Add non blocking time to the statistics panel of netmonitor;

https://reviewboard.mozilla.org/r/183010/#review194856

Looks great to me, thanks for working on this!

Honza
Attachment #8911591 - Flags: review?(odvarko) → review+
Just fixed a linting issue. The line 

(request.eventTimings.totalTime - request.eventTimings.timings.blocked) || 0;

exceeded the maximum line length.

Vincent
Honza, do you see any problem with this try push?

Vincent
Flags: needinfo?(odvarko)
I don't understand the:
distutils.errors.DistutilsError: Could not find suitable distribution for Requirement.parse('vcversioner')

Can you re-push once again to make sure?

Honza
Flags: needinfo?(odvarko)
The error you mentionned is still here:

distutils.errors.DistutilsError: Could not find suitable distribution for Requirement.parse('vcversioner')
11:59:06     INFO -      Complete output from command python setup.py egg_info:
11:59:06     INFO -      Couldn't find index page for 'vcversioner' (maybe misspelled?)
11:59:06     INFO -  No local packages or download links found for vcversioner
The error seems to be intermittent. If I click on "Similar Jobs" there are other jobs with the same error every once in a while.
Honza, I have pushed again to try. What do you think about this try push?
Flags: needinfo?(odvarko)
Can you please rebase the patch, there is a collision
when it's applied on the latest HEAD.

Thanks!
Honza
Flags: needinfo?(odvarko)
Flags: needinfo?(odvarko) → needinfo?(vi.le)
I have rebased the patch https://reviewboard.mozilla.org/r/183010/diff/6/

Vincent
Flags: needinfo?(vi.le)
I did another try push
https://treeherder.mozilla.org/#/jobs?repo=try&revision=6e4d5c0e615ebd8688f55e56ca26addf616e44b9

It shows the cgc error, but :Standard8 on IRC is confirming that it's an intermittent.

Let's try to land this!

Honza
Pushed by jodvarko@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/bad9f2a1be21
Add non blocking time to the statistics panel of netmonitor; r=Honza
https://hg.mozilla.org/mozilla-central/rev/bad9f2a1be21
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 58
(In reply to Jan Honza Odvarko [:Honza] from comment #34)
> I did another try push
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=6e4d5c0e615ebd8688f55e56ca26addf616e44b9
> 
> It shows the cgc error, but :Standard8 on IRC is confirming that it's an
> intermittent.
> 
> Let's try to land this!
> 
> Honza

Thank you :-)
Sorry but I need to ask sheriffs to back this patch out. 

When it comes to plural forms, the only placeholders acceptable for numbers are in the form #1, #2, etc. They can't be swapped with %S or similar.
https://developer.mozilla.org/en-US/docs/Mozilla/Localization/Localization_and_Plurals
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Backout by shindli@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/8acc12cf30b7
Backed out 1 changeset on request from flod for wrong placeholders r=backout
(In reply to Francesco Lodolo [:flod] from comment #38)
> Sorry but I need to ask sheriffs to back this patch out. 
> 
> When it comes to plural forms, the only placeholders acceptable for numbers
> are in the form #1, #2, etc. They can't be swapped with %S or similar.
> https://developer.mozilla.org/en-US/docs/Mozilla/Localization/
> Localization_and_Plurals

Thank you for your vigilance, and sorry for using the wrong placeholder.

I will update the patch soon.

Vincent
(In reply to Jan Honza Odvarko [:Honza] from comment #8)
> (In reply to David Smith from comment #6)
> > I can confirm that manually adding up all the individual .svg load times
> > gave me a total of 323.872 seconds, while re-running the diagnostics gave a
> > total of 333.81 seconds — within margin of variation from subsequent runs.
> Nice, thanks for verification!
> 
> > While that may be technically correct in a "these add up to that" way, I'd
> > say it wasn't useful, since the vast majority of the time being counted is
> > the 'blocked' total of each individual entry, which must necessarily be
> > considered as acting in parallel with everything else.  Perhaps if it added
> > up all non-blocked time for all entries?
> Yes, good question.
> 
> I am not entirely sure whether the blocked time should be removed. It's part
> of the loading process time too. Perhaps we could somehow display both times?
> This is part of the "Performance Analysis" action and providing detailed 
> timing info is expected (so, we shouldn't be afraid about providing more
> numbers)
> 
> (In reply to Vincent Lequertier from comment #7)
> > Maybe we can have a better documentation on how those load times are
> > calculated?
> Agree! (we should at least properly document the current state)
> 
> Honza

Hi there,

I'm looking to document this, but I can't see the blocked time as a separate entry in the perf analysis UI, and I am not sure what I need to write about load time calculation.

Can you give me some pointers here, or suggest what wording I should use? Thanks in advance.
Flags: needinfo?(odvarko)
(In reply to Chris Mills (Mozilla, MDN editor) [:cmills] from comment #43)
> I'm looking to document this, but I can't see the blocked time as a separate
> entry in the perf analysis UI, and I am not sure what I need to write about
> load time calculation.
> 
> Can you give me some pointers here, or suggest what wording I should use?
> Thanks in advance.

Sorry, this is now broken by bug 1417409
There should be a new filed called 'Non blocking time', but it isn't visible
since the panel doesn't produce any data.
As soon as bug 1417409 is fixed we can document this.

Honza
Depends on: 1417409
Flags: needinfo?(odvarko)
(In reply to Jan Honza Odvarko [:Honza] from comment #44)
> (In reply to Chris Mills (Mozilla, MDN editor) [:cmills] from comment #43)
> > I'm looking to document this, but I can't see the blocked time as a separate
> > entry in the perf analysis UI, and I am not sure what I need to write about
> > load time calculation.
> > 
> > Can you give me some pointers here, or suggest what wording I should use?
> > Thanks in advance.
> 
> Sorry, this is now broken by bug 1417409
> There should be a new filed called 'Non blocking time', but it isn't visible
> since the panel doesn't produce any data.
> As soon as bug 1417409 is fixed we can document this.
> 
> Honza

OK, thanks!
Flod, I have updated the patch to use '#1' as a placeholder. Does it look good?
Flags: needinfo?(francesco.lodolo)
(In reply to Vincent Lequertier from comment #46)
> Flod, I have updated the patch to use '#1' as a placeholder. Does it look
> good?

It looks good, thanks.
Flags: needinfo?(francesco.lodolo)
Honza, can we repush this, or we have to wait for bug 1417409?
Flags: needinfo?(odvarko)
Pushed by jodvarko@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e55035922259
Add non blocking time to the statistics panel of netmonitor; r=Honza
(In reply to Vincent Lequertier from comment #48)
> Honza, can we repush this, or we have to wait for bug 1417409?
Done!

Honza
Flags: needinfo?(odvarko)
https://hg.mozilla.org/mozilla-central/rev/e55035922259
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 59
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.