Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unskippable 50ms delay when making a POST/PUT/DELETE request with form-urlencoded or json data #3205

Closed
kevinburkeshyp opened this issue Sep 5, 2015 · 9 comments

Comments

@kevinburkeshyp
Copy link

@kevinburkeshyp kevinburkeshyp commented Sep 5, 2015

If you make a request to Sails with any content-type that's not a multipart form upload, Sails's default body parser will sleep for 50 milliseconds before yielding control. You can verify this by checking out the latest upstream (2b908c9, at the time of writing) and running the following commands:

  1. npm install
  2. ./bin/sails.js new slow-body-parser
  3. cd slow-body-parser
  4. DEBUG=skipper ./node_modules/sails/bin/sails.js lift

and then making a POST request to localhost:1337, for example:

/usr/bin/time curl -iXPOST -H 'Content-Type: application/json' localhost:1337 -o output.html -vv

You will observe the following in your Sails log output:

  skipper multiparty form emitted error: +45m [Error: missing content-type header]
  skipper passed control to app because 50ms elapsed +52ms
  skipper waiting for any text params +0ms
  skipper Passing control to app... +7ms

(I'm not sure where the 45m comes from; it seems like the skipper output is measuring the amount of time since the last request, which was about 45 minutes ago, on my machine)

Anyway, here's the time output:

0.08 real         0.00 user         0.00 sys

And here's the time output if I do a GET request, say /usr/bin/time curl -i localhost:1337 -o output.html -vv. Note that the total time has decreased from 80ms to 30ms.

0.03 real         0.00 user         0.00 sys

I'm sure there's a good reason for doing this, but it sure is unexpected, and I'd expect this behavior to be called out in large type in the README. I also expect that the vast majority of POST/PUT requests are using form-urlencoded or JSON content types instead of multipart file upload, which makes it a bit bewildering that these are handled by delaying.

You may be saying to yourself "50ms isn't actually that long." Without this in place, the average test time for a controller test drops from 70-100ms to 20-50ms, about a 100% speed improvement. Eyeballing our request logs, an average POST request takes anywhere from 80 to 150ms; it would be a pretty significant performance increase if this dropped to 30-100ms. The delay also means the web node is holding open the request/tying up memory for the duration of the 50ms sleep.

It looks like the offending code is here - the comment there about why the value is hard coded to 50ms seemed like it was committed when only half-complete. https://github.com/balderdashy/skipper/blob/master/lib/Parser/prototype.parseReq.js#L132. I'm also confused about why the behavior is to delay if the content-type is unknown, instead of just to hit the callback.

Anyway, I would appreciate advice on what I/we can do to mitigate this or work around it. Thanks!

@tjwebb
Copy link
Contributor

@tjwebb tjwebb commented Sep 5, 2015

You may be saying to yourself "50ms isn't actually that long."

I'm not saying that to myself. 50ms is a long time to waste on each and every request. I'll look into it. It smells like a workaround/hack that probably doesn't need to exist.

@kevinburkeshyp
Copy link
Author

@kevinburkeshyp kevinburkeshyp commented Sep 6, 2015

For the moment we're replacing these lines in config/http.js:

       'bodyParser',
       'handleBodyParserError',

with these

    [
       'jsonBodyParser',
       'formBodyParser',
    ],
    jsonBodyParser: bodyParser.json(),
    formBodyParser: bodyParser.urlencoded({extended: true}),
@sgress454
Copy link
Member

@sgress454 sgress454 commented Sep 10, 2015

This delay is covered in the FAQ for skipper. Its intent is to allow the body parser time to identity incoming file streams before passing control back to the controller. But, it should only need to do that for multipart requests; we should be able to avoid the delay for everything else. I'll look into it.

sgress454 added a commit to sailshq/skipper that referenced this issue Sep 18, 2015
@sgress454
Copy link
Member

@sgress454 sgress454 commented Sep 18, 2015

Ok! Published a new version of Skipper that skips (no pun intended) the 50ms delay for non-multipart requests.

@sgress454 sgress454 closed this Sep 18, 2015
@kevinburkeshyp
Copy link
Author

@kevinburkeshyp kevinburkeshyp commented Sep 18, 2015

Thanks!

@RWOverdijk
Copy link
Contributor

@RWOverdijk RWOverdijk commented Dec 6, 2015

Sleeping to fix something? Are you being serious?

@AeroNotix
Copy link

@AeroNotix AeroNotix commented May 5, 2016

The drama in node.js libraries never ceases to amaze. Good entertainment!

@sgress454
Copy link
Member

@sgress454 sgress454 commented May 5, 2016

Ha! To be clear though, this delay isn't "fixing" anything. You can look at it instead as guaranteeing that any request containing a file will pass control to app code in 50ms, versus having to possibly wait multiple seconds (minutes? hours?) for the file to upload (in the default Express bodyparser case, this meant buffering to disk/memory) before being able to run your code. If your code uses text params to determine whether or not to abort the upload, it sure is nice to only have to wait 50ms to do so! Obviously this didn't make sense for non-multipart requests, hence this issue, which is now fixed.

@mikermcneil
Copy link
Member

@mikermcneil mikermcneil commented May 5, 2016

@RWOverdijk I'm not sure I follow what you mean here, but I should reiterate that the 50ms timeout is not a hack-- it's intentional (more on that in a sec). Also, just to be clear, it is not a sleep because it does not block-- the Node process continues to handle requests.

@AeroNotix If performance patches for open-source modules aren't drama, I don't know what is. Maybe you could write a telenovela about this?

This is a closed issue that has been resolved with a fix published to NPM for over six months now, so I'm going to go ahead and wrap up:

You can choose to use any body parser you like in Sails-- like all of the other built-in middleware, it is completely configurable. As @sgress454 hinted at, our approach in the default body parser, Skipper, was a deliberate design decision I made in order to empower Sails apps to support terabyte file uploads instead of the original default behavior in Express and Sails, which left your app vulnerable to DoS attacks out of the box. The easy solution would have been to remove file upload support from core, which is what Express did (rightly IMO-- it's a different kind of framework). But I believed then (and still do now) that for Sails, that would be a cop-out.

What was not a deliberate decision was that, if an incoming request did not include a content-type header that explicitly declared itself a multipart upload, the underlying bodyparser (multiparty) would emit an error event. This is not necessarily wrong, but it sure was unexpected, because it worked differently from the implementation of the multipart body parser in Connect at the time (as well as Connect's other body parsers), which call next() when they see an unrecognized content-type.)

Re: error handling in general, rather than expecting you to bind an error listener on the multiparty form instance yourself in your app code and risk you forgetting to do so, crashing the Node process and thus your app, we handle it for you in Skipper core. The only problem is that multiparty does not emit a close event if it ALSO emits an error event That sounds simple enough, right? But here's the thing: aside from the main error event on the multiparty form instance, each "part" from the multipart stream is actually a stream itself, which can also emit multiple error events-- importantly: more than one per part (hence the spinlock we implemented in Skipper). So, long story short, if a parse error is emitted, the 50ms timeout comes into play for that specific request for which parsing failed. Which is no problem.

As you've probably figured out, the real issue was we were using the approach that Express and Connect's body parser used at the time (and still use today), which was to attempt to parse with each type of sub-parser. This relies on content-type headers to determine the appropriate behavior and, if the headers recognized by a particular parser are not sent, then that parser is skipped.... err... except for multiparty, which emits an error on its form stream, which Skipper handles to prevent from crashing the process-- but then close is not emitted, causing the upstream to time out after 50ms.

When replacing the built-in body parser with multiparty, we didn't notice the decrease in performance because it isn't visible to the naked eye. But luckily, at this point (Sep 2015), Shyp had scaled to the point where they making significant investment in performance anyway, and Kevin had a sharp eye. When profiling their Sails app, he noticed this and provided us with the excellent report above. After verifying that there wouldn't be any side-effects to compatibility, @sgress454 quickly published a patch that gave every Sails app a nice performance boost.

This was fixed in Skipper v0.5.7, so if you haven't run npm install in a while, be sure to do that to pick up the latest stable 0.5.x release of Skipper that includes this patch. If you are using Sails v0.10.2 or newer, this is taken care of automatically.

Thanks again for the help everyone.

@balderdashy balderdashy locked and limited conversation to collaborators May 5, 2016
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
6 participants
You can’t perform that action at this time.