search

apache / incubator-gluten

Gluten is a middle layer responsible for offloading JVM-based SQL engines' execution to native engines.
https://gluten.apache.org/
Apache License 2.0
1.16k stars 421 forks source link

[VL] Spill not release memory #6556

Open FelixYBW opened 2 months ago

FelixYBW commented 2 months ago

Backend

VL (Velox)

Bug description

org.apache.gluten.exception.GlutenException: java.lang.RuntimeException: Exception: VeloxRuntimeError
Error Source: RUNTIME
Error Code: INVALID_STATE
Reason: Operator::isBlocked failed for [operator: HashBuild, plan node ID: 2]: Error during calling Java code from native code: org.apache.gluten.memory.memtarget.ThrowOnOomMemoryTarget$OutOfMemoryException: Not enough spark off-heap execution memory. Acquired: 8.0 MiB, granted: 7.0 MiB. Try tweaking config option spark.memory.offHeap.size to get larger space to run this application (if spark.gluten.memory.dynamic.offHeap.sizing.enabled is not enabled). 
Current config settings: 
    spark.gluten.memory.offHeap.size.in.bytes=40.0 GiB
    spark.gluten.memory.task.offHeap.size.in.bytes=10.0 GiB
    spark.gluten.memory.conservative.task.offHeap.size.in.bytes=5.0 GiB
    spark.memory.offHeap.enabled=true
    spark.gluten.memory.dynamic.offHeap.sizing.enabled=false
Memory consumer stats: 
    Task.105759:                                       Current used bytes:  40.0 GiB, peak bytes:        N/A
    \- Gluten.Tree.180:                                Current used bytes:  40.0 GiB, peak bytes:   40.0 GiB
       \- root.180:                                    Current used bytes:  40.0 GiB, peak bytes:   40.0 GiB
          +- WholeStageIterator.180:                   Current used bytes:  40.0 GiB, peak bytes:   40.0 GiB
          |  \- single:                                Current used bytes:  40.0 GiB, peak bytes:   40.0 GiB
          |     +- WholeStageIterator_root:            Current used bytes:  40.0 GiB, peak bytes:   40.0 GiB
          |     |  +- task.Gluten_Stage_5_TID_105759:  Current used bytes:  40.0 GiB, peak bytes:   40.0 GiB
          |     |  |  +- node.2:                       Current used bytes:  40.0 GiB, peak bytes:   40.0 GiB
          |     |  |  |  +- op.2.1.0.HashBuild:        Current used bytes:  40.0 GiB, peak bytes:   40.0 GiB
          |     |  |  |  \- op.2.0.0.HashProbe:        Current used bytes: 481.9 KiB, peak bytes:   14.5 MiB
          |     |  |  +- node.1:                       Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     |  |  |  \- op.1.1.0.ValueStream:      Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     |  |  +- node.3:                       Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     |  |  |  \- op.3.0.0.FilterProject:    Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     |  |  +- node.4:                       Current used bytes:     0.0 B, peak bytes: 1024.0 KiB
          |     |  |  |  \- op.4.0.0.FilterProject:    Current used bytes:     0.0 B, peak bytes:   24.0 KiB
          |     |  |  \- node.0:                       Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     |  |     \- op.0.0.0.ValueStream:      Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     |  \- WholeStageIterator_default_leaf: Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     \- gluten::MemoryAllocator:            Current used bytes:     0.0 B, peak bytes:      0.0 B
          +- ShuffleReader.0:                          Current used bytes:   9.0 MiB, peak bytes:   24.0 MiB
          |  \- single:                                Current used bytes:   9.0 MiB, peak bytes:   24.0 MiB
          |     +- ShuffleReader_root:                 Current used bytes:   9.9 KiB, peak bytes:   16.0 MiB
          |     |  \- ShuffleReader_default_leaf:      Current used bytes:   9.9 KiB, peak bytes:   15.4 MiB
          |     \- gluten::MemoryAllocator:            Current used bytes:   128.0 B, peak bytes:    6.3 MiB
          +- ArrowContextInstance.172:                 Current used bytes:   8.0 MiB, peak bytes:    8.0 MiB
          +- ArrowContextInstance.173:                 Current used bytes:     0.0 B, peak bytes:      0.0 B
          +- ShuffleWriter.180:                        Current used bytes:     0.0 B, peak bytes: 1808.0 MiB
          |  \- single:                                Current used bytes:     0.0 B, peak bytes: 1808.0 MiB
          |     +- ShuffleWriter_root:                 Current used bytes:     0.0 B, peak bytes:   72.0 MiB
          |     |  \- ShuffleWriter_default_leaf:      Current used bytes:     0.0 B, peak bytes:   64.8 MiB
          |     \- gluten::MemoryAllocator:            Current used bytes:     0.0 B, peak bytes: 1733.7 MiB
          +- OverAcquire.DummyTarget.532:              Current used bytes:     0.0 B, peak bytes:    7.2 MiB
          +- OverAcquire.DummyTarget.533:              Current used bytes:     0.0 B, peak bytes:    8.9 GiB
          \- OverAcquire.DummyTarget.534:              Current used bytes:     0.0 B, peak bytes:  542.4 MiB

    at org.apache.gluten.memory.memtarget.ThrowOnOomMemoryTarget.borrow(ThrowOnOomMemoryTarget.java:105)
    at org.apache.gluten.memory.nmm.ManagedReservationListener.reserve(ManagedReservationListener.java:43)
    at org.apache.gluten.vectorized.ColumnarBatchOutIterator.nativeHasNext(Native Method)
    at org.apache.gluten.vectorized.ColumnarBatchOutIterator.hasNextInternal(ColumnarBatchOutIterator.java:65)
    at org.apache.gluten.vectorized.GeneralOutIterator.hasNext(GeneralOutIterator.java:37)
    at scala.collection.convert.Wrappers$JIteratorWrapper.hasNext(Wrappers.scala:43)
    at org.apache.gluten.utils.InvocationFlowProtection.hasNext(Iterators.scala:135)
    at org.apache.gluten.utils.IteratorCompleter.hasNext(Iterators.scala:69)
    at org.apache.gluten.utils.PayloadCloser.hasNext(Iterators.scala:35)
    at org.apache.gluten.utils.PipelineTimeAccumulator.hasNext(Iterators.scala:98)
    at scala.collection.Iterator$$anon$10.hasNext(Iterator.scala:458)
    at org.apache.spark.shuffle.ColumnarShuffleWriter.internalWrite(ColumnarShuffleWriter.scala:135)
    at org.apache.spark.shuffle.ColumnarShuffleWriter.write(ColumnarShuffleWriter.scala:242)
    at org.apache.spark.shuffle.ShuffleWriteProcessor.write(ShuffleWriteProcessor.scala:59)
    at org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:99)
    at org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:52)
    at org.apache.spark.scheduler.Task.run(Task.scala:131)
    at org.apache.spark.executor.Executor$TaskRunner.$anonfun$run$3(Executor.scala:506)
    at org.apache.spark.util.Utils$.tryWithSafeFinally(Utils.scala:1471)
    at org.apache.spark.executor.Executor$TaskRunner.run(Executor.scala:509)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:750)

Retriable: False
Function: runInternal
File: /home/binweiyang/gluten/ep/build-velox/build/velox_ep/velox/exec/Driver.cpp
Line: 587
Stack trace:
# 0  _ZN8facebook5velox7process10StackTraceC1Ei
# 1  _ZN8facebook5velox14VeloxExceptionC1EPKcmS3_St17basic_string_viewIcSt11char_traitsIcEES7_S7_S7_bNS1_4TypeES7_
# 2  _ZN8facebook5velox6detail14veloxCheckFailINS0_17VeloxRuntimeErrorERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEEEvRKNS1_18VeloxCheckFailArgsET0_
# 3  _ZN8facebook5velox4exec6Driver11runInternalERSt10shared_ptrIS2_ERS3_INS1_13BlockingStateEERS3_INS0_9RowVectorEE.cold
# 4  _ZN8facebook5velox4exec6Driver4nextERSt10shared_ptrINS1_13BlockingStateEE
# 5  _ZN8facebook5velox4exec4Task4nextEPN5folly10SemiFutureINS3_4UnitEEE
# 6  _ZN6gluten24WholeStageResultIterator4nextEv
# 7  Java_org_apache_gluten_vectorized_ColumnarBatchOutIterator_nativeHasNext
# 8  0x00007f0dcbc89568

@zhztheplayer

Spark version

Spark-3.2.x

Spark configurations

No response

System information

No response

Relevant logs

No response

FelixYBW commented 2 months ago

It's triggered by hashbuild, but hashbuild holds all memory

FelixYBW commented 2 months ago

Another one:

org.apache.gluten.exception.GlutenException: java.lang.RuntimeException: Exception: VeloxRuntimeError
Error Source: RUNTIME
Error Code: INVALID_STATE
Reason: Operator::addInput failed for [operator: Aggregation, plan node ID: 5]: Error during calling Java code from native code: org.apache.gluten.memory.memtarget.ThrowOnOomMemoryTarget$OutOfMemoryException: Not enough spark off-heap execution memory. Acquired: 8.0 MiB, granted: 0.0 B. Try tweaking config option spark.memory.offHeap.size to get larger space to run this application (if spark.gluten.memory.dynamic.offHeap.sizing.enabled is not enabled). 
Current config settings: 
    spark.gluten.memory.offHeap.size.in.bytes=40.0 GiB
    spark.gluten.memory.task.offHeap.size.in.bytes=10.0 GiB
    spark.gluten.memory.conservative.task.offHeap.size.in.bytes=5.0 GiB
    spark.memory.offHeap.enabled=true
    spark.gluten.memory.dynamic.offHeap.sizing.enabled=false
Memory consumer stats: 
    Task.932:                                             Current used bytes:  10.0 GiB, peak bytes:        N/A
    \- Gluten.Tree.0:                                     Current used bytes:  10.0 GiB, peak bytes:   10.0 GiB
       \- root.0:                                         Current used bytes:  10.0 GiB, peak bytes:   10.0 GiB
          +- WholeStageIterator.0:                        Current used bytes:  10.0 GiB, peak bytes:   10.0 GiB
          |  \- single:                                   Current used bytes:  10.0 GiB, peak bytes:   10.0 GiB
          |     +- WholeStageIterator_root:               Current used bytes: 277.8 MiB, peak bytes:    9.9 GiB
          |     |  +- task.Gluten_Stage_0_TID_932:        Current used bytes: 277.8 MiB, peak bytes:    9.9 GiB
          |     |  |  +- node.5:                          Current used bytes: 256.0 MiB, peak bytes:    9.9 GiB
          |     |  |  |  \- op.5.0.0.Aggregation:         Current used bytes: 256.0 MiB, peak bytes:    6.6 GiB
          |     |  |  +- node.0:                          Current used bytes:  20.9 MiB, peak bytes:   24.0 MiB
          |     |  |  |  +- op.0.0.0.TableScan:           Current used bytes:  20.9 MiB, peak bytes:   22.6 MiB
          |     |  |  |  \- op.0.0.0.TableScan.test-hive: Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     |  |  +- node.1:                          Current used bytes: 890.6 KiB, peak bytes:    2.0 MiB
          |     |  |  |  \- op.1.0.0.FilterProject:       Current used bytes: 890.6 KiB, peak bytes: 1087.6 KiB
          |     |  |  +- node.3:                          Current used bytes:  25.3 KiB, peak bytes: 1024.0 KiB
          |     |  |  |  \- op.3.0.0.FilterProject:       Current used bytes:  25.3 KiB, peak bytes:   26.1 KiB
          |     |  |  +- node.2:                          Current used bytes:   640.0 B, peak bytes: 1024.0 KiB
          |     |  |  |  \- op.2.0.0.Expand:              Current used bytes:   640.0 B, peak bytes:    640.0 B
          |     |  |  +- node.6:                          Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     |  |  |  \- op.6.0.0.FilterProject:       Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     |  |  \- node.4:                          Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     |  |     \- op.4.0.0.Expand:              Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     |  \- WholeStageIterator_default_leaf:    Current used bytes:  1536.0 B, peak bytes:   1664.0 B
          |     \- gluten::MemoryAllocator:               Current used bytes:     0.0 B, peak bytes:      0.0 B
          \- OverAcquire.DummyTarget.1:                   Current used bytes:     0.0 B, peak bytes:    2.2 GiB

looks it's caused by spill not triggered

query plan:

+- ColumnarExchange (10)
   +- ^ ProjectExecTransformer (8)
      +- ^ RegularHashAggregateExecTransformer (7)
         +- ^ ExpandExecTransformer (6)
            +- ^ ProjectExecTransformer (5)
               +- ^ ExpandExecTransformer (4)
                  +- ^ ProjectExecTransformer (3)
                     +- ^ FilterExecTransformer (2)
                        +- ^ Scan parquet distribution.video_feedview_logs (1)
zhztheplayer commented 2 months ago

Usually Velox's hash join stops spilling when it reaches the max spill level. But I am not sure if it's the case. Going through the full log may help diagnose. @FelixYBW

FelixYBW commented 1 month ago

issue is gone after rebase

FelixYBW commented 2 weeks ago

The issue is still there:

Aggregation didn't hold memory but its root pool still hold the memory.

24/09/19 08:59:37 ERROR [Executor task launch worker for task 270.0 in stage 0.0 (TID 270)] listener.ManagedReservationListener: Error reserving memory from target
org.apache.gluten.memory.memtarget.ThrowOnOomMemoryTarget$OutOfMemoryException: Not enough spark off-heap execution memory. Acquired: 1080.0 MiB, granted: 552.0 MiB. Try tweaking config option spark.memory.offHeap.size to get larger space to run this application (if spark.gluten.memory.dynamic.offHeap.sizing.enabled is not enabled). 
Current config settings: 
    spark.gluten.memory.offHeap.size.in.bytes=50.0 GiB
    spark.gluten.memory.task.offHeap.size.in.bytes=12.5 GiB
    spark.gluten.memory.conservative.task.offHeap.size.in.bytes=6.3 GiB
    spark.memory.offHeap.enabled=true
    spark.gluten.memory.dynamic.offHeap.sizing.enabled=false
Memory consumer stats: 
    Task.270:                                             Current used bytes:  12.0 GiB, peak bytes:        N/A
    \- Gluten.Tree.3:                                     Current used bytes:  12.0 GiB, peak bytes:   12.5 GiB
       \- root.3:                                         Current used bytes:  12.0 GiB, peak bytes:   12.5 GiB
          +- WholeStageIterator.0:                        Current used bytes:  12.0 GiB, peak bytes:   12.5 GiB
          |  \- single:                                   Current used bytes:  12.0 GiB, peak bytes:   12.0 GiB
          |     +- root:                                  Current used bytes: 281.2 MiB, peak bytes:   12.0 GiB
          |     |  +- task.Gluten_Stage_0_TID_270_VTID_0: Current used bytes: 281.2 MiB, peak bytes:   12.0 GiB
          |     |  |  +- node.5:                          Current used bytes: 256.0 MiB, peak bytes:   11.9 GiB
          |     |  |  |  \- op.5.0.0.Aggregation:         Current used bytes: 256.0 MiB, peak bytes:    7.9 GiB
          |     |  |  +- node.0:                          Current used bytes:  24.2 MiB, peak bytes:   28.0 MiB
          |     |  |  |  +- op.0.0.0.TableScan:           Current used bytes:  24.2 MiB, peak bytes:   26.3 MiB
          |     |  |  |  \- op.0.0.0.TableScan.test-hive: Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     |  |  +- node.1:                          Current used bytes: 986.5 KiB, peak bytes:    2.0 MiB
          |     |  |  |  \- op.1.0.0.FilterProject:       Current used bytes: 986.5 KiB, peak bytes: 1183.5 KiB
          |     |  |  +- node.3:                          Current used bytes:  25.3 KiB, peak bytes: 1024.0 KiB
          |     |  |  |  \- op.3.0.0.FilterProject:       Current used bytes:  25.3 KiB, peak bytes:   26.1 KiB
          |     |  |  +- node.2:                          Current used bytes:   512.0 B, peak bytes: 1024.0 KiB
          |     |  |  |  \- op.2.0.0.Expand:              Current used bytes:   512.0 B, peak bytes:    640.0 B
          |     |  |  +- node.4:                          Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     |  |  |  \- op.4.0.0.Expand:              Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     |  |  \- node.6:                          Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     |  |     \- op.6.0.0.FilterProject:       Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     |  \- default_leaf:                       Current used bytes:  1536.0 B, peak bytes:   1664.0 B
          |     \- gluten::MemoryAllocator:               Current used bytes:     0.0 B, peak bytes:      0.0 B
          +- ShuffleWriter.3.OverAcquire.0:               Current used bytes:     0.0 B, peak bytes:      0.0 B
          +- ShuffleWriter.3:                             Current used bytes:     0.0 B, peak bytes:      0.0 B
          |  \- single:                                   Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     +- root:                                  Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     |  \- default_leaf:                       Current used bytes:     0.0 B, peak bytes:      0.0 B
          |     \- gluten::MemoryAllocator:               Current used bytes:     0.0 B, peak bytes:      0.0 B
          \- WholeStageIterator.0.OverAcquire.0:          Current used bytes:     0.0 B, peak bytes:    3.0 GiB