Showing posts with label firefox. Show all posts
Showing posts with label firefox. Show all posts

Monday, July 1, 2013

Debugging Dart Applications in FireFox

‹prev | My Chain | next›

I have a problem with the ICE Code Editor, but only in Firefox. When Firefox first loads the editor, the preview layer is not showing. Strangely, this works in IE and Chrome, but not Firefox.

Since ICE is written in Dart, I am at something of a loss to explain this—after all, the whole point of Dart is to smooth out the differences between browser implementations. Still, this may not be so much Dart as it is a problem with application cache (which is where it resides in beta) or even a deployment issue.

Before I jump to conclusions, I need to start somewhere. That somewhere is setting a breakpoint on the preview layer's update callback in Firefox:



I do like the capabilities and the feel of the debugging tools in the newer versions of Firefox (I am using 22 here). What I see is that, when I load the editor the preview layer callbacks are not, in fact being called. If I press the Update button, then the callback is invoked as expected.

So why isn't the preview layer being told to update? Looking through the code, I do not see any obvious explanation. The content of the editor is being set correctly to the most recent entry in localStorage. As far as I can tell, this should always result in the preview layer being notified. In fact, I have several tests that attest to this and Chrome and IE similarly seem to agree.

And yet it is not working.

My next step is to try a non-appcache version of the editor. That is fairly easy—I have a full screen version of the editor in the example sub-directory of the ICE project. And I find... that it loads just fine locally:



I am unsure if I can eliminate any particular cause given this success. What I do know is that Firefox is definitely capable of displaying the preview correctly, but something in the beta setup is preventing this from occurring.

