1273760 - Blocking state in Network Monitor

Status: RESOLVED FIXED

(DevTools :: Netmonitor, defect, P2)

Description

[Ruturaj Vartak]

Attachment: firebug.png

User Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/50.0.2661.75 Safari/537.36
Build ID: 20160425114621

Steps to reproduce:

Just open a webpage with too many images listed..
ie. Search "jeans" on amazon.com (http://www.amazon.com/s/ref=nb_sb_noss/182-0829299-8092363?url=search-alias%3Daps&field-keywords=jeans)

Ensure you've enabled "Network" Monitor tab in Dev tools.


Actual results:

When images are getting loaded from ecx.images-amazon.com, Some of the images are blocked (due to host thread connection limit) which is shown clearly in Firebug


Expected results:

The Network Monitor timeline for a resource should've shown a clear split between "Blocking" and "Connecting" as its done in firebug.png vs devtools.png

Comment 1

[Ruturaj Vartak]

Attachment: devtools.png

Comment 2

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

Yes, this sounds like a bug.

Honza

Comment 3

[Ruturaj Vartak]

Hey Honza, I'm a web developer. can I pick up this task? Assuming that there is no C / C++ in this.

Comment 4

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

(In reply to Ruturaj from comment #3)
> Hey Honza, I'm a web developer. can I pick up this task? Assuming that there
> is no C / C++ in this.
Sure! 

And correct, there is no C/C++ involved (unless we need an extra platform support, but in that case we would ask the platform network team).

Honza

Comment 5

[Ruturaj Vartak]

Great!

Could you please direct me where I can start ? I've never committed to Fx repo, so its like a complex maze to me.

I'll start off on these to begin
- https://wiki.mozilla.org/DevTools/GetInvolved
- https://wiki.mozilla.org/DevTools/Hacking

Comment 6

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

(In reply to Ruturaj from comment #5)
> Great!
> 
> Could you please direct me where I can start ? I've never committed to Fx
> repo, so its like a complex maze to me.
> 
> I'll start off on these to begin
> - https://wiki.mozilla.org/DevTools/GetInvolved
> - https://wiki.mozilla.org/DevTools/Hacking
Good, these pages describe what you need, especially the second one.

All you need is (this is a summary of what you can see on the Hacking page):

* get the source: hg clone http://hg.mozilla.org/integration/fx-team
* build Firefox: mach build
* do changes in the code
* build Firefox: mach build faster #faster if only JavaScript code has changed
* Run and test: mach run -P development
* Generate patch: hg diff > bug1273760.patch
* Attach the patch here and ask me for the review

As soon as the patch is ready and working we'll ask for commit to the tree and somebody will do it for us.

As soon as you have the dev-env ready on you machine we can move further...

Honza

Comment 7

[Ruturaj Vartak]

My development setup is ready, I've successfully compiled Fx.

While looking at the code, (devtools/client/netmonitor/netmonitor-view.js) line 2032 - 2034.

It says
Skipping "blocked" because it doesn't work yet.

I used console.log("Blocked Values: " + timings["blocked"]); 
and I saw all values dumped as 0

Comment 8

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

(In reply to Ruturaj from comment #7)
> My development setup is ready, I've successfully compiled Fx.
> 
> While looking at the code, (devtools/client/netmonitor/netmonitor-view.js)
> line 2032 - 2034.
> 
> It says
> Skipping "blocked" because it doesn't work yet.
> 
> I used console.log("Blocked Values: " + timings["blocked"]); 
> and I saw all values dumped as 0
Please, NI-me [1] next time so, it isn't forgotten.

I don't know what the comment means but, blocking time is: elapsed time spent in a browser queue waiting for a network connection. 

Note that number of existing (parallel) connection is limited in the browser, network.http.max-connections.

---

In Firebug see this source: 
https://github.com/firebug/firebug/blob/master/extension/content/firebug/net/netUtils.js#L440

So, you need to know:
- when the request has been issued (resolveStarted)
- when the request has been really sent to the server (connectStarted or if missing sendStarted or if missing waitingForTime.

You need to find these timing is DevTools and calculate the blocking time.

Honza

[1] By using the 'Need more information from ...' field

Comment 9

[Ruturaj Vartak]

OK, let me dive into it.

Comment 10

[Ruturaj Vartak]

While looking at the code...

Would STATUS_RESOLVING [1] be considered equivalent of file.startTime [2] from firebug

Is the following chronology / order of events correct? 

STATUS_RESOLVING
STATUS_RESOLVED
STATUS_CONNECTING_TO
STATUS_CONNECTED_TO
STATUS_SENDING_TO
REQUEST_HEADER
REQUEST_BODY_SENT
STATUS_WAITING_FOR
STATUS_RECEIVING_FROM
RESPONSE_START
RESPONSE_HEADER
RESPONSE_COMPLETE
TRANSACTION_CLOSE


[1] https://dxr.mozilla.org/mozilla-central/source/devtools/shared/webconsole/network-monitor.js#731
[2] https://github.com/firebug/firebug/blob/b16a810c666a41a20da9cf511096f93d388bf4f3/extension/content/firebug/net/timeInfoTip.js#L153

Comment 11

[Ruturaj Vartak]

Attachment: tmp.patch

- The patch is a suggestion
- I'm not sure of REQUEST_HEADER, I had sorted all timings (first, last) and REQUEST_HEADER was the first, hence I've considered it to be initializing event. (First I had thought it would've been when Request Header were written)

Please and if someone could also answer comment#10

Comment 12

[Ruturaj Vartak]

Attachment: devtools-timings.ods

These are the sample timings that I've recorded.
- same_domain_last_object (its 20th image object of same domain, bound to be blocked somewhat)
- old_connection_first_object - Its the n'th object after which the connection was reused. This was the object which in another Firefox's firebug, showed no blocking (Can't guarantee if that would've been replicated in Dev firefox)
- Perhaps-new-connection - Its a completely new object for another domain
vedicvatica.com homepage - Its home page of a randomly opened http://vedicvatica.com/

- "start" and "end" are the timestamps available in "httpActivity.timings"

Comment 13

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

(In reply to Ruturaj Vartak from comment #10)
> While looking at the code...
> 
> Would STATUS_RESOLVING [1] be considered equivalent of file.startTime [2]
> from firebug
> 
> Is the following chronology / order of events correct? 
> 
> STATUS_RESOLVING
> STATUS_RESOLVED
> STATUS_CONNECTING_TO
> STATUS_CONNECTED_TO
> STATUS_SENDING_TO
> REQUEST_HEADER
> REQUEST_BODY_SENT
> STATUS_WAITING_FOR
> STATUS_RECEIVING_FROM
> RESPONSE_START
> RESPONSE_HEADER
> RESPONSE_COMPLETE
> TRANSACTION_CLOSE

Yes, this looks correct.

Note that there are also:
http-on-modify-request
http-on-opening-request 

These should be fired by nsIObserverService yet before STATUS_RESOLVING, but they don't have a `timestamp` argument passed in and so, you need to use JS Date().getTime() API to get the time. I am not sure whether JS engine uses the same timer as Necko (the one passed into nsIDistributorListener)


----

I tried the patch, but I am not seeing any 'blocking' time in the UI.

Here are some useful resources for testing:

1) Cuzillion: This page is great for HTTP timing testing

Here is the scenario I tested:
http://stevesouders.com/cuzillion/?c0=bi1hfff2_0_f&c1=bi1hfff2_0_f&c2=bi1hfff2_0_f&c3=bi1hfff2_0_f&c4=bi1hfff2_0_f&c5=bi1hfff2_0_f&c6=bi1hfff2_0_f&c7=bi1hfff2_0_f&t=1258547264277

2) Here is my blog post about the `blocking` time.
http://www.softwareishard.com/blog/firebug/page-load-analysis-using-firebug/

You should play with `network.http.max-persistent-connections-per-server` pref and see if the Network panel provides corresponding info (blocking waterfall timing).


3) I've been also using Chrome for testing/comparison. They are using 'Queuing' and 'Stalled' timing. Not sure what is the difference, but the output looks correct.

Honza

Comment 14

[Ruturaj Vartak]

Attachment: blocking-state.png

The blocking state is visible on my build. I have verified with Firebug 2.017 (Firefox 47.0). I had forked from master at bc94fc8, Perhaps that is the reason why it isn't working.

I'll use your tips and dig into this.

And yes, I try to validate the output with Firebug2x and Chrome's devtools :) However we can't get exact times which puts some doubt.

Comment 15

[Ruturaj Vartak]

The current state works only if the connections are "primed". If its a completely new request / domain, it doesn't (As you experienced)

Is there anyway in Firefox to disconnect all the connections to the domain[s]. It'll be very useful for me debug *new connection* state vs. an *connection open* state.

The cuzillion page makes the Netmonitor behave expected, when page was already loaded (primed with connections). If I open it after a few minutes later.

It'll be great if I can also make Firefox to *lookup* freshly as well.

Comment 16

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

(In reply to Ruturaj Vartak from comment #15)
> The current state works only if the connections are "primed". If its a
> completely new request / domain, it doesn't (As you experienced)
> 
> Is there anyway in Firefox to disconnect all the connections to the
> domain[s]. It'll be very useful for me debug *new connection* state vs. an
> *connection open* state.
@Honza: any tips?

Honza

Comment 17

[Honza Bambas (:mayhemer)]

You can switch to offline and back (File/Work Offline menu).  Just a note this doesn't effect localhost connections.

Comment 18

[Ruturaj Vartak]

Attachment: fix-1273760-1.patch

Summary
- checked along with Firebug and Google Chrome
- Fixed CSS variable typo

Comment 19

[Ruturaj Vartak]

Attachment: Archive 16-07-24 15-45-21.har

Checked page http://stevesouders.com/cuzillion/?c0=bi1hfff2_0_f&c1=bi1hfff2_0_f&c2=bi1hfff2_0_f&c3=bi1hfff2_0_f&c4=bi1hfff2_0_f&c5=bi2hfff2_0_f&c6=bi2hfff2_0_f&c7=bi2hfff2_0_f&c8=bi2hfff2_0_f&c9=bi2hfff2_0_f&t=1469354990  

with network.http.max-persistent-connections-per-server=2

HAR file attached for verification

Comment 20

[Ruturaj Vartak]

Guys, Any update if the patch works as expected ?

Comment 21

[Jarda Snajdr [:jsnajdr]]

(In reply to Ruturaj Vartak from comment #20)
> Guys, Any update if the patch works as expected ?

It works beautifully for me and also all netmonitor tests are passing.

By the way, the REQUEST_HEADER event is fired when the request is ready to be sent over network, but before any actual networking occurs. So it's always the first, and it's correct to use its as a start of the "blocking" period.

Please submit a patch with a correct commit message (bug number, r= flag), with removed console.log call, removed comment about "Not clear how we can determine blocked time", and rebased against the latest mozilla-central. Then you can ask me or Honza for review.

Comment 22

[Ruturaj Vartak]

Attachment: fix-1273760-2.patch

- Removed unnecessary console.log and comments
- Has been rebased from latest HEAD @622e92b - mozilla/fx-team

Comment 23

[Jarda Snajdr [:jsnajdr]]

Comment on attachment 8783267 [details] [diff] [review]
fix-1273760-2.patch

Review of attachment 8783267 [details] [diff] [review]:
-----------------------------------------------------------------

This patch doesn't have the correct format: missing commit message etc. Please follow this guide:

https://developer.mozilla.org/en-US/docs/Mercurial/Using_Mercurial#How_can_I_generate_a_patch_for_somebody_else_to_check-in_for_me.3F

or use the "git format-patch" command if you use Git.

Comment 24

[Ruturaj Vartak]

Attachment: fix-1273760-3.patch

Hey, I'm sorry. I've always been giving patches in that format earlier. :ntim did the hard work for me.

The new patch - I've created with format-patch and git-patch-to-hg-patch as mentioned in https://developer.mozilla.org/en-US/docs/Mercurial/Using_Mercurial#I%27m_all_used_to_Git_but_how_can_I_provide_Mercurial-ready_patches

Please check if this patch is in line.

Thanks

Comment 25

[Jarda Snajdr [:jsnajdr]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=9f00db209dfb

Comment 26

[Jarda Snajdr [:jsnajdr]]

Comment on attachment 8783550 [details] [diff] [review]
fix-1273760-3.patch

Review of attachment 8783550 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks for working on this and for updating the patch. It's perfect now and if the try run doesn't show any unexpected errors, we can land it.

Comment 27

[Ruturaj Vartak]

Thanks a lot!

Comment 28

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/fx-team/rev/7a35a32895ce
Blocking state in Network Monitor. r=jsnajdr

Comment 29

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/7a35a32895ce

Comment 30

[Ruturaj Vartak]

How and when would the documentation [1] be modified?

[1] https://developer.mozilla.org/en-US/docs/Tools/Network_Monitor ?

Comment 31

[Jarda Snajdr [:jsnajdr]]

(In reply to Ruturaj Vartak from comment #30)
> How and when would the documentation [1] be modified?

Set the "dev-doc-needed" keyword and the MDN team will pick it up.

Comment 32

[Will Bamberg [:wbamberg]]

-> https://developer.mozilla.org/en-US/docs/Tools/Network_Monitor#Timings

Please let me know if this covers it!

Comment 33

[Ruturaj Vartak]

Looks great.

If we link mozillazine articles in MDN - we could link text "network.http.max-persistent-connections-per-server" to [1] or an equivalent MDN article.

[1] http://kb.mozillazine.org/Network.http.max-persistent-connections-per-server

Comment 34

[Will Bamberg [:wbamberg]]

Thanks Rutaraj, I've added that link.

Comment 35

[Kazi Nuzhat Tasnem]

I have reproduced this bug with Firefox nightly 49.0a1(build ID:20160425114621)on 
windows 7(64 bit)

I have verified this bug as fixed with Firefox aurora 51.0a2(build Id:20161114004005)
User Agent:Mozilla/5.0 (Windows NT 6.1; WOW64; rv:51.0) Gecko/20100101 Firefox/51.0

[bugday-20161116]