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

Latencies in Top exclude lock acquisition time

    XMLWordPrintableJSON

Details

    • Icon: Bug Bug
    • Resolution: Duplicate
    • Icon: Major - P3 Major - P3
    • 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

        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: