Poor performance or normal behaviour?

[icalvete]

Issue Description

We in the middle of migration from parse.com to our own parse server on AWS EC2.

We are almost ready to go so we are testing the new platfrom.

We see weird behaviour. It's seems that parse-server don't works well with concurrent requests.

We have tested the whole app with jmeter and ab with the same result.

Parse-server tend to eat all free CPU. Even with a few requests.

We are using this simple script.

#!/bin/bash

ab -n1 -c1 \
-p parse.json \
-H "X-Parse-Application-Id: XXXXXXXXXXXX" \
-H "X-Parse-Client-Key: XXXXXXXXXXXX" \
-H "Content-Type: application/json" \
-H "Accept-Encoding: gzip" \
https://XXXXXXXXXXXX.XXXXXXXXXXXXcom:1337/parse/login

Where parse.json content is ...

{"username":"user1","password":"pass1","_method":"GET"}

We have done the tests with an empty database too. Our mongodb platform is really close to our parse-servers. There aren't any slow queries in our mongodb (80 ms is slow to us)

We hace un ELB with only one instance behind.

Results

10 requests. 1 concurrent request

Concurrency Level:      1
Time taken for tests:   2.266 seconds
Complete requests:      10
Failed requests:        0
Total transferred:      8890 bytes
Total body sent:        4090
HTML transferred:       3680 bytes
Requests per second:    4.41 [#/sec] (mean)
Time per request:       226.572 [ms] (mean)
Time per request:       226.572 [ms] (mean, across all concurrent requests)
Transfer rate:          3.83 [Kbytes/sec] received
                        1.76 kb/s sent
                        5.59 kb/s total

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        5    5   0.2      5       6
Processing:   219  221   2.2    221     225
Waiting:      218  221   2.2    221     225
Total:        224  226   2.2    226     231

Percentage of the requests served within a certain time (ms)
  50%    226
  66%    227
  75%    228
  80%    229
  90%    231
  95%    231
  98%    231
  99%    231
 100%    231 (longest request)

10 requests. 2 concurrent requests

Concurrency Level:      2
Time taken for tests:   2.169 seconds
Complete requests:      10
Failed requests:        0
Total transferred:      8890 bytes
Total body sent:        4090
HTML transferred:       3680 bytes
Requests per second:    4.61 [#/sec] (mean)
Time per request:       433.873 [ms] (mean)
Time per request:       216.936 [ms] (mean, across all concurrent requests)
Transfer rate:          4.00 [Kbytes/sec] received
                        1.84 kb/s sent
                        5.84 kb/s total

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        5    6   0.8      6       8
Processing:   414  428  10.0    431     440
Waiting:      414  428   9.9    431     440
Total:        419  434  10.2    439     446

Percentage of the requests served within a certain time (ms)
  50%    439
  66%    441
  75%    441
  80%    443
  90%    446
  95%    446
  98%    446
  99%    446
 100%    446 (longest request)

10 requests. 4 concurrent requests

Concurrency Level:      4
Time taken for tests:   2.145 seconds
Complete requests:      10
Failed requests:        0
Total transferred:      8890 bytes
Total body sent:        4090
HTML transferred:       3680 bytes
Requests per second:    4.66 [#/sec] (mean)
Time per request:       857.880 [ms] (mean)
Time per request:       214.470 [ms] (mean, across all concurrent requests)
Transfer rate:          4.05 [Kbytes/sec] received
                        1.86 kb/s sent
                        5.91 kb/s total

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        5    6   0.9      6       7
Processing:   426  765 177.6    849     857
Waiting:      426  765 177.6    849     857
Total:        431  771 178.0    856     863

Percentage of the requests served within a certain time (ms)
  50%    856
  66%    857
  75%    861
  80%    861
  90%    863
  95%    863
  98%    863
  99%    863
 100%    863 (longest request)

Even with only two concurrent requests response times grows to double.

2 requests. 2 concurrent requests

Concurrency Level:      2
Time taken for tests:   0.432 seconds
Complete requests:      2
Failed requests:        0
Total transferred:      1778 bytes
Total body sent:        818
HTML transferred:       736 bytes
Requests per second:    4.63 [#/sec] (mean)
Time per request:       432.359 [ms] (mean)
Time per request:       216.179 [ms] (mean, across all concurrent requests)
Transfer rate:          4.02 [Kbytes/sec] received
                        1.85 kb/s sent
                        5.86 kb/s total

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        6    6   0.8      7       7
Processing:   426  426   0.2    426     426
Waiting:      426  426   0.2    426     426
Total:        431  432   0.6    432     432
WARNING: The median and mean for the initial connection time are not within a normal deviation
        These results are probably not that reliable.

Percentage of the requests served within a certain time (ms)
  50%    432
  66%    432
  75%    432
  80%    432
  90%    432
  95%    432
  98%    432
  99%    432
 100%    432 (longest request)

Environment Setup

• Server
  • parse-server version: 2.2.17
  • Operating System: ubuntu 14.04
  • Hardware: AWS EC2 c4.large
• Database
  • MongoDB version: 3.0
  • Storage engine: WiredTiger
  • Hardware: AWS EC2 m4.large

Logs/Trace

[faizsameerahmed96]

It is always better to divide parse server up into multiple instance with a load balancer than using a scaled up instance. Also have you optimized your main.js file to make use of "workers" or use pm2 for deployment?

[icalvete]

Actually, since a AWS EC2 c4.large has two cores, we have two parser-server process. One listen on port 1338 and the other listen on port 1339. The c4.large run an haproxy listen on port 1337 and distributes requests between this local ports.

We use AWS EC2 auto scaling to scaling our platform, but we are running the test against the most simple case.

If we run the test against the haproxy, al work as expected. We can manage 2 concurrent 2 concurrent request without penalties (one request per core).

So our cuestion is about concurrent requests against one process.

[flovilmart]

That is very odd indeed, do you have any trace timing info about MongoDB queries and # of queries to mongo during those tests? Running a similar setup, and we don't see those latencies

[icalvete]

Except my process, no one is accesing to mongodb. I see 4 connections.

Launching 100 requests, 16 concurrent...

• 8 ops / sec (queries)
• No queries longer than 5 ms. ( I run db.setProfilingLevel(2,5) )

Document Path:          /parse/login
Document Length:        368 bytes

Concurrency Level:      16
Time taken for tests:   12.647 seconds
Complete requests:      100
Failed requests:        0
Total transferred:      88900 bytes
Total body sent:        40900
HTML transferred:       36800 bytes
Requests per second:    7.91 [#/sec] (mean)
Time per request:       2023.545 [ms] (mean)
Time per request:       126.472 [ms] (mean, across all concurrent requests)
Transfer rate:          6.86 [Kbytes/sec] received
                        3.16 kb/s sent
                        10.02 kb/s total

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        5    8   3.7      6      17
Processing:   487 1965 1165.3   2160    3866
Waiting:      487 1964 1165.3   2160    3866
Total:        493 1972 1166.3   2165    3877

Percentage of the requests served within a certain time (ms)
  50%   2165
  66%   2902
  75%   3111
  80%   3127
  90%   3352
  95%   3855
  98%   3871
  99%   3877
 100%   3877 (longest request)

I've tested my mongodb directly and is really fast. The bottleneck seems to be in parse-server. It can't manage concurrent requests.

[flovilmart]

What you describe is very odd... we currently process about 300rps (mostly reads and _Installation writes) and the CPU on each machine is at ~30%. And this is the most vanilla as possible as we don't leverage the cores through pm2/ cluster... what'a the result on a naked development machine with local MongoDB?

[icalvete]

Same.

I have installed a new machine (c4.large). Mongo is empty. Only one user. My main.is (Where the cloud code is going to be) is empty too.

More data:

Node version

node --version
v5.12.0

The way I run parse-server

node /usr/bin/parse-server /srv/cgib0/config.json

My config.json

{
  "appId": "xxxxxx",
  "masterKey": "xxxxxx",
  "databaseURI": "mongodb://localhost:27017/cgib",
  "port": "1337",
  "cloud": "/srv/cgib0/cloud/main.js",
  "javascriptKey": "xxxxxx",
  "restAPIKey": "xxxxxx",
  "clientKey": "xxxxxx",
  "publicServerURL": "http://xxxxxx:1337/parse",
  "filesAdapter": {
    "module": "parse-server-s3-adapter",
    "options": {
      "accessKey": "xxxxxx",
      "secretKey": "xxxxxx",
      "bucket": "xxxxxxpro",
      "region": "eu-west-1",
      "bucketPrefix": "",
      "directAccess": true,
      "baseUrl": "https://s3-eu-west-1.amazonaws.com/xxxxxxpro",
      "baseUrlDirect": true
    }
  },
  "verifyUserEmails": true,
  "emailAdapter": {
    "module": "parse-server-simple-mailgun-adapter",
    "options": {
      "fromAddress": "info@xxxxxx",
      "domain": "xxxxxx",
      "apiKey": "key-xxxxxx"
    }
  },
  "appName": "xxxxxx"
}

Remember that I'm testing only logins (https://XXXXXXXXXXXX.XXXXXXXXXXXXcom:1337/parse/login). Can you manage 300 login per second? I can't understand. What is happening?

parse.com need same time for a login (220 ms) too, but the service can manage concurrent requests without letting down (response always take 200/300 ms). With this data, they need almost 300 / 4 cores to get 300 logins per second. right?

(Thanks for your interest. I'm pretty lost)

[JeremyPlease]

I just spent some time looking into this issue. There is most definitely a performance problem with Parse Server signup/login.

Some background:

• nodejs is single-threaded so when any code does something intensive it blocks all other code from executing.
• By design and as a best practice, signup and login (any password hashing) should be slow.
• Parse Server uses the async methods of bcrypt-nodejs to hash and compare passwords. Hypothetically, this should make the code "non-blocking."

The problem:

• The async functions of the bcrypt-nodejs just call the synchronous functions within process.nextTick. See source code here.
• This means that any time that Parse Server uses the hash or compare functions it's going to become blocking on nextTick and block all other code execution.

My recommendation:
Replace the current bcrypt moule with the node.bcrypt.js module. This one uses node-gyp and native bindings so that the asynchronous functions are truly non-blocking.

Looks like we can update package.json dependencies and password.js with the new module and we should be good to go. @icalvete would you like to submit a pull request for this? If not, I'd be happy to.

[flovilmart]

The native bindings may be a good idea but may be problematic for users with limited compilation tools on the remote machine.

[JeremyPlease]

@flovilmart Good point... Windows users will most certainly run into issues as well.

Just came across bcrypt.js which appears to do a nice job or progressively handling hashing in a non-blocking way.

[flovilmart]

@JeremyPlease also on heroku, app engine etc... all thin containers may have problems with those native modules. We could definitely try bcrypt.js, run ab against it quickly. Wanna run the benchmarks?

[JeremyPlease]

Running some benchmarks now. Stay tuned... 📺

[flovilmart]

👍

[JeremyPlease]

Well... Here are some benchmarks. Ran with ab -n200 -c100 locally 5 times for each module.

• Baseline (immediately fulfill promises in password.js without bcrypt use): 250 req/sec
• bcrypt-nodejs (current implementation): 5 req/sec
• bcryptjs: 5 req/sec
• twin-bcrypt: 5 req/sec
• bcrypt (native bindings): 52 req/sec

Not sure where to go from here. We might just want to leave things as-is and note in the wiki/readme that Parse Server has a limitation around simultaneous login requests.

[flovilmart]

Maybe mark is as an optional dependency, if compilation fails, we use the std slow bcrypt-nodejs (current implementation).

Would that be reasonable?

[flovilmart]

@JeremyPlease did you use saltRounds = 10 in the hash function from bcrypt ? What was the value you used?

[JeremyPlease]

@flovilmart Yep, 10 saltRounds for .hash(password, saltRounds, ...)

[icalvete]

I've tried the bcrypt and works really fine.

To me this issue can be closed.

Thanks for all.

[flovilmart]

We'll try to do a release soon when thé PR has landed

[joeyslack]

It definitely does not work as a straight replacement.

[flovilmart]

@joeyslack the PR is open and that will also factor for setups where build tools are not available remotely

[joeyslack]

@flovilmart FYI, I'm unable to login to my app (facebook connect, and also manual login method) with this new patch on master. Would love to see if it works for anyone else....

[flovilmart]

What is the issue that you see? FBConnect should be un-affected by that change.

[flovilmart]

@joeyslack :

I just tried that:

var bcryptOriginal = require('bcrypt-nodejs'); // original bcrypt 
var bcryptNew = require('bcrypt'); // bcrypt native
bcryptOriginal.hash('my1Long:password', null, null, function(err, res) {
    bcryptNew.compare('my1Long:password', res, function(err, res) {
          expect(res).toBeTruthy();
          done();
    });
});

And that passes, unfortunately, we can't test it on travis as the bcrypt native module won't build

[joeyslack]

I don't have a lot of time to debug this now, but if it's working for everyone else, it's probably my VM. Will post back with more details if I find anything.

[flovilmart]

@joeyslack we're planing to release tonight 2.2.18. We don't want anyone to be locked out...

[joeyslack]

@flovilmart Turned out to be an issue with FileLoggerAdapter. I am using it in my app like:
var logger = require('parse-server/lib/Adapters/Logger/FileLoggerAdapter').FileLoggerAdapter;

Had to install this dep separately. Bcrypt changes seems to work fine.

2.2.18!