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

Fetch large data for reports slow #6543

Open
omkar-tenkale opened this issue Mar 27, 2020 · 67 comments
Open

Fetch large data for reports slow #6543

omkar-tenkale opened this issue Mar 27, 2020 · 67 comments
Labels
type:feature New feature or improvement of existing feature

Comments

@omkar-tenkale
Copy link

omkar-tenkale commented Mar 27, 2020

I'm trying to fetch more than 100,000 rows for report generation.
I tried these approaches,

  1. Recursive calls with 1,000 limit to fetch all rows
  2. Using query.each() and push row in array

Both the calls are slow,

For cloud code query

query = //new query
query.equalTo("SOMEKEY","SOMEVALUE")

For total of 1,500,000 rows
In cloud code,

In recursive call approach, there is approx 1 second waiting time per 1000 rows.

In query.each() approach this query takes approx 60 seconds to process, http waiting time

I assume this is fastest parse can work.

Can i see some improvement by indexing the mongodb objectId column?

Is there a better approach for processing such huge data.

One alternative I can think of is parse aggregate but this approach doesn't respect parse authentication, security, acl etc. and doesn't work with existing query logic.
Will this show any performance improvement and worth a try?

@acinader
Copy link
Contributor

acinader commented Mar 27, 2020

This should not be slow. The most obvious reasons why it may be slow:

  1. 'SOMEKEY' is not properly indexed
  2. Each object is very large

Considering your question, I suspect that the problem is the item 1.

Trying properly indexing your collection.

@acinader acinader reopened this Mar 27, 2020
@mtrezza
Copy link
Member

mtrezza commented Mar 28, 2020

@omkar-tenkale You can look at the logs of your database to find out how long the query takes on the DB side.

@omkar-tenkale
Copy link
Author

With mongo profiling i can see 58 queries are run for 58000 rows

The last 2 blocks of log


{
	"op" : "getmore",
	"ns" : "dev.Product",
	"cursorid" : 39369748207,
	"ntoreturn" : 1000,
	"keyUpdates" : 0,
	"numYield" : 0,
	"lockStats" : {
		"timeLockedMicros" : {
			"r" : NumberLong(1288),
			"w" : NumberLong(0)
		},
		"timeAcquiringMicros" : {
			"r" : NumberLong(3),
			"w" : NumberLong(3)
		}
	},
	"nreturned" : 1000,
	"responseLength" : 671635,
	"millis" : 1,
	"execStats" : {
		
	},
	"ts" : ISODate("2020-03-30T10:53:02.885Z"),
	"client" : "127.0.0.1",
	"allUsers" : [ ],
	"user" : ""
}
{
	"op" : "getmore",
	"ns" : "dev.Product",
	"cursorid" : 39369748207,
	"ntoreturn" : 1000,
	"keyUpdates" : 0,
	"numYield" : 0,
	"lockStats" : {
		"timeLockedMicros" : {
			"r" : NumberLong(1552),
			"w" : NumberLong(0)
		},
		"timeAcquiringMicros" : {
			"r" : NumberLong(2),
			"w" : NumberLong(3)
		}
	},
	"nreturned" : 1000,
	"responseLength" : 682352,
	"millis" : 1,
	"execStats" : {
		
	},
	"ts" : ISODate("2020-03-30T10:53:02.918Z"),
	"client" : "127.0.0.1",
	"allUsers" : [ ],
	"user" : ""
}
Type "it" for more
> 

@omkar-tenkale
Copy link
Author

Parse is still taking upto 10 seconds for 58000 items without any query constraints

@omkar-tenkale
Copy link
Author

omkar-tenkale commented Mar 30, 2020

The query i simple,this is the cloud codee

async function indexTest(req,res){
console.time("timelog");

var Product = Parse.Object.extend("Product");
var query = new Parse.Query(Product);
query.limit(1000000)
var res = await query.find();
console.timeEnd("timelog");
console.time("timelog");
console.log("resp size=="+res.length)
console.timeEnd("timelog");
return res.length;
}

@omkar-tenkale
Copy link
Author

omkar-tenkale commented Mar 30, 2020

This is the log (pm2 logs 0)

0|app1 | timelog: 10.097s
0|app1 | resp size==58110
0|app1 | timelog: 0.145ms
0|app1 | info: Ran cloud function indexTest for user undefined with:
0|app1 | Input: {}
0|app1 | Result: 58110 {"functionName":"indexTest","params":{}}

@mtrezza
Copy link
Member

mtrezza commented Mar 30, 2020

In your mongodb logs I don't see any excessive execution times.

Can you turn on profiling to only log queries that take longer than 100ms?

@mtrezza
Copy link
Member

mtrezza commented Mar 30, 2020

Actually, the execStats are empty in the logs you posted here. The stats should give you more hints about the execution time and whether an index was used for the scan, etc.

@omkar-tenkale
Copy link
Author

How can i include execStats?

@omkar-tenkale
Copy link
Author

Here's what i could find
Cloud code request from parse-dashboard console


> db.setProfilingLevel(2)
{ "was" : 0, "slowms" : -1, "ok" : 1 }
> db.system.profile.find().pretty()
{
        "op" : "query",
        "ns" : "dev.system.indexes",
        "query" : {
                "expireAfterSeconds" : {
                        "$exists" : true
                }
        },
        "ntoreturn" : 0,
        "ntoskip" : 0,
        "nscanned" : 29,
        "nscannedObjects" : 29,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(92),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(3),
                        "w" : NumberLong(2)
                }
        },
        "nreturned" : 0,
        "responseLength" : 20,
        "millis" : 0,
        "execStats" : {
                "type" : "COLLSCAN",
                "works" : 31,
                "yields" : 0,
                "unyields" : 0,
                "invalidates" : 0,
                "advanced" : 0,
                "needTime" : 30,
                "needFetch" : 0,
                "isEOF" : 1,
                "docsTested" : 29,
                "children" : [ ]
        },
        "ts" : ISODate("2020-03-31T08:01:25.597Z"),
        "client" : "0.0.0.0",
        "allUsers" : [
                {
                        "user" : "__system",
                        "db" : "local"
                }
        ],
        "user" : "__system@local"
}
>
>
>
>
> db.system.profile.find().pretty()
{
        "op" : "query",
        "ns" : "dev.system.indexes",
        "query" : {
                "expireAfterSeconds" : {
                        "$exists" : true
                }
        },
        "ntoreturn" : 0,
        "ntoskip" : 0,
        "nscanned" : 29,
        "nscannedObjects" : 29,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(92),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(3),
                        "w" : NumberLong(2)
                }
        },
        "nreturned" : 0,
        "responseLength" : 20,
        "millis" : 0,
        "execStats" : {
                "type" : "COLLSCAN",
                "works" : 31,
                "yields" : 0,
                "unyields" : 0,
                "invalidates" : 0,
                "advanced" : 0,
                "needTime" : 30,
                "needFetch" : 0,
                "isEOF" : 1,
                "docsTested" : 29,
                "children" : [ ]
        },
        "ts" : ISODate("2020-03-31T08:01:25.597Z"),
        "client" : "0.0.0.0",
        "allUsers" : [
                {
                        "user" : "__system",
                        "db" : "local"
                }
        ],
        "user" : "__system@local"
}
{
        "op" : "query",
        "ns" : "dev.system.profile",
        "query" : {

        },
        "ntoreturn" : 0,
        "ntoskip" : 0,
        "nscanned" : 1,
        "nscannedObjects" : 1,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(96),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(3),
                        "w" : NumberLong(4)
                }
        },
        "nreturned" : 1,
        "responseLength" : 649,
        "millis" : 0,
        "execStats" : {
                "type" : "COLLSCAN",
                "works" : 3,
                "yields" : 0,
                "unyields" : 0,
                "invalidates" : 0,
                "advanced" : 1,
                "needTime" : 1,
                "needFetch" : 0,
                "isEOF" : 1,
                "docsTested" : 1,
                "children" : [ ]
        },
        "ts" : ISODate("2020-03-31T08:01:28.613Z"),
        "client" : "157.33.212.99",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "query",
        "ns" : "dev._SCHEMA",
        "query" : {
                "$query" : {

                }
        },
        "ntoreturn" : 1000,
        "ntoskip" : 0,
        "nscanned" : 21,
        "nscannedObjects" : 21,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(132),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(2),
                        "w" : NumberLong(3)
                }
        },
        "nreturned" : 21,
        "responseLength" : 6562,
        "millis" : 0,
        "execStats" : {
                "type" : "COLLSCAN",
                "works" : 23,
                "yields" : 0,
                "unyields" : 0,
                "invalidates" : 0,
                "advanced" : 21,
                "needTime" : 1,
                "needFetch" : 0,
                "isEOF" : 1,
                "docsTested" : 21,
                "children" : [ ]
        },
        "ts" : ISODate("2020-03-31T08:02:05.054Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "query",
        "ns" : "dev._Session",
        "query" : {
                "$orderby" : {

                },
                "$query" : {
                        "_session_token" : "r:69bf2af111cc47a67c6d3119f282e5a1"
                }
        },
        "ntoreturn" : 1,
        "ntoskip" : 0,
        "nscanned" : 125,
        "nscannedObjects" : 125,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(176),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(2),
                        "w" : NumberLong(2)
                }
        },
        "nreturned" : 1,
        "responseLength" : 324,
        "millis" : 0,
        "execStats" : {
                "type" : "COLLSCAN",
                "works" : 126,
                "yields" : 0,
                "unyields" : 0,
                "invalidates" : 0,
                "advanced" : 1,
                "needTime" : 125,
                "needFetch" : 0,
                "isEOF" : 0,
                "docsTested" : 125,
                "children" : [ ]
        },
        "ts" : ISODate("2020-03-31T08:02:05.056Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "query",
        "ns" : "dev._User",
        "query" : {
                "$orderby" : {

                },
                "$query" : {
                        "_id" : "MoEjAOXpF4"
                }
        },
        "ntoreturn" : 1000,
        "ntoskip" : 0,
        "nscanned" : 1,
        "nscannedObjects" : 1,
        "idhack" : true,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(42),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(1),
                        "w" : NumberLong(2)
                }
        },
        "nreturned" : 1,
        "responseLength" : 419,
        "millis" : 0,
        "execStats" : {

        },
        "ts" : ISODate("2020-03-31T08:02:05.057Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "query",
        "ns" : "dev._Session",
        "query" : {
                "$orderby" : {

                },
                "$query" : {
                        "_session_token" : "r:69bf2af111cc47a67c6d3119f282e5a1"
                }
        },
        "ntoreturn" : 1000,
        "ntoskip" : 0,
        "nscanned" : 219,
        "nscannedObjects" : 219,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(281),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(4),
                        "w" : NumberLong(4)
                }
        },
        "nreturned" : 1,
        "responseLength" : 324,
        "millis" : 0,
        "execStats" : {
                "type" : "COLLSCAN",
                "works" : 221,
                "yields" : 1,
                "unyields" : 1,
                "invalidates" : 0,
                "advanced" : 1,
                "needTime" : 219,
                "needFetch" : 0,
                "isEOF" : 1,
                "docsTested" : 219,
                "children" : [ ]
        },
        "ts" : ISODate("2020-03-31T08:02:05.066Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "query",
        "ns" : "dev._SCHEMA",
        "query" : {
                "$query" : {

                }
        },
        "ntoreturn" : 1000,
        "ntoskip" : 0,
        "nscanned" : 21,
        "nscannedObjects" : 21,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(80),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(3),
                        "w" : NumberLong(2)
                }
        },
        "nreturned" : 21,
        "responseLength" : 6562,
        "millis" : 0,
        "execStats" : {
                "type" : "COLLSCAN",
                "works" : 23,
                "yields" : 0,
                "unyields" : 0,
                "invalidates" : 0,
                "advanced" : 21,
                "needTime" : 1,
                "needFetch" : 0,
                "isEOF" : 1,
                "docsTested" : 21,
                "children" : [ ]
        },
        "ts" : ISODate("2020-03-31T08:02:05.070Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "query",
        "ns" : "dev._Join:users:_Role",
        "query" : {
                "$orderby" : {

                },
                "$query" : {
                        "relatedId" : {
                                "$in" : [
                                        "MoEjAOXpF4"
                                ]
                        }
                }
        },
        "ntoreturn" : 1000,
        "ntoskip" : 0,
        "nscanned" : 0,
        "nscannedObjects" : 0,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(151),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(2),
                        "w" : NumberLong(3)
                }
        },
        "nreturned" : 0,
        "responseLength" : 20,
        "millis" : 0,
        "execStats" : {

        },
        "ts" : ISODate("2020-03-31T08:02:05.074Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "query",
        "ns" : "dev._Role",
        "query" : {
                "$orderby" : {
                        "_id" : 1
                },
                "$query" : {
                        "_id" : {
                                "$in" : [ ]
                        }
                }
        },
        "ntoreturn" : 100,
        "ntoskip" : 0,
        "nscanned" : 0,
        "nscannedObjects" : 0,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(183),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(2),
                        "w" : NumberLong(2)
                }
        },
        "nreturned" : 0,
        "responseLength" : 20,
        "millis" : 0,
        "execStats" : {
                "type" : "FETCH",
                "works" : 1,
                "yields" : 0,
                "unyields" : 0,
                "invalidates" : 0,
                "advanced" : 0,
                "needTime" : 0,
                "needFetch" : 0,
                "isEOF" : 1,
                "alreadyHasObj" : 0,
                "forcedFetches" : 0,
                "matchTested" : 0,
                "children" : [
                        {
                                "type" : "IXSCAN",
                                "works" : 1,
                                "yields" : 0,
                                "unyields" : 0,
                                "invalidates" : 0,
                                "advanced" : 0,
                                "needTime" : 0,
                                "needFetch" : 0,
                                "isEOF" : 1,
                                "keyPattern" : "{ _id: 1 }",
                                "isMultiKey" : 0,
                                "boundsVerbose" : "field #0['_id']: ",
                                "yieldMovedCursor" : 0,
                                "dupsTested" : 0,
                                "dupsDropped" : 0,
                                "seenInvalidated" : 0,
                                "matchTested" : 0,
                                "keysExamined" : 0,
                                "children" : [ ]
                        }
                ]
        },
        "ts" : ISODate("2020-03-31T08:02:05.075Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "query",
        "ns" : "dev.userMaster_Test",
        "query" : {
                "$orderby" : {

                },
                "$query" : {
                        "_rperm" : {
                                "$in" : [
                                        null,
                                        "*",
                                        "*",
                                        "MoEjAOXpF4"
                                ]
                        }
                }
        },
        "ntoreturn" : 1000,
        "ntoskip" : 0,
        "nscanned" : 1,
        "nscannedObjects" : 1,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(90),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(2),
                        "w" : NumberLong(1)
                }
        },
        "nreturned" : 1,
        "responseLength" : 169,
        "millis" : 0,
        "execStats" : {
                "type" : "COLLSCAN",
                "works" : 3,
                "yields" : 0,
                "unyields" : 0,
                "invalidates" : 0,
                "advanced" : 1,
                "needTime" : 1,
                "needFetch" : 0,
                "isEOF" : 1,
                "docsTested" : 1,
                "children" : [ ]
        },
        "ts" : ISODate("2020-03-31T08:02:05.076Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "query",
        "ns" : "dev._SCHEMA",
        "query" : {
                "$query" : {

                }
        },
        "ntoreturn" : 1000,
        "ntoskip" : 0,
        "nscanned" : 21,
        "nscannedObjects" : 21,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(91),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(3),
                        "w" : NumberLong(4)
                }
        },
        "nreturned" : 21,
        "responseLength" : 6562,
        "millis" : 0,
        "execStats" : {
                "type" : "COLLSCAN",
                "works" : 23,
                "yields" : 0,
                "unyields" : 0,
                "invalidates" : 0,
                "advanced" : 21,
                "needTime" : 1,
                "needFetch" : 0,
                "isEOF" : 1,
                "docsTested" : 21,
                "children" : [ ]
        },
        "ts" : ISODate("2020-03-31T08:02:05.151Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "command",
        "ns" : "dev.$cmd",
        "command" : {
                "findAndModify" : "_Session",
                "query" : {
                        "_id" : "SJhEylfnb3",
                        "_wperm" : {
                                "$in" : [
                                        null,
                                        "*",
                                        "MoEjAOXpF4"
                                ]
                        }
                },
                "new" : true,
                "remove" : false,
                "upsert" : false,
                "update" : {
                        "$set" : {
                                "_updated_at" : ISODate("2020-03-31T08:02:05.150Z")
                        }
                }
        },
        "updateobj" : {
                "$set" : {
                        "_updated_at" : ISODate("2020-03-31T08:02:05.150Z")
                }
        },
        "nscanned" : 1,
        "nscannedObjects" : 1,
        "nMatched" : 1,
        "nModified" : 1,
        "fastmod" : true,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(0),
                        "w" : NumberLong(278)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(0),
                        "w" : NumberLong(5)
                }
        },
        "responseLength" : 395,
        "millis" : 0,
        "execStats" : {

        },
        "ts" : ISODate("2020-03-31T08:02:05.153Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "query",
        "ns" : "dev._SCHEMA",
        "query" : {
                "$query" : {

                }
        },
        "ntoreturn" : 1000,
        "ntoskip" : 0,
        "nscanned" : 21,
        "nscannedObjects" : 21,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(240),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(5),
                        "w" : NumberLong(3)
                }
        },
        "nreturned" : 21,
        "responseLength" : 6562,
        "millis" : 0,
        "execStats" : {
                "type" : "COLLSCAN",
                "works" : 23,
                "yields" : 0,
                "unyields" : 0,
                "invalidates" : 0,
                "advanced" : 21,
                "needTime" : 1,
                "needFetch" : 0,
                "isEOF" : 1,
                "docsTested" : 21,
                "children" : [ ]
        },
        "ts" : ISODate("2020-03-31T08:02:16.592Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "query",
        "ns" : "dev.Product",
        "query" : {
                "$orderby" : {

                },
                "$query" : {
                        "_rperm" : {
                                "$in" : [
                                        null,
                                        "*",
                                        "*"
                                ]
                        }
                }
        },
        "cursorid" : 82313479072,
        "ntoreturn" : 1000,
        "ntoskip" : 0,
        "nscanned" : 1000,
        "nscannedObjects" : 1000,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(2778),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(3),
                        "w" : NumberLong(3)
                }
        },
        "nreturned" : 1000,
        "responseLength" : 687471,
        "millis" : 2,
        "execStats" : {
                "type" : "COLLSCAN",
                "works" : 1001,
                "yields" : 7,
                "unyields" : 7,
                "invalidates" : 0,
                "advanced" : 1000,
                "needTime" : 1,
                "needFetch" : 0,
                "isEOF" : 0,
                "docsTested" : 1000,
                "children" : [ ]
        },
        "ts" : ISODate("2020-03-31T08:02:16.598Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "getmore",
        "ns" : "dev.Product",
        "cursorid" : 82313479072,
        "ntoreturn" : 1000,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(2151),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(5),
                        "w" : NumberLong(5)
                }
        },
        "nreturned" : 1000,
        "responseLength" : 689544,
        "millis" : 2,
        "execStats" : {

        },
        "ts" : ISODate("2020-03-31T08:02:16.654Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "getmore",
        "ns" : "dev.Product",
        "cursorid" : 82313479072,
        "ntoreturn" : 1000,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(2144),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(2),
                        "w" : NumberLong(4)
                }
        },
        "nreturned" : 1000,
        "responseLength" : 697344,
        "millis" : 2,
        "execStats" : {

        },
        "ts" : ISODate("2020-03-31T08:02:16.690Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "getmore",
        "ns" : "dev.Product",
        "cursorid" : 82313479072,
        "ntoreturn" : 1000,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(1619),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(3),
                        "w" : NumberLong(4)
                }
        },
        "nreturned" : 1000,
        "responseLength" : 694691,
        "millis" : 1,
        "execStats" : {

        },
        "ts" : ISODate("2020-03-31T08:02:16.763Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "getmore",
        "ns" : "dev.Product",
        "cursorid" : 82313479072,
        "ntoreturn" : 1000,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(1525),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(3),
                        "w" : NumberLong(3)
                }
        },
        "nreturned" : 1000,
        "responseLength" : 682413,
        "millis" : 1,
        "execStats" : {

        },
        "ts" : ISODate("2020-03-31T08:02:16.797Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "getmore",
        "ns" : "dev.Product",
        "cursorid" : 82313479072,
        "ntoreturn" : 1000,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(2501),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(4),
                        "w" : NumberLong(3)
                }
        },
        "nreturned" : 1000,
        "responseLength" : 681485,
        "millis" : 2,
        "execStats" : {

        },
        "ts" : ISODate("2020-03-31T08:02:16.837Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "getmore",
        "ns" : "dev.Product",
        "cursorid" : 82313479072,
        "ntoreturn" : 1000,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(1579),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(3),
                        "w" : NumberLong(3)
                }
        },
        "nreturned" : 1000,
        "responseLength" : 691719,
        "millis" : 1,
        "execStats" : {

        },
        "ts" : ISODate("2020-03-31T08:02:16.883Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
Type "it" for more
>

@omkar-tenkale
Copy link
Author

slowquery1

slowquery2

@acinader
Copy link
Contributor

acinader commented Apr 1, 2020

it looks like the getmores are occurring in just a few milis.

there is a bottleneck of some sort.

  1. If your run a query against the database form the server the iterates through all the objects in you parouct tables, how long does it take?

  2. what does a product document 'look like' (i.e. how big is the json text).

  3. what is the network topology between the database server and the parse-server? Are they on the same network? What is latency and bandwidth between the two?

@omkar-tenkale
Copy link
Author

If your run a query against the database form the server the iterates through all the objects in you parouct tables, how long does it take?

In mongoshell its quiet fast,1-2 secs

what does a product document 'look like' (i.e. how big is the json text).

Closely similar to
{
"_id": "y2IEREsCJR",
"_p_createdBy": "Employee$nqzq73IJZn",
"_p_company": "Company$othercmpny",
"_p_brand": "Brand$5KUm1qj624",
"name": "SOME NAM NAME NAME",
"parentName": "SOME NAM NAME NAME",
"ERPName": "SOME NAM NAME NAME",
"description": "SOME NAM NAME NAME",
"quantity": "28",
"season": "SOME",
"sleeve": "",
"basicRate": 1899,
"ERPCode": "2423423523532",
"pattern": "",
"subCategory2": "SLIM FIT",
"HSCode": 0,
"content": "SOME NAM NAME NAME",
"source": "",
"category": "JEANS",
"exciseItem": false,
"subCategory": "SLIM FIT",
"EANCode": 24332543232532,
"neck": "",
"unitOfMeasurement": "SOME NAM NAME NAME",
"SellingPrice": 1899,
"_created_at": "2020-03-13T23:30:32.098Z",
"_updated_at": "2020-03-27T11:36:35.814Z",
}

what is the network topology between the database server and the parse-server? Are they on the same network? What is latency and bandwidth between the two?

Parse server specs
npm list
parse@2.11.0

Server version 3.9.0 (From Parse dashboard app list)

db.version()
2.6.10 <<Can be an issue?

System Ubuntu 16.04
Mongodb at localhost:27017 same server
Mongouri (parse default)

@omkar-tenkale
Copy link
Author

Tried accessing db directly

Included in index.js


const Config = require('./node_modules/parse-server/lib/Config');

  const config = Config.get(Parse.applicationId);
  const mongoAdapter = config.database.adapter;
 
  app.get('/mongotest',async function(req, res) {
    console.time("connect")
     await mongoAdapter.connect();
  const collection = await mongoAdapter.database.collection("Product");
  console.timeEnd("connect")
      console.time("find")

  var response = await collection.find().toArray();
    console.timeEnd("find")
console.log("totals="+response.length)

  res.status(200).send(response);
});

Processed in under 3 seconds,
Console log

0|app1  | connect: 0.375ms
0|app1  | find: 1.701s
0|app1  | totals=58110

@omkar-tenkale
Copy link
Author

So the problem lies not in db but the server

@mtrezza
Copy link
Member

mtrezza commented Apr 2, 2020

Are mongodb and server both run locally?

Sent with GitHawk

@omkar-tenkale
Copy link
Author

On the same Ubuntu 16.04 VPS server

@mtrezza
Copy link
Member

mtrezza commented Apr 2, 2020

  • Monitor your server resources during the slow request. Do CPU, IOPS, network connections, etc max out?

  • Are there any other apps running on Node that could be blocking the Node thread?

  • Profile Node app. For example, https://nodejs.org/en/docs/guides/simple-profiling/

  • Is the response also slow when you deploy the latest version of parse server and mongodb?

  • Debug parse server while running the request and inspect the code to see at which point it is slow.

Sent with GitHawk

@omkar-tenkale
Copy link
Author

Monitor your server resources during the slow request. Do CPU, IOPS, network connections, etc max out?

CPU > There's a visible spike but cpu usage doesn't become 100%
IOPS > Ram usage is increased but still no 100% usage.
RAM normally uses 1.1gb when api is hit it goes to around 400mb then gradually increases till 1.9gb then drops to original 1.1gb.
Strange?Please refer image

There may be a memory leak somewhere but this doesn't constitute to our problem as even a freshly restarted server with 86 mb usage gives slow response
pm2 restart > 86mb > cloudcodehit > 1.9gb gradual > response send > 1.2 gb

network connections > No idea on this,doesnt seem an issue as response is slow when no other client interacting with server

4 times api hit usage>
usage

@omkar-tenkale
Copy link
Author

omkar-tenkale commented Apr 2, 2020

Are there any other apps running on Node that could be blocking the Node thread

There are other pm2 parse instances but even stopping them doesn't solve the issue

@omkar-tenkale
Copy link
Author

Working on other checks.Does this info gives any clues?

@acinader
Copy link
Contributor

acinader commented Apr 2, 2020

db.version()
2.6.10 <<Can be an issue?

Is it possible to upgrade the database server? That is definitely an unsupported db version.

Can you test with >= Mongo 3.6?

@acinader acinader closed this as completed Apr 4, 2020
@omkar-tenkale
Copy link
Author

omkar-tenkale commented Apr 4, 2020

Is the response also slow when you deploy the latest version of parse server and mongodb?

After updating

Parse server specs
npm list
parse@2.12.0
parse-server@4.2.0

Server version 4.2.0 (From Parse dashboard app list)

db.version()
4.2.5

Updating has not solved the issue

@omkar-tenkale
Copy link
Author

This is the transaction details
slowtransaction

@omkar-tenkale
Copy link
Author

txnslow2

@mtrezza
Copy link
Member

mtrezza commented Apr 4, 2020

Did you try to profile the NodeJs app?

Sent with GitHawk

@omkar-tenkale
Copy link
Author

Seems to be related with mongoObjectToParseObject ,

Generated using node --prof index.js ...

This is the full log
processlog.txt

@mtrezza
Copy link
Member

mtrezza commented May 30, 2020

Maybe related to #4658 (comment):

In a previous series of load testing, we realized that JSON serialization of large objects was a large source of CPU consumption, and was inducing latency in the responses as serialization is blocking the node process.

In our case, we decided not to go with the direct access but to let internal cloud code calls reach another server, as it was the most optimal solution for our workload

@dplewis
Copy link
Member

dplewis commented Mar 16, 2021

Closing via #7214

@dplewis dplewis closed this as completed Mar 16, 2021
@dplewis
Copy link
Member

dplewis commented Mar 16, 2021

@omkar-tenkale It would be great if you could try the new master branch and confirm whether #7214 solves performance loss?

@omkar-tenkale
Copy link
Author

This issue made us move away from parse :(

@mtrezza
Copy link
Member

mtrezza commented Mar 19, 2021

@dplewis should we really close this already? We did quite some investigation into this one I remember, and the performance issue was evidently there. I think someone could re-run these perf tests.

@alan19031216
Copy link

may I know what is the solution? I also have the same issues.

@mtrezza mtrezza reopened this Nov 8, 2021
@mtrezza
Copy link
Member

mtrezza commented Nov 8, 2021

Re-opened for further investigation; however, the issues reported by different users here may or may not be related to each other. The underlying issue may be the conversion from MongoDB document to Parse Object which in its currently implementation seems to be quite resource demanding; maybe there is something to be improved.

In any case, we would need someone doing the testing to gather performance data to compare, otherwise we cannot investigate the issue and we may as well close it again.

@mtrezza mtrezza added type:feature New feature or improvement of existing feature and removed type:improvement labels Dec 6, 2021
@SebC99
Copy link
Contributor

SebC99 commented Aug 27, 2022

Old one, but while inspecting our servers for perf diagnostic, I discovered this issue.
It is not directly related but the parseDate.js (from the JS SDK) seems to be the major source of performance issues here:

const regexp = new RegExp('^([0-9]{1,4})-([0-9]{1,2})-([0-9]{1,2})' + 'T' + '([0-9]{1,2}):([0-9]{1,2}):([0-9]{1,2})' + '(.([0-9]+))?' + 'Z$');
const match = regexp.exec(iso8601);

In our case, this code block is taking 1% of our total CPU time 😅

@dplewis
Copy link
Member

dplewis commented Aug 31, 2022

@SebC99 I use query.find({ json: true }) to return the raw data because the JS encode to Parse.Object is slow.

@SebC99
Copy link
Contributor

SebC99 commented Sep 2, 2022

@dplewis I didn't even know we could do that... all the cloudcode could use this, and return json to the clients (we just need to add the __type: "Object" property).
We only need Parse.Object when we have specific parse operations to do on the objects (save/fetch/dirty, etc...)

@oallouch
Copy link
Contributor

@SebC99 I saw similar performance issues with the parseDate function.
Its source is :

export default function parseDate(iso8601: string): ?Date {
  const regexp = new RegExp(
    '^([0-9]{1,4})-([0-9]{1,2})-([0-9]{1,2})' +
      'T' +
      '([0-9]{1,2}):([0-9]{1,2}):([0-9]{1,2})' +
      '(.([0-9]+))?' +
      'Z$'
  );
  const match = regexp.exec(iso8601);
  if (!match) {
    return null;
  }

  const year = parseInt(match[1]) || 0;
  const month = (parseInt(match[2]) || 1) - 1;
  const day = parseInt(match[3]) || 0;
  const hour = parseInt(match[4]) || 0;
  const minute = parseInt(match[5]) || 0;
  const second = parseInt(match[6]) || 0;
  const milli = parseInt(match[8]) || 0;

  return new Date(Date.UTC(year, month, day, hour, minute, second, milli));
}```

I'm not a regexp expert, but shouldn't the regexp creation be outside the function ?

@SebC99
Copy link
Contributor

SebC99 commented May 11, 2023

True
But I don't even think we need the regex. An invalid date would be thrown which can be catch. I don't remember the fastest way to check if a string is a date + creating the date object, but if I remember well, it's not a regex :)

@SebC99
Copy link
Contributor

SebC99 commented May 11, 2023

And If I remember correctly, one issue of course is the parsing which is slow, but all the too many calls to this parsing, as every hooks (beforeFind, afterFind, etc.) create the string objects to log before checking if the log levels are met.

@oallouch
Copy link
Contributor

Oh. Nice find.
You could definitely do something here.

@SebC99
Copy link
Contributor

SebC99 commented May 12, 2023

I've just checked, and the regex is better outside for the function of course, but the impact isn't huge.

Replacing the regex by isNan(Date.parse(string)) or new Date(string) is 5 times faster. It slightly less rigid as it would accept "2022201" as a valid date String, but I don't think it would be an issue for Parse.
And as the encode/decode operations are very very very used, the impact can be significant.

@oallouch
Copy link
Contributor

oallouch commented Sep 8, 2023

@SebC99 any news on this optim ?

@oallouch
Copy link
Contributor

+1

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type:feature New feature or improvement of existing feature
Projects
None yet
Development

No branches or pull requests

9 participants