[
https://issues.apache.org/jira/browse/TEZ-4577?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17895253#comment-17895253
]
Seonggon Namgung commented on TEZ-4577:
---------------------------------------
Thanks for sharing the test. I have debugged this issue with your test and
concluded that the created small SortSpan will be immediately removed in the
upcoming sort() call. (For the detailed explanation, please see the below
paragraphs.) I have a little doubt about exploiting bufferOverflowRecursion,
but as you pointed out, it should be considered as a new issue. Overall, your
patch looks good to me.
--
We start from the following call stack: PipelinedSorter::collect --> catch
BufferOverflowException --> PipelinedSorter::sort --> span.next().
After the above calls, we have a small SortSpan and meet the if-clause guarding
spillSingleRecord().
{code:java}
if (span.length() == 0 || bufferOverflowRecursion > buffers.size()) { ... }
{code}
At this point, spen.length() is not zero and bufferOverflowRecusion is also
less than buffers.size() as it is the beginning of the recursion. Therefore, we
recursively call collect() again.
Now, we are in the following call stacks: PipelinedSorter::collect -->
PipelinedSorter::collect.
Since our new SortSpan is smaller than the previous one, we call this.sort() in
one of the following clause.
{code:java}
if (span.kvmeta.remaining() < METASIZE) { ... }{code}
{code:java}
catch(BufferOverflowException overflow) { ... }{code}
In either cases, we call PipelinedSorter::sort --> span.next() --> span.end().
Inside SortSpan::end(). Since we didn't write any items, now the length()
becomes 0. So the following code stops buffer reusing by returning null instead
of remaining buffer.
{code:java}
int items = length();
if(items == 0) {
return null;
} {code}
Since span.end() returns null, span.next() also returns null, and
PipelinedSorter::sort creates a new SortSpan with length=maxItems = 1024 *
1024. Therefore, we don't use a small SortSpan at all.
> 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: 50m
> 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)
