You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@tez.apache.org by "Ming Ma (JIRA)" <ji...@apache.org> on 2016/07/27 00:02:20 UTC
[jira] [Commented] (TEZ-3113) massive increase of run time using
PipelinedSorter rather than DefaultSorter
[ https://issues.apache.org/jira/browse/TEZ-3113?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15394807#comment-15394807 ]
Ming Ma commented on TEZ-3113:
------------------------------
We also ran into similar issue.
The pipeline sorter setting:
{noformat}
2016-07-26 18:05:48,398 [INFO] [TezChild] |impl.PipelinedSorter|: Setting up PipelinedSorter for CB70EF1A28614FED8BA2F7C7D271D11F: , UsingHashComparator=false#blocks=1, maxMemUsage=104857600, lazyAllocateMem=false, minBlockSize=2097152000, initial BLOCK_SIZE=104857600, finalMergeEnabled=true, pipelinedShuffle=false, sendEmptyPartitions=true, tez.runtime.io.sort.mb=100
{noformat}
From the call stack below, regularly a single record is larger than sort buffer size and thus caused the sorter to spill the single record.
{noformat}
at cascading.tuple.hadoop.TupleSerialization.getSerializationFactory(TupleSerialization.java:296)
at cascading.tuple.hadoop.TupleSerialization.getNewSerializer(TupleSerialization.java:602)
at cascading.tuple.hadoop.TupleSerialization$SerializationElementWriter.getSerializer(TupleSerialization.java:1033)
at cascading.tuple.hadoop.TupleSerialization$SerializationElementWriter.write(TupleSerialization.java:1013)
at cascading.tuple.io.TupleOutputStream.writeElement(TupleOutputStream.java:170)
at cascading.tuple.io.TupleOutputStream.writeUnTyped(TupleOutputStream.java:135)
at cascading.tuple.hadoop.io.BaseSerializer.serialize(BaseSerializer.java:72)
at cascading.tuple.hadoop.io.BaseSerializer.serialize(BaseSerializer.java:32)
at org.apache.tez.runtime.library.common.sort.impl.IFile$Writer.append(IFile.java:277)
at org.apache.tez.runtime.library.common.sort.impl.PipelinedSorter.spillSingleRecord(PipelinedSorter.java:484)
at org.apache.tez.runtime.library.common.sort.impl.PipelinedSorter.collect(PipelinedSorter.java:409)
- locked <0x00000007682297a8> (a org.apache.tez.runtime.library.common.sort.impl.PipelinedSorter)
at org.apache.tez.runtime.library.common.sort.impl.PipelinedSorter.collect(PipelinedSorter.java:415)
- locked <0x00000007682297a8> (a org.apache.tez.runtime.library.common.sort.impl.PipelinedSorter)
at org.apache.tez.runtime.library.common.sort.impl.PipelinedSorter.collect(PipelinedSorter.java:415)
- locked <0x00000007682297a8> (a org.apache.tez.runtime.library.common.sort.impl.PipelinedSorter)
at org.apache.tez.runtime.library.common.sort.impl.PipelinedSorter.write(PipelinedSorter.java:362)
at org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput$1.write(OrderedPartitionedKVOutput.java:163)
{noformat}
There are lots of entries like this in the container log.
{noformat}
2016-07-26 00:06:16,279 [INFO] [TezChild] |impl.PipelinedSorter|: C1A0DD178C964C6F90553E14996CD011: done sorting span=0, length=0, time=0
2016-07-26 00:06:16,279 [INFO] [TezChild] |impl.PipelinedSorter|: C1A0DD178C964C6F90553E14996CD011: reserved.remaining()=104857600, reserved.metasize=16777216
2016-07-26 00:06:16,279 [INFO] [TezChild] |impl.PipelinedSorter|: C1A0DD178C964C6F90553E14996CD011: done sorting span=0, length=0, time=0
2016-07-26 00:06:16,279 [INFO] [TezChild] |impl.PipelinedSorter|: C1A0DD178C964C6F90553E14996CD011: reserved.remaining()=104857600, reserved.metasize=16777216
2016-07-26 00:06:16,279 [INFO] [TezChild] |impl.PipelinedSorter|: C1A0DD178C964C6F90553E14996CD011: done sorting span=0, length=0, time=0
2016-07-26 00:06:16,280 [INFO] [TezChild] |impl.PipelinedSorter|: C1A0DD178C964C6F90553E14996CD011: reserved.remaining()=104857600, reserved.metasize=16777216
2016-07-26 00:06:16,280 [INFO] [TezChild] |impl.PipelinedSorter|: C1A0DD178C964C6F90553E14996CD011: Spilling to /.../application_1466709597073_272545/output/attempt_1466709597073_272545_1_02_001204_0_10007_14/file.out, indexFilename=/.../application_1466709597073_272545/output/attempt_1466709597073_272545_1_02_001204_0_10007_14/file.out.index
{noformat}
> massive increase of run time using PipelinedSorter rather than DefaultSorter
> ----------------------------------------------------------------------------
>
> Key: TEZ-3113
> URL: https://issues.apache.org/jira/browse/TEZ-3113
> Project: Apache Tez
> Issue Type: Bug
> Affects Versions: 0.8.2
> Environment: scalding 0.15-SNAPSHOT per https://github.com/twitter/scalding/pull/1446
> cascading 3.1.0-wip-54
> tez-0.8.2
> OpenJDK 8 on AMD64
> Hadoop 2.6.0 (YARN, HDFS); Apache distribution
> Debian Linux 8
> 8 * Intel Core i7-3770K
> Reporter: Cyrille Chépélov
>
> While running a (fairly complex) scalding DAG that was working fine using tez-0.6.2, now under tez-0.8.2, the run time became suddenly extremely large.
> Reverting "tez.runtime.sorter.class" -> "LEGACY" restored proper behaviour.
> Difficulties can be traced to this shape of code:
> {code:scala}
> val x: TypedPipe[(String, String)] = ??? // get *LARGE* dataset
> x
> .group
> .mapValues(x => 1L)
> .sum
> .write(TypedTsvHeader("foo.tsv", ('key, 'count)))
> {code}
> where the incoming data contains many, many different keys. Observed behaviour of PipelinedSorter is that several hundred thousand different files are put flat in the same per-TezChild local temporary directories, and thing become very slow (not alleging any causality).
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)