My next step it so try this locally in appcache. I can do this with the GitHub pages version of http://gamingjs.com/. In the root directory of my gh-pages branch, I fire up jekyll, which is the underlying technology behind GitHub pages:
➜  gamingjs git:(gh-pages) ✗ jekyll --auto --server
/home/chris/.rvm/gems/ruby-1.9.3-p194@gamingjs-site/gems/maruku-0.6.0/lib/maruku/input/parse_doc.rb:22:in `': iconv will be deprecated in the future, use String#encode instead.
Configuration from /home/chris/repos/gamingjs/_config.yml
Auto-regenerating enabled: /home/chris/repos/gamingjs -> /home/chris/repos/gamingjs/_site
[2013-07-01 22:17:28] regeneration: 385 files changed
[2013-07-01 22:17:28] INFO  WEBrick 1.3.1
[2013-07-01 22:17:28] INFO  ruby 1.9.3 (2012-04-20) [x86_64-linux]
[2013-07-01 22:17:28] WARN  TCPServer Error: Address already in use - bind(2)
[2013-07-01 22:17:28] INFO  WEBrick::HTTPServer#start: pid=17269 port=4000
...
Then I hit the page locally in Firefox to find:



It does not work locally either.

There should not be any differences between the gamingjs.com version of ICE and the version in my example directory, but to be sure, I remove the application cache manifest locally, force reload and find:



It works. Sigh.

I set the problem aside for tonight's #pairwithme session with Jon Kirkman. The #pairwithme session goes swimmingly (added the beginning of validations to prevent blank project names) and afterwards Jon starts asking questions about my Firefox issue. Eventually those questions result in some exploratory code and shortly thereafter we realize that the updatePreview() method is being called in all cases, but is having no effect under certain conditions in Firefox. Further exploratory code suggests that there is a race condition in here and, sure enough, if we add a 1000 millisecond delay between before actually updating the preview:
  updatePreview() {
    // ...
    var wait = new Duration(milliseconds: 1000);
    new Timer(wait, (){
      if (iframe.contentWindow == null) return;
      // ...
    });
  }
Then it works—even in Firefox.

Huge thanks to Jon for talking me through that problem—I had been banging my head against it too long to be in a position to make headway with it.

With the problem understood, I am ready to fix it. Tomorrow.



Day #799

Tuesday, May 15, 2012

Fix Node-Spdy's Flow Control for Firefox

‹prev | My Chain | next›

With much, much help from Patrick McManus, I think I finally understand what Firefox SPDY sandboxes are doing with respect to SPDY version 3 flow control. I also have a better understanding of Chrome flow control thanks to this exercise. I even think I have a solution to node-spdy's woes holding a spdy/3 conversation with Firefox.

At the outset of a SPDY conversation, Firefox specifies an initial receive window of 256mb for flow control. That is much higher than the 64kb default in the specification. I remain skeptical that Firefox's large window does little more than disable flow control, but it is definitely throwing real world stuff at node-spdy, so I must support it.

As I found last night, Firefox is sending additional WINDOW_UPDATE frames after node-spdy has sent the DATA FIN packet. Currently node-spdy handles this situation by closing the stream, forcing Firefox to open a new SPDY session to require any remaining resources (but giving up on in-transit resources).

Instead, I add code to RST_STREAM in response to a WINDOW_UPDATE on a closed stream. More specifically, I mark the stream as invalid (0x02):
function Connection(socket, pool, options) {
  // ...
  this.parser.on('frame', function (frame) {
    // ...
    if (frame.type === 'SYN_STREAM') { /* ... */ }
    else {
      if (frame.id) {
        // Load created one
        stream = self.streams[frame.id];

        // Fail if not found
        if (stream === undefined) {
          if (frame.type === 'RST_STREAM') return;
          console.log("frame not found: ", frame);
          //return self.emit('error', 'Stream ' + frame.id + ' not found');
          self.write(self.framer.rstFrame(frame.id, 2));
          return;
        }
      }
      // ...
    }
  });
  // ...
}
Now, when I point my sandbox version of Firefox at my nody-spdy site, I finally see the complete web page with no broken images:


Hooray!

The debugging code that I had added to node-spdy shows that Firefox in fact sends 26 WINDOW_UPDATE frames for the two large resources on that page:
➜  express-spdy-test  node app
Express server listening on port 3000 in development mode
settings.initial_window_size: 268435456
...
sending 7: 0 (false)
[secureConnection] finish
sending 7: 0 (true)
sending 9: 0 (false)
[secureConnection] finish
sending 9: 0 (true)
frame not found:  { type: 'WINDOW_UPDATE', id: 7, delta: 65660 }
frame not found:  { type: 'WINDOW_UPDATE', id: 7, delta: 66320 }
frame not found:  { type: 'WINDOW_UPDATE', id: 7, delta: 65660 }
frame not found:  { type: 'WINDOW_UPDATE', id: 9, delta: 65660 }
frame not found:  { type: 'WINDOW_UPDATE', id: 9, delta: 66320 }
frame not found:  { type: 'WINDOW_UPDATE', id: 9, delta: 65660 }
frame not found:  { type: 'WINDOW_UPDATE', id: 7, delta: 66320 }
frame not found:  { type: 'WINDOW_UPDATE', id: 9, delta: 66320 }
frame not found:  { type: 'WINDOW_UPDATE', id: 7, delta: 66320 }
frame not found:  { type: 'WINDOW_UPDATE', id: 9, delta: 66320 }
frame not found:  { type: 'WINDOW_UPDATE', id: 7, delta: 65660 }
frame not found:  { type: 'WINDOW_UPDATE', id: 9, delta: 65660 }
frame not found:  { type: 'WINDOW_UPDATE', id: 7, delta: 66320 }
frame not found:  { type: 'WINDOW_UPDATE', id: 9, delta: 66320 }
frame not found:  { type: 'WINDOW_UPDATE', id: 7, delta: 65660 }
frame not found:  { type: 'WINDOW_UPDATE', id: 9, delta: 65660 }
frame not found:  { type: 'WINDOW_UPDATE', id: 7, delta: 66320 }
frame not found:  { type: 'WINDOW_UPDATE', id: 9, delta: 66320 }
frame not found:  { type: 'WINDOW_UPDATE', id: 7, delta: 66320 }
frame not found:  { type: 'WINDOW_UPDATE', id: 9, delta: 66320 }
frame not found:  { type: 'WINDOW_UPDATE', id: 7, delta: 65660 }
frame not found:  { type: 'WINDOW_UPDATE', id: 9, delta: 65660 }
frame not found:  { type: 'WINDOW_UPDATE', id: 7, delta: 66320 }
frame not found:  { type: 'WINDOW_UPDATE', id: 9, delta: 66320 }
frame not found:  { type: 'WINDOW_UPDATE', id: 9, delta: 65660 }
frame not found:  { type: 'WINDOW_UPDATE', id: 9, delta: 66320 }
...
Looking through Firefox's HTTP log, it seems that Firefox is sending those WINDOW_UPDATE frames as it receives DATA frames. Where node-spdy sees the WINDOW_UPDATE frames after the DATA FIN, Firefox sees them before.

I have the feeling that my simple flow control buffer in node-spdy may be too simple. I will investigate that another night. Before calling it a night tonight, I make the localhost network interface (lo) a little more realistic with traffic control:
sudo tc qdisc add dev lo root netem delay 50ms
The hope is that perhaps the unrealistic testing on the loopback interface is somehow producing these weird results.

It is not.

I see the exact same number of WINDOW_UPDATE frames from Firefox even with a more realistic RTT in effect. Ah well, even eliminating the obvious solution is helpful sometimes.

I will pick back up tomorrow investigating the apparent discrepancy between when node-spdy sends DATA frames and when Firefox receives them.

UPDATE: I have updated the code on https://test.spdybook.com:3000/ to use this recent version of node-spdy in case anyone is interested in trying it. The certificate for that site is invalid, but is pulled from node-spdy if you want to decrypt the packets: https://github.com/indutny/node-spdy/tree/master/keys.

Day #387

Friday, May 11, 2012

Firefox SPDY/3

‹prev | My Chain | next›

For obvious reasons, I have done most of my SPDY experimentation in the Chrome browser. That has continued to be the case as I have explored flow control in the latest version 3 of the protocol specification.

As I found out the other night, not only is Chrome not the only game in SPDY town, but it may not even lay claim to the best tool for debugging SPDY implementations. Despite this, I have been exploring spdy/3 exclusively with Chrome because Firefox only supports spdy/2.

It turns out that the Firefox nightlies actually include experimental spdy/3. So tonight, I hope to kick the tires on Firefox spdy/3.

I start by downloading a recent build from the esteemed Patrick McManus:
➜  Downloads  wget https://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/mcmanus@ducksong.com-a695632fc51a/try-linux64/firefox-15.0a1.en-US.linux-x86_64.tar.bz2
I don't know if this is Patrick or Mozilla, but in the same FTP directory is a list of checksums for each download. That should be more common than it is—I hate running software without a simple way to double check that it has not been altered. To be sure, it is no guarantee, but it gives me some piece of mind.

Anyhow, I check the SHA512 signature:
➜  Downloads  sha512sum firefox-15.0a1.en-US.linux-x86_64.tar.bz2 
073fbf9827b120b4bc313553683ef2c8cee719d154fd2670b2380078c284c16ab97e6223619620e98dccfb76328415587a26bdff302f19571834fa8d382c8d33  firefox-15.0a1.en-US.linux-x86_64.tar.bz2
Indeed, that is the signature on the FTP server, so I proceed.

I extract the build into my $HOME/src directory:
➜  src  tar jxf ~/Downloads/firefox-15.0a1.en-US.linux-x86_64.tar.bz2
And fire up Firefox:
➜  firefox  ./firefox
I am greeted with an add-ons update dialog:


And eventually the start screen:


So I appear to be running the latest and greatest. Nice!

Next up, I hit my simple express.js test app that is powered by node-spdy and... it works:


Of course, I have no idea if that is spdy/3 (or even spdy/2). I could try installing one of the extensions that tells me if SPDY is being used, but it is more fun to use Firefox's awesome logging facilities. So I shut down the browser and re-run with the usual logging environment options:
➜  firefox  export NSPR_LOG_MODULES=nsHttp:5,nsSocketTransport:5,nsHostResolver:5
➜  firefox  export NSPR_LOG_FILE=/tmp/log.txt                                    
➜  firefox  ./firefox
In /tmp/log.txt, I see that it is, indeed, using spdy/3:
...
351270656[7fef27440e10]: nsHttpConnection::EnsureNPNComplete 7feefdae2200 negotiated to 'spdy/3'
...
Unfortunately, the page is not quite loading:


Only one of the images is only partially loaded. I do not know how the page loaded previously. My guess would be that Firefox had ignored SPDY, making an SSL connection instead. That or I had previously cached those images. At any rate, it is not working now, so...

To the log files!

I actually do not see any information in the log file about Firefox sending WINDOW_UPDATE frames to facilitate flow control. I would guess that it is because there seem to be a lot of DATA frames from both images in the log. In the end, I see what looks like an error:
...
nsHttpTransaction::ProcessData [this=3313fe30 count=1300]
nsHttpTransaction::HandleContent [this=3313fe30 count=1300]
nsHttpTransaction::HandleContent [this=3313fe30 count=1300 read=1300 mContentRead=185940 mContentLength=-1]
nsSocketInputStream::Read [this=32eda2f0 count=8]
  calling PR_Read [count=8]
nsHttpChannel::OnDataAvailable [this=7f9c4618b800 request=7f9c381ae5c0 offset=184640 count=1300]
sending status notification [this=7f9c4618b800 status=804b0006 progress=185940/18446744073709551615]
  PR_Read returned [n=-1]
ErrorAccordingToNSPR [in=-5961 out=804b0014]
nsSocketTransport::OnMsgInputClosed [this=32eda1c0 reason=804b0014]
SpdySession3 7f9c37936000 buffering frame header read failure 804b0014
nsHttpConnection::CloseTransaction[this=3311e020 trans=37936000 reason=804b0014]
SpdySession3::Close 7f9c37936000 804B0014
...
I troubleshoot this in node-spdy, scattering console.log() statements about in a vain search for WINDOW_UPDATE frames. I never see a single WINDOW_UPDATE from Firefox. Unless Firefox is completely ignoring the spdy/3 spec, the only way that I can see this being possible is if Firefox begins the SPDY conversation by setting an impossibly high initial window size.

So I log this value:
Connection.prototype.setDefaultTransferWindow = function(settings) {
  if (settings.initial_window_size) {
    console.log("settings.initial_window_size: " + settings.initial_window_size);
    this.transferWindowSize = settings.initial_window_size;
    // ...
  }
};
And, sure enough, in response to a Firefox connection, node-spdy sees:
settings.initial_window_size: 268435456
I have spent most of my time in flow control looking at smaller receive windows, not large ones. So I am unsure if the fault here lies with node-spdy or Firefox.

I will continue investigating tomorrow.


Day #383

Friday, July 15, 2011

Firefox Pipelining is Silly

‹prev | My Chain | next›

After a couple of days investigation, I realized that my experiment with pipelining in Firefox was actually perfectly crafted. Perfectly crafted for failure, that is.

My pipeline.html page referenced 10 images, each around 150 kb in size. I had hypothesized that, after loading a start page, Firefox would attempt to load pipeline.html and all 10 images in the same pipeline. I was wrong. After loading pipeline.html, Firefox downloaded 6 of the images in 6 different interweb tubes (all modern browser have 6 interweb tubes to load resources in parallel). When the first of those images completed, Firefox then proceeded to download the next 4 images over a single tube.

Given that those next 4 images, pipelined or not, were 600 kb in total, it took nearly a full second to download them over a single tube. Ultimately, pipelining was a significant loser over just using the normal 6 tubes.

I am unsure why Firefox choose this strategy. It already knows that the server can handle HTTP/1.1, why not try pipelining right away? Maybe it wants to ensure that it loads enough data to appear responsive before attempting something out of the norm?

If that is the case, then once Firefox knows that the server supports HTTP pipelining, surely it will use pipelining for all subsequent requests. Using a single tube will allow its TCP/IP congestion window (CWND) to quickly grow to a healthy maximum between the client and server since it would not have to compete with 5 other tubes. Large CWND means more data for each round trip, which means fewer round trips, which means speed (this is why SPDY uses a single tube for everything).

To test this hypothesis, I use a third page after pipeline.html. On this third page, I use smaller images (~10 kb each) to better represent normal web pages. Clicking on this page after pipeline.html should re-use the HTTP tube that ended up pipelining the last four images in pipeline.html.

After restarting Firefox and clearing my cache, I access the start page, the pipeline page and my new page (a hello world from SPDY Book). Checking things out with Wireshark, I find that the same four images from pipeline.html are still pipelined:



But, when I access the next page, Firefox goes back to its old ways. Specifically, it tosses all CWND goodness from the previously pipelined tube and makes 6 different connections on 6 different tubes:



When the first of those images are downloaded, Firefox again starts pipelining. The remaining 5 images from the final page are then loaded on the same tube.



That seems like a terrible strategy. First create 6 tubes that compete with each other for full access to the bandwidth between client and server, which does not allow any to quickly increase the CWND. Then pick one tube and ramp it up with a burst of data. With that tube properly warmed, then ditch it to use the other 5 tubes again, some of which may not be warmed enough to transfer data very fast. What's worse is that, because those 6 tubes are again competing with each other, the CWND may decrease because there is congestion going on. And finally, switch back to pipelining now that the 6 tubes are just getting warmed up.

Maybe there is some reason to this seeming madness. If so, I will try to dig it up tomorrow. For now, back to putting that hello world page to good use—in SPDY Book!


Day #74

Thursday, July 14, 2011

Firefox Pipelining: Be Afraid

‹prev | My Chain | next›

Continuing my adventures with Firefox and HTTP/1.1 pipelining (a partial SPDY competitor), I begin analysis of the sessions that I have captured the past couple of nights.

Last night, I was finally able to get pipelining working in Firefox (or at least confirm that I had it working). My test page contains:
<p><img src="pipeline01.png"/></p>
<p><img src="pipeline02.png"/></p>
<p><img src="pipeline03.png"/></p>
<p><img src="pipeline04.png"/></p>
<p><img src="pipeline05.png"/></p>
<p><img src="pipeline06.png"/></p>
<p><img src="pipeline07.png"/></p>
<p><img src="pipeline08.png"/></p>
<p><img src="pipeline09.png"/></p>
<p><img src="pipeline10.png"/></p>
Each of those images are ~150kb. That's more than a typical web image ought to be, but it ought to really push pipelining and TCP/IP congestion window (CWND) through their respective paces. So let's have a look-see.

The tcptrace tool serves the dual purpose of identifying the most heavily used TCP/IP pipes (in bold below) and generating xplot graphs:
➜  14 git:(master) tcptrace -S -n -zx -zy  ../13/firefox_pipeline.pcap
1 arg remaining, starting with '../13/firefox_pipeline.pcap'
Ostermann's tcptrace -- version 6.6.7 -- Thu Nov 4, 2004

240 packets seen, 240 TCP packets traced
elapsed wallclock time: 0:00:00.033535, 7156 pkts/sec analyzed
trace file elapsed time: 0:01:29.060533
TCP connection info:
1: :0001:60110 - :0001:80 (a2b) 1> 1< (reset)
2: 127.0.0.1:48979 - 127.0.0.1:80 (c2d) 12> 8< (complete)
3: :0001:49647 - :0001:80 (e2f) 1> 1< (reset)
4: 127.0.0.1:55785 - 127.0.0.1:80 (g2h) 33> 36< (complete)
5: :0001:49649 - :0001:80 (i2j) 1> 1< (reset)
6: :0001:49650 - :0001:80 (k2l) 1> 1< (reset)
7: :0001:49651 - :0001:80 (m2n) 1> 1< (reset)
8: :0001:49652 - :0001:80 (o2p) 1> 1< (reset)
9: :0001:49653 - :0001:80 (q2r) 1> 1< (reset)
10: 127.0.0.1:55791 - 127.0.0.1:80 (s2t) 13> 13< (complete)
11: 127.0.0.1:55792 - 127.0.0.1:80 (u2v) 13> 13< (complete)
12: 127.0.0.1:55793 - 127.0.0.1:80 (w2x) 12> 13< (complete)
13: 127.0.0.1:55794 - 127.0.0.1:80 (y2z) 12> 13< (complete)
14: 127.0.0.1:55795 - 127.0.0.1:80 (aa2ab) 12> 13< (complete)
15: 127.0.0.1:55796 - 127.0.0.1:80 (ac2ad) 6> 4< (complete) (reset)
The pipe with the most activity, designated g2h by tcptrace, is the one that pipelined the last four requests (for pipeline07.png, pipeline08.png, pipeline09.png, and pipeline10.png) into a single request. Checking the plot of those packets, I find:


(the distance between the segments comes from a 100ms round trip time)

Looking at that graph, two things stick out for me: (1) it takes a long time to transfer all of that data (well over a second) and (2) the CWND (blue bar at the top) is quite variable. With regards to the CWND in (2), I am used to seeing a CWND grow relatively steadily as the interweb tube warms (a.k.a. TCP/IP slow start kicks in) when using SPDY. That is clearly not happening here. At points, the CWND shrinks, limiting the amount of data that can be transferred before waiting until the next trip. That ultimately adds time to the transfer.

But I don't think that explains the full delay. Looking at a similar diagram from a non-pipelined Firefox request (from two nights ago prior to enabling pipelining), I find:



There is similar choppiness in the CWND, but... ah wait. I see that I do not have a direct comparison. The non-pipelined session had a only a little more than 30,000 TCP/IP sequences. The pipelined request saw 80,000. Zooming in on the first 30,000 sequences of the pipelined session, I see:



That is almost identical to the non-pipelined version. Both have about the same choppiness and take ~600ms to run through the same number of sequences. That is to be expected, after all they are both non-pipelined up until this point. So it seems that everything is more or less OK until pipelining kicks.

When HTTP pipelining does start, it has a negative impact. By the time the pipelining session kicks in, the 6 TCP/IP tubes are still warming up and likely competing with each other for resources. The single tube that gets the pipeline is also still warming. Slamming it with 4 150kb images only helps so much with the CWND (again, possibly due to the other 5 open sessions). The end result is that pipelining is a big loser—almost doubling the time needed to serve up the page. Serving those 4 images over 4 different tubes would have been a better choice in this case.

I suppose edge cases like this (150 kb images) are why Firefox does not have pipelining on by default. I think tomorrow I will investigate a more realistic web case to see how the results change. Regardless, single tube SPDY connections will certainly handle something like this. That's something to prove another day as well.

Day #73

Wednesday, July 13, 2011

Firefox Pipelined!

‹prev | My Chain | next›

Last night I unsuccessfully tried to explore HTTP pipelining in Firefox. Pipelining, the sending multiple requests before the web server has replied to the first request, is major feature of SPDY. Pipelining is actually a feature of HTTP/1.1 only no one supports it.

That's not 100% true. Opera supports it, though only under certain circumstances. Currently Firefox only supports it with an about:config change. Still, there is active work with pipelining ongoing in Firefox so it seemed worth checking out.

Except it did not work.

That seemed crazy to me. There are all sort of discussions about Firefox and pipelining to be found. How could it simply not work?

So I did a bit more research and finally read the second sentence of the fifth paragraph in Mozilla's HTTP/1.1 Pipelining FAQ:
We also should not pipeline requests on a new connection, since it has not yet been determined if the origin server (or proxy) supports HTTP/1.1. Hence, pipelining can only be done when reusing an existing keep-alive connection.
Aaahh...

That's not quite how RFC 2616 reads:
Clients which assume persistent connections and pipeline immediately after connection establishment SHOULD be prepared to retry their connection if the first pipelined attempt fails.
But what the hey? I can still test that.

I create a pre-pipelining page. After accessing pre-pipeline.html and then waiting for a 5-count, a subsequent request of pipeline.html should pipeline that resource and everything referenced inside:
<p><img src="pipeline01.png"/></p>
<p><img src="pipeline02.png"/></p>
<p><img src="pipeline03.png"/></p>
<p><img src="pipeline04.png"/></p>
<p><img src="pipeline05.png"/></p>
<p><img src="pipeline06.png"/></p>
<p><img src="pipeline07.png"/></p>
<p><img src="pipeline08.png"/></p>
<p><img src="pipeline09.png"/></p>
<p><img src="pipeline10.png"/></p>
They should be pipelined, only they are not. Firefox requests pipeline01.png only after the server's response for pipeline.html is complete as seen in Wireshark:



And the requests for pipeline02.png - pipeline06.png go out on separate interweb tubes (as evidenced by the ACKs to different ports):



Finally, Firefox does not issue a request for pipeline07.png until it has fully received one of the other images:


(The response is complete at the top, followed by additional packets for the other 5 images in transit, and finally the request for pipeline07.png is at the bottom)

Presumably it does the same for pipeline08.png, pipeline09.png, and pipeline10.png as well. Except...

I cannot find those requests. I examine each of the packets after the request for pipeline07.png individually. Twice. And do not see the requests for any of those images.

Eventually, I look closer a the request for pipeline07.png... And notice the request for pipeline08.png right next to it in the same packet! Scrolling through the contents of the packet I see a GET for pipeline07.png all the way through pipeline10.png:



So Firefox does pipeline after all. It just takes a really long time for it to kick-in. Well that's not exactly competing with SPDY for fast page load times, but it should definitely help subsequent resource loads.

I will pick back up tomorrow by analyzing the eventual-pipelined stream. For now, I'm off to write some more of SPDY Book!

Day #72

Tuesday, July 12, 2011

Firefox Pipelined?

‹prev | My Chain | next›

Due to time constraints related to my impending deadline for SPDY Book, I need to move from exploring alternative protocols to SPDY to alternative approaches.

A major feature of SPDY is pipelining—using a single interweb tube for all communication. Non-pipelined HTTP requests block an HTTP tube until the server completes sending a response. Only once the entire response has been sent can a second HTTP request go out. As you can imagine, this is terribly inefficient. All major browsers get around this by opening not one, but 6 interweb tubes to a single web server. But even those tubes block waiting on responses, which means that, if you need more than 6 resources, something is going to block.

It turns out that HTTP/1.1 actually has pipelining built in—only you wouldn't know it based on browser support. Opera is rumored to support it in certain, unrealistic edge cases, but that is it. Except...

Firefox supports it through an about:config setting.

But first, I create a dummy pipeline.html that loads in 10 pipelineXX.png images:
<p><img src="pipeline01.png"/></p>
<p><img src="pipeline02.png"/></p>
<p><img src="pipeline03.png"/></p>
<p><img src="pipeline04.png"/></p>
<p><img src="pipeline05.png"/></p>
<p><img src="pipeline06.png"/></p>
<p><img src="pipeline07.png"/></p>
<p><img src="pipeline08.png"/></p>
<p><img src="pipeline09.png"/></p>
<p><img src="pipeline10.png"/></p>
The images themselves are on the large side:
➜  www  ls -lh pipeline*
-rw-r--r-- 1 root root 157K 2011-07-12 23:06 pipeline01.png
-rw-r--r-- 1 root root 157K 2011-07-12 23:06 pipeline02.png
-rw-r--r-- 1 root root 157K 2011-07-12 23:06 pipeline03.png
-rw-r--r-- 1 root root 157K 2011-07-12 23:06 pipeline04.png
-rw-r--r-- 1 root root 157K 2011-07-12 23:06 pipeline05.png
-rw-r--r-- 1 root root 157K 2011-07-12 23:06 pipeline06.png
-rw-r--r-- 1 root root 157K 2011-07-12 23:07 pipeline07.png
-rw-r--r-- 1 root root 157K 2011-07-12 23:07 pipeline08.png
-rw-r--r-- 1 root root 157K 2011-07-12 23:07 pipeline09.png
-rw-r--r-- 1 root root 157K 2011-07-12 23:07 pipeline10.png
-rw-r--r-- 1 cstrom cstrom 351 2011-07-12 23:05 pipeline.html
To get a somewhat real-world feel for the interaction, I add a 50ms delay on my local network device:
➜  www  ping localhost
PING localhost.localdomain (127.0.0.1) 56(84) bytes of data.
64 bytes from localhost.localdomain (127.0.0.1): icmp_req=1 ttl=64 time=0.051 ms
64 bytes from localhost.localdomain (127.0.0.1): icmp_req=2 ttl=64 time=0.022 ms
^C
--- localhost.localdomain ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 999ms
rtt min/avg/max/mdev = 0.022/0.036/0.051/0.015 ms
➜ www sudo tc qdisc add dev lo root netem delay 50ms
➜ www ping localhost
PING localhost.localdomain (127.0.0.1) 56(84) bytes of data.
64 bytes from localhost.localdomain (127.0.0.1): icmp_req=1 ttl=64 time=100 ms
64 bytes from localhost.localdomain (127.0.0.1): icmp_req=2 ttl=64 time=100 ms
64 bytes from localhost.localdomain (127.0.0.1): icmp_req=3 ttl=64 time=100 ms
^C
--- localhost.localdomain ping statistics ---
3 packets transmitted, 3 received, 0% packet loss, time 2002ms
rtt min/avg/max/mdev = 100.164/100.197/100.226/0.025 ms
I load the page up in Firefox and capture all of the traffic in Wireshark. I save the filtered tcp.port == 80 traffic into a pcap which I analyze with tcptrace:
➜  not_pipelined git:(master) ✗ tcptrace -S -n -zx -zy  ../firefox_not_pipelined.pcap 
1 arg remaining, starting with '../firefox_not_pipelined.pcap'
Ostermann's tcptrace -- version 6.6.7 -- Thu Nov 4, 2004

246 packets seen, 246 TCP packets traced
elapsed wallclock time: 0:00:00.024607, 9997 pkts/sec analyzed
trace file elapsed time: 0:00:17.608415
TCP connection info:
1: :0001:58463 - :0001:80 (a2b) 1> 1< (reset)
2: 127.0.0.1:54606 - 127.0.0.1:80 (c2d) 21> 23< (complete)
3: :0001:58465 - :0001:80 (e2f) 1> 1< (reset)
4: :0001:58466 - :0001:80 (g2h) 1> 1< (reset)
5: :0001:58467 - :0001:80 (i2j) 1> 1< (reset)
6: :0001:58468 - :0001:80 (k2l) 1> 1< (reset)
7: :0001:58469 - :0001:80 (m2n) 1> 1< (reset)
8: 127.0.0.1:54612 - 127.0.0.1:80 (o2p) 15> 14< (complete)
9: 127.0.0.1:54613 - 127.0.0.1:80 (q2r) 15> 15< (complete)
10: 127.0.0.1:54614 - 127.0.0.1:80 (s2t) 16> 21< (complete)
11: 127.0.0.1:54615 - 127.0.0.1:80 (u2v) 16> 21< (complete)
12: 127.0.0.1:54616 - 127.0.0.1:80 (w2x) 16> 21< (complete)
13: 127.0.0.1:54617 - 127.0.0.1:80 (y2z) 6> 4< (complete) (reset)
14: 127.0.0.1:54618 - 127.0.0.1:80 (aa2ab) 6> 4< (complete) (reset)
Perfect. I do not even need to look at the graphs to see that all 6 interweb tubes were in action here (tubes with more than 4 response packets).

To enable pipelining in Firefox, I enter about:config in the address bar:



The default pipelining settings are:



I enable pipelining and set the maximum number of requests to 8:



I believe that 8 is the recommended number of max-requests.

I clear the browser cache, an re-request the pipeline page. Looking at the output with tcptrace, I see no change:
➜  pipelined git:(master) ✗ tcptrace -S -n -zx -zy  ../firefox_pipelined.pcap    
1 arg remaining, starting with '../firefox_pipelined.pcap'
Ostermann's tcptrace -- version 6.6.7 -- Thu Nov 4, 2004

223 packets seen, 223 TCP packets traced
elapsed wallclock time: 0:00:00.027996, 7965 pkts/sec analyzed
trace file elapsed time: 0:00:18.368731
TCP connection info:
1: :0001:47563 - :0001:80 (a2b) 1> 1< (reset)
2: 127.0.0.1:39393 - 127.0.0.1:80 (c2d) 32> 37< (complete)
3: :0001:47565 - :0001:80 (e2f) 1> 1< (reset)
4: :0001:47566 - :0001:80 (g2h) 1> 1< (reset)
5: :0001:47567 - :0001:80 (i2j) 1> 1< (reset)
6: :0001:47568 - :0001:80 (k2l) 1> 1< (reset)
7: :0001:47569 - :0001:80 (m2n) 1> 1< (reset)
8: 127.0.0.1:39399 - 127.0.0.1:80 (o2p) 13> 14< (complete)
9: 127.0.0.1:39400 - 127.0.0.1:80 (q2r) 13> 14< (complete)
10: 127.0.0.1:39401 - 127.0.0.1:80 (s2t) 13> 14< (complete)
11: 127.0.0.1:39402 - 127.0.0.1:80 (u2v) 13> 13< (complete)
12: 127.0.0.1:39403 - 127.0.0.1:80 (w2x) 13> 12< (complete)
13: 127.0.0.1:39404 - 127.0.0.1:80 (y2z) 6> 4< (complete) (reset)
Dang it. All 6 interweb tubes are still in use.

Checking it out in Wireshark, it really seems like nothing has changed. The browser still waits until it is done processing pipeline02.png before requesting pipeline07.png:



Hrm... I'm at a bit of a loss. Maybe Firefox 5's pipelined support is lacking or maybe I am just missing something. I'll see if I can figure out which is the case. Tomorrow.


Day #72

Thursday, June 30, 2011

Firefox CWND

‹prev | My Chain | next›

Up today, I release the beta version of SPDY Book! But the gods of my chain must first be appeased. Today is not the day to draw their ire.

So I take a break from my recent deep-in-the-bowels coding of node-spdy to play a bit with, of all things, Firefox. The latest version of Firefox boasts sorting of open HTTP pipes by TCP/IP congestion window (CWND). The CWND is the amount of data a TCP/IP connection will accept before an acknowledgement is sent. The CWND starts small, but increases quickly as the TCP/IP tubes are warmed by fresh data flowing through them.

Browsers open up 6 TCP/IP connections to a server. Sorting them by CWND does not address nearly the breadth of what SPDY is meant for, but it still might be a nice performance boost.

The test page put out by Patrick McManus includes 2 very large images and several smaller images. Loading this page should open up two interweb tubes for the large images and several other tubes for the small images.

By the the time the page is done loading the large images, the two tubes used to download those images should have very large CWNDs. The tubes that transport only tiny images will not have enough data flow through them to warm them (and increase their CWNDs). If Firefox truly does sort tubes by CWND, another click on the site should use one of those tubes.

To the Wiresharks!

I am only interested in which tubes are used for which HTTP requests, so I use Wireshark filters to only show packets with HTTP requests or responses in them. I then move through each tube (Wireshark calls them streams for some reason) in turn increasing the tube in in the filter expression: "(http.request or http.response) and tcp.stream eq 0".

The first tube contains, as expected the web page itself and one of the small images:



The second tube contains just a small image:



The third tube also holds only a small image.

On the fourth tube, I hit the jackpot:



It is the tube that downloaded the first large image and, as promised, it is also used by Firefox to download the secondary request that I made (a PNG) after the homepage and big images had finished loading.

Nice! That is a clever little change from the Firefox devs that did not require much code change, does not muck with TCP/IP, but ought to give users a nice performance boost. Kudos Firefox devs!

Day #62