Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-29435

Latencies in Top exclude lock acquisition time

    XMLWordPrintable

Details

    • Bug
    • Status: Closed
    • Major - P3
    • Resolution: Duplicate
    • None
    • None
    • Diagnostics
    • None
    • ALL
    • Query 2017-06-19

    Description

      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
      

      Attachments

        Issue Links

          Activity

            People

              david.storch@mongodb.com David Storch
              david.storch@mongodb.com David Storch
              Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: