What is "locks(micros) w:16035" and "locks(micros) r:10051" in the mongodb log
mongodb
Solution
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.
Problem
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?