A frequent a source of confusion is how to read and interpret the fields returned in the slow operation log. Making things a bit worse, it has also changed release over release.

One question that comes up often:
Q. How does the server count a slow query?
A. The time used as the threshold for a slow query is calculated from the moment a query acquires the first lock. The timeAcquiringMicros field is included for Global, Database, Collection, Oplog, Journal. These counters are ticking from when the operation first attempts to grab a lock. Thus, the total time reported for an operation (at the end of the line and used for the slowms threshold) may be less than if all the times printed in the log line are added up.

Example log line from v3.0:

2015-09-03T18:01:46.885Z I QUERY    [conn140189] getmore entities-collection cursorid:78668055085 ntoreturn:0 keyUpdates:0 writeConflicts:0 numYields:61 nreturned:4569 reslen:4194808 locks:{ Global: { acquireCount: { r: 124 }, acquireWaitCount: { r: 14 }, timeAcquiringMicros: { r: 187331912 } }, Database: { acquireCount: { r: 62 } }, Collection: { acquireCount: { r: 62 } } } 42544ms