slow mongo operations

[vondele]

To follow up on the discussion that started https://github.com/glinscott/fishtest/pull/1600 this issue is to track slow operations in the Mongo DB.

The following list are the top 10 slowest entries in the last 10k entries of the mongo log (/var/log/mongodb/mongod.log), they take between 5 and 10s:

{"t":{"$date":"2023-04-25T07:18:42.590+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn8","msg":"Slow query","attr":{"type":"command","ns":"fishtest_new.actions","command":{"find":"actions","filter":{"action":{"$nin":["system_event","update_stats","dead_task"]}},"sort":{"_id":-1},"skip":563750,"limit":25,"lsid":{"id":{"$uuid":"b42ea8ce-2a0d-4822-b35b-d05a745ea4e3"}},"$db":"fishtest_new"},"planSummary":"IXSCAN { _id: 1 }","keysExamined":947594,"docsExamined":947594,"fromMultiPlanner":true,"replanned":true,"replanReason":"cached plan was less efficient than expected: expected trial execution to take 711 works but it took at least 7110 works","cursorExhausted":true,"numYields":1239,"nreturned":10,"queryHash":"1D081B0E","planCacheKey":"11DC8B40","queryFramework":"classic","reslen":1931,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":1240}},"Global":{"acquireCount":{"r":1240}},"Mutex":{"acquireCount":{"r":1}}},"storage":{"data":{"bytesRead":1563166,"timeReadingMicros":34606}},"remote":"127.0.0.1:35618","protocol":"op_msg","durationMillis":4956}}



{"t":{"$date":"2023-04-25T04:11:48.488+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn12","msg":"Slow query","attr":{"type":"command","ns":"fishtest_new.actions","command":{"find":"actions","filter":{"action":{"$nin":["system_event","update_stats","dead_task"]}},"sort":{"_id":-1},"skip":563400,"limit":25,"lsid":{"id":{"$uuid":"5e7fa420-1e8e-42f8-ba8d-2d3d8f6e3933"}},"$db":"fishtest_new"},"planSummary":"IXSCAN { _id: 1 }","keysExamined":947241,"docsExamined":947241,"fromMultiPlanner":true,"cursorExhausted":true,"numYields":1231,"nreturned":25,"queryHash":"1D081B0E","planCacheKey":"11DC8B40","queryFramework":"classic","reslen":4463,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":1232}},"Global":{"acquireCount":{"r":1232}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"127.0.0.1:39578","protocol":"op_msg","durationMillis":5000}}



{"t":{"$date":"2023-04-25T05:25:34.575+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn16","msg":"Slow query","attr":{"type":"command","ns":"fishtest_new.actions","command":{"find":"actions","filter":{"action":{"$nin":["system_event","update_stats","dead_task"]}},"sort":{"_id":-1},"skip":563350,"limit":25,"lsid":{"id":{"$uuid":"0adbcff4-ea3c-42ec-9006-f74607242562"}},"$db":"fishtest_new"},"planSummary":"IXSCAN { _id: 1 }","keysExamined":947199,"docsExamined":947199,"fromMultiPlanner":true,"replanned":true,"replanReason":"cached plan was less efficient than expected: expected trial execution to take 342 works but it took at least 3420 works","cursorExhausted":true,"numYields":1235,"nreturned":25,"queryHash":"1D081B0E","planCacheKey":"11DC8B40","queryFramework":"classic","reslen":4486,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":1236}},"Global":{"acquireCount":{"r":1236}},"Mutex":{"acquireCount":{"r":1}}},"storage":{"data":{"bytesRead":1014737,"timeReadingMicros":48379}},"remote":"127.0.0.1:60826","protocol":"op_msg","durationMillis":5322}}



{"t":{"$date":"2023-04-25T03:36:03.424+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn18","msg":"Slow query","attr":{"type":"command","ns":"fishtest_new.actions","command":{"find":"actions","filter":{"action":{"$nin":["system_event","update_stats","dead_task"]}},"sort":{"_id":-1},"skip":563575,"limit":25,"lsid":{"id":{"$uuid":"0adbcff4-ea3c-42ec-9006-f74607242562"}},"$db":"fishtest_new"},"planSummary":"IXSCAN { _id: 1 }","keysExamined":947413,"docsExamined":947413,"fromMultiPlanner":true,"cursorExhausted":true,"numYields":1250,"nreturned":25,"queryHash":"1D081B0E","planCacheKey":"11DC8B40","queryFramework":"classic","reslen":4492,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":1251}},"Global":{"acquireCount":{"r":1251}},"Mutex":{"acquireCount":{"r":1}}},"storage":{"data":{"bytesRead":26074606,"timeReadingMicros":555783}},"remote":"127.0.0.1:6662","protocol":"op_msg","durationMillis":5703}}



{"t":{"$date":"2023-04-25T04:25:59.634+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn16","msg":"Slow query","attr":{"type":"command","ns":"fishtest_new.actions","command":{"find":"actions","filter":{"action":{"$nin":["system_event","update_stats","dead_task"]}},"sort":{"_id":-1},"skip":563550,"limit":25,"lsid":{"id":{"$uuid":"69b3ea30-6bc8-4f51-b88c-d669e8f48e4a"}},"$db":"fishtest_new"},"planSummary":"IXSCAN { _id: 1 }","keysExamined":947393,"docsExamined":947393,"fromMultiPlanner":true,"replanned":true,"replanReason":"cached plan was less efficient than expected: expected trial execution to take 468 works but it took at least 4680 works","cursorExhausted":true,"numYields":1266,"nreturned":25,"queryHash":"1D081B0E","planCacheKey":"11DC8B40","queryFramework":"classic","reslen":4522,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":1267}},"Global":{"acquireCount":{"r":1267}},"Mutex":{"acquireCount":{"r":1}}},"storage":{"data":{"bytesRead":8821821,"timeReadingMicros":1000883}},"remote":"127.0.0.1:60826","protocol":"op_msg","durationMillis":5909}}



{"t":{"$date":"2023-04-25T03:39:01.554+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn18","msg":"Slow query","attr":{"type":"command","ns":"fishtest_new.actions","command":{"find":"actions","filter":{"action":{"$nin":["system_event","update_stats","dead_task"]}},"sort":{"_id":-1},"skip":563600,"limit":25,"lsid":{"id":{"$uuid":"0adbcff4-ea3c-42ec-9006-f74607242562"}},"$db":"fishtest_new"},"planSummary":"IXSCAN { _id: 1 }","keysExamined":947439,"docsExamined":947439,"fromMultiPlanner":true,"cursorExhausted":true,"numYields":1257,"nreturned":25,"queryHash":"1D081B0E","planCacheKey":"11DC8B40","queryFramework":"classic","reslen":4444,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":1258}},"Global":{"acquireCount":{"r":1258}},"Mutex":{"acquireCount":{"r":1}}},"storage":{"data":{"bytesRead":21080762,"timeReadingMicros":846335}},"remote":"127.0.0.1:6662","protocol":"op_msg","durationMillis":6532}}



{"t":{"$date":"2023-04-25T04:08:10.712+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn18","msg":"Slow query","attr":{"type":"command","ns":"fishtest_new.actions","command":{"find":"actions","filter":{"action":{"$nin":["system_event","update_stats","dead_task"]}},"sort":{"_id":-1},"skip":563500,"limit":25,"lsid":{"id":{"$uuid":"69b3ea30-6bc8-4f51-b88c-d669e8f48e4a"}},"$db":"fishtest_new"},"planSummary":"IXSCAN { _id: 1 }","keysExamined":947341,"docsExamined":947341,"fromMultiPlanner":true,"cursorExhausted":true,"numYields":1242,"nreturned":25,"queryHash":"1D081B0E","planCacheKey":"11DC8B40","queryFramework":"classic","reslen":4357,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":1243}},"Global":{"acquireCount":{"r":1243}},"Mutex":{"acquireCount":{"r":1}}},"storage":{"data":{"bytesRead":10183916,"timeReadingMicros":2932670}},"remote":"127.0.0.1:6662","protocol":"op_msg","durationMillis":7641}}



{"t":{"$date":"2023-04-25T06:39:19.616+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn8","msg":"Slow query","attr":{"type":"command","ns":"fishtest_new.actions","command":{"find":"actions","filter":{"action":{"$nin":["system_event","update_stats","dead_task"]}},"sort":{"_id":-1},"skip":563300,"limit":25,"lsid":{"id":{"$uuid":"5e7fa420-1e8e-42f8-ba8d-2d3d8f6e3933"}},"$db":"fishtest_new"},"planSummary":"IXSCAN { _id: 1 }","keysExamined":947156,"docsExamined":947156,"fromMultiPlanner":true,"replanned":true,"replanReason":"cached plan was less efficient than expected: expected trial execution to take 683 works but it took at least 6830 works","cursorExhausted":true,"numYields":1350,"nreturned":25,"queryHash":"1D081B0E","planCacheKey":"11DC8B40","queryFramework":"classic","reslen":4361,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":1351}},"Global":{"acquireCount":{"r":1351}},"Mutex":{"acquireCount":{"r":1}}},"storage":{"data":{"bytesRead":89115341,"timeReadingMicros":4360711}},"remote":"127.0.0.1:35618","protocol":"op_msg","durationMillis":9549}}



{"t":{"$date":"2023-04-25T11:29:47.300+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn18","msg":"Slow query","attr":{"type":"command","ns":"fishtest_new.runs","command":{"aggregate":"runs","pipeline":[{"$match":{"finished":true,"tc_base":{"$gte":40},"is_green":true}},{"$group":{"_id":1,"n":{"$sum":1}}}],"cursor":{},"lsid":{"id":{"$uuid":"0adbcff4-ea3c-42ec-9006-f74607242562"}},"$db":"fishtest_new"},"planSummary":"IXSCAN { finished: 1, is_green: -1, last_updated: -1 }","keysExamined":12729,"docsExamined":12729,"fromMultiPlanner":true,"cursorExhausted":true,"numYields":571,"nreturned":1,"queryHash":"86AC6305","planCacheKey":"D67F1979","queryFramework":"classic","reslen":130,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":573}},"Global":{"acquireCount":{"r":573}},"Mutex":{"acquireCount":{"r":2}}},"storage":{"data":{"bytesRead":3019053235,"timeReadingMicros":6420624},"timeWaitingMicros":{"cache":433}},"remote":"127.0.0.1:6662","protocol":"op_msg","durationMillis":10785}}



{"t":{"$date":"2023-04-25T02:57:22.645+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn8","msg":"Slow query","attr":{"type":"command","ns":"fishtest_new.actions","command":{"find":"actions","filter":{"action":{"$nin":["system_event","update_stats","dead_task"]}},"sort":{"_id":-1},"skip":563450,"limit":25,"lsid":{"id":{"$uuid":"69b3ea30-6bc8-4f51-b88c-d669e8f48e4a"}},"$db":"fishtest_new"},"planSummary":"IXSCAN { _id: 1 }","keysExamined":947284,"docsExamined":947284,"fromMultiPlanner":true,"replanned":true,"replanReason":"cached plan was less efficient than expected: expected trial execution to take 27 works but it took at least 270 works","cursorExhausted":true,"numYields":1376,"nreturned":25,"queryHash":"1D081B0E","planCacheKey":"11DC8B40","queryFramework":"classic","reslen":4517,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":1377}},"Global":{"acquireCount":{"r":1377}},"Mutex":{"acquireCount":{"r":1}}},"storage":{"data":{"bytesRead":108608115,"timeReadingMicros":5873464}},"remote":"127.0.0.1:35618","protocol":"op_msg","durationMillis":11185}}