Of Stack

Deep dive into MongoDB's Slow log queries (profile)

  • 2020-06-23 02:12:51
  • OfStack

preface

Speaking of slow log analysis of MongoDB, it is necessary to mention the profile analyzer, which writes the slow logs to the system.profile set, which is a fixed set. We can optimize the database by querying this collection to understand the current slow logs.

The overall environment

MongoDB 3.2.5

In actual combat

Part1: Output demonstration

In the query system.profile We can observe that all operations, including remove,update,find and so on, are recorded system.profile Set, which contains a lot of information, such as: 


{
 "op" : "query",
 "ns" : "test.c",
 "query" : {
 "find" : "c",
 "filter" : {
  "a" : 1
 }
 },
 "keysExamined" : 2,
 "docsExamined" : 2,
 "cursorExhausted" : true,
 "keyUpdates" : 0,
 "writeConflicts" : 0,
 "numYield" : 0,
 "locks" : {
 "Global" : {
  "acquireCount" : {
  "r" : NumberLong(2)
  }
 },
 "Database" : {
  "acquireCount" : {
  "r" : NumberLong(1)
  }
 },
 "Collection" : {
  "acquireCount" : {
  "r" : NumberLong(1)
  }
 }
 },
 "nreturned" : 2,
 "responseLength" : 108,
 "millis" : 0,
 "execStats" : {
 "stage" : "FETCH",
 "nReturned" : 2,
 "executionTimeMillisEstimate" : 0,
 "works" : 3,
 "advanced" : 2,
 "needTime" : 0,
 "needYield" : 0,
 "saveState" : 0,
 "restoreState" : 0,
 "isEOF" : 1,
 "invalidates" : 0,
 "docsExamined" : 2,
 "alreadyHasObj" : 0,
 "inputStage" : {
  "stage" : "IXSCAN",
  "nReturned" : 2,
  "executionTimeMillisEstimate" : 0,
  "works" : 3,
  "advanced" : 2,
  "needTime" : 0,
  "needYield" : 0,
  "saveState" : 0,
  "restoreState" : 0,
  "isEOF" : 1,
  "invalidates" : 0,
  "keyPattern" : {
  "a" : 1
  },
  "indexName" : "a_1",
  "isMultiKey" : false,
  "isUnique" : false,
  "isSparse" : false,
  "isPartial" : false,
  "indexVersion" : 1,
  "direction" : "forward",
  "indexBounds" : {
  "a" : [
  "[1.0, 1.0]"
  ]
  },
  "keysExamined" : 2,
  "dupsTested" : 0,
  "dupsDropped" : 0,
  "seenInvalidated" : 0
 }
 },
 "ts" : ISODate("2015-09-03T15:26:14.948Z"),
 "client" : "127.0.0.1",
 "allUsers" : [ ],
 "user" : ""}

Part2: Output reading

system.profile.op

This item mainly includes the following categories

insert query update remove getmore command

Represents what kind of slow log is being queried, inserted, updated, deleted, or otherwise.

system.profile.ns

This item indicates that the slow log is the slow log corresponding to which collection under which library.

system.profile.query

This item details the statement and behavior of the slow log

system.profile.keysExamined

This shows how many key were searched to find the final result MongoDB

system.profile.docsExamined

This item indicates how many documents MongoDB searched in order to find the final result

system.profile.keyUpdates

How many index key the table name is changed in this operation, there is also a small performance cost to changing the index key, as the database not only removes the old Key, but inserts the new Key into the ES84en-ES85en index

system.profile.writeConflicts

Write the number of conflicts that occur, such as update1 documents that are being manipulated by another update

system.profile.numYield

The number of times to yield in order for another operation to complete, 1 generally occurs when the data to be accessed has not been fully read into memory, MongoDB will give priority to complete the operation in memory

system.profile0

The types of locks that are generated during operation are as follows:

Global Represents global lock.
MMAPV1Journal Represents MMAPv1 storage engine specific lock to synchronize journal writes; for non-MMAPv1 storage engines, the mode forMMAPV1Journal is empty.
Database Represents database lock.
Collection Represents collection lock.
Metadata Represents metadata lock.
oplog Represents lock on the oplog.

There are also various modes of locking, 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.

system.profile.locks.acquireCoun

The number of times a lock is requested in different categories

system.profile.nreturned

This operation eventually returns the number of documents

system.profile.responseLength

The size of the result returned is bytes, and if this value is too large, you need to consider ways such as limit() to reduce the output

system.profile.millis

How long does the operation take from start to finish, in milliseconds

system.profile.execStats

Contains 1 statistics for this operation, only query types are displayed

system.profile.execStats.stage

Contains the details of the operation, such as whether an index is used

system.profile.ts

The time at which the operation is performed

system.profile.client

Which client initiated the operation and shows ip or hostname for that client

system.profile.allUsers

Which authenticated user performed the operation

system.profile.op0

Whether to authenticate the user to perform the operation, if another user operation is used after authentication, the item is empty

conclusion

system.profile Set is one of the means to locate slow SQL. Knowing the meaning of each output item helps us to locate the problem faster. Due to the limited level of the author, the writing time is also very hasty, the article will inevitably appear 1 mistakes or inaccurate, inappropriate places ask readers to criticize and correct.

Related articles: