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

awaitData queries are logged to slow query log if maxTimeMS expires

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Fixed
    • Affects Version/s: 3.1.6
    • Fix Version/s: 3.1.8
    • Component/s: Querying
    • Labels:
    • Backwards Compatibility:
      Fully Compatible
    • Operating System:
      ALL
    • Steps To Reproduce:
      Hide

      var rst = new ReplSetTest({nodes: 3});
      rst.startSet();
      rst.initiate();
       
      // perform a dummy insert
      rst.getPrimary().getDB('test').foo.insert({});
       
      // sleep to allow time for the slow query messages to appear
      sleep(30000);
      

      Show
      var rst = new ReplSetTest({nodes: 3}); rst.startSet(); rst.initiate();   // perform a dummy insert rst.getPrimary().getDB('test').foo.insert({});   // sleep to allow time for the slow query messages to appear sleep(30000);
    • Sprint:
      Quint 9 09/18/15

      Description

      In recent versions of 3.1.x, an idle replica set will emit slow query messages for getMores on the primary:

      m31000| 2015-07-29T13:26:11.359-0400 I COMMAND  [conn10] command local.oplog.rs command: getMore { getMore: 22205584705, collection: "oplog.rs", maxTimeMS: 2000 } ntoreturn:1 ntoskip:0 keyUpdates:0 writeConflicts:0 numYields:1 reslen:86 locks:{ Global: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 3 } }, oplog: { acquireCount: { r: 3 } } } protocol:op_command 2001ms
      m31000| 2015-07-29T13:26:11.359-0400 I COMMAND  [conn11] command local.oplog.rs command: getMore { getMore: 21801738166, collection: "oplog.rs", maxTimeMS: 2000 } ntoreturn:1 ntoskip:0 keyUpdates:0 writeConflicts:0 numYields:1 reslen:86 locks:{ Global: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 3 } }, oplog: { acquireCount: { r: 3 } } } protocol:op_command 2001ms
      m31000| 2015-07-29T13:26:13.361-0400 I COMMAND  [conn11] command local.oplog.rs command: getMore { getMore: 21801738166, collection: "oplog.rs", maxTimeMS: 2000 } ntoreturn:1 ntoskip:0 keyUpdates:0 writeConflicts:0 numYields:1 reslen:86 locks:{ Global: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 3 } }, oplog: { acquireCount: { r: 3 } } } protocol:op_command 2000ms
      ...
      

      Potential issues here:
      1 - Idle replica sets shouldn't be so chatty (3.0.5 is much less verbose)
      2 - awaitData information seems to be missing from the log messages

        Attachments

          Issue Links

            Activity

              People

              • Votes:
                0 Vote for this issue
                Watchers:
                8 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: