-
Type:
Bug
-
Resolution: Unresolved
-
Priority:
Major - P3
-
None
-
Affects Version/s: None
-
Component/s: None
-
Storage Execution
-
ALL
-
v8.2
-
None
-
3
-
TBD
-
None
-
None
-
None
-
None
-
None
-
None
-
None
In many of our query spilling workloads, there is a lot of log spam that looks like this:
{"t":{"$date":"2025-07-25T00:33:01.852+00:00"},"s":"I", "c":"STORAGE", "id":10327300,"ctx":"conn99","msg":"Failed to drop spill table, retrying","attr":{"error":{"code":314,"codeName":"ObjectIsBusy","errmsg":"16: Device or resource busy - the table has uncommitted data and cannot be dropped yet"},"attempts":0}} {"t":{"$date":"2025-07-25T00:33:01.852+00:00"},"s":"I", "c":"STORAGE", "id":10327300,"ctx":"conn99","msg":"Failed to drop spill table, retrying","attr":{"error":{"code":314,"codeName":"ObjectIsBusy","errmsg":"16: Device or resource busy - the table has uncommitted data and cannot be dropped yet"},"attempts":1}} {"t":{"$date":"2025-07-25T00:33:01.852+00:00"},"s":"I", "c":"STORAGE", "id":10327300,"ctx":"conn99","msg":"Failed to drop spill table, retrying","attr":{"error":{"code":314,"codeName":"ObjectIsBusy","errmsg":"16: Device or resource busy - the table has uncommitted data and cannot be dropped yet"},"attempts":2}} {"t":{"$date":"2025-07-25T00:33:01.852+00:00"},"s":"I", "c":"STORAGE", "id":10327300,"ctx":"conn99","msg":"Failed to drop spill table, retrying","attr":{"error":{"code":314,"codeName":"ObjectIsBusy","errmsg":"16: Device or resource busy - the table has uncommitted data and cannot be dropped yet"},"attempts":3}} {"t":{"$date":"2025-07-25T00:33:01.852+00:00"},"s":"I", "c":"STORAGE", "id":10327300,"ctx":"conn99","msg":"Failed to drop spill table, retrying","attr":{"error":{"code":314,"codeName":"ObjectIsBusy","errmsg":"16: Device or resource busy - the table has uncommitted data and cannot be dropped yet"},"attempts":4}} {"t":{"$date":"2025-07-25T00:33:01.853+00:00"},"s":"I", "c":"STORAGE", "id":10327300,"ctx":"conn99","msg":"Failed to drop spill table, retrying","attr":{"error":{"code":314,"codeName":"ObjectIsBusy","errmsg":"16: Device or resource busy - the table has uncommitted data and cannot be dropped yet"},"attempts":5}} {"t":{"$date":"2025-07-25T00:33:01.855+00:00"},"s":"I", "c":"STORAGE", "id":10327300,"ctx":"conn99","msg":"Failed to drop spill table, retrying","attr":{"error":{"code":314,"codeName":"ObjectIsBusy","errmsg":"16: Device or resource busy - the table has uncommitted data and cannot be dropped yet"},"attempts":6}} {"t":{"$date":"2025-07-25T00:33:01.856+00:00"},"s":"I", "c":"STORAGE", "id":10327300,"ctx":"conn99","msg":"Failed to drop spill table, retrying","attr":{"error":{"code":314,"codeName":"ObjectIsBusy","errmsg":"16: Device or resource busy - the table has uncommitted data and cannot be dropped yet"},"attempts":7}} {"t":{"$date":"2025-07-25T00:33:01.857+00:00"},"s":"I", "c":"STORAGE", "id":10327300,"ctx":"conn99","msg":"Failed to drop spill table, retrying","attr":{"error":{"code":314,"codeName":"ObjectIsBusy","errmsg":"16: Device or resource busy - the table has uncommitted data and cannot be dropped yet"},"attempts":8}} {"t":{"$date":"2025-07-25T00:33:01.858+00:00"},"s":"I", "c":"STORAGE", "id":10327300,"ctx":"conn99","msg":"Failed to drop spill table, retrying","attr":{"error":{"code":314,"codeName":"ObjectIsBusy","errmsg":"16: Device or resource busy - the table has uncommitted data and cannot be dropped yet"},"attempts":9}} {"t":{"$date":"2025-07-25T00:33:01.865+00:00"},"s":"I", "c":"STORAGE", "id":10327300,"ctx":"conn99","msg":"Failed to drop spill table, retrying","attr":{"error":{"code":314,"codeName":"ObjectIsBusy","errmsg":"16: Device or resource busy - the table has uncommitted data and cannot be dropped yet"},"attempts":10}} {"t":{"$date":"2025-07-25T00:33:02.321+00:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn99","msg":"Slow query","attr":{"type":"command","isFromUserConnection":true,"ns":"query_spilling.large_docs","collectionType":"normal","command":{"getMore":4899685502487370533,"collection":"large_docs","lsid":{"id":{"$uuid":"ff91c3e0-dbb5-4167-91a5-e4775977f301"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1753403561,"i":1}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$db":"query_spilling"},"originatingCommand":{"aggregate":"large_docs","pipeline":[{"$match":{}},{"$group":{"_id":"$group_id","count":{"$sum":1},"all_sample_data":{"$push":{"data":"$data","scan_field":"$scan_field"}},"total_scan_field":{"$sum":"$scan_field"}}},{"$project":{"all_sample_data":0}}],"allowDiskUse":true,"cursor":{},"lsid":{"id":{"$uuid":"ff91c3e0-dbb5-4167-91a5-e4775977f301"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1753403531,"i":1}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$db":"query_spilling"},"planSummary":"COLLSCAN","cursorid":4899685502487370533,"keysExamined":0,"docsExamined":0,"usedDisk":true,"nBatches":1,"cursorExhausted":true,"numYields":364,"nreturned":899,"groupSpills":12525,"groupSpilledBytes":1313419095000,"groupSpilledRecords":1252500,"groupSpilledDataStorageSize":1311090290688,"planCacheShapeHash":"19FE91C5","queryHash":"19FE91C5","planCacheKey":"4EC75E96","queryFramework":"sbe","reslen":46876,"locks":{"Global":{"acquireCount":{"r":815}}},"readConcern":{"level":"local","provenance":"implicitDefault"},"writeConcern":{"w":"majority","wtimeout":0,"provenance":"implicitDefault"},"storage":{"timeWaitingMicros":{"storageExecutionMicros":1708709}},"cpuNanos":4285256446,"remote":"10.2.0.10:55586","protocol":"op_msg","delinquencyInfo":{"totalDelinquentAcquisitions":99,"totalAcquisitionDelinquencyMillis":7427,"maxAcquisitionDelinquencyMillis":1070},"queues":{"ingress":{"admissions":1},"execution":{"admissions":815,"totalTimeQueuedMicros":46016}},"workingMillis":14261,"durationMillis":14307}}
It seems like the ObjectIsBusy errors are expected, so we should reduce the amount of noise generated in the logs when this happens.