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

awaitData queries are logged to slow query log if maxTimeMS expires

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Major - P3 Major - P3
    • 3.1.8
    • Affects Version/s: 3.1.6
    • Component/s: Querying
    • Fully Compatible
    • ALL
    • 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);
    • Quint 9 09/18/15

      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

            Assignee:
            yunhe.wang YunHe Wang
            Reporter:
            kamran.khan Kamran K.
            Votes:
            0 Vote for this issue
            Watchers:
            7 Start watching this issue

              Created:
              Updated:
              Resolved: