Skip to content

ExecutionMemoryPool errors releasing more memory than allocated #2453

Closed

Description

@andygrove

Describe the bug

As seen in #2452, Comet sometimes tries to release memory that is not allocated.

25/09/24 21:24:57 WARN ExecutionMemoryPool: Internal error: release called on 917504 bytes but task only has 0 bytes of memory from the off-heap execution pool
25/09/24 21:24:57 WARN ExecutionMemoryPool: Internal error: release called on 839664 bytes but task only has 0 bytes of memory from the off-heap execution pool
25/09/24 21:24:57 WARN ExecutionMemoryPool: Internal error: release called on 917504 bytes but task only has 0 bytes of memory from the off-heap execution pool

Steps to reproduce

No response

Expected behavior

No response

Additional context

No response

Activity

  1. added this to the 0.11.0 milestone on Sep 25, 2025
  2. self-assigned this
    on Sep 25, 2025
  3. andygrove commented on Sep 25, 2025

    @andygrove
    MemberAuthor

    Here is some more info. I am running with this config:

        --conf spark.executor.cores=8 \
        --conf spark.executor.memory=16G \
        --conf spark.memory.offHeap.enabled=true \
        --conf spark.memory.offHeap.size=24g \
    

    The memory issues start to happen after the following code fails to allocate the requested memory:

      // Called by Comet native through JNI.
      // Returns the actual amount of memory (in bytes) granted.
      public long acquireMemory(long size) {
        long acquired = internal.acquireExecutionMemory(size, nativeMemoryConsumer);
        used.addAndGet(acquired);
        if (acquired < size) {
          // If memory manager is not able to acquire the requested size, log memory usage
          internal.showMemoryUsage();
        }
        return acquired;
      }

    The call to showMemoryUsage logs messages such as:

    INFO TaskMemoryManager: Memory used in task 21129
    INFO TaskMemoryManager: 3221225472 bytes of memory were used by task 21129 but are not associated with specific consumers
    INFO TaskMemoryManager: 18329799984 bytes of memory are used for execution and 1009734 bytes of memory are used for storage
    

    This indicates that one task is using 3GB, and a total of 18GB is allocated in the off-heap pool.

    This is followed by

    WARN ExecutionMemoryPool: Internal error: release called on 821408 bytes but task only has 0 bytes of memory from the off-heap execution pool
    ERROR Executor: Exception in task 113.0 in stage 199.3 (TID 21150)
    comet-benchmark-derived-from-tpch-08872799821543de-exec-7 spark-kubernetes-executor org.apache.comet.CometNativeException: Additional allocation failed with top memory consumers (across reservations) as:
    comet-benchmark-derived-from-tpch-08872799821543de-exec-7 spark-kubernetes-executor   ExternalSorter[138]#692(can spill: true) consumed 2.9 GB, peak 3.1 GB,
    comet-benchmark-derived-from-tpch-08872799821543de-exec-7 spark-kubernetes-executor   ExternalSorterMerge[138]#693(can spill: false) consumed 70.2 MB, peak 70.2 MB,
    comet-benchmark-derived-from-tpch-08872799821543de-exec-7 spark-kubernetes-executor   SMJStream[138]#694(can spill: false) consumed 0.0 B, peak 0.0 B.
    comet-benchmark-derived-from-tpch-08872799821543de-exec-7 spark-kubernetes-executor Error: Failed to acquire 409640 bytes, only got 83912. Reserved: 3222910152
    
  4. andygrove commented on Sep 26, 2025

    @andygrove
    MemberAuthor

    more debug logging, which now more clearly shows what is happening:

    25/09/26 15:50:30 INFO CometTaskMemoryManager: Task 1561 requested 734496 bytes
    25/09/26 15:50:30 INFO core/src/execution/memory_pools/unified_pool.rs: Task 1561 shrink() release_to_spark(734496)
    25/09/26 15:50:30 INFO CometTaskMemoryManager: Task 1561 released 734496 bytes
    25/09/26 15:50:30 WARN ExecutionMemoryPool: Internal error: release called on 734496 bytes but task only has 0 bytes of memory from the off-heap execution pool
    
  5. parthchandra commented on Sep 27, 2025

    @parthchandra
    Contributor
    25/09/26 15:50:30 INFO CometTaskMemoryManager: Task 1561 released 734496 bytes
    25/09/26 15:50:30 WARN ExecutionMemoryPool: Internal error: release called on 734496 bytes but task only has 0 bytes of memory from the off-heap execution pool
    

    Isn't CometTaskMemoryManager calling the memory pool to do the release? Is this simply a question of updating the memory accounting and then actually trying to release (which checks if there is enough memory to release)?

  6. parthchandra commented on Sep 27, 2025

    @parthchandra
    Contributor

    Either way, tremendous bit of debugging!

  7. andygrove commented on Oct 3, 2025

    @andygrove
    MemberAuthor

    DataFusion operators are attempting to release more memory than acquired. We could choose to just ignore attempts to make pools negative, but I'd rather track down the root cause because it seems like a bug.

  8. modified the milestones: 0.12.0, 0.11.0 on Oct 11, 2025
  9. modified the milestones: 0.12.0, 0.13.0 on Nov 7, 2025
  10. removed this from the 0.13.0 milestone on Jan 30, 2026
  11. 2 remaining items

  12. added
    priority:highCrashes, panics, segfaults, major functional breakage
    on Mar 27, 2026
  13. added this to the 0.15.0 milestone on Mar 27, 2026
  14. added a commit that references this issue on Mar 28, 2026
    e25a87c
  15. modified the milestones: 0.15.0, 0.16.0 on Apr 25, 2026
  16. modified the milestones: 0.17.0, 1.0.0 on Jun 25, 2026
  17. modified the milestones: 1.0.0, 1.1.0 on Aug 17, 2026
  18. andygrove commented on Sep 26, 2026

    @andygrove
    MemberAuthor

    I can reproduce this on main, and the cause is not what I originally suspected. #6128 made the pools repay any shortfall before handing bytes back to Spark. In a pressure run with spilling sorts, a spilling aggregate and a failing hash join, none of those tests logged an over-release. The warnings come from plans that outlive their task.

    A plan with only native inputs runs its stream on a Tokio task that executePlan spawns without keeping the handle (jni_api.rs#L1161-L1189). releasePlan drops the receiving end of the channel. The producer keeps the stream, and every reservation in it, until its next send fails. So when the JVM side stops early or fails, the Spark task finishes first.

    I ran a native sort over a native Parquet scan with 96 MB of off-heap memory on local[4], with a JVM consumer that either stops after 10 rows or throws after 1000. Every task logged this:

    WARN CometExecIterator: CometExecIterator closed with non-zero memory usage : 24248400
    WARN Executor: Managed memory leak detected; size = 24248400 bytes, task 1.0 in stage 10.0 (TID 28)
    WARN ExecutionMemoryPool: Internal error: release called on 24248400 bytes but task only has 0 bytes of memory from the off-heap execution pool
    

    The middle line only appears when the task stops early; a failed task skips it. The last line comes from a Tokio thread a few milliseconds after Spark's end-of-task cleanup. Between the two, Spark had freed that memory for other tasks while native code still held it. A producer that is still computing at that point keeps going until it next tries to send, and it can keep reserving against the finished task in the meantime.

    #5504 already proposes the fix: keep the producer's handle, and have releasePlan cancel it and wait for it within a bounded time. I'm going to treat that as the fix for this issue too.

  19. added a commit that references this issue on Sep 29, 2026
    8805e3f
  20. added a commit that references this issue on Sep 30, 2026
    8e4bded
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

bugSomething isn't workingpriority:highCrashes, panics, segfaults, major functional breakage

Type

No type

Projects

No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions