Buffers allocated by ParquetFileReader.readVectored() are not being released

[steveloughran]

Describe the bug, including details regarding any error messages, version, and platform.

this surfaces when running TestParquetReader with hadoop >= 3.4.0

mvn -Dtest=TestParquetReader -Dhadoop.version=3.4.1

This is disappointing as it means

1. the hadoop release process hasn't been doing the parquet build and test (it's an optional action)
2. this got through our own large scale QE testing.

The good news: this hasn't surfaced in production, presumably because nothing is trying to read into direct buffers -something parquet blocks automatically.

[ERROR] org.apache.parquet.hadoop.TestParquetReader.testCurrentRowIndex[2] -- Time elapsed: 0.013 s <<< ERROR!
org.apache.parquet.bytes.TrackingByteBufferAllocator$LeakedByteBufferException: 2 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
        at org.apache.parquet.bytes.TrackingByteBufferAllocator.close(TrackingByteBufferAllocator.java:171)
        at org.apache.parquet.hadoop.TestParquetReader.closeAllocator(TestParquetReader.java:175)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
Caused by: org.apache.parquet.bytes.TrackingByteBufferAllocator$ByteBufferAllocationStacktraceException: Allocation stacktrace of the first ByteBuffer:
        at org.apache.parquet.bytes.TrackingByteBufferAllocator$ByteBufferAllocationStacktraceException.create(TrackingByteBufferAllocator.java:100)
        at org.apache.parquet.bytes.TrackingByteBufferAllocator$ByteBufferAllocationStacktraceException.access$300(TrackingByteBufferAllocator.java:94)
        at org.apache.parquet.bytes.TrackingByteBufferAllocator.allocate(TrackingByteBufferAllocator.java:140)
        at org.apache.hadoop.fs.RawLocalFileSystem$LocalFSFileInputStream.readVectored(RawLocalFileSystem.java:336)
        at org.apache.hadoop.fs.BufferedFSInputStream.readVectored(BufferedFSInputStream.java:182)
        at org.apache.hadoop.fs.FSDataInputStream.readVectored(FSDataInputStream.java:307)
        at org.apache.hadoop.fs.ChecksumFileSystem$ChecksumFSInputChecker.readVectored(ChecksumFileSystem.java:444)
        at org.apache.hadoop.fs.FSDataInputStream.readVectored(FSDataInputStream.java:307)

Component(s)

Core

[steveloughran]

can be seen on master with hadoop 3.3.5+ i.e. when vector IO went in.

full stacks on that branch

[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Running org.apache.parquet.hadoop.TestParquetReader
[ERROR] Tests run: 12, Failures: 0, Errors: 12, Skipped: 0, Time elapsed: 1.378 s <<< FAILURE! -- in org.apache.parquet.hadoop.TestParquetReader
[ERROR] org.apache.parquet.hadoop.TestParquetReader.testRangeFiltering[0] -- Time elapsed: 0.123 s <<< ERROR!
org.apache.parquet.bytes.TrackingByteBufferAllocator$LeakedByteBufferException: 24 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
        at org.apache.parquet.bytes.TrackingByteBufferAllocator.close(TrackingByteBufferAllocator.java:160)
        at org.apache.parquet.hadoop.TestParquetReader.closeAllocator(TestParquetReader.java:175)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
Caused by: org.apache.parquet.bytes.TrackingByteBufferAllocator$ByteBufferAllocationStacktraceException: Set org.apache.parquet.bytes.TrackingByteBufferAllocator.DEBUG = true for more info

[ERROR] org.apache.parquet.hadoop.TestParquetReader.testNoFiltering[0] -- Time elapsed: 0.068 s <<< ERROR!
org.apache.parquet.bytes.TrackingByteBufferAllocator$LeakedByteBufferException: 80 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
        at org.apache.parquet.bytes.TrackingByteBufferAllocator.close(TrackingByteBufferAllocator.java:160)
        at org.apache.parquet.hadoop.TestParquetReader.closeAllocator(TestParquetReader.java:175)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
Caused by: org.apache.parquet.bytes.TrackingByteBufferAllocator$ByteBufferAllocationStacktraceException: Set org.apache.parquet.bytes.TrackingByteBufferAllocator.DEBUG = true for more info

[ERROR] org.apache.parquet.hadoop.TestParquetReader.testSimpleFiltering[0] -- Time elapsed: 0.064 s <<< ERROR!
org.apache.parquet.bytes.TrackingByteBufferAllocator$LeakedByteBufferException: 40 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
        at org.apache.parquet.bytes.TrackingByteBufferAllocator.close(TrackingByteBufferAllocator.java:160)
        at org.apache.parquet.hadoop.TestParquetReader.closeAllocator(TestParquetReader.java:175)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
Caused by: org.apache.parquet.bytes.TrackingByteBufferAllocator$ByteBufferAllocationStacktraceException: Set org.apache.parquet.bytes.TrackingByteBufferAllocator.DEBUG = true for more info

[ERROR] org.apache.parquet.hadoop.TestParquetReader.testCurrentRowIndex[0] -- Time elapsed: 0.019 s <<< ERROR!
org.apache.parquet.bytes.TrackingByteBufferAllocator$LeakedByteBufferException: 20 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
        at org.apache.parquet.bytes.TrackingByteBufferAllocator.close(TrackingByteBufferAllocator.java:160)
        at org.apache.parquet.hadoop.TestParquetReader.closeAllocator(TestParquetReader.java:175)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
Caused by: org.apache.parquet.bytes.TrackingByteBufferAllocator$ByteBufferAllocationStacktraceException: Set org.apache.parquet.bytes.TrackingByteBufferAllocator.DEBUG = true for more info

[ERROR] org.apache.parquet.hadoop.TestParquetReader.testRangeFiltering[1] -- Time elapsed: 0.047 s <<< ERROR!
org.apache.parquet.bytes.TrackingByteBufferAllocator$LeakedByteBufferException: 14 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
        at org.apache.parquet.bytes.TrackingByteBufferAllocator.close(TrackingByteBufferAllocator.java:160)
        at org.apache.parquet.hadoop.TestParquetReader.closeAllocator(TestParquetReader.java:175)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
Caused by: org.apache.parquet.bytes.TrackingByteBufferAllocator$ByteBufferAllocationStacktraceException: Set org.apache.parquet.bytes.TrackingByteBufferAllocator.DEBUG = true for more info

[ERROR] org.apache.parquet.hadoop.TestParquetReader.testNoFiltering[1] -- Time elapsed: 0.044 s <<< ERROR!
org.apache.parquet.bytes.TrackingByteBufferAllocator$LeakedByteBufferException: 48 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
        at org.apache.parquet.bytes.TrackingByteBufferAllocator.close(TrackingByteBufferAllocator.java:160)
        at org.apache.parquet.hadoop.TestParquetReader.closeAllocator(TestParquetReader.java:175)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
Caused by: org.apache.parquet.bytes.TrackingByteBufferAllocator$ByteBufferAllocationStacktraceException: Set org.apache.parquet.bytes.TrackingByteBufferAllocator.DEBUG = true for more info

[ERROR] org.apache.parquet.hadoop.TestParquetReader.testSimpleFiltering[1] -- Time elapsed: 0.055 s <<< ERROR!
org.apache.parquet.bytes.TrackingByteBufferAllocator$LeakedByteBufferException: 28 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
        at org.apache.parquet.bytes.TrackingByteBufferAllocator.close(TrackingByteBufferAllocator.java:160)
        at org.apache.parquet.hadoop.TestParquetReader.closeAllocator(TestParquetReader.java:175)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
Caused by: org.apache.parquet.bytes.TrackingByteBufferAllocator$ByteBufferAllocationStacktraceException: Set org.apache.parquet.bytes.TrackingByteBufferAllocator.DEBUG = true for more info

[ERROR] org.apache.parquet.hadoop.TestParquetReader.testCurrentRowIndex[1] -- Time elapsed: 0.016 s <<< ERROR!
org.apache.parquet.bytes.TrackingByteBufferAllocator$LeakedByteBufferException: 12 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
        at org.apache.parquet.bytes.TrackingByteBufferAllocator.close(TrackingByteBufferAllocator.java:160)
        at org.apache.parquet.hadoop.TestParquetReader.closeAllocator(TestParquetReader.java:175)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
Caused by: org.apache.parquet.bytes.TrackingByteBufferAllocator$ByteBufferAllocationStacktraceException: Set org.apache.parquet.bytes.TrackingByteBufferAllocator.DEBUG = true for more info

[ERROR] org.apache.parquet.hadoop.TestParquetReader.testRangeFiltering[2] -- Time elapsed: 0.029 s <<< ERROR!
org.apache.parquet.bytes.TrackingByteBufferAllocator$LeakedByteBufferException: 4 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
        at org.apache.parquet.bytes.TrackingByteBufferAllocator.close(TrackingByteBufferAllocator.java:160)
        at org.apache.parquet.hadoop.TestParquetReader.closeAllocator(TestParquetReader.java:175)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
Caused by: org.apache.parquet.bytes.TrackingByteBufferAllocator$ByteBufferAllocationStacktraceException: Set org.apache.parquet.bytes.TrackingByteBufferAllocator.DEBUG = true for more info

[ERROR] org.apache.parquet.hadoop.TestParquetReader.testNoFiltering[2] -- Time elapsed: 0.029 s <<< ERROR!
org.apache.parquet.bytes.TrackingByteBufferAllocator$LeakedByteBufferException: 8 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
        at org.apache.parquet.bytes.TrackingByteBufferAllocator.close(TrackingByteBufferAllocator.java:160)
        at org.apache.parquet.hadoop.TestParquetReader.closeAllocator(TestParquetReader.java:175)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
Caused by: org.apache.parquet.bytes.TrackingByteBufferAllocator$ByteBufferAllocationStacktraceException: Set org.apache.parquet.bytes.TrackingByteBufferAllocator.DEBUG = true for more info

[ERROR] org.apache.parquet.hadoop.TestParquetReader.testSimpleFiltering[2] -- Time elapsed: 0.019 s <<< ERROR!
org.apache.parquet.bytes.TrackingByteBufferAllocator$LeakedByteBufferException: 4 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
        at org.apache.parquet.bytes.TrackingByteBufferAllocator.close(TrackingByteBufferAllocator.java:160)
        at org.apache.parquet.hadoop.TestParquetReader.closeAllocator(TestParquetReader.java:175)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
Caused by: org.apache.parquet.bytes.TrackingByteBufferAllocator$ByteBufferAllocationStacktraceException: Set org.apache.parquet.bytes.TrackingByteBufferAllocator.DEBUG = true for more info

[ERROR] org.apache.parquet.hadoop.TestParquetReader.testCurrentRowIndex[2] -- Time elapsed: 0.011 s <<< ERROR!
org.apache.parquet.bytes.TrackingByteBufferAllocator$LeakedByteBufferException: 2 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
        at org.apache.parquet.bytes.TrackingByteBufferAllocator.close(TrackingByteBufferAllocator.java:160)
        at org.apache.parquet.hadoop.TestParquetReader.closeAllocator(TestParquetReader.java:175)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
Caused by: org.apache.parquet.bytes.TrackingByteBufferAllocator$ByteBufferAllocationStacktraceException: Set org.apache.parquet.bytes.TrackingByteBufferAllocator.DEBUG = true for more info

[INFO] 
[INFO] Results:
[INFO] 
[ERROR] Errors: 
[ERROR]   TestParquetReader.closeAllocator:175 » LeakedByteBuffer 20 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
[ERROR]   TestParquetReader.closeAllocator:175 » LeakedByteBuffer 12 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
[ERROR]   TestParquetReader.closeAllocator:175 » LeakedByteBuffer 2 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
[ERROR]   TestParquetReader.closeAllocator:175 » LeakedByteBuffer 80 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
[ERROR]   TestParquetReader.closeAllocator:175 » LeakedByteBuffer 48 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
[ERROR]   TestParquetReader.closeAllocator:175 » LeakedByteBuffer 8 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
[ERROR]   TestParquetReader.closeAllocator:175 » LeakedByteBuffer 24 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
[ERROR]   TestParquetReader.closeAllocator:175 » LeakedByteBuffer 14 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
[ERROR]   TestParquetReader.closeAllocator:175 » LeakedByteBuffer 4 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
[ERROR]   TestParquetReader.closeAllocator:175 » LeakedByteBuffer 40 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
[ERROR]   TestParquetReader.closeAllocator:175 » LeakedByteBuffer 28 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
[ERROR]   TestParquetReader.closeAllocator:175 » LeakedByteBuffer 4 ByteBuffer object(s) is/are remained unreleased after closing this allocator.
[INFO] 
[ERROR] Tests run: 12, Failures: 0, Errors: 12, Skipped: 0