-
Type:
Bug
-
Resolution: Done
-
Priority:
Major - P3
-
None
-
Affects Version/s: 2.2.0
-
Component/s: Concurrency, Internal Code
-
Query
-
ALL
After investigating this more, and discussing this with others, here is what I've found:
- The entries (lock time specifically) in the profile collection include the time taken to write to the system.profile collection, in addition to the orig. op
- We do not separate the user operation from the system logging/profiling.
- This is confusing for read-only operations like queries and getmores, since they never need a write lock
- It would be good if we can get trace or separate levels of reporting for the various stages of the whole operation so it is clear what the cost of the user operation would be without profiling
Originally I had expected, as did the users who noticed this, that "lockStats.timeAcquiringMicros.w" should be zero since it was a read-only operation.
{
"ts" : ISODate("2012-09-21T18:50:05.301Z"),
"op" : "query",
"ns" : "l.c",
"query" : {
},
"cursorid" : NumberLong("168104220735197301"),
"ntoreturn" : 0,
"ntoskip" : 0,
"nscanned" : 102,
"keyUpdates" : 0,
"numYield" : 0,
"lockStats" : {
"timeLockedMicros" : {
"r" : NumberLong(73),
"w" : NumberLong(0)
},
"timeAcquiringMicros" : {
"r" : NumberLong(3),
"w" : NumberLong(2)
}
},
"nreturned" : 101,
"responseLength" : 17815,
"millis" : 0,
"client" : "127.0.0.1",
"user" : ""
}
{
"ts" : ISODate("2012-09-21T18:50:05.425Z"),
"op" : "getmore",
"ns" : "l.c",
"cursorid" : NumberLong("168104220735197301"),
"ntoreturn" : 0,
"keyUpdates" : 0,
"numYield" : 0,
"lockStats" : {
"timeLockedMicros" : {
"r" : NumberLong(8781),
"w" : NumberLong(0)
},
"timeAcquiringMicros" : {
"r" : NumberLong(11),
"w" : NumberLong(5)
}
},
"nreturned" : 865,
"responseLength" : 150008,
"millis" : 8,
"client" : "127.0.0.1",
"user" : ""
}
- is related to
-
-
- Closed
-