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

Don't log waiting change stream getMores as slow queries

XMLWordPrintableJSON

    • Type: Icon: Improvement Improvement
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 5.1.0-rc0
    • Affects Version/s: 4.0.19, 4.4.1
    • Component/s: None
    • Labels:
    • Minor Change
    • Query 2020-11-30, Query Execution 2021-05-31, Query Execution 2021-06-14, Query Execution 2021-06-28, Query Execution 2021-07-12

      This messages show up every second even there is no traffic form application to this mongos:  

      2020-08-26T04:34:45.045+0000 I COMMAND [conn21283] command altconfig-b2b-perf.oplog command: getMore \{ getMore: 3513599116181216748, collection: "oplog", $db: "altconfig-b2b-perf", $clusterTime: { clusterTime: Timestamp(1598416483, 1), signature: { hash: BinData(0, EC3841EB1FB7A34F897688BB5983E32E2ADF6763), keyId: 6855385090000683010 } }, lsid: \{ id: UUID("72864d11-c0f8-48bb-823e-de5f18a9c409") } } originatingCommand: \{ find: "oplog", filter: { timestamp: { $gte: new Date(1597895390009) } }, tailable: true, awaitData: true, $db: "altconfig-b2b-perf", $clusterTime: \{ clusterTime: Timestamp(1597895487, 1), signature: { hash: BinData(0, AAAE33D5688F935C70469CBDB8EB1F6882749A40), keyId: 6855385090000683010 } }, lsid: \{ id: UUID("72864d11-c0f8-48bb-823e-de5f18a9c409") } } nShards:1 cursorid:3513599116181216748 numYields:0 nreturned:0 reslen:237 protocol:op_msg 1000ms
2020-08-26T04:34:46.046+0000 I COMMAND [conn21283] command altconfig-b2b-perf.oplog command: getMore \{ getMore: 3513599116181216748, collection: "oplog", $db: "altconfig-b2b-perf", $clusterTime: { clusterTime: Timestamp(1598416483, 1), signature: { hash: BinData(0, EC3841EB1FB7A34F897688BB5983E32E2ADF6763), keyId: 6855385090000683010 } }, lsid: \{ id: UUID("72864d11-c0f8-48bb-823e-de5f18a9c409") } } originatingCommand: \{ find: "oplog", filter: { timestamp: { $gte: new Date(1597895390009) } }, tailable: true, awaitData: true, $db: "altconfig-b2b-perf", $clusterTime: \{ clusterTime: Timestamp(1597895487, 1), signature: { hash: BinData(0, AAAE33D5688F935C70469CBDB8EB1F6882749A40), keyId: 6855385090000683010 } }, lsid: \{ id: UUID("72864d11-c0f8-48bb-823e-de5f18a9c409") } } nShards:1 cursorid:3513599116181216748 numYields:0 nreturned:0 reslen:237 protocol:op_msg 999ms

       
      After we made change to use stream instead of tailable cursor, still get the messages:

      2020-08-26T22:23:09.044+0000 I COMMAND [conn40485] command altconfig-b2b-perf.oplog command: getMore \{ getMore: 6960529238130512337, collection: "oplog", $db: "altconfig-b2b-perf", $clusterTime: { clusterTime: Timestamp(1598480586, 1), signature: { hash: BinData(0, 65DB7FE3D57B6415BAEDFBF72E74803E5C7D61C2), keyId: 6855385090000683010 } }, lsid: \{ id: UUID("30f97283-dbab-46e5-a142-42efb258f9b0") } } originatingCommand: \{ aggregate: "oplog", pipeline: [ { $changeStream: { fullDocument: "default" } } ], cursor: {}, $db: "altconfig-b2b-perf", $clusterTime: \{ clusterTime: Timestamp(1598416557, 4), signature: { hash: BinData(0, A10C3281F6948F187698FD220A217D02409A1912), keyId: 6855385090000683010 } }, lsid: \{ id: UUID("30f97283-dbab-46e5-a142-42efb258f9b0") } } nShards:1 cursorid:6960529238130512337 numYields:0 nreturned:0 reslen:344 protocol:op_msg 999ms
2020-08-26T22:23:10.044+0000 I COMMAND [conn40485] command altconfig-b2b-perf.oplog command: getMore \{ getMore: 6960529238130512337, collection: "oplog", $db: "altconfig-b2b-perf", $clusterTime: { clusterTime: Timestamp(1598480587, 1), signature: { hash: BinData(0, 7226F82A5EFECCCB9F212F9409359FFE1B6C9CD0), keyId: 6855385090000683010 } }, lsid: \{ id: UUID("30f97283-dbab-46e5-a142-42efb258f9b0") } } originatingCommand: \{ aggregate: "oplog", pipeline: [ { $changeStream: { fullDocument: "default" } } ], cursor: {}, $db: "altconfig-b2b-perf", $clusterTime: \{ clusterTime: Timestamp(1598416557, 4), signature: { hash: BinData(0, A10C3281F6948F187698FD220A217D02409A1912), keyId: 6855385090000683010 } }, lsid: \{ id: UUID("30f97283-dbab-46e5-a142-42efb258f9b0") } } nShards:1 cursorid:6960529238130512337 numYields:0 nreturned:0 reslen:344 protocol:op_msg 999ms

       
      Is there a change in the 4.0 version? how can we stop this message?

      Thanks,

      Jing

            Assignee:
            denis.grebennicov@mongodb.com Denis Grebennicov
            Reporter:
            jing66wu@yahoo.com Jing Wu
            Votes:
            0 Vote for this issue
            Watchers:
            7 Start watching this issue

              Created:
              Updated:
              Resolved: