When querying a (large) class on a non-existing, parse causes huge amounts of iOPS on Mongo

[SebC99]

Issue Description

I have a collection (parse class) with more than 8M documents in it, and when we make a query on a non-indexed field, or even worse on a non-existing field (by mistake), it leads to huge amount of iOPS on MongoDB instances, which leads to a hang of the parse server becoming unreachable (timeout issues).
When I run the same queries via a mongo shell, it takes some time (around 10-20 seconds) but never leads to those kind of amount of iOPS... whereas it should be the exact same query.

Below is a screen capture of the MongoDB metrics, showing the IOPS peak at 10:54 (corresponding to the parse query), and then the IOPS "non peak" at 11:01, 11:03, 11:06 corresponding to the same query via Mongo Shell (reproduced 3 times to be sure).

Any idea?

Environment Setup

• Server

  • parse-server version: 2.6.5
  • Operating System: Amazon Linux
  • Hardware: EC2 M1 Instance
  • Localhost or remote server? AWS (or localhost)

• Database

  • MongoDB version: 3.4
  • Storage engine: wiredTiger
  • Hardware: EC2 M1 Instances
  • Localhost or remote server? Mongo Atlas

[montymxb]

@SebC99 That's not so great :/. This is a hard one for us to replicate... Can you provide details on the queries involved as well as the relevant structure of the classes that this happens on (omitting anything extraneous or sensitive as you need to). If there's nothing suspicious you should take profiles of parse-server while this happening, could help pin down what's causing all the activity a bit more. Additionally any relevant information noted in the logs would be handy (with VERBOSE of course).

[flovilmart]

perhaps the IOPS happened because data went to RAM, then everything was read from there no?

[flovilmart]

In any case I recommend you to use the maxTimeMS to prevent stalling the DB.

  appId: ...
  masterKey: ...
  databaseURL: ...
  databaseOptions: {
    maxTimeMS: 500,
  },

This willl let mongo kill the long query (if it exceeds 500ms)

[SebC99]

@montymxb who can I get that profile of parse-server?
Even with VERBOSE I can only the requested url in logs:

verbose: REQUEST for [GET] /parse/classes/Place?where=%7B%22owner%22:%22me%22%7D: {} method=GET, url=/parse/classes/Place?where=%7B%22owner%22:%22me%22%7D, cache-control=no-cache, x-parse-application-id=XXXX, content-type=application/json, accept=*/*, host=localhost:1337, accept-encoding=gzip, deflate, connection=keep-alive

And then I have this peak in IOPS.

I have a "Place" collection, in which there's 8 millions document. This class doesn't have any field named "owner", but I try to query on this field:

• through Parse server: IOPS peak
• same query in mongo shell (db.Place.find({"owner" : "me"})): no IOPS Peak

The IOPS peak comes with an increase of Read Cache Activity, and with an huge increase in Query Targeting index ("The ratio of the number of documents scanned to the number of documents returned by queries"). The targeting index increases 5 time less with the same query in mongo shell.

Any idea how to investigate more?

[montymxb]

As far as profiling goes there a # of choices, but V8 has a built in one that node js talks about here that would be handy.

Thanks for adding those extra details by the way. I would think that it would simply check _Schema, see that the field in the query does not exist, and simply return out. But instead, from what you're describing, it seems like it's just trying way too much for what should be a simple resolution when the field isn't even present.

[flovilmart]

Ost probably because we add the additional _rperm constraint, making the issue even worst

[steven-supersolid]

As this is a database issue then the mongodb log file would help further diagnose. Both the parse query and the console query take more than 100ms so should both appear in the log. You should be able to download the log for the primary from Atlas on the Cluster Overview and restrict timestamps to cover the range of interest.

You may want to sanitize the log to remove data or if you are up for it run mtools on the log to summarise the data https://github.com/rueckstiess/mtools. I suggest running mloginfo --queries name_of_logfile which will generate a report of queries in the log

Checking schema before querying seems like a great solution.

[SebC99]

Hello, I'm still trying to investigate these performance issues.
When I look at mongoDB live operations, something weird is happening:

• let's say I'm querying a collection with a 10000 limit option
• and that query should return 101 results
  When I run this through parse-server I can see some getMore operation on mongoDB with a batch size of 1000 whereas with 101 results, there shouldn't be any getMore operation at all.

For example, here's an extract of the logs:

2017-12-01T21:36:49.872+0000 I COMMAND  [conn87176] command db.place command: find { find: "place", filter: { _p_addedBy: { $in: [ "_User$3HSZicG3W9" ] }, isPrivate: false, deleted: false, _rperm: { $in: [ null, "*" ] } }, sort: {}, projection: { name: 1, address: 1, geopoint: 1, _p_addedBy: 1, _id: 1, _created_at: 1, _updated_at: 1 }, limit: 10000 } planSummary: IXSCAN { _p_addedBy: 1, deleted: 1, isPrivate: 1 } cursorid:85829072385 keysExamined:101 docsExamined:101 numYields:79 nreturned:101 reslen:63471 locks:{ Global: { acquireCount: { r: 160 } }, Database: { acquireCount: { r: 80 } }, Collection: { acquireCount: { r: 80 } } } protocol:op_query 2274ms
2017-12-01T21:36:55.440+0000 I COMMAND  [conn87174] command db.place command: getMore { getMore: 85829072385, collection: "place", batchSize: 1000 } originatingCommand: { find: "place", filter: { _p_addedBy: { $in: [ "_User$3HSZicG3W9" ] }, isPrivate: false, deleted: false, _rperm: { $in: [ null, "*" ] } }, sort: {}, projection: { name: 1, address: 1, geopoint: 1, _p_addedBy: 1, _id: 1, _created_at: 1, _updated_at: 1 }, limit: 10000 } planSummary: IXSCAN { _p_addedBy: 1, deleted: 1, isPrivate: 1 } cursorid:85829072385 keysExamined:698 docsExamined:698 cursorExhausted:1 numYields:183 nreturned:698 reslen:455003 locks:{ Global: { acquireCount: { r: 368 } }, Database: { acquireCount: { r: 184 } }, Collection: { acquireCount: { r: 184 } } } protocol:op_query 5561ms
2017-12-01T21:36:55.442+0000 I COMMAND  [conn87175] command db.place command: getMore { getMore: 83739267493, collection: "place", batchSize: 1000 } originatingCommand: { find: "place", filter: { _p_addedBy: { $in: [ "_User$3HSZicG3W9" ] }, isPrivate: false, deleted: false, _rperm: { $in: [ null, "*" ] } }, sort: {}, projection: { name: 1, address: 1, geopoint: 1, _p_addedBy: 1, _id: 1, _created_at: 1, _updated_at: 1 }, limit: 10000 } planSummary: IXSCAN { _p_addedBy: 1, deleted: 1, isPrivate: 1 } cursorid:83739267493 keysExamined:698 docsExamined:698 cursorExhausted:1 numYields:181 nreturned:698 reslen:455003 locks:{ Global: { acquireCount: { r: 364 } }, Database: { acquireCount: { r: 182 } }, Collection: { acquireCount: { r: 182 } } } protocol:op_query 5560ms

When running in shell, the same query doesn't seem to trigger getMore operations...
Hope that helps!

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.