0

I have a MongoDB replica set. The primary one creates a huge amount of temp files with the name extsort-sort-executor in every seconds, which generates more than 80Gb of temp files under 10 minutes...

If I set the allowDiskUseByDefault to false I get the following error: Plan executor error during find command

  "stats": {
    "works": 88450,
    "restoreState": 88,
    "saveState": 88,
    "advanced": 0,
    "spilledDataStorageSize": 0,
    "nReturned": 0,
    "inputStage": {
      "works": 88450,
      "restoreState": 88,
      "stage": "COLLSCAN",
      "saveState": 88,
      "advanced": 88450,
      "nReturned": 88450,
      "needYield": 0,
      "docsExamined": 88450,
      "needTime": 0,
      "isEOF": 0,
      "direction": "forward"
    },
    "failed": true,
    "usedDisk": false,
    "type": "simple",
    "isEOF": 0,
    "memLimit": 104857600,
    "stage": "SORT",
    "sortPattern": {
      "-$natural": 1
    },
    "needYield": 0,
    "needTime": 88449,
    "totalDataSizeSorted": 0,
    "spills": 0
  },
  "cmd": {
    "filter": {},
    "lsid": {
      "id": {
        "$uuid": "2617b402-0c61-4035-bc39-d616e412fbb3"
      }
    },
    "$readPreference": {
      "mode": "primary"
    },
    "$db": "local",
    "$clusterTime": {
      "clusterTime": {
        "$timestamp": {
          "t": 1704123123,
          "i": 1
        }
      },
      "signature": {
        "keyId": 0,
        "hash": {
          "$binary": {
            "base64": "AAAAAAAAAAAAAAAAAAAAAAAAAAA=",
            "subType": "0"
          }
        }
      }
    },
    "find": "oplog.rs",
    "sort": {
      "-$natural": 1
    }
  },
  "error": {
    "code": 292,
    "codeName": "QueryExceededMemoryLimitNoDiskUseAllowed",
    "errmsg": "Sort exceeded memory limit of 104857600 bytes, but did not opt in to external sorting."
  }
}

Can someone point me to the right direction where can I found the source of issue?

    rs.status()

    {
      set: 'hz0',
      date: 2024-01-01T20:30:05.973Z,
      myState: 1,
      term: Long('12'),
      syncSourceHost: '',
      syncSourceId: -1,
      heartbeatIntervalMillis: Long('2000'),
      majorityVoteCount: 3,
      writeMajorityCount: 3,
      votingMembersCount: 4,
      writableVotingMembersCount: 4,
      optimes: {
        lastCommittedOpTime: { ts: Timestamp({ t: 1704141003, i: 1 }), t: Long('12') },
        lastCommittedWallTime: 2024-01-01T20:30:03.989Z,
        readConcernMajorityOpTime: { ts: Timestamp({ t: 1704141003, i: 1 }), t: Long('12') },
        appliedOpTime: { ts: Timestamp({ t: 1704141003, i: 1 }), t: Long('12') },
        durableOpTime: { ts: Timestamp({ t: 1704141003, i: 1 }), t: Long('12') },
        lastAppliedWallTime: 2024-01-01T20:30:03.989Z,
        lastDurableWallTime: 2024-01-01T20:30:03.989Z
      },
      lastStableRecoveryTimestamp: Timestamp({ t: 1704140953, i: 1 }),
      electionCandidateMetrics: {
        lastElectionReason: 'priorityTakeover',
        lastElectionDate: 2024-01-01T12:39:12.915Z,
        electionTerm: Long('12'),
        lastCommittedOpTimeAtElection: { ts: Timestamp({ t: 1704112747, i: 1 }), t: Long('11') },
        lastSeenOpTimeAtElection: { ts: Timestamp({ t: 1704112747, i: 1 }), t: Long('11') },
        numVotesNeeded: 3,
        priorityAtElection: 15,
        electionTimeoutMillis: Long('10000'),
        priorPrimaryMemberId: 1,
        numCatchUpOps: Long('0'),
        newTermStartDate: 2024-01-01T12:39:12.926Z,
        wMajorityWriteAvailabilityDate: 2024-01-01T12:39:12.944Z
      },
      members: [
        {
          _id: 0,
          name: 'thor-live.d1:27017',
          health: 1,
          state: 1,
          stateStr: 'PRIMARY',
          uptime: 28268,
          optime: [Object],
          optimeDate: 2024-01-01T20:30:03.000Z,
          lastAppliedWallTime: 2024-01-01T20:30:03.989Z,
          lastDurableWallTime: 2024-01-01T20:30:03.989Z,
          syncSourceHost: '',
          syncSourceId: -1,
          infoMessage: '',
          electionTime: Timestamp({ t: 1704112752, i: 1 }),
          electionDate: 2024-01-01T12:39:12.000Z,
          configVersion: 15,
          configTerm: 12,
          self: true,
          lastHeartbeatMessage: ''
        },
        {
          _id: 1,
          name: 'thor-live.d2:27017',
          health: 1,
          state: 2,
          stateStr: 'SECONDARY',
          uptime: 28263,
          optime: [Object],
          optimeDurable: [Object],
          optimeDate: 2024-01-01T20:30:03.000Z,
          optimeDurableDate: 2024-01-01T20:30:03.000Z,
          lastAppliedWallTime: 2024-01-01T20:30:03.989Z,
          lastDurableWallTime: 2024-01-01T20:30:03.989Z,
          lastHeartbeat: 2024-01-01T20:30:04.769Z,
          lastHeartbeatRecv: 2024-01-01T20:30:04.202Z,
          pingMs: Long('0'),
          lastHeartbeatMessage: '',
          syncSourceHost: 'thor-live.d1:27017',
          syncSourceId: 0,
          infoMessage: '',
          configVersion: 15,
          configTerm: 12
        },
        {
          _id: 2,
          name: 'thor-live.d3:27017',
          health: 1,
          state: 2,
          stateStr: 'SECONDARY',
          uptime: 28263,
          optime: [Object],
          optimeDurable: [Object],
          optimeDate: 2024-01-01T20:30:03.000Z,
          optimeDurableDate: 2024-01-01T20:30:03.000Z,
          lastAppliedWallTime: 2024-01-01T20:30:03.989Z,
          lastDurableWallTime: 2024-01-01T20:30:03.989Z,
          lastHeartbeat: 2024-01-01T20:30:04.769Z,
          lastHeartbeatRecv: 2024-01-01T20:30:04.762Z,
          pingMs: Long('0'),
          lastHeartbeatMessage: '',
          syncSourceHost: 'thor-live.d2:27017',
          syncSourceId: 1,
          infoMessage: '',
          configVersion: 15,
          configTerm: 12
        },
        {
          _id: 3,
          name: 'thor-live.d4:27017',
          health: 1,
          state: 2,
          stateStr: 'SECONDARY',
          uptime: 28263,
          optime: [Object],
          optimeDurable: [Object],
          optimeDate: 2024-01-01T20:30:03.000Z,
          optimeDurableDate: 2024-01-01T20:30:03.000Z,
          lastAppliedWallTime: 2024-01-01T20:30:03.989Z,
          lastDurableWallTime: 2024-01-01T20:30:03.989Z,
          lastHeartbeat: 2024-01-01T20:30:04.769Z,
          lastHeartbeatRecv: 2024-01-01T20:30:04.760Z,
          pingMs: Long('0'),
          lastHeartbeatMessage: '',
          syncSourceHost: 'thor-live.d2:27017',
          syncSourceId: 1,
          infoMessage: '',
          configVersion: 15,
          configTerm: 12
        }
      ],
      ok: 1,
      '$clusterTime': {
        clusterTime: Timestamp({ t: 1704141003, i: 1 }),
        signature: {
          hash: Binary.createFromBase64('AAAAAAAAAAAAAAAAAAAAAAAAAAA=', 0),
          keyId: Long('0')
        }
      },
      operationTime: Timestamp({ t: 1704141003, i: 1 })
    }

9
  • What is the specific concern behind generating temp files? Is the storage cost high for you? From the information you provided, you are sorting in reverse natural order. If you just want to find the latest inserted documents, you may want to add a created_at date field and index it. You can potentially avoid doing a COLLSCAN that uses a lot of memory.
    – ray
    Jan 1 at 17:18
  • 2
    It looks to me like there is a typo here. "-$natural": 1 is not reverse natural order. Instead it is an ascending sort on a field called -$natural which almost certainly doesn't exist. Try "$natural": -1 instead if you are looking for reverse insertion order (or do something like @ray mentions). See also the documentation here for more about efficient sorting on fields Jan 1 at 17:30
  • @ray Yes, the storage cost concerns me because it increases until the mongodb stop working.
    – SnackK0515
    Jan 1 at 19:07
  • I forgot to mention that I don't really know what cause this issue. I don't really start any related process. After some research I thought this problem related to replica set.
    – SnackK0515
    Jan 1 at 19:08
  • 1
    If that error appears in the mongod log, you should be able to see the source IP address and user account in the other log entries for the connection
    – Joe
    Jan 2 at 23:12

1 Answer 1

0

The problem is not specifically the mongod service. The problem is the current load makes heavy use of in-memory sorting.

The mongodb query executor limits in-memory sort operations to 100MB. It is possible for some of the data to be written to a temporary file on disk when the sort would exceed that amount of memory, but this behavior must be specifically allowed.

The error message "Sort exceeded memory limit of 104857600 bytes, but did not opt in to external sorting." indicates that a query uses an in-memory sort that would require more than 100MB of memory, and using temporary disk files was not permitted.

Some things you can do:

  • add more disk space to permit the current usages
  • modify the schema and/or queries so the sort is not required
  • create indexes to support the sort so it is not done in memory
3
  • It looks the the memory consumption is used at oplog.rs, i.e. nothing which is defined at application level nor by a manual query. Jan 2 at 20:45
  • oplog.rs doesn't create temp files though. that would be a single .wt file in the dbpath, and replication would use a long-running cursor. Your suggestion to fix the sort field from -$natrual to $natural would fall under "modify the query", and should resolve that one particular instance.
    – Joe
    Jan 2 at 23:06
  • Also note than anything that uses watch or a change stream is going to be querying oplog.rs.
    – Joe
    Jan 2 at 23:17

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.