Logs are too noisy when dropping spill tables

XMLWordPrintableJSON

    • 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.

              Assignee:
              Unassigned
              Reporter:
              Louis Williams
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Created:
                Updated: