777354 - Regression in shutdown time of httpd.js (~6s) when multiple local pages have been opened

Status: RESOLVED FIXED

(Testing :: General, defect)

Description

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Over on bug 767332 I have noticed that at some point in the past we have introduced a big regression range in shutting down httpd.js. I did some time measurements with the Mozmill test attached to the before mentioned bug and a Nightly and Release build, whereby the latter behaves correctly.

Nightly:

TEST-START | testHTTPd1.js | setupModule
TEST-START | testHTTPd1.js | testOpenLocalPages
TEST-PASS | testHTTPd1.js | testOpenLocalPages
INFO | ** Shutdown duration: 5617
TEST-START | testHTTPd2.js | setupModule
TEST-START | testHTTPd2.js | testHttpFailure
TEST-PASS | testHTTPd2.js | testHttpFailure
TEST-START | testHTTPd2.js | teardownModule
INFO | ** Shutdown duration: 96

Release (14.0)
TEST-START | testHTTPd1.js | setupModule
TEST-START | testHTTPd1.js | testOpenLocalPages
TEST-PASS | testHTTPd1.js | testOpenLocalPages
INFO | ** Shutdown duration: 100
TEST-START | testHTTPd2.js | setupModule
TEST-START | testHTTPd2.js | testHttpFailure
TEST-PASS | testHTTPd2.js | testHttpFailure
TEST-START | testHTTPd2.js | teardownModule
INFO | ** Shutdown duration: 97

I will have to check for the regression range and hope that we can fix that before the current beta gets merged to release.

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+1]]

This is a huge regression somewhere in the core or httpd.js code which causes our Mozmill tests to execute absolutely slow. After nearly each single test we can expect a delay of 5-6s.

If QA should still be up in signing off from any kind of release or build, we have to get this fixed. Asking for tracking the affected branches.

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Regression range matches the one from bug 767332, which regressed on mozilla-central between the builds 2012-04-25-03-06-47 and 2012-04-26-03-05-04.

PASS: http://hg.mozilla.org/mozilla-central/rev/75c7378c87b6
FAIL: http://hg.mozilla.org/mozilla-central/rev/cc5254f9825f

Pushlog:
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=75c7378c87b6&tochange=cc5254f9825f

Looks like I should do a hg bisect to find the causing changeset.

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+1]]

The first bad revision is:
changeset:   92418:c773ee0f0245
user:        Patrick McManus <[e-mail]>
date:        Wed Apr 25 08:54:42 2012 -0400
summary:     bug 729133 - internal necko speculative connections r=honzab

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+1]]

So steps to reproduce:

1. Create a virtual env and install mozmill: 'pip install mozmill'
2. Clone https://github.com/mozilla/mozmill
3. Run: mozmill -b %path_to_firefox% -m mutt/mutt/tests/js/frame/httpd/tests.ini

Notice the long delay after 'TEST-PASS | testHTTPd1.js | testOpenLocalPages'.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Attachment: HTTP log

Comment 6

[Lukas Blakk [:lsblakk] use ?needinfo]

Adding qawanted and regression-window wanted - yes, let's get on this while we're still in Beta and identify the problem here.

Comment 7

[Patrick McManus [:mcmanus]]

henrik already indicated the changeset that triggers the bug is the speculative connection code in necko.

but the bug is in the server not shutting down based on the new idle connection, not the new code. The idle connection is an expected artifact of the feature.

Comment 8

[Henrik Skupin [:whimboo][⌚️UTC+1]]

(In reply to Lukas Blakk [:lsblakk] from comment #6)
> Adding qawanted and regression-window wanted - yes, let's get on this while
> we're still in Beta and identify the problem here.

Not sure QA or I can do anything more on it.

(In reply to Patrick McManus [:mcmanus] from comment #7)
> but the bug is in the server not shutting down based on the new idle
> connection, not the new code. The idle connection is an expected artifact of
> the feature.

So how should this be solved? Is it part of the httpd.js code or is a core fix necessary? If the first, should the connection be hard-killed by getting rid of the existent idle connection? Or what would be the right behavior of the server? Shall we move it back to testing/httpd.js?

Comment 9

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Ed, are you aware of any slowdowns when running our in-tree tests with mochitest and others? I just would like to know how wide-spread this issue is and how much does it affect us in testing.

Comment 10

[Ed Morley [:emorley]]

Unfortunately much of the slowdowns I notice are in total end-to-end time, which are dependant on pending time + build time + test run time + setup/cleanup inbetween. These vary significantly by time of day and by week-to-week infra issues, so it's hard to notice regressions like this.

I would say to look a the GoFaster dashboard (http://brasstacks.mozilla.com/gofaster/#/executiontime/test?range=all&include_outliers=0), but it only goes back as far as June.

Believe catlee has helped espindola answer end-to-end time questions recently, so might be able to advise further; CCing.

Comment 11

[Henrik Skupin [:whimboo][⌚️UTC+1]]

(In reply to Ed Morley [:edmorley] from comment #10)
> Unfortunately much of the slowdowns I notice are in total end-to-end time,
> which are dependant on pending time + build time + test run time +
> setup/cleanup inbetween. These vary significantly by time of day and by
> week-to-week infra issues, so it's hard to notice regressions like this.

Wait. Probably other frameworks are not affected because they don't shutdown httpd.js after each test. So please scratch that idea.

Comment 12

[Patrick McManus [:mcmanus]]

This is a problem in httpd.js, which won't shut itself down when it has an open client connection. I don't know all that much about how httpd.js is more widely used, but presumably some users call stop() to stop accepting new connections and want to kindly wind down the ones underway.

onStopListening: function(socket, status)
  {
    dumpn(">>> shutting down server on port " + socket.port);
    this._socketClosed = true;
    if (!this._hasOpenConnections())
    {
      dumpn("*** no open connections, notifying async from onStopListening");


I guess the easiest thing to do if you don't want that behavior is to add a reap() function to nsIHttpServer that closes open connections.

Comment 13

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Thanks Patrick. I will try if I can get it working with Mozmill. If it does it's hopefully easy to port forward to the original implementation under network/test/.

Lets move it back to the httpd.js component then.

Comment 14

[Patrick McManus [:mcmanus]]

another approach would be something like this (completely untested and undebugged!) - to automagically close any socket that hadn't seen at least a request line at the time of stop().. this has the advantage that the calling code doesn't need to call reap() to make the right thing happen.

hth

diff --git a/netwerk/test/httpserver/httpd.js b/netwerk/test/httpserver/httpd.js
--- a/netwerk/test/httpserver/httpd.js
+++ b/netwerk/test/httpserver/httpd.js
@@ -467,16 +467,24 @@ nsHttpServer.prototype =
    *   the reason the socket stopped listening (NS_BINDING_ABORTED if the server
    *   was stopped using nsIHttpServer.stop)
    * @see nsIServerSocketListener.onStopListening
    */
   onStopListening: function(socket, status)
   {
     dumpn(">>> shutting down server on port " + socket.port);
     this._socketClosed = true;
+    for (var n in this._connections) {
+      if (!n._requestStarted)
+          n.close();
+    }
+
     if (!this._hasOpenConnections())
     {
       dumpn("*** no open connections, notifying async from onStopListening");
 
       // Notify asynchronously so that any pending teardown in stop() has a
       // chance to run first.
       var self = this;
       var stopEvent =
@@ -1127,16 +1135,19 @@ function Connection(input, output, serve
   /**
    * The request for which a response is being generated, null if the
    * incoming request has not been fully received or if it had errors.
    */
   this.request = null;
 
   /** State variables for debugging. */
   this._closed = this._processed = false;
+
+  /** whether or not 1st line of request has been received */
+  this._requestStarted = false; 
 }
 Connection.prototype =
 {
   /** Closes this connection's input/output streams. */
   close: function()
   {
     dumpn("*** closing connection " + this.number +
           " on port " + this._outgoingPort);
@@ -1190,16 +1201,21 @@ Connection.prototype =
   },
 
   /** Converts this to a string for debugging purposes. */
   toString: function()
   {
     return "<Connection(" + this.number +
            (this.request ? ", " + this.request.path : "") +"): " +
            (this._closed ? "closed" : "open") + ">";
+  },
+
+  requestStarted: function()
+  {
+      this._requestStarted = true;
   }
 };
 
 
 
 /** Returns an array of count bytes from the given input stream. */
 function readBytes(inputStream, count)
 {
@@ -1376,16 +1392,17 @@ RequestReader.prototype =
     if (!readSuccess)
       return false;
 
     // we have the first non-blank line
     try
     {
       this._parseRequestLine(line.value);
       this._state = READER_IN_HEADERS;
+      this._connection.requestStarted();
       return true;
     }
     catch (e)
     {
       this._handleError(e);
       return false;
     }

Comment 15

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Attachment: WIP

Something along those lines? Works at least for me but not sure if it is the right way to close all the open connections. Not sure whom I should ask for feedback given that Jeff is out right now. Patrick, would you mind to have a look at? The patch doesn't include any tests yet.

Comment 16

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Hm, haven't seen the latest comment. So this WIP implements the formerly proposed solution.

Comment 17

[Patrick McManus [:mcmanus]]

Comment on attachment 646141 [details] [diff] [review]
WIP

the problem here is that it shuts down already established connections that are maybe actively doing something. Jeff wrote a bunch of code to make that happen, so presumably something is using it.

so I think the approach in comment 14 works better.. if you want to go with reap it probly needs to be called from mozmill, not internal to httpd.js

but I'm not an httpd.js expert :)

Comment 18

[Alex Keybl [:akeybl]]

Untracking based upon Comment 7.

Comment 19

[cmtalbert]

(In reply to Henrik Skupin (:whimboo) [away 07/27 - 08/05] from comment #11)
> (In reply to Ed Morley [:edmorley] from comment #10)
> > Unfortunately much of the slowdowns I notice are in total end-to-end time,
> > which are dependant on pending time + build time + test run time +
> > setup/cleanup inbetween. These vary significantly by time of day and by
> > week-to-week infra issues, so it's hard to notice regressions like this.
> 
> Wait. Probably other frameworks are not affected because they don't shutdown
> httpd.js after each test. So please scratch that idea.

Quick drive by comment - fwiw, both reftest and xpcshell start up httpd.js on demand like mozmill does.

Comment 20

[Honza Bambas (:mayhemer)]

As I understand, this is caused by the 250ms syn-retry, right?  We could then turn the syn-retry pref off for xpcshell tests.  Any test depending on it, like the test for that feature it self, should explicitly change the pref and then clean it up.

Comment 21

[Patrick McManus [:mcmanus]]

it could also be some form of speculative connect. In generally we'll be doing more of this stuff by default, and we should test in the default config if at all possible.. so imo fixing the server is preferrable (and I think pretty easy).

Comment 22

[Henrik Skupin [:whimboo][⌚️UTC+1]]

It's probably worth to wait until Jeff Walden is back. I will hold of with other patches for now and await his feedback.

Comment 23

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Jeff, would you mind to give us some feedback on how we should proceed here? Thanks!

Comment 24

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Re-ping again. Jeff Walden, it would be really great to get feedback from you. This bug is causing a massive slowdown of our Mozmill tests execution, which I want to see fixed.

Comment 25

[Jeff Walden [:Waldo]]

Sigh, been juggling too many browser profiles, this tab got dropped in one I haven't opened recently.  Looking now...

Comment 26

[Jeff Walden [:Waldo]]

I don't think it's acceptable for stopping the server to kill in-progress connections by default.  The approach in comment 14 is about as far as I think we might, maybe, reasonably go in the server itself in a way that would affect all httpd.js users unavoidably.  A separate reap() or whatever that clients could call if they wanted wouldn't be a bad idea, either.  It's just something people should have to make an affirmative effort to use -- connections once made successfully, with data transmitted, shouldn't be closed of the server's own volition.

Comment 27

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Comment on attachment 646141 [details] [diff] [review]
WIP

Sounds like a good approach. Jeff, would you have time to work on this? I'm totally loaded with WebRTC and B2G tests at the moment.

Comment 28

[Henrik Skupin [:whimboo][⌚️UTC+1]]

(In reply to Henrik Skupin (:whimboo) from comment #27)
> Sounds like a good approach. Jeff, would you have time to work on this? I'm
> totally loaded with WebRTC and B2G tests at the moment.

Re-ping a month later. Would you be able to help us?

Comment 29

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Jeff, can we please get feedback from you? I requested the needinfo flag a half month ago. Thanks!

Comment 30

[Jeff Walden [:Waldo]]

...given I haven't had time to get to this in that time, I think it's pretty clear the answer's going to have to be no.  :-\

I can answer questions from people who have them, but I have some pretty pressing JS work that needs doing well before I could possibly get to this on my own time.

Comment 31

[Henrik Skupin [:whimboo][⌚️UTC+1]]

(In reply to Jeff Walden [:Waldo] (remove +bmo to email) from comment #30)
> I can answer questions from people who have them, but I have some pretty
> pressing JS work that needs doing well before I could possibly get to this
> on my own time.

Thanks for the update Jeff. I hope you have nothing against it when I put this bug into mentored bucket. We can hopefully find someone to work on it.

Given that we will have a larger cluster for Mozmill tests soon this is no longer a real blocker for us, it's just an annoying issue.

Comment 32

[Andrew Halberstadt [:ahal]]

Reading the bug, there isn't a clear solution. Not sure that this is a great first bug.

Comment 33

[Henrik Skupin [:whimboo][⌚️UTC+1]]

(In reply to Andrew Halberstadt [:ahal] from comment #32)
> Reading the bug, there isn't a clear solution. Not sure that this is a great
> first bug.

It indeed doesn't contain all the information necessary to fix the bug. Waldo, if you are interested to be the mentor can you please point out what would be necessary to do and give links to the source code? The following link will help in terms of necessary information: http://www.joshmatthews.net/deck.js/mentor/#onemore

Comment 34

[Jeff Walden [:Waldo]]

Source code is <http://mxr.mozilla.org/mozilla-central/source/netwerk/test/httpserver/httpd.js>.  As for what to do, you'd have to skim this bug to figure it out.  :-\  My recollection is that the last dozen or so comments discuss the issue, but they probably don't explain it all in TPS-note-formatted details.

This is still first-bug territory, for someone motivated and not looking for just a change-the-code-simply patch.  But I probably don't have time right now to handhold anyone through a solution to it.  :-(

Comment 35

[Brian Smith (:briansmith, :bsmith, use NEEDINFO?)]

Attachment: A failed attempt to implement Patrick's suggested fix

With this patch, I am able to get test_update.js to finish, but there are various assertions:

ASSERTION: closing a connection [object Object] that we never added to the set of open connections?
ASSERTION: double-notifying?

It would be great if somebody who understands httpd.js could resolve this soon, because this is now blocking bug 754356, which is a high-priority bug for the networking team.

Comment 36

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Jeff, it looks like we need your help here to get this blocker fixed and to finish the work on bug 754356. Could you have a look at Brian's last comment please?

Comment 37

[Patrick McManus [:mcmanus]]

Attachment: make httpd.js shutdown quickly with idle never used sockets

Comment 38

[Patrick McManus [:mcmanus]]

Brian. I was able to easily repro your asserts and I made a couple changes to cope with them

1] a flag to figure out the double close because closing the socket has the side effect of making the state code that is reading from the input stream see an EOF (which it assumes is coming from the other end) and close it again.

2] reorder the existing "server is closed" flag to be after we reap the idle sockets instead of before it to take care of the double-notify problem.

I'm sorry it took to long - I'm still very interested in 754356 :)

Comment 39

[Patrick McManus [:mcmanus]]

https://tbpl.mozilla.org/?tree=Try&rev=7cba79f7bdc4

Comment 40

[Patrick McManus [:mcmanus]]

Comment on attachment 801752 [details] [diff] [review]
make httpd.js shutdown quickly with idle never used sockets

Actually I think jason said he knew something about this code

Comment 41

[Jason Duell]

Comment on attachment 801752 [details] [diff] [review]
make httpd.js shutdown quickly with idle never used sockets

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

nice stuff.  Thanks for fixing this, Patrick.  I assume you tested and it makes the shutdown regression go away?  Someone should verify that that's the case (maybe Henrik can do that if mcmanus didn't get around to it).

::: netwerk/test/httpserver/httpd.js
@@ +483,1 @@
>      if (!this._hasOpenConnections())

testing "if (foo)" then "if (!foo)": would be prettier as "if... else".  Not a big deal.

Comment 42

[Patrick McManus [:mcmanus]]

(In reply to Jason Duell (:jduell) from comment #41)

> nice stuff.  Thanks for fixing this, Patrick.  I assume you tested and it
> makes the shutdown regression go away?  Someone should verify that that's
> the case (maybe Henrik can do that if mcmanus didn't get around to it).

I verified that it will shutdown with an open connection that has not yet been used, and will not do so without this patch. I did not specifically verify with mozmill - I'm not well versed in that harness.

remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/3b2327d30b10

Comment 43

[Henrik Skupin [:whimboo][⌚️UTC+1]]

(In reply to Jason Duell (:jduell) from comment #41)
> makes the shutdown regression go away?  Someone should verify that that's
> the case (maybe Henrik can do that if mcmanus didn't get around to it).

Yes, I can check the fix with Mozmill. Will do it soon.

Comment 44

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Wow, that makes a huge difference! With it a lot of our tests are running twice that fast now! Functional tests which take 15 minutes now are run in nearly 7 minutes with the patch.

Comment 45

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/3b2327d30b10

Comment 46

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/494772cbf209

Comment 47

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g26_v1_2/rev/494772cbf209