[ 
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)

Reply via email to