1381648 - Dev tools network performance analysis gives incorrect time values

Status: RESOLVED FIXED

(DevTools :: Netmonitor, defect, P3)

Description

[David Smith]

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.

Comment 1

[Vincent Lequertier]

Hi, can I work on this? :-)

Comment 2

[Jan Honza Odvarko [:Honza] (always need-info? me)]

(In reply to Vincent Lequertier from comment #1)
> Hi, can I work on this? :-)
Sure, assigned to you!
Honza

Comment 3

[Vincent Lequertier]

Attachment: Bug 1381648 - Add non blocking time to the statistics panel of netmonitor;

Review commit: https://reviewboard.mozilla.org/r/183010/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/183010/

Comment 4

[Vincent Lequertier]

Here is a patch. I haven't found a test which looks for load times in the statistics panel.

Comment 5

[Jan Honza Odvarko [:Honza] (always need-info? me)]

(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

Comment 6

[David Smith]

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?

Comment 7

[Vincent Lequertier]

Maybe we can have a better documentation on how those load times are calculated?

Comment 8

[Jan Honza Odvarko [:Honza] (always need-info? me)]

(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

Comment 9

[Jan Honza Odvarko [:Honza] (always need-info? me)]

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

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

Comment 10

[[e-mail]]

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.

Comment 11

[Vincent Lequertier]

Ok, I'll see if I can sum up the timestamps of images.

Vincent

Comment 12

[Vincent Lequertier]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/183010/diff/1-2/

Comment 13

[Vincent Lequertier]

This patch adds a new column for non-blocking time.

Comment 14

[Jan Honza Odvarko [:Honza] (always need-info? me)]

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`

Comment 15

[Vincent Lequertier]

Thanks for the review!

Comment 16

[Vincent Lequertier]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/183010/diff/2-3/

Comment 17

[[e-mail]]

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 18

[Vincent Lequertier]

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 19

[Vincent Lequertier]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/183010/diff/3-4/

Comment 20

[Vincent Lequertier]

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 21

[Jan Honza Odvarko [:Honza] (always need-info? me)]

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

Comment 22

[Vincent Lequertier]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/183010/diff/4-5/

Comment 23

[Vincent Lequertier]

Just fixed a linting issue. The line 

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

exceeded the maximum line length.

Vincent

Comment 24

[Vincent Lequertier]

Try push here: https://treeherder.mozilla.org/#/jobs?repo=try&revision=3748c83666f9f8162c8fc044ebfd33c6973ecfd7

Comment 25

[Vincent Lequertier]

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

Vincent

Comment 26

[Jan Honza Odvarko [:Honza] (always need-info? me)]

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

Comment 27

[Vincent Lequertier]

New try push https://treeherder.mozilla.org/#/jobs?repo=try&revision=0a5a0a53add42658d963b31f031d4593b67a3da2

Comment 28

[Vincent Lequertier]

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

Comment 29

[Vincent Lequertier]

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.

Comment 30

[Vincent Lequertier]

Honza, I have pushed again to try. What do you think about this try push?

Comment 31

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Can you please rebase the patch, there is a collision
when it's applied on the latest HEAD.

Thanks!
Honza

Comment 32

[Vincent Lequertier]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/183010/diff/5-6/

Comment 33

[Vincent Lequertier]

I have rebased the patch https://reviewboard.mozilla.org/r/183010/diff/6/

Vincent

Comment 34

[Jan Honza Odvarko [:Honza] (always need-info? me)]

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

Comment 35

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/bad9f2a1be21
Add non blocking time to the statistics panel of netmonitor; r=Honza

Comment 36

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/mozilla-central/rev/bad9f2a1be21

Comment 37

[Vincent Lequertier]

(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 :-)

Comment 38

[Francesco Lodolo [:flod]]

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

Comment 39

[Pulsebot]

Backout by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/8acc12cf30b7
Backed out 1 changeset on request from flod for wrong placeholders r=backout

Comment 40

[Ryan VanderMeulen [:RyanVM]]

Merge of backout:
https://hg.mozilla.org/mozilla-central/rev/8acc12cf30b7

Comment 41

[Vincent Lequertier]

(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

Comment 42

[Vincent Lequertier]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/183010/diff/6-7/

Comment 43

[Chris Mills [:cmills]]

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

Comment 44

[Jan Honza Odvarko [:Honza] (always need-info? me)]

(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

Comment 45

[Chris Mills [:cmills]]

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

Comment 46

[Vincent Lequertier]

Flod, I have updated the patch to use '#1' as a placeholder. Does it look good?

Comment 47

[Francesco Lodolo [:flod]]

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

Comment 48

[Vincent Lequertier]

Honza, can we repush this, or we have to wait for bug 1417409?

Comment 49

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e55035922259
Add non blocking time to the statistics panel of netmonitor; r=Honza

Comment 50

[Jan Honza Odvarko [:Honza] (always need-info? me)]

(In reply to Vincent Lequertier from comment #48)
> Honza, can we repush this, or we have to wait for bug 1417409?
Done!

Honza

Comment 51

[Stefan Hindli [:stefan_hindli]]

https://hg.mozilla.org/mozilla-central/rev/e55035922259