Closed simllll closed 5 years ago
vkarpov15
commented
6 years ago Are any of these operations exceptionally slow? Also, do you have any place where you're explicitly disconnecting? Those are 2 possible explanations. Also, do you have noCursorTimeout set for the query you're running eachAsync on?
simllll
commented
6 years ago Well, the query is a fetch all query from one collection. No query conditions, one iteration is below 10ms. I have no disconnects at any place.
I haven't set any cursor options except the batchsize, which I was playing around with. So no, there is no nocursortiemout set. I'm actually bit afraid of this option ;)
Thanks for your reply. Simon
vkarpov15
commented
6 years ago Hmm have you tried this without elastic-apm-node? Also, can you describe the general shape of the scripts? Is it just a loop with a bunch of fast queries running in series? Or something more sophisticated? Some skeleton code might be helpful.
simllll
commented
6 years ago Hi, just have removed elastic-apm-node to see if the issue reoccurs.. didn't took long, but it's still there:
{"stack":"MongoError: pool destroyed\n at Pool.write (/var/app/current/node_modules/mongodb-core/lib/connection/pool.js:1113:12)\n at WireProtocol.getMore (/var/app/current/node_modules/mongodb-core/lib/wireprotocol/3_2_support.js:344:14)\n at Cursor._getmore (/var/app/current/node_modules/mongodb-core/lib/cursor.js:349:35)\n at nextFunction (/var/app/current/node_modules/mongodb-core/lib/cursor.js:653:10)\n at Cursor.next (/var/app/current/node_modules/mongodb-core/lib/cursor.js:833:3)\n at Cursor._next (/var/app/current/node_modules/mongodb/lib/cursor.js:211:36)\n at nextObject (/var/app/current/node_modules/mongodb/lib/operations/cursor_ops.js:179:10)\n at next (/var/app/current/node_modules/mongodb/lib/operations/cursor_ops.js:158:3)\n at executeOperation (/var/app/current/node_modules/mongodb/lib/utils.js:420:24)\n at Cursor.next (/var/app/current/node_modules/mongodb/lib/cursor.js:253:10)\n at _next (/var/app/current/node_modules/mongoose/lib/cursor/QueryCursor.js:248:23)\n at /var/app/current/node_modules/mongoose/lib/cursor/QueryCursor.js:201:42\n at /var/app/current/node_modules/mongoose/lib/helpers/cursor/eachAsync.js:42:7\n at /var/app/current/node_modules/async/dist/async.js:4096:9\n at Object.process (/var/app/current/node_modules/async/dist/async.js:2344:17)\n at /var/app/current/node_modules/async/dist/async.js:2252:19\n at Immediate. (/var/app/current/node_modules/async/dist/async.js:119:16)\n at runCallback (timers.js:810:20)\n at tryOnImmediate (timers.js:768:5)\n at processImmediate [as _immediateCallback] (timers.js:745:5)","message":"pool destroyed","name":"MongoError"}
What's happening is following: a whole collection is processed document per document (eachAsync with cursor). Each loop does a little calcuation and in some cases also some more mongodb lookups.. finally it writes the result of this process to redis. This is done for the whole collection (collection has around 65.000.000 entries).
Regards Simon
vkarpov15
commented
6 years ago Are each of the lookups in eachAsync fast or is it possible for one of them to take several seconds?
simllll
commented
6 years ago In General they are very fast,but could be due to some circumstances that it takes a bit longer from time to time. But not more than a second, in average it processes between 500 and 1000 entries per second.
vkarpov15
commented
6 years ago In the interest of making some progress on this, I started a minimal sharded cluster using this script and ran the below script for 15 mins. No errors.
const assert = require('assert');
const mongoose = require('mongoose');
const GITHUB_ISSUE = `gh6998`;
const connectionString = `mongodb://localhost:51000/${ GITHUB_ISSUE }`;
const { Schema } = mongoose;
run().then(() => console.log('done')).catch(error => console.error(error.stack));
async function run() {
await mongoose.connect(connectionString);
//await mongoose.connection.dropDatabase();
const Model = mongoose.model('Foo', new Schema({ name: String }));
/*for (let i = 0; i < 5000; ++i) {
const docs = [];
for (let j = 0; j < 10000; ++j) {
docs.push({ name: `doc_${i}_${j}` });
}
await Model.insertMany(docs);
console.log('inserted', i);
}*/
const start = Date.now();
await Model.find().cursor().eachAsync(async (doc) => {
console.log(`+${Date.now() - start}`, doc.name);
await Model.findOne();
await new Promise(resolve => setTimeout(resolve, 25));
});
}Can you try modifying the above script to repro your issue?
simllll
commented
6 years ago I was playing around with this already more, unfortunantely I was not able to extract the issue. Most of the time it works now though, I guess it only happens under high server load. As soon as I find any new insights I will let you know
vkarpov15
commented
5 years ago I'll close this for now, re open if you have more info
Hi all, I have some long running scripts which got due to some rewrites a way better performance and throughput. But since then I suddenly see a lot of "Pool destroyed" messages, like this:
What is causing this? What does it actually mean? I have set timeouts and reconnect tries to very high values, but didn't change anything. Mongos is also alife all time (it's a sharded mongodb cluster)
Latest mongoose version. Linux. Mongodb cluster with a mongos instance on each host (connecting through a unix socket).
Thanks Simon