MongoDB cluster_events collection - SessionDeletedEvent - Slow query

## Expected Behavior

Sub-second response times from MongoDB when querying the `cluster_events` collection for documents/keys/events related to SessionDeletedEvent.

## Current Behavior

Slow query log-messages from MongoDB might indicate some potential for optimization in the way User sessions are managed:

-----

{"t":{"$date":"2023-11-16T22:39:48.744+00:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn7955","msg":"Slow query","attr":{"type":"command","ns":"graylog.cluster_events","command":{"find":"cluster_events","filter":{"consumers":{"$nin":["5f7a607b-ad99-4120-9e1c-f76cd81a0b75"]}},"sort":{"timestamp":1},"$db":"graylog","$clusterTime":{"clusterTime":{"$timestamp":{"t":1700174386,"i":36}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"lsid":{"id":{"$uuid":"2fc51f58-7ade-476b-b843-57294dbdd708"}}},"planSummary":"IXSCAN { timestamp: 1, producer: 1, consumers: 1

-----

Each Graylog Node needs to maintain its cache of User Sessions, which leads to this activity being executed by every Graylog Node approximately every second. This activity of course generates events, which in this issue roughly +70k of type `SessionDeletedEvent` existed in the `cluster_events` collection of the graylog MongoDB database.

In large-scale deployments with many Graylog Nodes & Users, this might lead to excessive cpu utilization by Mongo that we observed during benchmarks of 10TB/day ingest.

```
Tasks: 231 total, 1 running, 230 sleeping, 0 stopped, 0 zombie
%Cpu(s): 99.2 us, 0.8 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
MiB Mem : 31304.4 total, 18345.4 free, 3937.3 used, 9021.7 buff/cache
MiB Swap: 0.0 total, 0.0 free, 0.0 used. 26930.1 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
46379 mongodb 20 0 4827584 1.3g 70768 S 1600 4.2 16208:29 mongod
85592 graylog 20 0 11.8g 2.2g 26044 S 6.7 7.2 3:20.32 java
87151 ubuntu 20 0 11180 4040 3200 R 6.7 0.0 0:00.01 top
1 root 20 0 169384 12848 8332 S 0.0 0.0 1:41.28 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.01 kthreadd
```

And this behavior persists shortly after restarting all Graylog nodes & MongoDB Replica nodes and then leaving the deployment "idle".

At the time of discovering this behavior, the MongoDB Profiler after 1-2 minutes of sampling showed this operation to the the longest-running which seems to be the largest contributor to cpu utilization by Mongo:

MongoDB Profiler Output

```
rs01 [direct: primary] graylog> db.system.profile.find().sort({ ts: -1 }).limit(10)
[
{
op: 'query',
ns: 'graylog.cluster_events',
command: {
find: 'cluster_events',
filter: {
consumers: { '$nin': [ '7ebed3e2-cacf-447f-a572-cc916b6b90ff' ] }
},
sort: { timestamp: 1 },
'$db': 'graylog',
'$clusterTime': {
clusterTime: Timestamp({ t: 1700167543, i: 59 }),
signature: {
hash: Binary.createFromBase64("AAAAAAAAAAAAAAAAAAAAAAAAAAA=", 0),
keyId: Long("0")
}
},
lsid: { id: new UUID("c6bc7479-31d5-4748-9632-4d4544320daa") }
},
keysExamined: 1466890,
docsExamined: 77205,
cursorExhausted: true,
numYield: 1495,
nreturned: 1,
queryHash: '60B21C01',
planCacheKey: '2C1663A1',
queryFramework: 'classic',
locks: {
FeatureCompatibilityVersion: { acquireCount: { r: Long("1497") } },
Global: { acquireCount: { r: Long("1497") } },
Mutex: { acquireCount: { r: Long("1") } }
},
flowControl: {},
readConcern: { level: 'local', provenance: 'implicitDefault' },
storage: {},
responseLength: 1093,
protocol: 'op_msg',
zooms: 3275,
planSummary: 'IXSCAN { timestamp: 1, producer: 1, consumers: 1 }',
execStats: {
stage: 'FETCH',
filter: {
consumers: { '$not': { '$eq': '7ebed3e2-cacf-447f-a572-cc916b6b90ff' } }
},
nReturned: 1,
executionTimeMillisEstimate: 3082,
works: 1466891,
advanced: 1,
needTime: 1466889,
needYield: 0,
saveState: 1495,
restoreState: 1495,
isEOF: 1,
docsExamined: 77205,
alreadyHasObj: 0,
inputStage: {
stage: 'IXSCAN',
nReturned: 77205,
executionTimeMillisEstimate: 2793,
works: 1466891,
advanced: 77205,
needTime: 1389685,
needYield: 0,
saveState: 1495,
restoreState: 1495,
isEOF: 1,
keyPattern: { timestamp: 1, producer: 1, consumers: 1 },
indexName: 'timestamp_1_producer_1_consumers_1',
isMultiKey: true,
multiKeyPaths: { timestamp: [], producer: [], consumers: [ 'consumers' ] },
isUnique: false,
isSparse: false,
isPartial: false,
indexVersion: 2,
direction: 'forward',
indexBounds: {
timestamp: [ '[MinKey, MaxKey]' ],
producer: [ '[MinKey, MaxKey]' ],
consumers: [ '[MinKey, MaxKey]' ]
},
keysExamined: 1466890,
seeks: 1,
dupsTested: 1466890,
dupsDropped: 1389685
}
},
ts: ISODate("2023-11-16T20:45:46.541Z"),
client: '10.0.1.4',
allUsers: [ { user: 'admin', db: 'graylog' } ],
user: 'admin@graylog'
}
```

Execution Stats from Mongo show that the index built on the collection is being selected when deciding a query-path

MongoDB Execution Stats

```
rs01 [direct: primary] graylog> db.graylog.cluster_events.find({
... "consumers": { "$nin": ["30f3a731-ca46-42c4-90e7-0b08796b5553"] }
... }).sort({ "timestamp": 1 }).explain("executionStats")
{
explainVersion: '1',
queryPlanner: {
namespace: 'graylog.graylog.cluster_events',
indexFilterSet: false,
parsedQuery: {
consumers: { '$not': { '$eq': '30f3a731-ca46-42c4-90e7-0b08796b5553' } }
},
queryHash: '60B21C01',
planCacheKey: '2C1663A1',
maxIndexedOrSolutionsReached: false,
maxIndexedAndSolutionsReached: false,
maxScansToExplodeReached: false,
winningPlan: {
stage: 'FETCH',
inputStage: {
stage: 'SORT',
sortPattern: { timestamp: 1 },
memLimit: 104857600,
type: 'default',
inputStage: {
stage: 'IXSCAN',
keyPattern: { consumers: 1, timestamp: 1 },
indexName: 'consumers_1_timestamp_1',
isMultiKey: false,
multiKeyPaths: { consumers: [], timestamp: [] },
isUnique: false,
isSparse: false,
isPartial: false,
indexVersion: 2,
direction: 'forward',
indexBounds: {
consumers: [
'[MinKey, "30f3a731-ca46-42c4-90e7-0b08796b5553")',
'("30f3a731-ca46-42c4-90e7-0b08796b5553", MaxKey]'
],
timestamp: [ '[MinKey, MaxKey]' ]
}
}
}
},
rejectedPlans: []
},
executionStats: {
executionSuccess: true,
nReturned: 0,
executionTimeMillis: 0,
totalKeysExamined: 0,
totalDocsExamined: 0,
executionStages: {
stage: 'FETCH',
nReturned: 0,
executionTimeMillisEstimate: 0,
works: 2,
advanced: 0,
needTime: 1,
needYield: 0,
saveState: 0,
restoreState: 0,
isEOF: 1,
docsExamined: 0,
alreadyHasObj: 0,
inputStage: {
stage: 'SORT',
nReturned: 0,
executionTimeMillisEstimate: 0,
works: 2,
advanced: 0,
needTime: 1,
needYield: 0,
saveState: 0,
restoreState: 0,
isEOF: 1,
sortPattern: { timestamp: 1 },
memLimit: 104857600,
type: 'default',
totalDataSizeSorted: 0,
usedDisk: false,
spills: 0,
inputStage: {
stage: 'IXSCAN',
nReturned: 0,
executionTimeMillisEstimate: 0,
works: 1,
advanced: 0,
needTime: 0,
needYield: 0,
saveState: 0,
restoreState: 0,
isEOF: 1,
keyPattern: { consumers: 1, timestamp: 1 },
indexName: 'consumers_1_timestamp_1',
isMultiKey: false,
multiKeyPaths: { consumers: [], timestamp: [] },
isUnique: false,
isSparse: false,
isPartial: false,
indexVersion: 2,
direction: 'forward',
indexBounds: {
consumers: [
'[MinKey, "30f3a731-ca46-42c4-90e7-0b08796b5553")',
'("30f3a731-ca46-42c4-90e7-0b08796b5553", MaxKey]'
],
timestamp: [ '[MinKey, MaxKey]' ]
},
keysExamined: 0,
seeks: 1,
dupsTested: 0,
dupsDropped: 0
}
}
}
},
command: {
find: 'graylog.cluster_events',
filter: {
consumers: { '$nin': [ '30f3a731-ca46-42c4-90e7-0b08796b5553' ] }
},
sort: { timestamp: 1 },
'$db': 'graylog'
},
serverInfo: {
host: 'ip-10-0-1-97',
port: 27017,
version: '6.0.11',
gitVersion: 'f797f841eaf1759c770271ae00c88b92b2766eed'
},
serverParameters: {
internalQueryFacetBufferSizeBytes: 104857600,
internalQueryFacetMaxOutputDocSizeBytes: 104857600,
internalLookupStageIntermediateDocumentMaxSizeBytes: 104857600,
internalDocumentSourceGroupMaxMemoryBytes: 104857600,
internalQueryMaxBlockingSortMemoryUsageBytes: 104857600,
internalQueryProhibitBlockingMergeOnMongoS: 0,
internalQueryMaxAddToSetBytes: 104857600,
internalDocumentSourceSetWindowFieldsMaxMemoryBytes: 104857600
},
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1700166849, i: 72 }),
signature: {
hash: Binary.createFromBase64("AAAAAAAAAAAAAAAAAAAAAAAAAAA=", 0),
keyId: Long("0")
}
},
operationTime: Timestamp({ t: 1700166849, i: 72 })
}
```

## Possible Solution

A different index that only consists of the timestamp & consumers, both in ascending order, might improve the execution time of the find-cmds.

## Steps to Reproduce (for bugs)

1. Create Graylog deployment consisting of multiple Graylog nodes.
2. Create many (tens of thousands) User sessions to Graylog which logout.
3. Monitor `mongod.log` for evidence of Slow Query on the `cluster_events` collection.
4. Observe cpu utilization of MongoD Replica Members.

## Context

## Your Environment

* Graylog Version: 5.2
* Java Version: 17
* OpenSearch Version: 2.2
* MongoDB Version: 6.0.11
* Operating System: Ubuntu 20.04.4 LTS (Focal Fossa)
* Browser version: Mozilla Firefox 119.0.1