Parse Server much slower than Parse.com with same database

[zingano]

I have migrated (and finalised) my database from Parse.com to mLab. My (production) client applications are still using the parse.com API, but in test I am using both that and my own Parse Server running on Heroku for comparison.

Steps to reproduce

Please include a detailed list of steps that reproduce the issue. Include curl commands when applicable.

1. Run OS X test of finding Job objects (with many includeKeys) on parse.com
2. Run the same test on parse server
3. Run cloud code test of finding Task objects in a large geographical area on parse.com
4. Run the same test on parse server

Expected Results

The times for the tests should be roughly the same.

Actual Outcome

Parse Server tests are 2 - 3x the time of the Parse.com tests.
Find jobs is around 4.8 seconds on parse.com, 14 seconds on parse server.
Find tasks is around 7.7 seconds on parse.com, 16 seconds on parse server

This does not happen just in these tests, but permeates the app, with each "page" being 2-3x as slow to load on parse server.

Environment Setup

• Server
  • parse-server version 2.2.8
  • Operating System:
  • Hardware:
  • Localhost or remote server?

Heroku, US East. 6 of 1x web instances, 1 of 1x worker instance. I have tried other combinations, even up to Performance-M but the difference is not close to being eradicated) Note the worker thread is not used in either of the tests.

• Database
  • MongoDB version: 3.0.12
  • Storage engine: MMAPv1
  • Hardware: Shared Cluster 8GB
  • Localhost or remote server? mLab via Heroku add-on (both in US East)

There are around 250K Task objects in the database, and around 900 job objects.

I have added indices for any queries that mLab thinks are slow, except one that cannot be automatically indexed, although none of them have been close to as slow as the actual transaction time - which is often in seconds. The most they have been is the order of 100 milliseconds.

I have added individual column indices as it helped so much here, but it made no difference to me.
#2537

Logs/Trace

I am using New Relic to trace / analyse but I am getting nowhere as all New Relic shows is that a high percentage (almost 100% in my most recent test) is taken up by Middleware: anonymous which I know from similar defects on here is parse server.

Since the database is the same in both cases, I assume the blame must be within Parse Server, but would like to find out more. Could it be that this would help me? #2316

Or am I seeing something like this with authentication? #2556

Basically without more instrumentation I won't find out.

The New Relic people are saying that perhaps I'm not getting more out of this analysis because Parse Server is passing through async boundaries in which the transaction is lost. They say that using custom instrumentation could help - trouble is I would have no idea where to put it. If anyone could help with that - or add commented out lines to Parse server to help all of us who use New Relic to instrument, that would be great.

https://docs.newrelic.com/docs/agents/nodejs-agent/supported-features/nodejs-custom-instrumentation#expanding-instrumentation

The code for my tests, run from an OS X app, is below.

- (IBAction)timeFetchJobs:(id)sender {

    [self.testConsoleView setString:@""];
    __block NSString* consoleText = @"";
    __block NSDate* debugStartTime = [NSDate date];

    PFQuery* postQuery = [PFQuery queryWithClassName:@"Job"];
    postQuery.limit = appDelegate.mainWC.numberOfRecordsInPage;
    postQuery.skip = appDelegate.mainWC.numberOfRecordsToSkip;
    [postQuery whereKey:@"status" containedIn:@[kOFEJobStatusAwaitingApproval,kOFEJobStatusDraft,kOFEJobStatusLive,kOFEJobStatusReadyToGoLive,kOFEJobStatusClosing]];
    [postQuery includeKey:@"account"];
    [postQuery includeKey:@"account.customer"];
    [postQuery includeKey:@"account.customer.locationListsArray"];
    [postQuery includeKey:@"locationList"];
    [postQuery includeKey:@"publicJob"];
    [postQuery includeKey:@"publicJob.stepsArray"];
    [postQuery includeKey:@"agentList"];
    [postQuery orderByDescending:@"createdAt"];

    [postQuery findObjectsInBackgroundWithBlock:^(NSArray *objects, NSError *error) {

        PFQuery* postQuery2 = [PFQuery queryWithClassName:@"Job"];
        postQuery2.limit = appDelegate.mainWC.numberOfRecordsInPage;
        postQuery2.skip = appDelegate.mainWC.numberOfRecordsToSkip;
        [postQuery2 whereKey:@"status" containedIn:@[kOFEJobStatusAwaitingApproval,kOFEJobStatusDraft,kOFEJobStatusLive,kOFEJobStatusReadyToGoLive,kOFEJobStatusClosing]];
        [postQuery2 includeKey:@"account"];
        [postQuery2 includeKey:@"account.customer"];
        [postQuery2 includeKey:@"account.customer.locationListsArray"];
        [postQuery2 includeKey:@"locationList"];
        [postQuery2 includeKey:@"publicJob"];
        [postQuery2 includeKey:@"publicJob.stepsArray"];
        [postQuery2 includeKey:@"agentList"];
        [postQuery2 orderByDescending:@"createdAt"];

        [postQuery2 findObjectsInBackgroundWithBlock:^(NSArray *objects, NSError *error) {
            NSDate* debugEndTime = [NSDate date];
            NSTimeInterval parseLoadTime = [debugEndTime timeIntervalSinceDate:debugStartTime];
            consoleText = [NSString stringWithFormat:@"Find jobs (2x): %f",parseLoadTime];
            [self.testConsoleView setString:consoleText];
        }];
    }];
}

- (IBAction)timeFindTasks:(id)sender {

    [self.testConsoleView setString:@""];
    __block NSString* consoleText = @"";
    __block NSDate* debugStartTime = [NSDate date];

    __block NSDictionary* params = @{@"appversion" : @(1.9),
                             @"swlat": @(49.84),
                             @"swlon": @(-9.23),
                             @"nelat": @(60.85),
                             @"nelon": @(2.69)};

    [PFCloud callFunctionInBackground:@"findTasks" withParameters:params block:^(id objects, NSError *error) {

        if (!error) {
            [PFCloud callFunctionInBackground:@"findTasks" withParameters:params block:^(id objects, NSError *error) {

                if (!error) {
                    NSDate* debugEndTime = [NSDate date];
                    NSTimeInterval parseLoadTime = [debugEndTime timeIntervalSinceDate:debugStartTime];
                    consoleText = [NSString stringWithFormat:@"Find tasks (twice): %f",parseLoadTime];
                    [self.testConsoleView setString:consoleText];

                }
                else {
                    consoleText = [NSString stringWithFormat:@"ERROR in find tasks: %@",error];
                    [self.testConsoleView setString:consoleText];
                }
            }];
        }
        else {
            consoleText = [NSString stringWithFormat:@"ERROR in find tasks: %@",error];
            [self.testConsoleView setString:consoleText];
        }
    }];

}

[flovilmart]

@zingano Thanks for the detailed report. What kind of dyno are you running on? When running parse-server on your local development machine, do you see similar times? I'm asking that as I want to rule out deployment related problems before any further investigation.

The number of includes you ask for is probably the source of the issue as I believe we sequentially resolves them instead of in parallel

Another thing you could test is to remove some includes, if you see the time dropping, that would indicate that we're running in O(n) time for resolving each include instead of being closer to O(1) (running in parallel)

[flovilmart]

@zingano Do you feel like working on an improvement for that feature running all handleIncludes in parallel instead of sequentially like we do?

[zingano]

@flovilmart Dynos, it says above :-) - Heroku, US East. 6 of 1x web instances, 1 of 1x worker instance. I have tried other combinations, even up to Performance-M but the difference is not close to being eradicated) Note the worker thread is not used in either of the tests.

[flovilmart]

@zingano sorry, I misread. So I can definitely say that the includes occur sequentially. Do you want to improve that?

[zingano]

However, I disagree with changing this to be only about running the includes in parallel. As I said, my findTasks is also slow (and this is a more complex cloud function with more at play than just include keys - there are multiple finds over various classes).

I also have a minimal findJobs, the same as the code above but without any includeKeys or whereKey, but this time with a limit of 1000.

In this case parse.com has a time of around 3.5 secs and parse server has a much more variable time of around 6-8 seconds.

[zingano]

And if I drop the limit to 200, parse.com falls to 1.1s pretty consistently, but parse server is around 3s, but varying wildly up to around 9s.

[flovilmart]

For cloud functions, they take time as they are using the HTTP API instead of a direct access. This PR will enable direct interaction with parse-server API's instead of using HTTP requests. You can try that PR by setting the parse-server version to 2.3.0-alpha1

[zingano]

Thanks, I'll do that.

The minimal findJobs mentioned above, with no includeKeys, is OS X client code with no cloud code, like so:

- (IBAction)timeSimpleFindJobs:(id)sender {

    [self.testConsoleView setString:@""];
    __block NSString* consoleText = @"";
    __block NSDate* debugStartTime = [NSDate date];

    PFQuery* postQuery = [PFQuery queryWithClassName:@"Job"];
    postQuery.limit = 200;
    postQuery.skip = 0;
    [postQuery findObjectsInBackgroundWithBlock:^(NSArray *objects, NSError *error) {

        PFQuery* postQuery2 = [PFQuery queryWithClassName:@"Job"];
        postQuery2.limit = 200;
        postQuery2.skip = 0;
        [postQuery2 findObjectsInBackgroundWithBlock:^(NSArray *objects, NSError *error) {

            NSDate* debugEndTime = [NSDate date];
            NSTimeInterval parseLoadTime = [debugEndTime timeIntervalSinceDate:debugStartTime];
            consoleText = [NSString stringWithFormat:@"Simple find jobs (2x): %f",parseLoadTime];
            [self.testConsoleView setString:consoleText];
        }];
    }];

[flovilmart]

On your dynos, do you run with NODE_ENV=production ?