4

We have a mongodb 4.0.10 cluster, backed by WiredTiger, in production, with a 3 node replica set consisting of a master and two slaves. One of the slaves has another service co-located that queries the slave extensively. In addressing some slowness in the co-located service I'm seeing a lot of surprisingly slow queries. This one took 3.3 seconds:

  find: "myColl",
  filter: { myField: "myValue" },
  projection: { name: 1 },
  $db: "myDb",
  $clusterTime: { clusterTime: Timestamp(1568198047, 3), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } },
  lsid: { id: UUID("2ed823aa-e6af-4898-a4c1-c039d28a32ab") },
  $readPreference: { mode: "secondary" } }
  planSummary: IXSCAN { myField: 1 } keysExamined:0 docsExamined:0 cursorExhausted:1 numYields:0 nreturned:0 reslen:232
  locks:{ Global: { acquireCount: { r: 1 } },
          Database: { acquireCount: { r: 1 } },
          Collection: { acquireCount: { r: 1 } } }
  storage:{ data: { bytesRead: 355, timeReadingMicros: 4 }, timeWaitingMicros: { schemaLock: 3284692 }

The line that stands out to me here, is the last one, indicating that it spends 99.9% of its time waiting to acquire something called a schema lock.

I checked this particular database and collection and it turns out the collection had 50 items at query time and the database itself was tiny (less than 1k documents in total). Furthermore, there's also an index on myField.

Here's some other data about our particular usage of mongodb that might be relevant:

  • Multi tenancy by having a database per customer
  • Most documents are small
  • Most documents will have a similar size throughout their life cycle (I read some others here had performance issues related to padding and documents getting moved around as they grew in size)
  • Customer data grows through document count, not document size

I've been monitoring these slows queries for a while now and I can't see any pattern. It's like mongodb is doing some maintenance task every so often and whatever query runs at that time is forced to wait.

Why is a read query waiting to acquire a schema lock? What can I do to eliminate this long wait?

  • I suspect the issue may be related to attributes of your overall deployment rather than specific queries which happen to be periodically affected. Can you provide some stats on the total number of WiredTiger files (*.wt) in your dbPath? The schema lock is needed for anything that can modify schema (create, drop, rename, salvage, compact, verify, ...) and also to prevent changes while a certain stage of checkpoint is going on. Usually schema lock isn't a problem, but it could be if you have a large number of WT tables (on the order of 100s of thousands) and a checkpoint is in progress. – Stennie Oct 2 at 1:27
  • Can you also share some further detail on the types of colocated queries that are being run extensively -- are these simple find() queries, aggregate() commands, or perhaps some other combination of commands? – Stennie Oct 2 at 1:27
  • We have 135k WiredTiger files at present. Most of the queries are simple find() queries, with the occasional aggregate() (let's say 1-2% or so). – expez Oct 2 at 15:08
  • This problem doesn't only affect the secondary, with the co-located service, that's just where I noticed it first. I'm seeing the same behavior on the primary now. I went through the logs to find when it appeared first and that time coincided with our upgrade from 4.0.6 to 4.0.10. We've recently dropped a lot of unused databases (40% of our total), but that didn't really improve the situation. In other words we had a lot more *.wt files before yet never experienced a schema lock on v 4.0.6. – expez Oct 2 at 15:19

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.