[
https://issues.apache.org/jira/browse/TEZ-4577?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Yi Zhang updated TEZ-4577:
--------------------------
Description:
we run into a issue with overflow as in TEZ-4542, with TEZ-4542 applied, it
then run into an issue of real small sortspan (per record in this case),
eventually the job failed due to timeout
from sample logs it looks like
SortSpan(ByteBuffer source, int maxItems, int perItem, RawComparator comparator)
once it get into a situation of maxItems=1, then it persists with maxItems=1
(also a side issue, the logging in this situation becomes huge)
sample logs:
2024-08-19 19:01:37,704 [INFO]
[TezTaskEventRouter\{attempt_1724090939581_0001_1_00_000097_2}]
|input.MRInput|: scope-20 -> scope-302 initialized RecordReader from event
2024-08-19 19:01:37,709 [INFO] [TezChild] |runtime.PigProcessor|: Starting
output org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput@e3a121c
to vertex scope-308
2024-08-19 19:01:37,742 [INFO] [TezChild] |impl.ExternalSorter|: scope-302 ->
scope-308 using: memoryMb=256, keySerializerClass=class
org.apache.pig.impl.io.NullableTuple,
valueSerializerClass=org.apache.hadoop.io.serializer.WritableSerialization$WritableSerializer@1fe3d5ed,
comparator=org.apache.pig.backend.hadoop.executionengine.mapReduceLayer.PigTupleSortComparator@3d696d6,
partitioner=org.apache.tez.mapreduce.partition.MRPartitioner,
serialization=org.apache.hadoop.io.serializer.WritableSerialization,
org.apache.hadoop.io.serializer.avro.AvroSpecificSerialization,
org.apache.hadoop.io.serializer.avro.AvroReflectSerialization,
reportPartitionStats=MEMORY_OPTIMIZED
2024-08-19 19:01:37,758 [INFO] [TezChild] |partition.MRPartitioner|: Using
newApi,
MRpartitionerClass=org.apache.hadoop.mapreduce.lib.partition.HashPartitioner
2024-08-19 19:01:37,758 [INFO] [TezChild] |impl.PipelinedSorter|: Setting up
PipelinedSorter for scope-302 -> scope-308: , UsingHashComparator=false
2024-08-19 19:01:37,800 [INFO] [TezChild] |impl.PipelinedSorter|: Newly
allocated block size=268435456, index=0, Number of buffers=1,
currentAllocatableMemory=0, currentBufferSize=268435456, total=268435456
2024-08-19 19:01:37,800 [INFO] [TezChild] |impl.PipelinedSorter|: Pre
allocating rest of memory buffers upfront
2024-08-19 19:01:37,800 [INFO] [TezChild] |impl.PipelinedSorter|: Setting up
PipelinedSorter for scope-302 -> scope-308: ,
UsingHashComparator=false#blocks=1, maxMemUsage=268435456,
lazyAllocateMem=false, minBlockSize=2097152000, initial BLOCK_SIZE=268435456,
finalMergeEnabled=true, pipelinedShuffle=false, sendEmptyPartitions=true,
tez.runtime.io.sort.mb=256
2024-08-19 19:01:37,802 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268435456, reserved.metasize=16777216
2024-08-19 19:01:37,827 [INFO] [TezChild] |operator.POLocalRearrangeTez|:
Attached output to vertex scope-308 :
output=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput@e3a121c,
writer=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput$1@148db3c7
2024-08-19 19:01:37,827 [INFO] [TezChild] |runtime.PigProcessor|: Aliases being
processed per job phase (AliasName[line,offset]):
prev_partition_data[13,28],prev_partition_req_fields[24,28],prev_curr_grp[95,16]
2024-08-19 19:01:45,632 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span0.length = 1048573, perItem = 138
2024-08-19 19:01:45,633 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=106530636, reserved.metasize=11068112
2024-08-19 19:01:45,633 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span1.length = 691757, perItem = 138, counter:1048573
2024-08-19 19:01:49,491 [INFO] [Sorter \{scope_302 -> scope_308} #0]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=0,
length=1048573, time=3857
2024-08-19 19:01:51,495 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span1.length = 689460, perItem = 138
2024-08-19 19:01:53,482 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: done sorting span=1, length=689460, time=1986
2024-08-19 19:01:53,484 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Heap = SpanIterator<0:1048572>
(span=Span[16777216,145127604]),SpanIterator<0:689459>
(span=Span[11068112,95462505]),
2024-08-19 19:01:53,601 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Spilling to
/hadoop/yarn/nm-local-dir/usercache/root/appcache/application_1724090939581_0001/output/attempt_1724090939581_0001_1_00_000097_2_10003_0/file.out
2024-08-19 19:01:55,217 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268435456, reserved.metasize=11068112
2024-08-19 19:02:00,213 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span0.length = 691754, perItem = 134
2024-08-19 19:02:00,213 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=164176480, reserved.metasize=11068064
2024-08-19 19:02:00,213 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span1.length = 691754, perItem = 134, counter:2429787
2024-08-19 19:02:02,681 [INFO] [Sorter \{scope_302 -> scope_308} #1]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=0,
length=691754, time=2467
2024-08-19 19:02:05,552 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span1.length = 691751, perItem = 134
2024-08-19 19:02:05,552 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=59905155, reserved.metasize=6389872
2024-08-19 19:02:05,552 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span2.length = 399367, perItem = 134, counter:3121538
2024-08-19 19:02:08,036 [INFO] [Sorter \{scope_302 -> scope_308} #0]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=1,
length=691751, time=2484
2024-08-19 19:02:08,656 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span2.length = 397155, perItem = 134
2024-08-19 19:02:09,786 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: done sorting span=2, length=397155, time=1130
2024-08-19 19:02:09,787 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Heap = SpanIterator<0:691753>
(span=Span[11068112,93190864]),SpanIterator<0:397154>
(span=Span[6389872,53515175]),SpanIterator<0:691750>
(span=Span[11068064,93203261]),
2024-08-19 19:02:09,788 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Spilling to
/hadoop/yarn/nm-local-dir/usercache/root/appcache/application_1724090939581_0001/output/attempt_1724090939581_0001_1_00_000097_2_10003_1/file.out
2024-08-19 19:02:11,268 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268435456, reserved.metasize=6389872
2024-08-19 19:02:14,288 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span0.length = 399364, perItem = 134
2024-08-19 19:02:14,288 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=208231459, reserved.metasize=6389824
2024-08-19 19:02:14,289 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span1.length = 399364, perItem = 134, counter:3918057
2024-08-19 19:02:15,648 [INFO] [Sorter \{scope_302 -> scope_308} #1]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=0,
length=399364, time=1359
2024-08-19 19:02:17,427 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span1.length = 399361, perItem = 134
2024-08-19 19:02:17,427 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=148031349, reserved.metasize=6389776
2024-08-19 19:02:17,427 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span2.length = 399361, perItem = 134, counter:4317418
2024-08-19 19:02:18,882 [INFO] [Sorter \{scope_302 -> scope_308} #0]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=1,
length=399361, time=1454
2024-08-19 19:02:21,187 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span2.length = 399358, perItem = 134
2024-08-19 19:02:21,187 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=87832625, reserved.metasize=6389728
2024-08-19 19:02:21,187 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span3.length = 399358, perItem = 134, counter:4716776
2024-08-19 19:02:22,390 [INFO] [Sorter \{scope_302 -> scope_308} #1]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=2,
length=399358, time=1202
2024-08-19 19:02:24,108 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span3.length = 399355, perItem = 133
2024-08-19 19:02:24,108 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=28235071, reserved.metasize=3031952
2024-08-19 19:02:24,108 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span4.length = 189497, perItem = 133, counter:5116131
2024-08-19 19:02:25,514 [INFO] [Sorter \{scope_302 -> scope_308} #0]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=3,
length=399355, time=1405
2024-08-19 19:02:25,787 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span4.length = 189494, perItem = 132
2024-08-19 19:02:25,787 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=165604, reserved.metasize=17888
2024-08-19 19:02:25,787 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span5.length = 1118, perItem = 132, counter:5305625
2024-08-19 19:02:25,793 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span5.length = 1115, perItem = 132
2024-08-19 19:02:25,793 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=397, reserved.metasize=32
2024-08-19 19:02:25,793 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span6.length = 2, perItem = 132, counter:5306740
2024-08-19 19:02:25,793 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span6.length = 1, perItem = 126
2024-08-19 19:02:25,794 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=239, reserved.metasize=16
2024-08-19 19:02:25,794 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span7.length = 1, perItem = 126, counter:5306741
2024-08-19 19:02:25,794 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span7.length = 1, perItem = 127
2024-08-19 19:02:25,794 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: done sorting span=7, length=1, time=0
2024-08-19 19:02:25,794 [INFO] [Sorter \{scope_302 -> scope_308} #0]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=5,
length=1115, time=1
2024-08-19 19:02:25,794 [INFO] [Sorter \{scope_302 -> scope_308} #0]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=6, length=1,
time=0
2024-08-19 19:02:26,186 [INFO] [Sorter \{scope_302 -> scope_308} #1]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=4,
length=189494, time=398
2024-08-19 19:02:26,187 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Heap = SpanIterator<0:399363>
(span=Span[6389872,53814125]),SpanIterator<0:399357>
(span=Span[6389776,53808948]),SpanIterator<0:399360>
(span=Span[6389824,53810286]),SpanIterator<0:0>
(span=Span[16,127]),SpanIterator<0:399354>
(span=Span[6389728,53207826]),SpanIterator<0:189493>
(span=Span[3031952,25037515]),SpanIterator<0:1114>
(span=Span[17888,147319]),SpanIterator<0:0> (span=Span[32,126]),
2024-08-19 19:02:26,188 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Spilling to
/hadoop/yarn/nm-local-dir/usercache/root/appcache/application_1724090939581_0001/output/attempt_1724090939581_0001_1_00_000097_2_10003_2/file.out
2024-08-19 19:02:28,031 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268435456, reserved.metasize=16
2024-08-19 19:02:28,032 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span0.length = 1, perItem = 137
2024-08-19 19:02:28,032 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268435303, reserved.metasize=16
2024-08-19 19:02:28,033 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span1.length = 1, perItem = 137, counter:5306743
2024-08-19 19:02:28,033 [INFO] [Sorter \{scope_302 -> scope_308} #0]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=0, length=1,
time=0
2024-08-19 19:02:28,033 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span1.length = 1, perItem = 145
2024-08-19 19:02:28,033 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268435142, reserved.metasize=16
2024-08-19 19:02:28,033 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span2.length = 1, perItem = 145, counter:5306744
2024-08-19 19:02:28,033 [INFO] [Sorter \{scope_302 -> scope_308} #1]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=1, length=1,
time=0
2024-08-19 19:02:28,033 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span2.length = 1, perItem = 140
2024-08-19 19:02:28,036 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268434986, reserved.metasize=16
2024-08-19 19:02:28,037 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span3.length = 1, perItem = 140, counter:5306745
2024-08-19 19:02:28,038 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span3.length = 1, perItem = 135
2024-08-19 19:02:28,038 [INFO] [Sorter \{scope_302 -> scope_308} #0]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=2, length=1,
time=1
2024-08-19 19:02:28,038 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268434835, reserved.metasize=16
2024-08-19 19:02:28,038 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span4.length = 1, perItem = 135, counter:5306746
2024-08-19 19:02:28,038 [INFO] [Sorter \{scope_302 -> scope_308} #1]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=3, length=1,
time=0
2024-08-19 19:02:28,038 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span4.length = 1, perItem = 128
2024-08-19 19:02:28,038 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268434691, reserved.metasize=16
2024-08-19 19:02:28,039 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span5.length = 1, perItem = 128, counter:5306747
2024-08-19 19:02:28,039 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span5.length = 1, perItem = 137
2024-08-19 19:02:28,039 [INFO] [Sorter \{scope_302 -> scope_308} #0]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=4, length=1,
time=0
2024-08-19 19:02:28,039 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268434538, reserved.metasize=16
2024-08-19 19:02:28,039 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span6.length = 1, perItem = 137, counter:5306748
2024-08-19 19:02:28,039 [INFO] [Sorter \{scope_302 -> scope_308} #1]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=5, length=1,
time=0
2024-08-19 19:02:28,039 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span6.length = 1, perItem = 121
2024-08-19 19:02:28,039 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268434401, reserved.metasize=16
2024-08-19 19:02:28,040 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span7.length = 1, perItem = 121, counter:5306749
2024-08-19 19:02:28,040 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span7.length = 1, perItem = 128
2024-08-19 19:02:28,040 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268434257, reserved.metasize=16
2024-08-19 19:02:28,040 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span8.length = 1, perItem = 128, counter:5306750
2024-08-19 19:02:28,040 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span8.length = 1, perItem = 139
2024-08-19 19:02:28,040 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268434102, reserved.metasize=16
2024-08-19 19:02:28,040 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span9.length = 1, perItem = 139, counter:5306751
2024-08-19 19:02:28,040 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span9.length = 1, perItem = 123
2024-08-19 19:02:28,041 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268433963, reserved.metasize=16
2024-08-19 19:02:28,041 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span10.length = 1, perItem = 123, counter:5306752
2024-08-19 19:02:28,041 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span10.length = 1, perItem = 128
2024-08-19 19:02:28,041 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268433819, reserved.metasize=16
2024-08-19 19:02:28,041 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span11.length = 1, perItem = 128, counter:5306753
2024-08-19 19:02:28,041 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span11.length = 1, perItem = 133
2024-08-19 19:02:28,041 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268433670, reserved.metasize=16
2024-08-19 19:02:28,041 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span12.length = 1, perItem = 133, counter:5306754
2024-08-19 19:02:28,042 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span12.length = 1, perItem = 152
2024-08-19 19:02:28,042 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268433502, reserved.metasize=16
2024-08-19 19:02:28,042 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span13.length = 1, perItem = 152, counter:5306755
2024-08-19 19:02:28,042 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span13.length = 1, perItem = 130
2024-08-19 19:02:28,042 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268433356, reserved.metasize=16
2024-08-19 19:02:28,042 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span14.length = 1, perItem = 130, counter:5306756
2024-08-19 19:02:28,042 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span14.length = 1, perItem = 128
2024-08-19 19:02:28,042 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268433212, reserved.metasize=16
2024-08-19 19:02:28,042 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span15.length = 1, perItem = 128, counter:5306757
2024-08-19 19:02:28,043 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span15.length = 1, perItem = 137
2024-08-19 19:02:28,043 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268433059, reserved.metasize=16
2024-08-19 19:02:28,043 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span16.length = 1, perItem = 137, counter:5306758
2024-08-19 19:02:28,043 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span16.length = 1, perItem = 137
2024-08-19 19:02:28,043 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268432906, reserved.metasize=16
2024-08-19 19:02:28,043 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span17.length = 1, perItem = 137, counter:5306759
2024-08-19 19:02:28,043 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span17.length = 1, perItem = 128
2024-08-19 19:02:28,043 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268432762, reserved.metasize=16
2024-08-19 19:02:28,043 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span18.length = 1, perItem = 128, counter:5306760
2024-08-19 19:02:28,044 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span18.length = 1, perItem = 125
2024-08-19 19:02:28,044 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268432621, reserved.metasize=16
2024-08-19 19:02:28,044 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span19.length = 1, perItem = 125, counter:5306761
2024-08-19 19:02:28,044 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span19.length = 1, perItem = 128
2024-08-19 19:02:28,044 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268432477, reserved.metasize=16
2024-08-19 19:02:28,044 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span20.length = 1, perItem = 128, counter:5306762
2024-08-19 19:02:28,044 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span20.length = 1, perItem = 141
2024-08-19 19:02:28,044 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268432320, reserved.metasize=16
2024-08-19 19:02:28,044 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span21.length = 1, perItem = 141, counter:5306763
2024-08-19 19:02:28,045 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span21.length = 1, perItem = 128
2024-08-19 19:02:28,045 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268432176, reserved.metasize=16
2024-08-19 19:02:28,045 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span22.length = 1, perItem = 128, counter:5306764
2024-08-19 19:02:28,045 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span22.length = 1, perItem = 128
was:
we run into a issue with overflow as in TEZ-4542, with TEZ-4542 applied, it
then run into an issue of real small sortspan (per record in this case),
eventually the job failed due to timeout
from sample logs it looks like
SortSpan(ByteBuffer source, int maxItems, int perItem, RawComparator comparator)
once it get into a situation of maxItems=1, then it persists with maxItems=1
(also a side issue, the logging in this situation becomes huge)
sample logs:
2024-08-19 19:02:28,157 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span260.length = 1, perItem = 139
2024-08-19 19:02:28,157 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268396925, reserved.metasize=16
2024-08-19 19:02:28,157 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span261.length = 1, perItem = 139, counter:5307003
2024-08-19 19:02:28,157 [INFO] [Sorter \{scope_302 -> scope_308} #1|#1]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=260,
length=1, time=0
2024-08-19 19:02:28,157 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span261.length = 1, perItem = 128
2024-08-19 19:02:28,157 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268396781, reserved.metasize=16
2024-08-19 19:02:28,157 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span262.length = 1, perItem = 128, counter:5307004
2024-08-19 19:02:28,158 [INFO] [Sorter \{scope_302 -> scope_308} #0|#0]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=261,
length=1, time=0
2024-08-19 19:02:28,158 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span262.length = 1, perItem = 145
2024-08-19 19:02:28,158 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268396620, reserved.metasize=16
2024-08-19 19:02:28,158 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span263.length = 1, perItem = 145, counter:5307005
2024-08-19 19:02:28,158 [INFO] [Sorter \{scope_302 -> scope_308} #1|#1]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=262,
length=1, time=0
2024-08-19 19:02:28,158 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span263.length = 1, perItem = 139
2024-08-19 19:02:28,158 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268396465, reserved.metasize=16
2024-08-19 19:02:28,158 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span264.length = 1, perItem = 139, counter:5307006
2024-08-19 19:02:28,158 [INFO] [Sorter \{scope_302 -> scope_308} #0|#0]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=263,
length=1, time=0
2024-08-19 19:02:28,158 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: Span264.length = 1, perItem = 129
2024-08-19 19:02:28,158 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: reserved.remaining()=268396320, reserved.metasize=16
2024-08-19 19:02:28,158 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302 ->
scope-308: New Span265.length = 1, perItem = 129, counter:5307007
2024-08-19 19:02:28,158 [INFO] [Sorter \{scope_302 -> scope_308} #1|#1]
|impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=264,
length=1, time=0
> SortSpan could be created real small, resulting in eventual job failure
> -----------------------------------------------------------------------
>
> Key: TEZ-4577
> URL: https://issues.apache.org/jira/browse/TEZ-4577
> Project: Apache Tez
> Issue Type: Bug
> Affects Versions: 0.10.4
> Reporter: Yi Zhang
> Priority: Major
> Time Spent: 0.5h
> Remaining Estimate: 0h
>
> we run into a issue with overflow as in TEZ-4542, with TEZ-4542 applied, it
> then run into an issue of real small sortspan (per record in this case),
> eventually the job failed due to timeout
> from sample logs it looks like
>
> SortSpan(ByteBuffer source, int maxItems, int perItem, RawComparator
> comparator)
>
> once it get into a situation of maxItems=1, then it persists with maxItems=1
>
> (also a side issue, the logging in this situation becomes huge)
>
> sample logs:
> 2024-08-19 19:01:37,704 [INFO]
> [TezTaskEventRouter\{attempt_1724090939581_0001_1_00_000097_2}]
> |input.MRInput|: scope-20 -> scope-302 initialized RecordReader from event
> 2024-08-19 19:01:37,709 [INFO] [TezChild] |runtime.PigProcessor|: Starting
> output
> org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput@e3a121c to
> vertex scope-308
> 2024-08-19 19:01:37,742 [INFO] [TezChild] |impl.ExternalSorter|: scope-302 ->
> scope-308 using: memoryMb=256, keySerializerClass=class
> org.apache.pig.impl.io.NullableTuple,
> valueSerializerClass=org.apache.hadoop.io.serializer.WritableSerialization$WritableSerializer@1fe3d5ed,
>
> comparator=org.apache.pig.backend.hadoop.executionengine.mapReduceLayer.PigTupleSortComparator@3d696d6,
> partitioner=org.apache.tez.mapreduce.partition.MRPartitioner,
> serialization=org.apache.hadoop.io.serializer.WritableSerialization,
> org.apache.hadoop.io.serializer.avro.AvroSpecificSerialization,
> org.apache.hadoop.io.serializer.avro.AvroReflectSerialization,
> reportPartitionStats=MEMORY_OPTIMIZED
> 2024-08-19 19:01:37,758 [INFO] [TezChild] |partition.MRPartitioner|: Using
> newApi,
> MRpartitionerClass=org.apache.hadoop.mapreduce.lib.partition.HashPartitioner
> 2024-08-19 19:01:37,758 [INFO] [TezChild] |impl.PipelinedSorter|: Setting up
> PipelinedSorter for scope-302 -> scope-308: , UsingHashComparator=false
> 2024-08-19 19:01:37,800 [INFO] [TezChild] |impl.PipelinedSorter|: Newly
> allocated block size=268435456, index=0, Number of buffers=1,
> currentAllocatableMemory=0, currentBufferSize=268435456, total=268435456
> 2024-08-19 19:01:37,800 [INFO] [TezChild] |impl.PipelinedSorter|: Pre
> allocating rest of memory buffers upfront
> 2024-08-19 19:01:37,800 [INFO] [TezChild] |impl.PipelinedSorter|: Setting up
> PipelinedSorter for scope-302 -> scope-308: ,
> UsingHashComparator=false#blocks=1, maxMemUsage=268435456,
> lazyAllocateMem=false, minBlockSize=2097152000, initial BLOCK_SIZE=268435456,
> finalMergeEnabled=true, pipelinedShuffle=false, sendEmptyPartitions=true,
> tez.runtime.io.sort.mb=256
> 2024-08-19 19:01:37,802 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268435456, reserved.metasize=16777216
> 2024-08-19 19:01:37,827 [INFO] [TezChild] |operator.POLocalRearrangeTez|:
> Attached output to vertex scope-308 :
> output=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput@e3a121c,
>
> writer=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput$1@148db3c7
> 2024-08-19 19:01:37,827 [INFO] [TezChild] |runtime.PigProcessor|: Aliases
> being processed per job phase (AliasName[line,offset]):
> prev_partition_data[13,28],prev_partition_req_fields[24,28],prev_curr_grp[95,16]
> 2024-08-19 19:01:45,632 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span0.length = 1048573, perItem = 138
> 2024-08-19 19:01:45,633 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=106530636, reserved.metasize=11068112
> 2024-08-19 19:01:45,633 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span1.length = 691757, perItem = 138, counter:1048573
> 2024-08-19 19:01:49,491 [INFO] [Sorter \{scope_302 -> scope_308} #0]
> |impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=0,
> length=1048573, time=3857
> 2024-08-19 19:01:51,495 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span1.length = 689460, perItem = 138
> 2024-08-19 19:01:53,482 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: done sorting span=1, length=689460, time=1986
> 2024-08-19 19:01:53,484 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Heap = SpanIterator<0:1048572>
> (span=Span[16777216,145127604]),SpanIterator<0:689459>
> (span=Span[11068112,95462505]),
> 2024-08-19 19:01:53,601 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Spilling to
> /hadoop/yarn/nm-local-dir/usercache/root/appcache/application_1724090939581_0001/output/attempt_1724090939581_0001_1_00_000097_2_10003_0/file.out
> 2024-08-19 19:01:55,217 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268435456, reserved.metasize=11068112
> 2024-08-19 19:02:00,213 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span0.length = 691754, perItem = 134
> 2024-08-19 19:02:00,213 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=164176480, reserved.metasize=11068064
> 2024-08-19 19:02:00,213 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span1.length = 691754, perItem = 134, counter:2429787
> 2024-08-19 19:02:02,681 [INFO] [Sorter \{scope_302 -> scope_308} #1]
> |impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=0,
> length=691754, time=2467
> 2024-08-19 19:02:05,552 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span1.length = 691751, perItem = 134
> 2024-08-19 19:02:05,552 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=59905155, reserved.metasize=6389872
> 2024-08-19 19:02:05,552 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span2.length = 399367, perItem = 134, counter:3121538
> 2024-08-19 19:02:08,036 [INFO] [Sorter \{scope_302 -> scope_308} #0]
> |impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=1,
> length=691751, time=2484
> 2024-08-19 19:02:08,656 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span2.length = 397155, perItem = 134
> 2024-08-19 19:02:09,786 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: done sorting span=2, length=397155, time=1130
> 2024-08-19 19:02:09,787 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Heap = SpanIterator<0:691753>
> (span=Span[11068112,93190864]),SpanIterator<0:397154>
> (span=Span[6389872,53515175]),SpanIterator<0:691750>
> (span=Span[11068064,93203261]),
> 2024-08-19 19:02:09,788 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Spilling to
> /hadoop/yarn/nm-local-dir/usercache/root/appcache/application_1724090939581_0001/output/attempt_1724090939581_0001_1_00_000097_2_10003_1/file.out
> 2024-08-19 19:02:11,268 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268435456, reserved.metasize=6389872
> 2024-08-19 19:02:14,288 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span0.length = 399364, perItem = 134
> 2024-08-19 19:02:14,288 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=208231459, reserved.metasize=6389824
> 2024-08-19 19:02:14,289 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span1.length = 399364, perItem = 134, counter:3918057
> 2024-08-19 19:02:15,648 [INFO] [Sorter \{scope_302 -> scope_308} #1]
> |impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=0,
> length=399364, time=1359
> 2024-08-19 19:02:17,427 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span1.length = 399361, perItem = 134
> 2024-08-19 19:02:17,427 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=148031349, reserved.metasize=6389776
> 2024-08-19 19:02:17,427 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span2.length = 399361, perItem = 134, counter:4317418
> 2024-08-19 19:02:18,882 [INFO] [Sorter \{scope_302 -> scope_308} #0]
> |impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=1,
> length=399361, time=1454
> 2024-08-19 19:02:21,187 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span2.length = 399358, perItem = 134
> 2024-08-19 19:02:21,187 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=87832625, reserved.metasize=6389728
> 2024-08-19 19:02:21,187 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span3.length = 399358, perItem = 134, counter:4716776
> 2024-08-19 19:02:22,390 [INFO] [Sorter \{scope_302 -> scope_308} #1]
> |impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=2,
> length=399358, time=1202
> 2024-08-19 19:02:24,108 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span3.length = 399355, perItem = 133
> 2024-08-19 19:02:24,108 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=28235071, reserved.metasize=3031952
> 2024-08-19 19:02:24,108 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span4.length = 189497, perItem = 133, counter:5116131
> 2024-08-19 19:02:25,514 [INFO] [Sorter \{scope_302 -> scope_308} #0]
> |impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=3,
> length=399355, time=1405
> 2024-08-19 19:02:25,787 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span4.length = 189494, perItem = 132
> 2024-08-19 19:02:25,787 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=165604, reserved.metasize=17888
> 2024-08-19 19:02:25,787 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span5.length = 1118, perItem = 132, counter:5305625
> 2024-08-19 19:02:25,793 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span5.length = 1115, perItem = 132
> 2024-08-19 19:02:25,793 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=397, reserved.metasize=32
> 2024-08-19 19:02:25,793 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span6.length = 2, perItem = 132, counter:5306740
> 2024-08-19 19:02:25,793 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span6.length = 1, perItem = 126
> 2024-08-19 19:02:25,794 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=239, reserved.metasize=16
> 2024-08-19 19:02:25,794 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span7.length = 1, perItem = 126, counter:5306741
> 2024-08-19 19:02:25,794 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span7.length = 1, perItem = 127
> 2024-08-19 19:02:25,794 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: done sorting span=7, length=1, time=0
> 2024-08-19 19:02:25,794 [INFO] [Sorter \{scope_302 -> scope_308} #0]
> |impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=5,
> length=1115, time=1
> 2024-08-19 19:02:25,794 [INFO] [Sorter \{scope_302 -> scope_308} #0]
> |impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=6,
> length=1, time=0
> 2024-08-19 19:02:26,186 [INFO] [Sorter \{scope_302 -> scope_308} #1]
> |impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=4,
> length=189494, time=398
> 2024-08-19 19:02:26,187 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Heap = SpanIterator<0:399363>
> (span=Span[6389872,53814125]),SpanIterator<0:399357>
> (span=Span[6389776,53808948]),SpanIterator<0:399360>
> (span=Span[6389824,53810286]),SpanIterator<0:0>
> (span=Span[16,127]),SpanIterator<0:399354>
> (span=Span[6389728,53207826]),SpanIterator<0:189493>
> (span=Span[3031952,25037515]),SpanIterator<0:1114>
> (span=Span[17888,147319]),SpanIterator<0:0> (span=Span[32,126]),
> 2024-08-19 19:02:26,188 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Spilling to
> /hadoop/yarn/nm-local-dir/usercache/root/appcache/application_1724090939581_0001/output/attempt_1724090939581_0001_1_00_000097_2_10003_2/file.out
> 2024-08-19 19:02:28,031 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268435456, reserved.metasize=16
> 2024-08-19 19:02:28,032 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span0.length = 1, perItem = 137
> 2024-08-19 19:02:28,032 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268435303, reserved.metasize=16
> 2024-08-19 19:02:28,033 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span1.length = 1, perItem = 137, counter:5306743
> 2024-08-19 19:02:28,033 [INFO] [Sorter \{scope_302 -> scope_308} #0]
> |impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=0,
> length=1, time=0
> 2024-08-19 19:02:28,033 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span1.length = 1, perItem = 145
> 2024-08-19 19:02:28,033 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268435142, reserved.metasize=16
> 2024-08-19 19:02:28,033 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span2.length = 1, perItem = 145, counter:5306744
> 2024-08-19 19:02:28,033 [INFO] [Sorter \{scope_302 -> scope_308} #1]
> |impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=1,
> length=1, time=0
> 2024-08-19 19:02:28,033 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span2.length = 1, perItem = 140
> 2024-08-19 19:02:28,036 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268434986, reserved.metasize=16
> 2024-08-19 19:02:28,037 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span3.length = 1, perItem = 140, counter:5306745
> 2024-08-19 19:02:28,038 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span3.length = 1, perItem = 135
> 2024-08-19 19:02:28,038 [INFO] [Sorter \{scope_302 -> scope_308} #0]
> |impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=2,
> length=1, time=1
> 2024-08-19 19:02:28,038 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268434835, reserved.metasize=16
> 2024-08-19 19:02:28,038 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span4.length = 1, perItem = 135, counter:5306746
> 2024-08-19 19:02:28,038 [INFO] [Sorter \{scope_302 -> scope_308} #1]
> |impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=3,
> length=1, time=0
> 2024-08-19 19:02:28,038 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span4.length = 1, perItem = 128
> 2024-08-19 19:02:28,038 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268434691, reserved.metasize=16
> 2024-08-19 19:02:28,039 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span5.length = 1, perItem = 128, counter:5306747
> 2024-08-19 19:02:28,039 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span5.length = 1, perItem = 137
> 2024-08-19 19:02:28,039 [INFO] [Sorter \{scope_302 -> scope_308} #0]
> |impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=4,
> length=1, time=0
> 2024-08-19 19:02:28,039 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268434538, reserved.metasize=16
> 2024-08-19 19:02:28,039 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span6.length = 1, perItem = 137, counter:5306748
> 2024-08-19 19:02:28,039 [INFO] [Sorter \{scope_302 -> scope_308} #1]
> |impl.PipelinedSorter|: scope-302 -> scope-308: done sorting span=5,
> length=1, time=0
> 2024-08-19 19:02:28,039 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span6.length = 1, perItem = 121
> 2024-08-19 19:02:28,039 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268434401, reserved.metasize=16
> 2024-08-19 19:02:28,040 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span7.length = 1, perItem = 121, counter:5306749
> 2024-08-19 19:02:28,040 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span7.length = 1, perItem = 128
> 2024-08-19 19:02:28,040 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268434257, reserved.metasize=16
> 2024-08-19 19:02:28,040 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span8.length = 1, perItem = 128, counter:5306750
> 2024-08-19 19:02:28,040 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span8.length = 1, perItem = 139
> 2024-08-19 19:02:28,040 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268434102, reserved.metasize=16
> 2024-08-19 19:02:28,040 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span9.length = 1, perItem = 139, counter:5306751
> 2024-08-19 19:02:28,040 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span9.length = 1, perItem = 123
> 2024-08-19 19:02:28,041 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268433963, reserved.metasize=16
> 2024-08-19 19:02:28,041 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span10.length = 1, perItem = 123, counter:5306752
> 2024-08-19 19:02:28,041 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span10.length = 1, perItem = 128
> 2024-08-19 19:02:28,041 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268433819, reserved.metasize=16
> 2024-08-19 19:02:28,041 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span11.length = 1, perItem = 128, counter:5306753
> 2024-08-19 19:02:28,041 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span11.length = 1, perItem = 133
> 2024-08-19 19:02:28,041 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268433670, reserved.metasize=16
> 2024-08-19 19:02:28,041 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span12.length = 1, perItem = 133, counter:5306754
> 2024-08-19 19:02:28,042 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span12.length = 1, perItem = 152
> 2024-08-19 19:02:28,042 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268433502, reserved.metasize=16
> 2024-08-19 19:02:28,042 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span13.length = 1, perItem = 152, counter:5306755
> 2024-08-19 19:02:28,042 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span13.length = 1, perItem = 130
> 2024-08-19 19:02:28,042 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268433356, reserved.metasize=16
> 2024-08-19 19:02:28,042 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span14.length = 1, perItem = 130, counter:5306756
> 2024-08-19 19:02:28,042 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span14.length = 1, perItem = 128
> 2024-08-19 19:02:28,042 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268433212, reserved.metasize=16
> 2024-08-19 19:02:28,042 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span15.length = 1, perItem = 128, counter:5306757
> 2024-08-19 19:02:28,043 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span15.length = 1, perItem = 137
> 2024-08-19 19:02:28,043 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268433059, reserved.metasize=16
> 2024-08-19 19:02:28,043 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span16.length = 1, perItem = 137, counter:5306758
> 2024-08-19 19:02:28,043 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span16.length = 1, perItem = 137
> 2024-08-19 19:02:28,043 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268432906, reserved.metasize=16
> 2024-08-19 19:02:28,043 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span17.length = 1, perItem = 137, counter:5306759
> 2024-08-19 19:02:28,043 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span17.length = 1, perItem = 128
> 2024-08-19 19:02:28,043 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268432762, reserved.metasize=16
> 2024-08-19 19:02:28,043 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span18.length = 1, perItem = 128, counter:5306760
> 2024-08-19 19:02:28,044 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span18.length = 1, perItem = 125
> 2024-08-19 19:02:28,044 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268432621, reserved.metasize=16
> 2024-08-19 19:02:28,044 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span19.length = 1, perItem = 125, counter:5306761
> 2024-08-19 19:02:28,044 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span19.length = 1, perItem = 128
> 2024-08-19 19:02:28,044 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268432477, reserved.metasize=16
> 2024-08-19 19:02:28,044 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span20.length = 1, perItem = 128, counter:5306762
> 2024-08-19 19:02:28,044 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span20.length = 1, perItem = 141
> 2024-08-19 19:02:28,044 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268432320, reserved.metasize=16
> 2024-08-19 19:02:28,044 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span21.length = 1, perItem = 141, counter:5306763
> 2024-08-19 19:02:28,045 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span21.length = 1, perItem = 128
> 2024-08-19 19:02:28,045 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: reserved.remaining()=268432176, reserved.metasize=16
> 2024-08-19 19:02:28,045 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: New Span22.length = 1, perItem = 128, counter:5306764
> 2024-08-19 19:02:28,045 [INFO] [TezChild] |impl.PipelinedSorter|: scope-302
> -> scope-308: Span22.length = 1, perItem = 128
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
