Database Profiler Output¶

On this page

Example system.profile Document
Output Reference

The database profiler captures data information about read and write operations, cursor operations, and database commands. To configure the database profile and set the thresholds for capturing profile data, see the Database Profiler section.

The database profiler writes data in the system.profile collection, which is a capped collection. To view the profiler’s output, use normal MongoDB queries on the system.profile collection.

Note

Because the database profiler writes data to the system.profile collection in a database, the profiler will profile some write activity, even for databases that are otherwise read-only.

Changed in version 3.4.

currentOp and the database profiler report the same basic diagnostic information for all CRUD operations, including the following:

These operations are also included in the logging of slow queries (see slowOpThresholdMs for more information about slow query logging).

Example `system.profile` Document¶

The following presents some sample documents found in the system.profile collection for operations on a standalone:

Find Operation
Update Operation

The following document in the system.profile reflects a find operation:

copy

{
   "op" : "query",
   "ns" : "test.report",
   "command" : {
      "find" : "report",
      "filter" : { "a" : { "$lte" : 500 } },
      "lsid" : {
         "id" : UUID("5ccd5b81-b023-41f3-8959-bf99ed696ce9")
      },
      "$db" : "test"
   },
   "cursorid" : 33629063128,
   "keysExamined" : 101,
   "docsExamined" : 101,
   "fromMultiPlanner" : true,
   "numYield" : 2,
   "nreturned" : 101,
   "queryHash" : "811451DD",
   "planCacheKey" : "759981BA",
   "locks" : {
      "Global" : {
         "acquireCount" : {
            "r" : NumberLong(3),
            "w" : NumberLong(3)
         }
      },
      "Database" : {
         "acquireCount" : { "r" : NumberLong(3) },
         "acquireWaitCount" : { "r" : NumberLong(1) },
         "timeAcquiringMicros" : { "r" : NumberLong(69130694) }
      },
      "Collection" : {
         "acquireCount" : { "r" : NumberLong(3) }
      }
   },
   "storage" : {
      "data" : {
         "bytesRead" : NumberLong(14736),
         "timeReadingMicros" : NumberLong(17)
      }
   },
   "responseLength" : 1305014,
   "protocol" : "op_msg",
   "millis" : 69132,
   "planSummary" : "IXSCAN { a: 1, _id: -1 }",
   "execStats" : {
      "stage" : "FETCH",
      "nReturned" : 101,
      "executionTimeMillisEstimate" : 0,
      "works" : 101,
      "advanced" : 101,
      "needTime" : 0,
      "needYield" : 0,
      "saveState" : 3,
      "restoreState" : 2,
      "isEOF" : 0,
      "docsExamined" : 101,
      "alreadyHasObj" : 0,
      "inputStage" : {
         ...
      }
   },
   "ts" : ISODate("2019-01-14T16:57:33.450Z"),
   "client" : "127.0.0.1",
   "appName" : "MongoDB Shell",
   "allUsers" : [
      {
         "user" : "someuser",
         "db" : "admin"
      }
   ],
   "user" : "someuser@admin"
}

The profile entry for update (and delete) operation contains the entire update command.

The following example reflects an update operation on a collection named report.

copy

{
   "op" : "update",
   "ns" : "test.report",
   "command" : {
      "q" : { },
      "u" : { "$rename" : { "a" : "b" } },
      "multi" : true,
      "upsert" : false
   },
   "keysExamined" : 0,
   "docsExamined" : 25000,
   "nMatched" : 25000,
   "nModified" : 25000,
   "keysInserted" : 25000,
   "keysDeleted" : 25000000,
   "numYield" : 6985,
   "locks" : {
      "Global" : {
         "acquireCount" : { "r" : NumberLong(6986), "w" : NumberLong(13972) }
      },
      "Database" : {
         "acquireCount" : { "w" : NumberLong(6986) },
         "acquireWaitCount" : { "w" : NumberLong(1) },
         "timeAcquiringMicros" : { "w" : NumberLong(60899375) }
      },
      "Collection" : {
         "acquireCount" : { "w" : NumberLong(6986) }
      },
      "Mutex" : {
         "acquireCount" : { "r" : NumberLong(25000) }
      }
   },
   "storage" : {
      "data" : {
         "bytesRead" : NumberLong(126344060),
         "bytesWritten" : NumberLong(281834762),
         "timeReadingMicros" : NumberLong(94549),
         "timeWritingMicros" : NumberLong(139361)
      }
   },
   "millis" : 164687,
   "planSummary" : "COLLSCAN",
   "execStats" : {
      "stage" : "UPDATE",
      "nReturned" : 0,
      "executionTimeMillisEstimate" : 103771,
      "works" : 25003,
      "advanced" : 0,
      "needTime" : 25002,
      "needYield" : 0,
      "saveState" : 6985,
      "restoreState" : 6985,
      "isEOF" : 1,
      "nMatched" : 25000,
      "nWouldModify" : 25000,
      "wouldInsert" : false,
      "inputStage" : {
         "stage" : "COLLSCAN",
         "nReturned" : 25000,
         "executionTimeMillisEstimate" : 0,
         "works" : 25002,
         "advanced" : 25000,
         "needTime" : 1,
         "needYield" : 0,
         "saveState" : 31985,
         "restoreState" : 31985,
         "isEOF" : 1,
         "direction" : "forward",
         "docsExamined" : 25000
      }
   },
   "ts" : ISODate("2019-01-14T23:33:01.806Z"),
   "client" : "127.0.0.1",
   "appName" : "MongoDB Shell",
   "allUsers" : [
      {
         "user" : "someuser",
         "db" : "admin"
      }
   ],
   "user" : "someuser@admin"
}

Output Reference¶

For any single operation, the documents created by the database profiler will include a subset of the following fields. The precise selection of fields in these documents depends on the type of operation.

Starting in MongoDB 4.2 (and in 4.0.9), for slow operations, the profiler entries and diagnostic log messages include storage information.

Note

For the output specific to the version of your MongoDB, refer to the appropriate version of the MongoDB Manual.

system.profile.op¶

The type of operation. The possible values are:

command
count
distinct
geoNear
getMore
group
insert
mapReduce
query
remove
update

system.profile.ns¶: The namespace the operation targets. Namespaces in MongoDB take the form of the database, followed by a dot (.), followed by the name of the collection.

system.profile.command¶

Changed in version 3.6.

A document containing the full command object associated with this operation.

For example, the following output contains the command object for a find operation on a collection named items in a database named test:

copy

"command" : {
  "find" : "items",
  "filter" : {
    "sku" : 1403978
  },
  ...
  "$db" : "test"
}

The following example output contains the command object for a getMore operation generated by a command with cursor id 19234103609 on a collection named items in a database named test:

copy

"command" : {
    "getMore" : NumberLong("19234103609"),
    "collection" : "items",
    "batchSize" : 10,
    ...
    "$db" : "test"
},

If the command document exceeds 50 kilobytes, the document has the following form:

copy

"command" : {
  "$truncated": <string>,
  "comment": <string>
}

The $truncated field contains a string summary of the document excluding the document’s comment field if present. If the summary still exceeds 50 kilobytes then it is further truncated, denoted by an ellipsis (…) at the end of the string.

The comment field is present if a comment was passed to the operation. Starting in MongoDB 4.4, a comment may be attached to any database command.

system.profile.originatingCommand¶: Changed in version 3.6.

For "getmore" operations which retrieve the next batch of results from a cursor, the originatingCommand field contains the full command object (e.g. find or aggregate) which originally created that cursor.

system.profile.cursorid¶: The ID of the cursor accessed by a query and getmore operations.

system.profile.keysExamined¶

Changed in version 3.2.0.

Renamed from system.profile.nscanned. The number of index keys that MongoDB scanned in order to carry out the operation.

In general, if keysExamined is much higher than nreturned, the database is scanning many index keys to find the result documents. Consider creating or adjusting indexes to improve query performance..

Changed in version 3.4.

keysExamined is available for the following commands and operations:

system.profile.docsExamined¶

Changed in version 3.2.0: Renamed from system.profile.nscannedObjects.

The number of documents in the collection that MongoDB scanned in order to carry out the operation.

Changed in version 3.4.

docsExamined is available for the following commands and operations:

system.profile.hasSortStage¶

Changed in version 3.2.0: Renamed from system.profile.scanAndOrder.

hasSortStage is a boolean that is true when a query cannot use the ordering in the index to return the requested sorted results; i.e. MongoDB must sort the documents after it receives the documents from a cursor. The field only appears when the value is true.

Changed in version 3.4.

hasSortStage is available for the following commands and operations:

system.profile.usedDisk¶

New in version 4.2.

A boolean that indicates whether any aggregation stage wrote data to temporary files due to memory restrictions.

Only appears if usedDisk is true.

system.profile.ndeleted¶: The number of documents deleted by the operation.

system.profile.ninserted¶: The number of documents inserted by the operation.

system.profile.nMatched¶: The number of documents that match the system.profile.query condition for the update operation.

system.profile.nModified¶: The number of documents modified by the update operation.

system.profile.upsert¶: A boolean that indicates the update operation’s upsert option value. Only appears if upsert is true.

system.profile.fromMultiPlanner¶

New in version 3.2.5.

A boolean that indicates whether the query planner evaluated multiple plans before choosing the winning execution plan for the query.

Only present when value is true.

system.profile.replanned¶

New in version 3.2.5.

A boolean that indicates whether the query system evicted a cached plan and re-evaluated all candidate plans.

Only present when value is true.

system.profile.replanReason¶

New in version 4.4.

A string that indicates the specific reason a cached plan was evicted.

Only present when value for replanned is true.

system.profile.keysInserted¶: The number of index keys inserted for a given write operation.

system.profile.keysDeleted¶

Removed in 3.4.

The number of index keys the update changed in the operation. Changing an index key carries a small performance cost because the database must remove the old key and inserts a new key into the B-tree index.

system.profile.writeConflicts¶: The number of conflicts encountered during the write operation; e.g. an update operation attempts to modify the same document as another update operation. See also write conflict.

system.profile.numYield¶: The number of times the operation yielded to allow other operations to complete. Typically, operations yield when they need access to data that MongoDB has not yet fully read into memory. This allows other operations that have data in memory to complete while MongoDB reads in data for the yielding operation. For more information, see the FAQ on when operations yield.

system.profile.queryHash¶

A hexadecimal string that represents a hash of the query shape and is dependent only on the query shape. queryHash can help identify slow queries (including the query filter of write operations) with the same query shape.

Note

As with any hash function, two different query shapes may result in the same hash value. However, the occurrence of hash collisions between different query shapes is unlikely.

For more information on queryHash and planCacheKey, see queryHash and planCacheKey.

New in version 4.2.

system.profile.planCacheKey¶

A hash of the key for the plan cache entry associated with the query.

Unlike the queryHash, the planCacheKey is a function of both the query shape and the currently available indexes for that shape. That is, if indexes that can support the query shape are added/dropped, the planCacheKey value may change whereas the queryHash value would not change.

For more information on queryHash and planCacheKey, see queryHash and planCacheKey.

New in version 4.2.

system.profile.locks¶

The system.profile.locks provides information for various lock types and lock modes held during the operation.

The possible lock types are:

Lock Type	Description
`ParallelBatchWriterMode`	Represents a lock for parallel batch writer mode. In earlier versions, PBWM information was reported as part of the `Global` lock information. New in version 4.2.
`ReplicationStateTransition`	Represents lock taken for replica set member state transitions. New in version 4.2.
`Global`	Represents global lock.
`Database`	Represents database lock.
`Collection`	Represents collection lock.
`Mutex`	Represents mutex.
`Metadata`	Represents metadata lock.
`oplog`	Represents lock on the oplog.

The possible locking modes for the lock types are as follows:

Lock Mode	Description
`R`	Represents Shared (S) lock.
`W`	Represents Exclusive (X) lock.
`r`	Represents Intent Shared (IS) lock.
`w`	Represents Intent Exclusive (IX) lock.

The returned lock information for the various lock types include:

system.profile.locks.acquireCount¶: Number of times the operation acquired the lock in the specified mode.

system.profile.locks.acquireWaitCount¶: Number of times the operation had to wait for the acquireCount lock acquisitions because the locks were held in a conflicting mode. acquireWaitCount is less than or equal to acquireCount.

system.profile.locks.timeAcquiringMicros¶

Cumulative time in microseconds that the operation had to wait to acquire the locks.

timeAcquiringMicros divided by acquireWaitCount gives an approximate average wait time for the particular lock mode.

system.profile.locks.deadlockCount¶: Number of times the operation encountered deadlocks while waiting for lock acquisitions.

For more information on lock modes, see What type of locking does MongoDB use?.

system.profile.storage¶

New in version 4.2: (Also available starting in 4.0.9)

The system.profile.storage information provides metrics on the storage engine data and wait time for the operation.

Specific storage metrics are returned only if the values are greater than zero.

system.profile.storage.data.bytesRead¶: New in version 4.2: (Also available starting in 4.0.9)

Number of bytes read by the operation from the disk to the cache.

system.profile.storage.data.timeReadingMicros¶: New in version 4.2: (Also available starting in 4.0.9)

Time in microseconds that the operation had to spend to read from the disk.

system.profile.storage.data.bytesWritten¶: New in version 4.2: (Also available starting in 4.0.9)

Number of bytes written by the operation from the cache to the disk.

system.profile.storage.data.timeWritingMicros¶: New in version 4.2: (Also available starting in 4.0.9)

Time in microseconds that the operation had to spend to write to the disk.

system.profile.storage.timeWaitingMicros.cache¶: New in version 4.2: (Also available starting in 4.0.9)

Time in microseconds that the operation had to wait for space in the cache.

system.profile.storage.timeWaitingMicros.schemaLock¶: New in version 4.2: (Also available starting in 4.0.9)

Time in microseconds that the operation (if modifying the schema) had to wait to acquire a schema lock.

system.profile.storage.timeWaitingMicros.handleLock¶: New in version 4.2: (Also available starting in 4.0.9)

Time in microseconds that the operation had to wait to acquire the a lock on the needed data handles.

system.profile.nreturned¶: The number of documents returned by the operation.

system.profile.responseLength¶

The length in bytes of the operation’s result document. A large responseLength can affect performance. To limit the size of the result document for a query operation, you can use any of the following:

Note

When MongoDB writes query profile information to the log, the responseLength value is in a field named reslen.

system.profile.protocol¶: The MongoDB Wire Protocol request message format.

system.profile.millis¶: The time in milliseconds from the perspective of the mongod from the beginning of the operation to the end of the operation.

system.profile.planSummary¶: New in version 3.4.

A summary of the execution plan.

system.profile.execStats¶

A document that contains the execution statistics of the query operation. For other operations, the value is an empty document.

The system.profile.execStats presents the statistics as a tree; each node provides the statistics for the operation executed during that stage of the query operation.

Note

The following fields list for execStats is not meant to be exhaustive as the returned fields vary per stage.

system.profile.execStats.stage¶

The descriptive name for the operation performed as part of the query execution; e.g.

COLLSCAN for a collection scan
IXSCAN for scanning index keys
FETCH for retrieving documents

system.profile.execStats.inputStages¶: An array that contains statistics for the operations that are the input stages of the current stage.

system.profile.ts¶: The timestamp of the operation.

system.profile.client¶: The IP address or hostname of the client connection where the operation originates.

system.profile.appName¶: New in version 3.4.

The identifier of the client application which ran the operation. Use the appName connection string option to set a custom value for the appName field.

system.profile.allUsers¶: An array of authenticated user information (user name and database) for the session. See also Users.

system.profile.user¶: The authenticated user who ran the operation. If the operation was not run by an authenticated user, this field’s value is an empty string.

← Database Profiler Disable Transparent Huge Pages (THP) →

Database Profiler Output¶

Example system.profile Document¶

Output Reference¶

Example `system.profile` Document¶