The changes in SERVER-88168 made it such that workingMillis and durationMillis no longer come at the very end of slow query log lines. These are the two most relevant fields in a slow query log and should stay in the most visually important part of the log line.
Example:
[j4:c:prim] | 2024-04-15T08:02:20.405+00:00 I COMMAND 51803 [S] [conn239] "Slow query","attr":{"type":"command","isFromUserConnection":true,"ns":"config.databases","collectionType":"config","appName":"/data/mci/a5b01e74117a968cf5c310c7e9fc161a/src/dist-test/bin/mongos","command":{"aggregate":"databases","pipeline":[{"$group":{"_id":"$primary"}}],"cursor":{"batchSize":101},"maxTimeMS":90000,"readConcern":{"level":"majority"},"writeConcern":{"w":1,"wtimeout":0},"$queryOptions":{"$readPreference":{"mode":"nearest"}},"maxTimeMSOpOnly":90000,"$readPreference":{"mode":"nearest","hedge":{"enabled":true}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1713168135,"i":1}}},"$configTime":{"$timestamp":{"t":1713168128,"i":2}},"$topologyTime":{"$timestamp":{"t":1713167526,"i":2}},"$db":"config"},"planSummary":"COLLSCAN","planningTimeMicros":808,"numYields":0,"queryHash":"214330E9","planCacheKey":"B48E7F75","queryFramework":"sbe","ok":0,"errMsg":"PlanExecutor error during aggregation :: caused by :: Caused by :: WiredTigerRecordStore::insertRecord :: Please retry your operation or multi-document transaction.","errName":"WriteConflict","errCode":112,"reslen":360,"locks":{"Global":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":3}}},"readConcern":{"level":"majority","provenance":"clientSupplied"},"writeConcern":{"w":1,"wtimeout":0,"provenance":"clientSupplied"},"storage":{"timeWaitingMicros":{"cache":7179}},"cpuNanos":2451666998,"remote":"127.0.0.1:46648","protocol":"op_msg","workingMillis":2589,"durationMillis":2589,"queues":{"execution":{"admissions":2,"totalTimeQueuedMicros":0},"ingress":{"admissions":1,"totalTimeQueuedMicros":0}}}
I would also request that we only report non-zero "totalTimeQueuedMicros" to reduce noise.
- is depended on by
-
COMPASS-7927 Investigate changes in SERVER-90064: Move durationMillis back to end of slow query log lines
-
- Closed
-
- related to
-
SERVER-88168 Report admission control diagnostics in a way that is consistent across admission control mechanisms
-
- Closed
-