What is "locks(micros) w:16035" and "locks(micros) r:10051" in the mongodb log

Question

I have enabled profiling in the MongoDb config file.

profile=2
slowms=5

The mongodb log contains all the queries that took longer than 5 milliseconds (weird, I thought profile=2 meant log ALL queries).

For all update entries, the line ends with locks(micros) w:17738 17ms (the actual number varies). For all the query entries, the line contains locks(micros) r:15208

Sample line

Tue Dec 03 02:29:43.084 [conn11] update DbName.CollectionName query: { _id: ObjectId('51dfd2791bbdbe0b44395553')} update: { json for new document } nscanned:1 nmoved:1 nupdated:1 keyUpdates:0 locks(micros) w:17738 17ms

Reading the docs, I found the following section,

system.profile.lockStats

New in version 2.2.

The time in microseconds the operation spent acquiring and holding locks. This field reports data for the following lock types:

    R - global read lock
    W - global write lock
    r - database-specific read lock
    w - database-specific write lock

Okay, so the r & w are some database-specific lock times. But which one? Is it time spent holding the lock or time spent waiting to acquire a lock?

Answer 1

profile=2 slowms=5

The mongodb log contains all the queries that took longer than 5 milliseconds (weird, I thought profile=2 meant log ALL queries).

Setting profile to level 2 means that all queries are included in the system.profile capped collection irrespective of the slowms value. This does not affect what queries will be included in the mongod log.

Setting slowms to 5ms defines the threshold for slow queries that will be logged (irrespective of profiling) and included in the system.profile collection if profile is level 1 (i.e. profile slow queries).

If you want to see queries in your logs as well, you can increase the loglevel to 1 or higher:

db.adminCommand( { setParameter: 1, logLevel: 1 } )

WARNING: increased log levels get very noisy, and the logs are not capped like the system.profile collection!

Okay, so the r & w are some database-specific lock times. But which one? Is it time spent holding the lock or time spent waiting to acquire a lock?

For the system.profile.lockStats there are separate fields for acquiring (timeAcquiringMicros) and holding (timeLockedMicros) locks.

The "locks(micros)" details in the log are only showing the timeLockedMicros details (source reference: db/lockstat.cpp.

I was hoping for a link that mentions what the various fields of the log file are

I'm not aware of any detailed documentation for the log file format, and there are definitely some variations between major MongoDB releases. A great open source toolkit for working with MongoDB log files is mtools. You could peek into the code there to see how it parses different log lines.