-
Type:
Bug
-
Resolution: Duplicate
-
Priority:
Major - P3
-
None
-
Affects Version/s: None
-
Component/s: Diagnostics
-
Labels:None
-
ALL
-
Query 2017-06-19
Due to the introduction of the AutoStatsTracker for reporting latencies to Top in SERVER-22541 (in particular, see commit 584ca76de9e), these latencies now exclude time spent acquiring locks. The issue can be demonstrated by applying the following patch, which adds sleeps to simulate super long lock acquisition times:
diff --git a/src/mongo/db/db_raii.cpp b/src/mongo/db/db_raii.cpp
index 9098e3b..977d291 100644
--- a/src/mongo/db/db_raii.cpp
+++ b/src/mongo/db/db_raii.cpp
@@ -107,6 +107,9 @@ AutoStatsTracker::~AutoStatsTracker() {
AutoGetCollectionForRead::AutoGetCollectionForRead(OperationContext* opCtx,
const NamespaceString& nss,
AutoGetCollection::ViewMode viewMode) {
+ // Simulate a 2 second lock acquisition.
+ sleepmillis(2000);
+
_autoColl.emplace(opCtx, nss, MODE_IS, MODE_IS, viewMode);
// Note: this can yield.
Then run the following:
> db.c.drop() true > db.c.insert({_id: 1}) WriteResult({ "nInserted" : 1 }) > db.c.aggregate([{$collStats: {latencyStats: {}}}]).pretty() { "ns" : "test.c", "localTime" : ISODate("2017-06-02T21:17:22.267Z"), "latencyStats" : { "reads" : { "latency" : NumberLong(163), "ops" : NumberLong(2) }, "writes" : { "latency" : NumberLong(143438), "ops" : NumberLong(1) }, "commands" : { "latency" : NumberLong(0), "ops" : NumberLong(0) } } } > db.c.find() { "_id" : 1 } > db.c.aggregate([{$collStats: {latencyStats: {}}}]).pretty() { "ns" : "test.c", "localTime" : ISODate("2017-06-02T21:17:35.243Z"), "latencyStats" : { "reads" : { "latency" : NumberLong(401), "ops" : NumberLong(4) }, "writes" : { "latency" : NumberLong(143438), "ops" : NumberLong(1) }, "commands" : { "latency" : NumberLong(0), "ops" : NumberLong(0) } } }
You should observe that the find commands take a few seconds to return, but the cumulative read latency reported in $collStats only increases by tens or hundreds of microseconds. Note that latency reported in slow query log lines is not affected by this bug. Re-using the example above, the log line for the find command reports a latency of 2000ms, which of course is dominated by the simulated 2 second lock acquisition:
2017-06-02T17:18:01.340-0400 I COMMAND [conn1] command test.c appName: "MongoDB Shell" command: find { find: "c", filter: {}, $db: "test" } planSummary: COLLSCAN keysExamined:0 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:100 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_msg 2000ms
- duplicates
-
SERVER-29304 Exclude time spent blocking for awaitData from latency metrics
-
- Closed
-