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

Change stream aggregation fails with "operation exceeded time limit" if maxTimeMS is specified

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Works as Designed
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: None
    • None
    • ALL
    • Hide

      Specify a maxTimeMS with the aggregate command with a $changeStream pipeline shorter than the amount of time it will take to scan the oplog.

      I produced this by opening 300 concurrent change streams with startAfter pointing to an entry earlier in the oplog and a maxTimeMS of 1000 on a 4 core machine.

      Show
      Specify a  maxTimeMS with the aggregate command with a  $changeStream pipeline shorter than the amount of time it will take to scan the oplog. I produced this by opening 300 concurrent change streams with startAfter pointing to an entry earlier in the oplog and a maxTimeMS of 1000 on a 4 core machine.
    • Query 2019-11-18, Query 2019-12-02, Query 2019-12-16

      For $changeStream, if the initial aggregate command specifies an explicit maxTimeMS and the work of constructing the first batch takes longer than maxTimeMS, the command will fail with ErrorCodes::MaxTimeMSExpired despite the fact that this is a tailable awaitData cursor.

      Full log line of one such command failing:

      2019-10-18T05:29:42.763+0000 I  COMMAND  [conn1316] command local.oplog.rs command: aggregate { aggregate: "fts", cursor: {}, maxTimeMS: 1000, pipeline: [ { $changeStream: { startAfter: { _data: "825DA9470E000000012B0229296E04" }, fullDocument: "updateLookup" } } ], $db: "test", $clusterTime: { clusterTime: Timestamp(1571376579, 1), signature: { hash: BinData(0, 00F7C4A3426B593FA553F668DD7DBA4E1C0B6F33), keyId: 6745581691277934593 } }, lsid: { id: UUID("3655f6dd-aabb-49e7-b582-b1459d4c879b") }, $readPreference: { mode: "primaryPreferred" } } planSummary: COLLSCAN numYields:58 ok:0 errMsg:"Error in $cursor stage :: caused by :: operation exceeded time limit" errName:MaxTimeMSExpired errCode:50 reslen:285 locks:{ ReplicationStateTransition: { acquireCount: { w: 61 } }, Global: { acquireCount: { r: 61 } }, Database: { acquireCount: { r: 60 } }, Collection: { acquireCount: { r: 1 } }, Mutex: { acquireCount: { r: 3 } }, oplog: { acquireCount: { r: 59 } } } protocol:op_msg 1103ms

            Assignee:
            bernard.gorman@mongodb.com Bernard Gorman
            Reporter:
            kevin.rosendahl@mongodb.com Kevin Rosendahl
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: