TEZ-4295: Could not decompress data. Buffer length is too small. #130

abstractdog · 2021-06-04T08:20:29Z

No description provided.

hadoop-yetus · 2021-06-07T12:21:49Z

🎊 +1 overall

Vote	Subsystem	Runtime	Comment
+0 🆗	reexec	1m 5s	Docker mode activated.
		_ Prechecks _
+1 💚	dupname	0m 1s	No case conflicting files found.
+1 💚	@author	0m 0s	The patch does not contain any @author tags.
+1 💚	test4tests	0m 0s	The patch appears to include 1 new or modified test files.
		_ master Compile Tests _
+1 💚	mvninstall	12m 18s	master passed
+1 💚	compile	0m 35s	master passed with JDK Ubuntu-11.0.11+9-Ubuntu-0ubuntu2.20.04
+1 💚	compile	0m 31s	master passed with JDK Private Build-1.8.0_292-8u292-b10-0ubuntu1~20.04-b10
+1 💚	checkstyle	1m 12s	master passed
+1 💚	javadoc	0m 40s	master passed with JDK Ubuntu-11.0.11+9-Ubuntu-0ubuntu2.20.04
+1 💚	javadoc	0m 30s	master passed with JDK Private Build-1.8.0_292-8u292-b10-0ubuntu1~20.04-b10
+0 🆗	spotbugs	1m 26s	Used deprecated FindBugs config; considering switching to SpotBugs.
+1 💚	findbugs	1m 24s	master passed
		_ Patch Compile Tests _
+1 💚	mvninstall	0m 20s	the patch passed
+1 💚	compile	0m 21s	the patch passed with JDK Ubuntu-11.0.11+9-Ubuntu-0ubuntu2.20.04
+1 💚	javac	0m 21s	the patch passed
+1 💚	compile	0m 19s	the patch passed with JDK Private Build-1.8.0_292-8u292-b10-0ubuntu1~20.04-b10
+1 💚	javac	0m 19s	the patch passed
+1 💚	checkstyle	0m 15s	the patch passed
+1 💚	whitespace	0m 0s	The patch has no whitespace issues.
+1 💚	javadoc	0m 18s	the patch passed with JDK Ubuntu-11.0.11+9-Ubuntu-0ubuntu2.20.04
+1 💚	javadoc	0m 16s	the patch passed with JDK Private Build-1.8.0_292-8u292-b10-0ubuntu1~20.04-b10
+1 💚	findbugs	0m 52s	the patch passed
		_ Other Tests _
+1 💚	unit	5m 19s	tez-runtime-library in the patch passed.
+1 💚	asflicense	0m 14s	The patch does not generate ASF License warnings.
		27m 22s

Subsystem	Report/Notes
Docker	ClientAPI=1.41 ServerAPI=1.41 base: https://ci-hadoop.apache.org/job/tez-multibranch/job/PR-130/3/artifact/out/Dockerfile
GITHUB PR	#130
JIRA Issue	TEZ-4295
Optional Tests	dupname asflicense javac javadoc unit spotbugs findbugs checkstyle compile
uname	Linux 0bc127046881 4.15.0-112-generic #113-Ubuntu SMP Thu Jul 9 23:41:39 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
Build tool	maven
Personality	personality/tez.sh
git revision	master / `0af54df`
Default Java	Private Build-1.8.0_292-8u292-b10-0ubuntu1~20.04-b10
Multi-JDK versions	/usr/lib/jvm/java-11-openjdk-amd64:Ubuntu-11.0.11+9-Ubuntu-0ubuntu2.20.04 /usr/lib/jvm/java-8-openjdk-amd64:Private Build-1.8.0_292-8u292-b10-0ubuntu1~20.04-b10
Test Results	https://ci-hadoop.apache.org/job/tez-multibranch/job/PR-130/3/testReport/
Max. process+thread count	2101 (vs. ulimit of 5500)
modules	C: tez-runtime-library U: tez-runtime-library
Console output	https://ci-hadoop.apache.org/job/tez-multibranch/job/PR-130/3/console
versions	git=2.25.1 maven=3.6.3 findbugs=3.0.1
Powered by	Apache Yetus 0.12.0 https://yetus.apache.org

This message was automatically generated.

tprelle · 2021-06-08T20:43:36Z

Hi,
Why do not report the IFile fix part of the patch in the Jira ? https://issues.apache.org/jira/secure/attachment/13020838/TEZ-4295.01.patch
I just test your patch in my prod env and i still have the issue.
If i add the part inside IFile it's fixing the issue.

Regards

abstractdog · 2021-06-09T05:34:33Z

Hi,
Why do not report the IFile fix part of the patch in the Jira ? https://issues.apache.org/jira/secure/attachment/13020838/TEZ-4295.01.patch
I just test your patch in my prod env and i still have the issue.
If i add the part inside IFile it's fixing the issue.

Regards

Thanks @tprelle for letting us know! It's very strange, I haven't been able to reproduce by unit test, that's why went only for fixing CodecUtils.getDecompressedInputStreamWithBufferSize. Let me think about this again before committing the fix. Could you share some details about your workload: what exception trace did you get (the same as reported in jira)? What's your upstream application, hive, or something else?

I'm 100% about including the fix for every compressor/decompressor instantiation (so including changes in IFile you mentioned), I just want to cover it by a unit test in order to prevent regressions in the future.

UPDATE: I've just reproduced from hive, I'll update the PR once I reproduced this problem from a UT

, errorMessage=Cannot recover from this error:java.lang.RuntimeException: java.lang.InternalError: Could not compress data. Buffer length is too small.
        at org.apache.hadoop.hive.ql.exec.tez.MapRecordSource.processRow(MapRecordSource.java:101)
        at org.apache.hadoop.hive.ql.exec.tez.MapRecordSource.pushRecord(MapRecordSource.java:76)
        at org.apache.hadoop.hive.ql.exec.tez.MapRecordProcessor.run(MapRecordProcessor.java:437)
        at org.apache.hadoop.hive.ql.exec.tez.TezProcessor.initializeAndRunProcessor(TezProcessor.java:282)
        at org.apache.hadoop.hive.ql.exec.tez.TezProcessor.run(TezProcessor.java:265)
        at org.apache.tez.runtime.LogicalIOProcessorRuntimeTask.run(LogicalIOProcessorRuntimeTask.java:374)
        at org.apache.tez.runtime.task.TaskRunner2Callable$1.run(TaskRunner2Callable.java:75)
        at org.apache.tez.runtime.task.TaskRunner2Callable$1.run(TaskRunner2Callable.java:62)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Subject.java:422)
        at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1898)
        at org.apache.tez.runtime.task.TaskRunner2Callable.callInternal(TaskRunner2Callable.java:62)
        at org.apache.tez.runtime.task.TaskRunner2Callable.callInternal(TaskRunner2Callable.java:38)
        at org.apache.tez.common.CallableWithNdc.call(CallableWithNdc.java:36)
        at org.apache.hadoop.hive.llap.daemon.impl.StatsRecordingThreadPool$WrappedCallable.call(StatsRecordingThreadPool.java:118)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        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:748)
Caused by: java.lang.InternalError: Could not compress data. Buffer length is too small.
        at org.apache.hadoop.io.compress.snappy.SnappyCompressor.compressBytesDirect(Native Method)
        at org.apache.hadoop.io.compress.snappy.SnappyCompressor.compress(SnappyCompressor.java:228)
        at org.apache.hadoop.io.compress.BlockCompressorStream.compress(BlockCompressorStream.java:149)
        at org.apache.hadoop.io.compress.BlockCompressorStream.write(BlockCompressorStream.java:131)
        at org.apache.hadoop.fs.FSDataOutputStream$PositionCache.write(FSDataOutputStream.java:62)
        at java.io.DataOutputStream.write(DataOutputStream.java:107)
        at org.apache.tez.runtime.library.common.sort.impl.IFile$Writer.writeKVPair(IFile.java:618)
        at org.apache.tez.runtime.library.common.sort.impl.IFile$FileBackedInMemIFileWriter.writeKVPair(IFile.java:223)
        at org.apache.tez.runtime.library.common.sort.impl.IFile$Writer.append(IFile.java:481)
        at org.apache.tez.runtime.library.common.writers.UnorderedPartitionedKVWriter.write(UnorderedPartitionedKVWriter.java:400)
        at org.apache.hadoop.hive.ql.exec.tez.TezProcessor$TezKVOutputCollector.collect(TezProcessor.java:378)
        at org.apache.hadoop.hive.ql.exec.vector.reducesink.VectorReduceSinkCommonOperator.doCollect(VectorReduceSinkCommonOperator.java:384)
        at org.apache.hadoop.hive.ql.exec.vector.reducesink.VectorReduceSinkCommonOperator.collect(VectorReduceSinkCommonOperator.java:358)
        at org.apache.hadoop.hive.ql.exec.vector.reducesink.VectorReduceSinkUniformHashOperator.process(VectorReduceSinkUniformHashOperator.java:185)
        at org.apache.hadoop.hive.ql.exec.Operator.vectorForward(Operator.java:969)
        at org.apache.hadoop.hive.ql.exec.vector.VectorSelectOperator.process(VectorSelectOperator.java:158)
        at org.apache.hadoop.hive.ql.exec.Operator.vectorForward(Operator.java:969)
        at org.apache.hadoop.hive.ql.exec.vector.VectorFilterOperator.process(VectorFilterOperator.java:136)
        at org.apache.hadoop.hive.ql.exec.Operator.vectorForward(Operator.java:969)
        at org.apache.hadoop.hive.ql.exec.TableScanOperator.process(TableScanOperator.java:172)
        at org.apache.hadoop.hive.ql.exec.vector.VectorMapOperator.deliverVectorizedRowBatch(VectorMapOperator.java:809)
        at org.apache.hadoop.hive.ql.exec.vector.VectorMapOperator.process(VectorMapOperator.java:842)
        at org.apache.hadoop.hive.ql.exec.tez.MapRecordSource.processRow(MapRecordSource.java:92)
        ... 18 more

abstractdog · 2021-06-09T14:34:17Z

@tprelle : could you please try the latest commit? 7ffc783#diff-7ae0f0c86feac929c1490f9938cad5c25d46435d6f80de2455e64f11a49da1c8R44

very interestingly, I reproduced the problem and I found that synchronization didn't solve the issue for me, and then I found that the problem is the default buffer size I choose regardless of codec type (128K), which led to errors in case of snappy

with default 256K, everything worked fine

could you please try this patch on your cluster to confirm if we're hitting the very same issue?
https://github.com/apache/tez/commit/7ffc7832af935449554537b52b03e37120ac5799.patch

tprelle · 2021-06-09T15:21:07Z

Hi @abstractdog thanks to look into it
I add the issue on the reader of IFile.


 org.apache.tez.runtime.library.common.shuffle.orderedgrouped.Shuffle$ShuffleError: Error while doing final merge
        at org.apache.tez.runtime.library.common.shuffle.orderedgrouped.Shuffle$RunShuffleCallable.callInternal(Shuffle.java:312)
        at org.apache.tez.runtime.library.common.shuffle.orderedgrouped.Shuffle$RunShuffleCallable.callInternal(Shuffle.java:277)
        at org.apache.tez.common.CallableWithNdc.call(CallableWithNdc.java:36)
        at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:125)
        at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:69)
        at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:78)
        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:748)
Caused by: java.lang.InternalError: Could not decompress data. Buffer length is too small.
        at org.apache.hadoop.io.compress.snappy.SnappyDecompressor.decompressBytesDirect(Native Method)
        at org.apache.hadoop.io.compress.snappy.SnappyDecompressor.decompress(SnappyDecompressor.java:235)
        at org.apache.hadoop.io.compress.BlockDecompressorStream.decompress(BlockDecompressorStream.java:88)
        at org.apache.hadoop.io.compress.DecompressorStream.read(DecompressorStream.java:105)
        at org.apache.hadoop.io.compress.DecompressorStream.read(DecompressorStream.java:92)
        at java.io.DataInputStream.readByte(DataInputStream.java:265)
        at org.apache.hadoop.io.WritableUtils.readVLong(WritableUtils.java:308)
        at org.apache.hadoop.io.WritableUtils.readVInt(WritableUtils.java:329)
        at org.apache.tez.runtime.library.common.sort.impl.IFile$Reader.readKeyValueLength(IFile.java:935)
        at org.apache.tez.runtime.library.common.sort.impl.IFile$Reader.positionToNextRecord(IFile.java:965)
        at org.apache.tez.runtime.library.common.sort.impl.IFile$Reader.readRawKey(IFile.java:1006)
        at org.apache.tez.runtime.library.common.sort.impl.IFile$Reader.nextRawKey(IFile.java:987)
        at org.apache.tez.runtime.library.common.sort.impl.TezMerger$Segment.nextRawKey(TezMerger.java:317)
        at org.apache.tez.runtime.library.common.sort.impl.TezMerger$MergeQueue.merge(TezMerger.java:777)
        at org.apache.tez.runtime.library.common.sort.impl.TezMerger.merge(TezMerger.java:206)
        at org.apache.tez.runtime.library.common.shuffle.orderedgrouped.MergeManager.finalMerge(MergeManager.java:1298)
        at org.apache.tez.runtime.library.common.shuffle.orderedgrouped.MergeManager.close(MergeManager.java:666)
        at org.apache.tez.runtime.library.common.shuffle.orderedgrouped.Shuffle$RunShuffleCallable.callInternal(Shuffle.java:308)
        ... 8 more

I was not able to reproduce it on unit test but i run this type of query on a large dataset.


WITH cte_setting AS (
  SELECT
    a,
    ARRAY(
      NAMED_STRUCT(
        "b",
        "c",
        "d",
        MAX(
          STRUCT(
            date,
            CASE WHEN e IS NOT NULL
            AND e <> '' THEN e END
          )
        ).col2
      ),
      NAMED_STRUCT(
        "b",
        "c",
        "d",
        MAX(
          STRUCT(
            date,
            CASE WHEN "f" IS NOT NULL
            AND "f" <> '' THEN "f" END
          )
        ).col2
      )
    ) AS arrayOption
  FROM
    table
  GROUP BY
    id
)
SELECT
  id,
  t.col.b AS b,
  t.col.b AS b
FROM
  cte_setting LATERAL VIEW explode(arrayOption) t
LIMIT
  1000

tprelle · 2021-06-09T15:27:11Z

I just see the previous message i was searching the stackstrace. I will test the lastest patch.

abstractdog · 2021-06-11T07:38:45Z

@tprelle: kindly reminder, if you have the chance to try out the latest patch on your cluster

tprelle · 2021-06-11T13:37:54Z

Hi @abstractdog sorry i was OOO yesterday.
I just test and still have the exact error that before (without IFile fix part of https://issues.apache.org/jira/secure/attachment/13020838/TEZ-4295.01.patch)

#130 (comment)

abstractdog · 2021-06-11T14:18:44Z

Hi @abstractdog sorry i was OOO yesterday.
I just test and still have the exact error that before (without IFile fix part of https://issues.apache.org/jira/secure/attachment/13020838/TEZ-4295.01.patch)

#130 (comment)

thanks for the feedback again @tprelle!
are you open to trying out a test patch with some INFO messages and share tez application logs (if possible)? this is just because I want to understand why my patch hasn't been solved the very same exception at your side
I still agree that we might want to synchronize on every involved codepath, just wondering if there is a chance to understand this better before committing

tprelle · 2021-06-11T15:37:57Z

Yes which log do you want me to add ?

abstractdog · 2021-06-11T16:46:20Z

Yes which log do you want me to add ?

I'm about to add a few lines to my patch and share with you later
you only have to collect tez application logs from an app that failed (let me know if you have any questions about that)

tprelle · 2021-06-11T16:49:11Z

Hi @abstractdog again,
Even with the current patch (https://issues.apache.org/jira/secure/attachment/13020838/TEZ-4295.01.patch) i found another issue :


java.io.IOException: java.lang.InternalError: Could not decompress data. Buffer length is too small.
	at org.apache.tez.runtime.library.common.shuffle.ShuffleUtils.shuffleToMemory(ShuffleUtils.java:134)
	at org.apache.tez.runtime.library.common.shuffle.orderedgrouped.FetcherOrderedGrouped.copyMapOutput(FetcherOrderedGrouped.java:552)
	at org.apache.tez.runtime.library.common.shuffle.orderedgrouped.FetcherOrderedGrouped.copyFromHost(FetcherOrderedGrouped.java:284)
	at org.apache.tez.runtime.library.common.shuffle.orderedgrouped.FetcherOrderedGrouped.fetchNext(FetcherOrderedGrouped.java:184)
	at org.apache.tez.runtime.library.common.shuffle.orderedgrouped.FetcherOrderedGrouped.callInternal(FetcherOrderedGrouped.java:196)
	at org.apache.tez.runtime.library.common.shuffle.orderedgrouped.FetcherOrderedGrouped.callInternal(FetcherOrderedGrouped.java:59)
	at org.apache.tez.common.CallableWithNdc.call(CallableWithNdc.java:36)
	at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:125)
	at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:69)
	at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:78)
	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:748)
Caused by: java.lang.InternalError: Could not decompress data. Buffer length is too small.
	at org.apache.hadoop.io.compress.snappy.SnappyDecompressor.decompressBytesDirect(Native Method)
	at org.apache.hadoop.io.compress.snappy.SnappyDecompressor.decompress(SnappyDecompressor.java:235)
	at org.apache.hadoop.io.compress.BlockDecompressorStream.decompress(BlockDecompressorStream.java:88)
	at org.apache.hadoop.io.compress.DecompressorStream.read(DecompressorStream.java:105)
	at org.apache.hadoop.io.IOUtils.readFully(IOUtils.java:210)
	at org.apache.tez.runtime.library.common.sort.impl.IFile$Reader.readToMemory(IFile.java:848)
	at org.apache.tez.runtime.library.common.shuffle.ShuffleUtils.shuffleToMemory(ShuffleUtils.java:121)
	... 12 more

tprelle · 2021-06-11T20:37:54Z

@abstractdog FYI if i combined your last commit and IFIle patch it's seem working for my two issue.

abstractdog · 2021-06-12T06:06:24Z

@tprelle: what's very strange is those seem to be the same issue that disappeared in my environment after applying only my patch...but before guessing I've uploaded a new patch with some additional INFO messages (0d04a2f), could you please try this one and upload app logs somewhere in case of a failure?

UPDATE: nevermind, finally I reproduced it from unit test, creating the final fix

tprelle · 2021-06-12T21:05:31Z

Nice thanks :)

abstractdog · 2021-06-14T06:46:05Z

@tprelle: could you please do final testing with the last patch?

hadoop-yetus · 2021-06-14T14:41:41Z

🎊 +1 overall

Vote	Subsystem	Runtime	Comment
+0 🆗	reexec	1m 38s	Docker mode activated.
		_ Prechecks _
+1 💚	dupname	0m 0s	No case conflicting files found.
+1 💚	@author	0m 0s	The patch does not contain any @author tags.
+1 💚	test4tests	0m 0s	The patch appears to include 4 new or modified test files.
		_ master Compile Tests _
+1 💚	mvninstall	13m 13s	master passed
+1 💚	compile	0m 43s	master passed with JDK Ubuntu-11.0.11+9-Ubuntu-0ubuntu2.20.04
+1 💚	compile	0m 31s	master passed with JDK Private Build-1.8.0_292-8u292-b10-0ubuntu1~20.04-b10
+1 💚	checkstyle	1m 16s	master passed
+1 💚	javadoc	0m 43s	master passed with JDK Ubuntu-11.0.11+9-Ubuntu-0ubuntu2.20.04
+1 💚	javadoc	0m 30s	master passed with JDK Private Build-1.8.0_292-8u292-b10-0ubuntu1~20.04-b10
+0 🆗	spotbugs	1m 29s	Used deprecated FindBugs config; considering switching to SpotBugs.
+1 💚	findbugs	1m 26s	master passed
		_ Patch Compile Tests _
+1 💚	mvninstall	0m 21s	the patch passed
+1 💚	compile	0m 22s	the patch passed with JDK Ubuntu-11.0.11+9-Ubuntu-0ubuntu2.20.04
+1 💚	javac	0m 22s	the patch passed
+1 💚	compile	0m 20s	the patch passed with JDK Private Build-1.8.0_292-8u292-b10-0ubuntu1~20.04-b10
+1 💚	javac	0m 20s	the patch passed
+1 💚	checkstyle	0m 17s	the patch passed
+1 💚	whitespace	0m 0s	The patch has no whitespace issues.
+1 💚	javadoc	0m 19s	the patch passed with JDK Ubuntu-11.0.11+9-Ubuntu-0ubuntu2.20.04
+1 💚	javadoc	0m 16s	the patch passed with JDK Private Build-1.8.0_292-8u292-b10-0ubuntu1~20.04-b10
+1 💚	findbugs	0m 56s	the patch passed
		_ Other Tests _
+1 💚	unit	5m 11s	tez-runtime-library in the patch passed.
+1 💚	asflicense	0m 15s	The patch does not generate ASF License warnings.
		29m 17s

Subsystem	Report/Notes
Docker	ClientAPI=1.41 ServerAPI=1.41 base: https://ci-hadoop.apache.org/job/tez-multibranch/job/PR-130/8/artifact/out/Dockerfile
GITHUB PR	#130
JIRA Issue	TEZ-4295
Optional Tests	dupname asflicense javac javadoc unit spotbugs findbugs checkstyle compile
uname	Linux 7aea6c17f943 4.15.0-112-generic #113-Ubuntu SMP Thu Jul 9 23:41:39 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
Build tool	maven
Personality	personality/tez.sh
git revision	master / `0af54df`
Default Java	Private Build-1.8.0_292-8u292-b10-0ubuntu1~20.04-b10
Multi-JDK versions	/usr/lib/jvm/java-11-openjdk-amd64:Ubuntu-11.0.11+9-Ubuntu-0ubuntu2.20.04 /usr/lib/jvm/java-8-openjdk-amd64:Private Build-1.8.0_292-8u292-b10-0ubuntu1~20.04-b10
Test Results	https://ci-hadoop.apache.org/job/tez-multibranch/job/PR-130/8/testReport/
Max. process+thread count	2099 (vs. ulimit of 5500)
modules	C: tez-runtime-library U: tez-runtime-library
Console output	https://ci-hadoop.apache.org/job/tez-multibranch/job/PR-130/8/console
versions	git=2.25.1 maven=3.6.3 findbugs=3.0.1
Powered by	Apache Yetus 0.12.0 https://yetus.apache.org

This message was automatically generated.

tprelle · 2021-06-14T20:16:45Z

hi @abstractdog it seems working with the last patch
thanks

abstractdog · 2021-06-16T08:36:44Z

discussed offline, Ashutosh's +1 still holds after the latest fixes, I'm merging this to master
thanks @tprelle for testing this so patiently!

… (Laszlo Bodor reviewed by Ashutosh Chauhan)

abstractdog force-pushed the TEZ-4295 branch from 93a9ba3 to 7b9eba8 Compare June 4, 2021 08:42