MongoDB – Missing acquireWaitCount and timeAcquiringMicros in system.profile Output

mongodb

I enabled profiling in a mongodb database since sometimes a query is fast while sometimes the exact same query takes a very long time, despite the execution plan being a IXSCAN. I suspect it is due to locking issues but in the database profiler output acquireWaitCount, timeAcquiringMicros and deadlockCount are missing. How can I find these values and how can I find the query that holds those locks? I am using mongodb 4.2

Here is the output from a database profiler query:

{
  "op": "query",
  "ns": "db.Caratula-221",
  "command": {
    "find": "Caratula-221",
    "filter": {
      "EmpresaId": "33707830439",
      "Carpeta": "VALOR CRITERIO"
    },
    "limit": 1,
    "readConcern": {
      "level": "linearizable"
    },
    "$db": "db",
    "lsid": {
      "id": "a4c0937f-a77c-40c4-ae4a-f14fc8c67042"
    },
    "$clusterTime": {
      "clusterTime": "Timestamp(1598361984, 1)",
      "signature": {
        "hash": "BinData(0,\"AAAAAAAAAAAAAAAAAAAAAAAAAAA=\")",
        "keyId": 0
      }
    }
  },
  "keysExamined": 1,
  "docsExamined": 1,
  "cursorExhausted": true,
  "numYield": 0,
  "nreturned": 1,
  "queryHash": "D282DB09",
  "planCacheKey": "8921BB9F",
  "locks": {
    "ParallelBatchWriterMode": {
      "acquireCount": {
        "r": 2
      }
    },
    "ReplicationStateTransition": {
      "acquireCount": {
        "w": 3
      }
    },
    "Global": {
      "acquireCount": {
        "r": 2,
        "w": 1
      }
    },
    "Database": {
      "acquireCount": {
        "r": 1,
        "w": 1
      }
    },
    "Collection": {
      "acquireCount": {
        "r": 1
      }
    },
    "Mutex": {
      "acquireCount": {
        "r": 1
      }
    },
    "oplog": {
      "acquireCount": {
        "w": 1
      }
    }
  },
  "flowControl": {
    "acquireCount": 1
  },
  "storage": {},
  "responseLength": 2492,
  "protocol": "op_msg",
  "millis": 8383,
  "planSummary": "IXSCAN { EmpresaId: 1, Carpeta: 1 }",
  "ts": "2020-08-25T13:26:32.526Z",
  "client": "192.168.2.78",
  "allUsers": [
    {
      "user": "dbadmin",
      "db": "admin"
    }
  ],
  "user": "dbadmin@admin"
}

Best Answer

When those fields are not present in the profiling output, it means their value was 0.

That is, if the query never had to wait to acquire a lock, the acquireWaitCount field will not be present in the profiling data.

The profiling data out contains "storage": {} which could mean 2 things:

  • all necessary documents and indexes were already in cache so the query didn't need to request anything from storage
  • there was a timeout attempting to retrieve the storage data

In the second case, there should be a log entry to that effect in the mongod log.

Another possibility is too many simultaneous read operations. The storage engine has an upper limit on the number of concurrent reads it can handle, when that limit is exceeded, operations queue waiting for a turn in the storage engine. This is not the same as locking, and is not reported in the profiling data. You can see this occurring in the output of the serverStatus command

Related Question