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

Operations that time out from maxTimeMS before constructing an AutoStatsTracker don't get profiled

    XMLWordPrintableJSON

Details

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Major - P3 Major - P3
    • None
    • None
    • Querying
    • Query Execution
    • ALL
    • Hide

      > db.dropDatabase()
      { "dropped" : "test", "ok" : 1 }
      > db.setProfilingLevel(2)
      { "was" : 0, "slowms" : 100, "sampleRate" : 1, "ok" : 1 }
      > db.foo.runCommand({insert:'foo', documents:[{a:1}]})
      { "n" : 1, "ok" : 1 }
      > db.foo.runCommand({insert:'foo', documents:[{b:1}], maxTimeMS:1000})
      { "n" : 1, "ok" : 1 }
      > db.adminCommand({configureFailPoint: 'maxTimeAlwaysTimeOut', mode:'alwaysOn'})
      { "count" : 7, "ok" : 1 }
      > db.foo.runCommand({insert:'foo', documents:[{c:1}], maxTimeMS:1000})
      {
              "ok" : 0,
              "errmsg" : "operation exceeded time limit",
              "code" : 50,
              "codeName" : "MaxTimeMSExpired"
      }
      > db.setProfilingLevel(0)
      { "was" : 2, "slowms" : 100, "sampleRate" : 1, "ok" : 1 }
      > db.system.profile.find()
      { "op" : "insert", "ns" : "test.foo", "command" : { "insert" : "foo", "lsid" : { "id" : UUID("419c35a3-39fe-46cc-9a7a-23847478330b") }, "$db" : "test" }, "ninserted" : 1, "keysInserted" : 1, "numYield" : 0, "locks" : { "ParallelBatchWriterMode" : { "acquireCount" : { "r" : NumberLong(3) } }, "ReplicationStateTransition" : { "acquireCount" : { "w" : NumberLong(3) } }, "Global" : { "acquireCount" : { "w" : NumberLong(3) } }, "Database" : { "acquireCount" : { "w" : NumberLong(3) } }, "Collection" : { "acquireCount" : { "r" : NumberLong(1), "w" : NumberLong(3) } }, "Mutex" : { "acquireCount" : { "r" : NumberLong(3) } } }, "flowControl" : { "acquireCount" : NumberLong(3), "timeAcquiringMicros" : NumberLong(7) }, "responseLength" : 45, "protocol" : "op_msg", "millis" : 11, "ts" : ISODate("2020-05-06T20:43:18.817Z"), "client" : "127.0.0.1", "appName" : "MongoDB Shell", "allUsers" : [ ], "user" : "" }
      { "op" : "insert", "ns" : "test.foo", "command" : { "insert" : "foo", "maxTimeMS" : 1000, "lsid" : { "id" : UUID("419c35a3-39fe-46cc-9a7a-23847478330b") }, "$db" : "test" }, "ninserted" : 1, "keysInserted" : 1, "numYield" : 0, "locks" : { "ParallelBatchWriterMode" : { "acquireCount" : { "r" : NumberLong(1) } }, "ReplicationStateTransition" : { "acquireCount" : { "w" : NumberLong(1) } }, "Global" : { "acquireCount" : { "w" : NumberLong(1) } }, "Database" : { "acquireCount" : { "w" : NumberLong(1) } }, "Collection" : { "acquireCount" : { "w" : NumberLong(1) } }, "Mutex" : { "acquireCount" : { "r" : NumberLong(1) } } }, "flowControl" : { "acquireCount" : NumberLong(1), "timeAcquiringMicros" : NumberLong(3) }, "responseLength" : 45, "protocol" : "op_msg", "millis" : 0, "ts" : ISODate("2020-05-06T20:43:22.792Z"), "client" : "127.0.0.1", "appName" : "MongoDB Shell", "allUsers" : [ ], "user" : "" }
      Fetched 2 record(s) in 24ms
      

      Notice that only the first two inserts show up in system.profile (the inserts of {a:1} and {b:1}, which both complete successfully). The insert of {c:1}, which times out, doesn't show up in the profiler.

      Show
      > db.dropDatabase() { "dropped" : "test", "ok" : 1 } > db.setProfilingLevel(2) { "was" : 0, "slowms" : 100, "sampleRate" : 1, "ok" : 1 } > db.foo.runCommand({insert:'foo', documents:[{a:1}]}) { "n" : 1, "ok" : 1 } > db.foo.runCommand({insert:'foo', documents:[{b:1}], maxTimeMS:1000}) { "n" : 1, "ok" : 1 } > db.adminCommand({configureFailPoint: 'maxTimeAlwaysTimeOut', mode:'alwaysOn'}) { "count" : 7, "ok" : 1 } > db.foo.runCommand({insert:'foo', documents:[{c:1}], maxTimeMS:1000}) { "ok" : 0, "errmsg" : "operation exceeded time limit", "code" : 50, "codeName" : "MaxTimeMSExpired" } > db.setProfilingLevel(0) { "was" : 2, "slowms" : 100, "sampleRate" : 1, "ok" : 1 } > db.system.profile.find() { "op" : "insert", "ns" : "test.foo", "command" : { "insert" : "foo", "lsid" : { "id" : UUID("419c35a3-39fe-46cc-9a7a-23847478330b") }, "$db" : "test" }, "ninserted" : 1, "keysInserted" : 1, "numYield" : 0, "locks" : { "ParallelBatchWriterMode" : { "acquireCount" : { "r" : NumberLong(3) } }, "ReplicationStateTransition" : { "acquireCount" : { "w" : NumberLong(3) } }, "Global" : { "acquireCount" : { "w" : NumberLong(3) } }, "Database" : { "acquireCount" : { "w" : NumberLong(3) } }, "Collection" : { "acquireCount" : { "r" : NumberLong(1), "w" : NumberLong(3) } }, "Mutex" : { "acquireCount" : { "r" : NumberLong(3) } } }, "flowControl" : { "acquireCount" : NumberLong(3), "timeAcquiringMicros" : NumberLong(7) }, "responseLength" : 45, "protocol" : "op_msg", "millis" : 11, "ts" : ISODate("2020-05-06T20:43:18.817Z"), "client" : "127.0.0.1", "appName" : "MongoDB Shell", "allUsers" : [ ], "user" : "" } { "op" : "insert", "ns" : "test.foo", "command" : { "insert" : "foo", "maxTimeMS" : 1000, "lsid" : { "id" : UUID("419c35a3-39fe-46cc-9a7a-23847478330b") }, "$db" : "test" }, "ninserted" : 1, "keysInserted" : 1, "numYield" : 0, "locks" : { "ParallelBatchWriterMode" : { "acquireCount" : { "r" : NumberLong(1) } }, "ReplicationStateTransition" : { "acquireCount" : { "w" : NumberLong(1) } }, "Global" : { "acquireCount" : { "w" : NumberLong(1) } }, "Database" : { "acquireCount" : { "w" : NumberLong(1) } }, "Collection" : { "acquireCount" : { "w" : NumberLong(1) } }, "Mutex" : { "acquireCount" : { "r" : NumberLong(1) } } }, "flowControl" : { "acquireCount" : NumberLong(1), "timeAcquiringMicros" : NumberLong(3) }, "responseLength" : 45, "protocol" : "op_msg", "millis" : 0, "ts" : ISODate("2020-05-06T20:43:22.792Z"), "client" : "127.0.0.1", "appName" : "MongoDB Shell", "allUsers" : [ ], "user" : "" } Fetched 2 record(s) in 24ms Notice that only the first two inserts show up in system.profile (the inserts of {a:1} and {b:1}, which both complete successfully). The insert of {c:1}, which times out, doesn't show up in the profiler.
    • Query 2020-06-01

    Attachments

      Activity

        People

          backlog-query-execution Backlog - Query Execution
          spencer@mongodb.com Spencer Brody (Inactive)
          Votes:
          0 Vote for this issue
          Watchers:
          8 Start watching this issue

          Dates

            Created:
            Updated: