MongoDB running slow with Meteor app

Ingaborg · May 2, 2018, 9:48am

My MongoDB database is running very slowly and I’m having trouble figuring out what is the problem. From the logfile /var/log/mongodb/mongod.log it seems to me that:

Queries are taking over 100ms to run even though they are using indexes.
The database is being queried continually even though I am only looking at the site, not interacting with it.
There seem to be multiple connections listed for a single user.

The app runs fine on my local machine with a copy of the live database, which only has a few hundred documents. But on the production server it is unusably slow with 3 or 4 users connected.

I’ve been reading about oplog and oplog tailing but I haven’t found a clear, up-to-date explanation of how to set it up or whether it really is what I need. Shouldn’t the default setup work OK for a small app with not that many users?

I’d be grateful for any suggestions or ideas how to figure out what I’m doing wrong.

System:

METEOR@1.6.0.1 running on a Digital Ocean droplet (Ubuntu 16.04)

Deployed using Phusion Passenger 5.2.3

MongoDB version 3.4.1

Here’s a typical extract from the logfile:

2018-04-25T10:59:07.986+0000 I COMMAND  [conn96] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: null } ] }, sort: { name_sort: 1 }, skip: 36, limit: 12 } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } keysExamined:134 docsExamined:133 hasSortStage:1 cursorExhausted:1 numYields:7 nreturned:12 reslen:1536157 locks:{ Global: { acquireCount: { r: 16 } }, MMAPV1Journal: { acquireCount: { r: 8 } }, Database: { acquireCount: { r: 8 } }, Collection: { acquireCount: { R: 8 } } } protocol:op_query 105ms
2018-04-25T10:59:08.002+0000 I COMMAND  [conn98] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: null } ] }, sort: { name_sort: 1 }, skip: 12, limit: 12 } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } keysExamined:134 docsExamined:133 hasSortStage:1 cursorExhausted:1 numYields:8 nreturned:12 reslen:2226386 locks:{ Global: { acquireCount: { r: 18 } }, MMAPV1Journal: { acquireCount: { r: 9 } }, Database: { acquireCount: { r: 9 } }, Collection: { acquireCount: { R: 9 } } } protocol:op_query 131ms
2018-04-25T10:59:08.055+0000 I COMMAND  [conn95] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user3_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:83336218087 keysExamined:101 docsExamined:101 numYields:10 nreturned:101 reslen:13408742 locks:{ Global: { acquireCount: { r: 22 } }, MMAPV1Journal: { acquireCount: { r: 11 } }, Database: { acquireCount: { r: 11 } }, Collection: { acquireCount: { R: 11 } } } protocol:op_query 162ms
2018-04-25T10:59:13.826+0000 I COMMAND  [conn97] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user1_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:84388091558 keysExamined:109 docsExamined:101 numYields:9 nreturned:101 reslen:15163185 locks:{ Global: { acquireCount: { r: 20 } }, MMAPV1Journal: { acquireCount: { r: 10 } }, Database: { acquireCount: { r: 10 } }, Collection: { acquireCount: { R: 10 } } } protocol:op_query 167ms
2018-04-25T10:59:16.226+0000 I COMMAND  [conn96] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: null } ] }, sort: { name_sort: 1 }, skip: 48, limit: 12 } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } keysExamined:134 docsExamined:133 hasSortStage:1 cursorExhausted:1 numYields:7 nreturned:12 reslen:1812760 locks:{ Global: { acquireCount: { r: 16 } }, MMAPV1Journal: { acquireCount: { r: 8 } }, Database: { acquireCount: { r: 8 } }, Collection: { acquireCount: { R: 8 } } } protocol:op_query 137ms
2018-04-25T10:59:16.231+0000 I COMMAND  [conn97] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: null } ] }, sort: { name_sort: 1 }, skip: 84, limit: 12 } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } keysExamined:134 docsExamined:133 hasSortStage:1 cursorExhausted:1 numYields:7 nreturned:12 reslen:1516442 locks:{ Global: { acquireCount: { r: 16 } }, MMAPV1Journal: { acquireCount: { r: 8 } }, Database: { acquireCount: { r: 8 } }, Collection: { acquireCount: { R: 8 } } } protocol:op_query 119ms
2018-04-25T10:59:16.237+0000 I COMMAND  [conn95] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: null } ] }, sort: { name_sort: 1 }, limit: 12 } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } keysExamined:134 docsExamined:133 hasSortStage:1 cursorExhausted:1 numYields:8 nreturned:12 reslen:1671866 locks:{ Global: { acquireCount: { r: 18 } }, MMAPV1Journal: { acquireCount: { r: 9 } }, Database: { acquireCount: { r: 9 } }, Collection: { acquireCount: { R: 9 } } } protocol:op_query 149ms
2018-04-25T10:59:16.288+0000 I COMMAND  [conn94] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user2_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:85501389604 keysExamined:101 docsExamined:101 numYields:8 nreturned:101 reslen:13271844 locks:{ Global: { acquireCount: { r: 18 } }, MMAPV1Journal: { acquireCount: { r: 9 } }, Database: { acquireCount: { r: 9 } }, Collection: { acquireCount: { R: 9 } } } protocol:op_query 187ms
2018-04-25T10:59:18.072+0000 I COMMAND  [conn95] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user3_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:82711174454 keysExamined:101 docsExamined:101 numYields:9 nreturned:101 reslen:13408742 locks:{ Global: { acquireCount: { r: 20 } }, MMAPV1Journal: { acquireCount: { r: 10 } }, Database: { acquireCount: { r: 10 } }, Collection: { acquireCount: { R: 10 } } } protocol:op_query 171ms
2018-04-25T10:59:18.077+0000 I COMMAND  [conn94] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: null } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:83227284863 keysExamined:101 docsExamined:101 numYields:8 nreturned:101 reslen:13656126 locks:{ Global: { acquireCount: { r: 18 } }, MMAPV1Journal: { acquireCount: { r: 9 } }, Database: { acquireCount: { r: 9 } }, Collection: { acquireCount: { R: 9 } } } protocol:op_query 153ms
2018-04-25T10:59:18.173+0000 I COMMAND  [conn96] command mydb.mycollection command: getMore { getMore: 85501389604, collection: "mycollection", batchSize: 1000 } originatingCommand: { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user2_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:85501389604 keysExamined:39 docsExamined:38 cursorExhausted:1 numYields:6 nreturned:38 reslen:7396099 locks:{ Global: { acquireCount: { r: 14 } }, MMAPV1Journal: { acquireCount: { r: 7 } }, Database: { acquireCount: { r: 7 } }, Collection: { acquireCount: { R: 7 } } } protocol:op_query 138ms
2018-04-25T10:59:23.882+0000 I COMMAND  [conn95] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: null } ] }, sort: { name_sort: 1 }, skip: 132, limit: 12 } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } keysExamined:134 docsExamined:133 hasSortStage:1 cursorExhausted:1 numYields:9 nreturned:1 reslen:852679 locks:{ Global: { acquireCount: { r: 20 } }, MMAPV1Journal: { acquireCount: { r: 10 } }, Database: { acquireCount: { r: 10 } }, Collection: { acquireCount: { R: 10 } } } protocol:op_query 149ms
2018-04-25T10:59:23.958+0000 I COMMAND  [conn94] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user1_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:85689537829 keysExamined:109 docsExamined:101 numYields:17 nreturned:101 reslen:15163185 locks:{ Global: { acquireCount: { r: 36 } }, MMAPV1Journal: { acquireCount: { r: 18 } }, Database: { acquireCount: { r: 18 } }, Collection: { acquireCount: { R: 18 } } } protocol:op_query 285ms
2018-04-25T10:59:26.235+0000 I COMMAND  [conn95] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: null } ] }, sort: { name_sort: 1 }, skip: 120, limit: 12 } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } keysExamined:134 docsExamined:133 hasSortStage:1 cursorExhausted:1 numYields:5 nreturned:12 reslen:2429543 locks:{ Global: { acquireCount: { r: 12 } }, MMAPV1Journal: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 6 } }, Collection: { acquireCount: { R: 6 } } } protocol:op_query 123ms
2018-04-25T10:59:28.007+0000 I COMMAND  [conn97] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: null } ] }, sort: { name_sort: 1 }, skip: 12, limit: 12 } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } keysExamined:134 docsExamined:133 hasSortStage:1 cursorExhausted:1 numYields:7 nreturned:12 reslen:2226386 locks:{ Global: { acquireCount: { r: 16 } }, MMAPV1Journal: { acquireCount: { r: 8 } }, Database: { acquireCount: { r: 8 } }, Collection: { acquireCount: { R: 8 } } } protocol:op_query 124ms
2018-04-25T10:59:28.258+0000 I COMMAND  [conn95] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: null } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:84936294363 keysExamined:101 docsExamined:101 numYields:10 nreturned:101 reslen:13656126 locks:{ Global: { acquireCount: { r: 22 } }, MMAPV1Journal: { acquireCount: { r: 11 } }, Database: { acquireCount: { r: 11 } }, Collection: { acquireCount: { R: 11 } } } protocol:op_query 254ms
2018-04-25T10:59:33.777+0000 I COMMAND  [conn94] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user1_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:81855053356 keysExamined:109 docsExamined:101 numYields:7 nreturned:101 reslen:15163185 locks:{ Global: { acquireCount: { r: 16 } }, MMAPV1Journal: { acquireCount: { r: 8 } }, Database: { acquireCount: { r: 8 } }, Collection: { acquireCount: { R: 8 } } } protocol:op_query 110ms
2018-04-25T10:59:36.212+0000 I COMMAND  [conn96] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: null } ] }, sort: { name_sort: 1 }, skip: 48, limit: 12 } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } keysExamined:134 docsExamined:133 hasSortStage:1 cursorExhausted:1 numYields:7 nreturned:12 reslen:1812760 locks:{ Global: { acquireCount: { r: 16 } }, MMAPV1Journal: { acquireCount: { r: 8 } }, Database: { acquireCount: { r: 8 } }, Collection: { acquireCount: { R: 8 } } } protocol:op_query 104ms
2018-04-25T10:59:36.295+0000 I COMMAND  [conn95] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user2_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:81865981454 keysExamined:101 docsExamined:101 numYields:9 nreturned:101 reslen:13271844 locks:{ Global: { acquireCount: { r: 20 } }, MMAPV1Journal: { acquireCount: { r: 10 } }, Database: { acquireCount: { r: 10 } }, Collection: { acquireCount: { R: 10 } } } protocol:op_query 181ms
2018-04-25T10:59:38.049+0000 I COMMAND  [conn98] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: null } ] }, sort: { name_sort: 1 }, skip: 24, limit: 12 } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } keysExamined:134 docsExamined:133 hasSortStage:1 cursorExhausted:1 numYields:8 nreturned:12 reslen:1303021 locks:{ Global: { acquireCount: { r: 18 } }, MMAPV1Journal: { acquireCount: { r: 9 } }, Database: { acquireCount: { r: 9 } }, Collection: { acquireCount: { R: 9 } } } protocol:op_query 161ms
2018-04-25T10:59:38.087+0000 I COMMAND  [conn97] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: null } ] }, sort: { name_sort: 1 }, skip: 36, limit: 12 } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } keysExamined:134 docsExamined:133 hasSortStage:1 cursorExhausted:1 numYields:9 nreturned:12 reslen:1536157 locks:{ Global: { acquireCount: { r: 20 } }, MMAPV1Journal: { acquireCount: { r: 10 } }, Database: { acquireCount: { r: 10 } }, Collection: { acquireCount: { R: 10 } } } protocol:op_query 199ms
2018-04-25T10:59:38.113+0000 I COMMAND  [conn95] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: null } ] }, sort: { name_sort: 1 }, skip: 12, limit: 12 } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } keysExamined:134 docsExamined:133 hasSortStage:1 cursorExhausted:1 numYields:9 nreturned:12 reslen:2226386 locks:{ Global: { acquireCount: { r: 20 } }, MMAPV1Journal: { acquireCount: { r: 10 } }, Database: { acquireCount: { r: 10 } }, Collection: { acquireCount: { R: 10 } } } protocol:op_query 226ms
2018-04-25T10:59:38.300+0000 I COMMAND  [conn94] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: null } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:81961357963 keysExamined:101 docsExamined:101 numYields:10 nreturned:101 reslen:13656126 locks:{ Global: { acquireCount: { r: 22 } }, MMAPV1Journal: { acquireCount: { r: 11 } }, Database: { acquireCount: { r: 11 } }, Collection: { acquireCount: { R: 11 } } } protocol:op_query 327ms
2018-04-25T10:59:43.808+0000 I COMMAND  [conn95] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user1_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:81883376628 keysExamined:109 docsExamined:101 numYields:8 nreturned:101 reslen:15163185 locks:{ Global: { acquireCount: { r: 18 } }, MMAPV1Journal: { acquireCount: { r: 9 } }, Database: { acquireCount: { r: 9 } }, Collection: { acquireCount: { R: 9 } } } protocol:op_query 143ms
2018-04-25T11:00:03.764+0000 I COMMAND  [conn95] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user1_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:83376889974 keysExamined:109 docsExamined:101 numYields:7 nreturned:101 reslen:15163185 locks:{ Global: { acquireCount: { r: 16 } }, MMAPV1Journal: { acquireCount: { r: 8 } }, Database: { acquireCount: { r: 8 } }, Collection: { acquireCount: { R: 8 } } } protocol:op_query 111ms
2018-04-25T11:00:13.787+0000 I COMMAND  [conn97] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user1_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:84784676389 keysExamined:109 docsExamined:101 numYields:6 nreturned:101 reslen:15163185 locks:{ Global: { acquireCount: { r: 14 } }, MMAPV1Journal: { acquireCount: { r: 7 } }, Database: { acquireCount: { r: 7 } }, Collection: { acquireCount: { R: 7 } } } protocol:op_query 118ms
2018-04-25T11:00:43.795+0000 I COMMAND  [conn96] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user1_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:82406146359 keysExamined:109 docsExamined:101 numYields:6 nreturned:101 reslen:15163185 locks:{ Global: { acquireCount: { r: 14 } }, MMAPV1Journal: { acquireCount: { r: 7 } }, Database: { acquireCount: { r: 7 } }, Collection: { acquireCount: { R: 7 } } } protocol:op_query 126ms
2018-04-25T11:00:58.105+0000 I COMMAND  [conn95] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user3_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:82192722075 keysExamined:101 docsExamined:101 numYields:7 nreturned:101 reslen:13408742 locks:{ Global: { acquireCount: { r: 16 } }, MMAPV1Journal: { acquireCount: { r: 8 } }, Database: { acquireCount: { r: 8 } }, Collection: { acquireCount: { R: 8 } } } protocol:op_query 103ms
2018-04-25T11:01:18.097+0000 I COMMAND  [conn97] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user3_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:84413219787 keysExamined:101 docsExamined:101 numYields:6 nreturned:101 reslen:13408742 locks:{ Global: { acquireCount: { r: 14 } }, MMAPV1Journal: { acquireCount: { r: 7 } }, Database: { acquireCount: { r: 7 } }, Collection: { acquireCount: { R: 7 } } } protocol:op_query 111ms
2018-04-25T11:01:23.823+0000 I COMMAND  [conn98] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user1_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:82892140473 keysExamined:109 docsExamined:101 numYields:7 nreturned:101 reslen:15163185 locks:{ Global: { acquireCount: { r: 16 } }, MMAPV1Journal: { acquireCount: { r: 8 } }, Database: { acquireCount: { r: 8 } }, Collection: { acquireCount: { R: 8 } } } protocol:op_query 145ms
2018-04-25T11:02:03.784+0000 I COMMAND  [conn95] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user1_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:82310902412 keysExamined:109 docsExamined:101 numYields:5 nreturned:101 reslen:15163185 locks:{ Global: { acquireCount: { r: 12 } }, MMAPV1Journal: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 6 } }, Collection: { acquireCount: { R: 6 } } } protocol:op_query 107ms
2018-04-25T11:02:33.788+0000 I COMMAND  [conn98] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user1_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:81823088573 keysExamined:109 docsExamined:101 numYields:5 nreturned:101 reslen:15163185 locks:{ Global: { acquireCount: { r: 12 } }, MMAPV1Journal: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 6 } }, Collection: { acquireCount: { R: 6 } } } protocol:op_query 108ms
2018-04-25T11:02:43.791+0000 I COMMAND  [conn94] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user1_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:84344130917 keysExamined:109 docsExamined:101 numYields:7 nreturned:101 reslen:15163185 locks:{ Global: { acquireCount: { r: 16 } }, MMAPV1Journal: { acquireCount: { r: 8 } }, Database: { acquireCount: { r: 8 } }, Collection: { acquireCount: { R: 8 } } } protocol:op_query 112ms
2018-04-25T11:04:33.821+0000 I COMMAND  [conn98] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user1_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:85552175444 keysExamined:109 docsExamined:101 numYields:8 nreturned:101 reslen:15163185 locks:{ Global: { acquireCount: { r: 18 } }, MMAPV1Journal: { acquireCount: { r: 9 } }, Database: { acquireCount: { r: 9 } }, Collection: { acquireCount: { R: 9 } } } protocol:op_query 127ms
2018-04-25T12:40:14.616+0000 I COMMAND  [conn98] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user1_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:83783641075 keysExamined:109 docsExamined:101 numYields:6 nreturned:101 reslen:15163185 locks:{ Global: { acquireCount: { r: 14 } }, MMAPV1Journal: { acquireCount: { r: 7 } }, Database: { acquireCount: { r: 7 } }, Collection: { acquireCount: { R: 7 } } } protocol:op_query 106ms
2018-04-25T12:40:28.907+0000 I COMMAND  [conn95] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user3_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:83691420199 keysExamined:101 docsExamined:101 numYields:8 nreturned:101 reslen:13408742 locks:{ Global: { acquireCount: { r: 18 } }, MMAPV1Journal: { acquireCount: { r: 9 } }, Database: { acquireCount: { r: 9 } }, Collection: { acquireCount: { R: 9 } } } protocol:op_query 151ms
2018-04-25T12:40:28.932+0000 I COMMAND  [conn97] command mydb.mycollection command: find { find: "mycollection", filter: { private: { $ne: true } } } planSummary: IXSCAN { private: 1 } cursorid:85014875379 keysExamined:101 docsExamined:101 numYields:9 nreturned:101 reslen:13656126 locks:{ Global: { acquireCount: { r: 20 } }, MMAPV1Journal: { acquireCount: { r: 10 } }, Database: { acquireCount: { r: 10 } }, Collection: { acquireCount: { R: 10 } } } protocol:op_query 199ms
2018-04-25T12:40:34.618+0000 I COMMAND  [conn97] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user1_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:81942241093 keysExamined:109 docsExamined:101 numYields:7 nreturned:101 reslen:15163185 locks:{ Global: { acquireCount: { r: 16 } }, MMAPV1Journal: { acquireCount: { r: 8 } }, Database: { acquireCount: { r: 8 } }, Collection: { acquireCount: { R: 8 } } } protocol:op_query 106ms
2018-04-25T12:44:24.658+0000 I COMMAND  [conn94] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user1_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:82494645813 keysExamined:109 docsExamined:101 numYields:8 nreturned:101 reslen:15163185 locks:{ Global: { acquireCount: { r: 18 } }, MMAPV1Journal: { acquireCount: { r: 9 } }, Database: { acquireCount: { r: 9 } }, Collection: { acquireCount: { R: 9 } } } protocol:op_query 113ms
2018-04-25T12:46:08.743+0000 I COMMAND  [conn97] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user2_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:83393262122 keysExamined:101 docsExamined:101 numYields:7 nreturned:101 reslen:13271844 locks:{ Global: { acquireCount: { r: 16 } }, MMAPV1Journal: { acquireCount: { r: 8 } }, Database: { acquireCount: { r: 8 } }, Collection: { acquireCount: { R: 8 } } } protocol:op_query 106ms
2018-04-25T12:46:14.668+0000 I COMMAND  [conn96] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user1_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:83287023997 keysExamined:109 docsExamined:101 numYields:6 nreturned:101 reslen:15163185 locks:{ Global: { acquireCount: { r: 14 } }, MMAPV1Journal: { acquireCount: { r: 7 } }, Database: { acquireCount: { r: 7 } }, Collection: { acquireCount: { R: 7 } } } protocol:op_query 117ms
2018-04-25T12:46:55.673+0000 I COMMAND  [conn94] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user3_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:85500377486 keysExamined:101 docsExamined:101 numYields:4 nreturned:101 reslen:13408742 locks:{ Global: { acquireCount: { r: 10 } }, MMAPV1Journal: { acquireCount: { r: 5 } }, Database: { acquireCount: { r: 5 } }, Collection: { acquireCount: { R: 5 } } } protocol:op_query 144ms
2018-04-25T12:46:58.776+0000 I COMMAND  [conn95] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user2_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:81656430938 keysExamined:101 docsExamined:101 numYields:8 nreturned:101 reslen:13271844 locks:{ Global: { acquireCount: { r: 18 } }, MMAPV1Journal: { acquireCount: { r: 9 } }, Database: { acquireCount: { r: 9 } }, Collection: { acquireCount: { R: 9 } } } protocol:op_query 135ms
2018-04-25T12:46:59.117+0000 I COMMAND  [conn98] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user3_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:85243285750 keysExamined:101 docsExamined:101 numYields:9 nreturned:101 reslen:13408742 locks:{ Global: { acquireCount: { r: 20 } }, MMAPV1Journal: { acquireCount: { r: 10 } }, Database: { acquireCount: { r: 10 } }, Collection: { acquireCount: { R: 10 } } } protocol:op_query 170ms
2018-04-25T12:47:04.677+0000 I COMMAND  [conn94] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user1_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:85651420717 keysExamined:109 docsExamined:101 numYields:5 nreturned:101 reslen:15163185 locks:{ Global: { acquireCount: { r: 12 } }, MMAPV1Journal: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 6 } }, Collection: { acquireCount: { R: 6 } } } protocol:op_query 112ms
2018-04-25T12:47:08.745+0000 I COMMAND  [conn95] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user2_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:84542545523 keysExamined:101 docsExamined:101 numYields:5 nreturned:101 reslen:13271844 locks:{ Global: { acquireCount: { r: 12 } }, MMAPV1Journal: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 6 } }, Collection: { acquireCount: { R: 6 } } } protocol:op_query 104ms
2018-04-25T13:36:39.739+0000 I COMMAND  [conn96] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user3_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:83367894125 keysExamined:101 docsExamined:101 numYields:10 nreturned:101 reslen:13408742 locks:{ Global: { acquireCount: { r: 22 } }, MMAPV1Journal: { acquireCount: { r: 11 } }, Database: { acquireCount: { r: 11 } }, Collection: { acquireCount: { R: 11 } } } protocol:op_query 160ms
2018-04-25T13:36:40.552+0000 I COMMAND  [conn97] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: null } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:85829377385 keysExamined:101 docsExamined:101 numYields:5 nreturned:101 reslen:13656126 locks:{ Global: { acquireCount: { r: 12 } }, MMAPV1Journal: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 6 } }, Collection: { acquireCount: { R: 6 } } } protocol:op_query 106ms
2018-04-25T13:36:44.958+0000 I COMMAND  [conn96] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user1_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:85645824554 keysExamined:109 docsExamined:101 numYields:5 nreturned:101 reslen:15163185 locks:{ Global: { acquireCount: { r: 12 } }, MMAPV1Journal: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 6 } }, Collection: { acquireCount: { R: 6 } } } protocol:op_query 103ms
2018-04-25T13:37:40.646+0000 I COMMAND  [conn96] command mydb.mycollection command: find { find: "mycollection", filter: { $or: [ { private: { $ne: true } }, { created_by: "user3_id" } ] } } planSummary: IXSCAN { created_by: 1 }, IXSCAN { private: 1 } cursorid:85301123581 keysExamined:101 docsExamined:101 numYields:6 nreturned:101 reslen:13408742 locks:{ Global: { acquireCount: { r: 14 } }, MMAPV1Journal: { acquireCount: { r: 7 } }, Database: { acquireCount: { r: 7 } }, Collection: { acquireCount: { R: 7 } } } protocol:op_query 105ms

Here is part of the schema and code that sets up the collection and indexes. There are more fields in the collection in the real code but they are not used in the queries.

var Schema = new SimpleSchema({
	'created_at': {
		'type': Number,
		'label': 'Created at',
	},
	'created_by': {
		'type': String,
		'label': 'Created by',
	},
	'private': {
		'type': Boolean,
		'label': 'Private',
		'optional': true,
	},
});

MyCollection = new Meteor.Collection('mycollection');

if (Meteor.isServer) {
	MyCollection.rawCollection().createIndex( {'created_by': 1} );
	MyCollection.rawCollection().createIndex( {'private': 1} );
	MyCollection.rawCollection().createIndex( {'created_at': -1} );
}

MyCollection.attachSchema(Schema);

SkyRooms · May 3, 2018, 3:31am

Get Kadira, without it you will be blind.

vigorwebsolutions · May 3, 2018, 3:56am

While you can definitely run meteor/mongo on the same server, I’d strongly suggest checking out something like mlab (which offers a free tier).

I haven’t run a meteor project without oplog in a long time, but I would expect there to be performance issues, especially on a shared server setup like the one you are describing.

theara · May 3, 2018, 8:44am

@vigorwebsolutions, Which one better mLab VS Compose (Feature and Price)?
Could you share?

Ingaborg · May 3, 2018, 11:05am

Hasn’t Kadira shut down?

https://kadira.io/

Ingaborg · May 3, 2018, 11:10am

Hi, can you explain please why is it better to use an external server for the database?

The mlab free tier seems to be for sandboxing. Would it be suitable for deployment data that I care about?

https://mlab.com/plans/pricing/

SkyRooms · May 3, 2018, 3:29pm

You need to get to NodeChef to use Kadiara. It will help you solve your problems. $10 a month.

I’m hosted with mLab. They’re great.

Sure you can host yourself, but good luck trying to get that sorted out.

vigorwebsolutions · May 3, 2018, 3:56pm

There are a number of performance reasons why you wouldn’t want to share a server between your app code and your db – you ideally want each of those to be able to scale independently. Also, per https://12factor.net/backing-services, you want to be able to quickly/easily swap out pieces of your app. Co-locating your db and code means you can’t switch out that server without addressing both needs.

Didn’t know you were in production, so yeah, a sandbox might not be a good fit, then. The $15/mo shared tier has been good for me on smaller apps, and the price point is easy to justify once you realize that anything more than 15 min/mo spent on mongodb devops is covered by that cost.

Just my two cents, though =)

Ingaborg · May 3, 2018, 5:52pm

Thanks, that’s interesting to know and it would be great to have more visibility.

I’m currently paying $6 per month for a Digital Ocean droplet on which I have several prototype apps and my one ‘live’ one which I think is never going to be huge as it’s quite niche. It’s so nearly working that I hate to give up - other folks must have got the same setup working?

SkyRooms · May 3, 2018, 6:51pm

@Ingaborg the fact you’re still asking these questions indicates you don’t have the skills to run your own professional setup.

Use Galaxy + mLab and focus on developing your app.

Anything else is a huge waste of time lol. Trust me…

doctorpangloss · May 5, 2018, 12:29am

I’ll answer your question for you.

First, to get started with the oplog, take a look at my notes here:

It’s hard to say with a Digital Ocean droplet what its performance limitations are. It must be a little related, because it runs fine on your laptop. Cheap instances are extremely slow, like as slow as $35 Raspberry Pis slow.

Judging from your logs, your documents are very large, which is what’ slowing things down pretty badly. IO on instances like these is very, very slow, it could conceivably take 100ms to read these 15MB worth of document data.

Your index doesn’t help you here. It doesn’t matter if you indexed “private,” you’re scanning a lot of documents anyway because it seems like you actually need all the documents.

If you switch to a dedicated database provider, it will probably go a lot slower. You’re transferring a lot of data.

Oplog will help, but it really depends on your application; are you making small changes to large documents? If yes, it will help a lot. Large changes to large documents will still be pretty slow, but not this slow.

It looks like you’re probably storing image or file data. Considering using S3 instead, its better suited for this problem.

Ingaborg · May 7, 2018, 5:54pm

Thank you. Image data is on S3, but the body of the document is in MongoDB, however I don’t think my documents are very large - maybe 40kb for the main text field. And on the listings page I have been careful only to request the fields that are required, which are small e.g. document id, id of creator, name.

So I wouldn’t think I’m loading an excessive amount of data?

I originally deployed using mup-legacy a couple of years ago and that was fine. The problem started when I upgraded from Meteor 1.2 to Meteor 1.6 and couldn’t get mupx to work. So I switched to Phusion Passenger, and now I have these problems.

doctorpangloss · May 7, 2018, 11:13pm

That’s interesting. I suspected the document sizes were unusual because your logs show 15MB responses (the reslength part) for 100 some documents, which is consistent with what you’re saying but is still “large” in the sense of being many.

I’m pretty confident if you e.g. tested your code to just retrieve the _id fields, you’ll see everything is zippity quick. All these other things you’re pointing out aren’t as big of a red flag as the logs, so I think you were right to look at them first. My interpretation may be wrong though.

SkyRooms · May 8, 2018, 1:17am

Stop wasting your time. Get Kadira on Galaxy or NodeChef and fix your problem.

I wasted 40 hours goofing around, 10 minutes after I bit the bullet at NodeChef problem was solved – and very obvious.

Until you do this, no one can help you.

Ingaborg · May 8, 2018, 10:18am

Thanks, I’m looking into a dedicated Meteor hosting service. scalingo also looks reasonable, does anybody know a reason to pick either NodeChef or Scalingo?

doctorpangloss · May 10, 2018, 12:39am

That part of the log is trying to say that you transferred 15MB from your database to get 101 documents. That’s 150KB documents. Without oplog enabled, you’ll see that every five seconds, which is exactly what appears in your logs. You’ll probably see significantly reduced latency if you enable oplog.

I’m not sure if this is wasting time per-se, your logs are telling you exactly what the issue is. You should probably enable oplog, and use limit in your queries. Don’t page on the client. I don’t think just using an external service, insofar as it will create an oplog user and replica set for you (which are exactly two commands), will help you here.

Ingaborg · May 10, 2018, 8:59am

Thanks! Yes, maybe pagination is part of the problem, I am using alethes:pages. I expected that a plugin would be smart enough to page on the server, not the client, but maybe it is not, I will check that out.

I now have several things to look at and try out, thank you everybody!

Ingaborg · May 11, 2018, 8:29am

Can anybody explain to me why there are so many connections per user and whether that is an issue? Thank you!

doctorpangloss · May 12, 2018, 12:32am

Regarding alethes:pages, looking at their code…

github.com

alethes/meteor-pages/blob/d04eef808e388f4abf9f857e9ade1650913c6917/lib/pages.coffee#L918


# The contents will be updated (as will the page) as data arrives from the server


if @infinite
  n = @Collection.find({},
    fields: @fields
    sort: @sort
  ).count()
  c = @Collection.find({},
    fields: @fields
    sort: @sort
    skip: if n > @infiniteItemsLimit then n - @infiniteItemsLimit else 0
    limit: @sess("limit") or @infiniteItemsLimit
  )
else
  c = @Collection.find(
    _.object([
      ["_#{@id}_p", page]
    ]),
    fields: @fields
    sort: _.object([
      ["_#{@id}_i", 1]

The package uses skip and limit to do paging. The thing about skip is that, on mongo, it requires scanning all the documents prior to the skip anyway. A skip and limit paging implementation is inherently inefficient, and it’s probably part of the reason your database queries return a hundred documents (I assume all the products) despite a user maybe looking at just 12.

As an aside, the correct way to do paging is to precompute a sort order number for each document (i.e., product), add an index for the field used for the sort order number, and use $gte and $lt in your query to specify the page. It’s generally smart to preload the next page, and this will give you the absolute best UX for paging. For the most robust to program, you generally have to just cache pages (i.e., save a mongo document representing a whole page of search results) for each query (which is a combination of search terms, categories and page number), providing a brief delay for users who make uncommon queries. This is more or less what Amazon does, and isn’t nearly as complicated as it seems, especially not in an architecture like Meteor.

The connections per user is a little bit more surprising. If you mean subscriptions, alethes:pages does indeed create at most 20 subscriptions (1 for each page before it starts recycling):

github.com

alethes/meteor-pages/blob/d04eef808e388f4abf9f857e9ade1650913c6917/lib/pages.coffee#L40


auth: [false, Match.Optional(Function), undefined]
availableSettings: [false, Object, {}]
fastRender: [false, Boolean, false]
homeRoute: [false, Match.OneOf(String, Array, Boolean), "/"]
infinite: [false, Boolean, false]
infiniteItemsLimit: [false, Number, Infinity]
infiniteTrigger: [false, Number, .9]
infiniteRateLimit: [false, Number, 1]
infiniteStep: [false, Number, 10]
initPage: [false, Number, 1]
maxSubscriptions: [false, Number, 20]
navTemplate: [false, String, "_pagesNavCont"]
onDeniedSetting: [false, Function, (k, v, e) -> console?.log "Changing #{k} not allowed."]
pageCountFrequency: [false, Number, 10000]
pageSizeLimit: [false, Number, 60]
pageTemplate: [false, String, "_pagesPageCont"]
rateLimit: [false, Number, 1]
routeSettings: [false, Match.Optional(Function), undefined]
scrollBoxSelector: [ String, undefined ]
scrollContentSelector: [ String, undefined ]
table: [false, Match.OneOf(Boolean, Object), false]

If you mean connections according to mongo, that I’m not sure about.

Ingaborg · May 12, 2018, 9:16am

Thank you so much for all your help and advice. Now that you have helped me to understand the logs, I’ve checked my code more carefully and in fact I was not limiting certain queries. I thought I was but I was mistakenly only setting limits on the client. Fixing that has made the database much happier! I am still looking at other issues and the possibility of oplog tailing, but setting limits alone seems to have made the difference between “OK” and “not OK”. Thanks again!