Description

Description:

With this change, the slow operation's log messages could additionally have the storage statistics information like shown below :

2018-07-05T14:13:21.744+1000 I COMMAND  [conn1] command test.coll appName: "MongoDB Shell" command: insert { insert: "coll", ordered: true, $db: "test" } ninserted:1 keysInserted:1 numYields:0 reslen:45 
locks:{ Global: { acquireCount: { r: 3, w: 3 } }, Database: { acquireCount: { w: 2, W: 1 } }, Collection: { acquireCount: { w: 2 }}}, storage: { data: { bytesRead: 1, bytesWritten: 123, timeReadingMicros: 123, timeWritingMicros: 231 }, timeWaitingMicros: { cache: 2, schemaLock: 1, handleLock: 3}} protocol:op_msg 12ms

The system.profile collection can also contain the additional storage statistics information like this:

{"op":"query","ns":"test.foo.abcd","command":{"find":"foo.abcd","filter":{},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1537768648,"i":1}},"signature":{"hash":{"$binary":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","$type":"00"},"keyId":{"$numberLong":"0"}}},"$db":"test"},"keysExamined":0,"docsExamined":6,"cursorExhausted":true,"numYield":0,"locks":{"Global":{"acquireCount":{"r":{"$numberLong":"2"}}},"Database":{"acquireCount":{"r":{"$numberLong":"1"}}},"Collection":{"acquireCount":{"r":{"$numberLong":"1"}}}},"storage":{"data":{{"bytesRead":{"$numberLong":"1"}}},{"bytesWritten":{"$numberLong":"123"}},{"timeReadingMicros":{"$numberLong":"123"}}},{"timeWritingMicros":{"$numberLong":"123"}},"timeWaitingMicros":{{"cache":{"$numberLong":"2"}},{"schemaLock":{"$numberLong":"123"}},{"handleLock":{"$numberLong":"3"}},"nreturned":6,"responseLength":3965,"protocol":"op_msg","millis":0,"planSummary":"COLLSCAN","execStats":{"stage":"COLLSCAN","nReturned":6,"executionTimeMillisEstimate":0,"works":8,"advanced":6,"needTime":1,"needYield":0,"saveState":0,"restoreState":0,"isEOF":1,"invalidates":0,"direction":"forward","docsExamined":6},"ts":{"$date":"2018-09-24T05:57:31.071Z"},"client":"127.0.0.1","appName":"MongoDB Shell","allUsers":[],"user":""}

"storage" : {
      "data" : {
         "bytesRead" : NumberLong(2097229),
         "timeReadingMicros" : NumberLong(8116)
         "bytesWritten" : NumberLong(4194458),
         "timeWritingMicros" : NumberLong(203)
        }
       "timeWaitingMicros" : {
         "cache" : NumberLong(558),
         "schemaLock": NumberLong(442),
         "handleLock" : NumberLong(342)
        }
    },

The description for the new fields:

system.profile.storage.data.bytesRead : Number of bytes read by the operation from the disk to the cache.
system.profile.storage.data.timeReadingMicros : Time in microseconds that the operation had to spend to read from the disk.
system.profile.storage.data.bytesWritten : Number of bytes written by the operation from the cache to the disk.
system.profile.storage.data.timeWritingMicros : Time in microseconds that the operation had to spend to write to the disk.
system.profile.storage.timeWaitingMicros.cache : Time in microseconds that the operation had to wait for space in the cache.
system.profile.storage.timeWaitingMicros.schemaLock : Time in microseconds that the operation had to wait to acquire the schemaLock.
system.profile.storage.timeWaitingMicros.handleLock : Time in microseconds that the operation had to wait to acquire the handleLock.

Engineering Ticket Description:

Add boost::optional<BSONObj> OperationStorageStats and provide setter method to populate it with storage statistics.
Extend OpDebug::append() and OpDebug::report() to use OperationStorageStats for report generation on storage statistics.

Scope of changes

Impact to Other Docs

MVP (Work and Date)

Resources (Scope or Design Docs, Invision, etc.)