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

XMLWordPrintableJSON

    • Type: Bug
    • Resolution: Unresolved
    • Priority: Major - P3
    • None
    • Affects Version/s: None
    • Component/s: 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
    • None
    • 3
    • None
    • None
    • None
    • None
    • None
    • None

          Assignee:
          [DO NOT USE] Backlog - Query Execution
          Reporter:
          Spencer Brody (Inactive)
          Votes:
          0 Vote for this issue
          Watchers:
          9 Start watching this issue

            Created:
            Updated: