[ https://issues.apache.org/jira/browse/DRILL-5804?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Robert Hou updated DRILL-5804: ------------------------------ Description: Query is: {noformat} ALTER SESSION SET `exec.sort.disable_managed` = false; select count(*) from ( select * from ( select s1.type type, flatten(s1.rms.rptd) rptds, s1.rms, s1.uid from ( select d.type type, d.uid uid, flatten(d.map.rm) rms from dfs.`/drill/testdata/resource-manager/nested_large` d order by d.uid ) s1 ) s2 order by s2.rms.mapid, s2.rptds.a, s2.rptds.do_not_exist ); {noformat} Plan is: {noformat} | 00-00 Screen 00-01 Project(EXPR$0=[$0]) 00-02 StreamAgg(group=[{}], EXPR$0=[$SUM0($0)]) 00-03 UnionExchange 01-01 StreamAgg(group=[{}], EXPR$0=[COUNT()]) 01-02 Project($f0=[0]) 01-03 SingleMergeExchange(sort0=[4 ASC], sort1=[5 ASC], sort2=[6 ASC]) 02-01 SelectionVectorRemover 02-02 Sort(sort0=[$4], sort1=[$5], sort2=[$6], dir0=[ASC], dir1=[ASC], dir2=[ASC]) 02-03 Project(type=[$0], rptds=[$1], rms=[$2], uid=[$3], EXPR$4=[$4], EXPR$5=[$5], EXPR$6=[$6]) 02-04 HashToRandomExchange(dist0=[[$4]], dist1=[[$5]], dist2=[[$6]]) 03-01 UnorderedMuxExchange 04-01 Project(type=[$0], rptds=[$1], rms=[$2], uid=[$3], EXPR$4=[$4], EXPR$5=[$5], EXPR$6=[$6], E_X_P_R_H_A_S_H_F_I_E_L_D=[hash32AsDouble($6, hash32AsDouble($5, hash32AsDouble($4, 1301011)))]) 04-02 Project(type=[$0], rptds=[$1], rms=[$2], uid=[$3], EXPR$4=[ITEM($2, 'mapid')], EXPR$5=[ITEM($1, 'a')], EXPR$6=[ITEM($1, 'do_not_exist')]) 04-03 Flatten(flattenField=[$1]) 04-04 Project(type=[$0], rptds=[ITEM($2, 'rptd')], rms=[$2], uid=[$1]) 04-05 SingleMergeExchange(sort0=[1 ASC]) 05-01 SelectionVectorRemover 05-02 Sort(sort0=[$1], dir0=[ASC]) 05-03 Project(type=[$0], uid=[$1], rms=[$2]) 05-04 HashToRandomExchange(dist0=[[$1]]) 06-01 UnorderedMuxExchange 07-01 Project(type=[$0], uid=[$1], rms=[$2], E_X_P_R_H_A_S_H_F_I_E_L_D=[hash32AsDouble($1, 1301011)]) 07-02 Flatten(flattenField=[$2]) 07-03 Project(type=[$0], uid=[$1], rms=[ITEM($2, 'rm')]) 07-04 Scan(groupscan=[ParquetGroupScan [entries=[ReadEntryWithPath [path=maprfs:///drill/testdata/resource-manager/nested_large]], selectionRoot=maprfs:/drill/testdata/resource-manager/nested_large, numFiles=1, usedMetadataFile=false, columns=[`type`, `uid`, `map`.`rm`]]]) {noformat} Here is a segment of the drillbit.log, starting at line 55890: {noformat} 2017-09-19 04:22:56,258 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:2] DEBUG o.a.d.e.t.g.SingleBatchSorterGen44 - Took 142 us to sort 1023 records 2017-09-19 04:22:56,265 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:4] DEBUG o.a.d.e.t.g.SingleBatchSorterGen44 - Took 105 us to sort 1023 records 2017-09-19 04:22:56,268 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:3:0] DEBUG o.a.d.e.p.i.p.PartitionSenderRootExec - Partitioner.next(): got next record batch with status OK 2017-09-19 04:22:56,275 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:7] DEBUG o.a.d.e.t.g.SingleBatchSorterGen44 - Took 145 us to sort 1023 records 2017-09-19 04:22:56,354 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:3:0] DEBUG o.a.d.e.p.i.p.PartitionSenderRootExec - Partitioner.next(): got next record batch with status OK 2017-09-19 04:22:56,357 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:2] DEBUG o.a.d.e.t.g.SingleBatchSorterGen44 - Took 143 us to sort 1023 records 2017-09-19 04:22:56,361 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:0] DEBUG o.a.d.exec.compile.ClassTransformer - Compiled and merged PriorityQueueCopierGen50: bytecode size = 11.0 KiB, time = 124 ms. 2017-09-19 04:22:56,365 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:4] DEBUG o.a.d.e.t.g.SingleBatchSorterGen44 - Took 108 us to sort 1023 records 2017-09-19 04:22:56,367 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:0] DEBUG o.a.d.e.p.i.x.m.PriorityQueueCopierWrapper - Copier setup complete 2017-09-19 04:22:56,375 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:7] DEBUG o.a.d.e.t.g.SingleBatchSorterGen44 - Took 144 us to sort 1023 records 2017-09-19 04:22:56,396 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:0] DEBUG o.a.drill.exec.vector.BigIntVector - Reallocating vector [$data$(BIGINT:REQUIRED)]. # of bytes: [0] -> [0] 2017-09-19 04:22:56,396 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:0] DEBUG o.a.drill.exec.vector.BigIntVector - Reallocating vector [$data$(BIGINT:REQUIRED)]. # of bytes: [0] -> [0] 2017-09-19 04:22:56,396 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:0] DEBUG o.a.drill.exec.vector.BigIntVector - Reallocating vector [$data$(BIGINT:REQUIRED)]. # of bytes: [0] -> [0] {noformat} >From here on out, the drillbit.log file is filled with "Reallocating vector" >messages. The log seems to be written as fast as Drill can write to disk. >The logs are filled within a minute. sing cln2 q40.q was: Query is: {noformat} ALTER SESSION SET `exec.sort.disable_managed` = false; select count(*) from ( select * from ( select s1.type type, flatten(s1.rms.rptd) rptds, s1.rms, s1.uid from ( select d.type type, d.uid uid, flatten(d.map.rm) rms from dfs.`/drill/testdata/resource-manager/nested_large` d order by d.uid ) s1 ) s2 order by s2.rms.mapid, s2.rptds.a, s2.rptds.do_not_exist ); {noformat} Plan is: {noformat} | 00-00 Screen 00-01 Project(EXPR$0=[$0]) 00-02 StreamAgg(group=[{}], EXPR$0=[$SUM0($0)]) 00-03 UnionExchange 01-01 StreamAgg(group=[{}], EXPR$0=[COUNT()]) 01-02 Project($f0=[0]) 01-03 SingleMergeExchange(sort0=[4 ASC], sort1=[5 ASC], sort2=[6 ASC]) 02-01 SelectionVectorRemover 02-02 Sort(sort0=[$4], sort1=[$5], sort2=[$6], dir0=[ASC], dir1=[ASC], dir2=[ASC]) 02-03 Project(type=[$0], rptds=[$1], rms=[$2], uid=[$3], EXPR$4=[$4], EXPR$5=[$5], EXPR$6=[$6]) 02-04 HashToRandomExchange(dist0=[[$4]], dist1=[[$5]], dist2=[[$6]]) 03-01 UnorderedMuxExchange 04-01 Project(type=[$0], rptds=[$1], rms=[$2], uid=[$3], EXPR$4=[$4], EXPR$5=[$5], EXPR$6=[$6], E_X_P_R_H_A_S_H_F_I_E_L_D=[hash32AsDouble($6, hash32AsDouble($5, hash32AsDouble($4, 1301011)))]) 04-02 Project(type=[$0], rptds=[$1], rms=[$2], uid=[$3], EXPR$4=[ITEM($2, 'mapid')], EXPR$5=[ITEM($1, 'a')], EXPR$6=[ITEM($1, 'do_not_exist')]) 04-03 Flatten(flattenField=[$1]) 04-04 Project(type=[$0], rptds=[ITEM($2, 'rptd')], rms=[$2], uid=[$1]) 04-05 SingleMergeExchange(sort0=[1 ASC]) 05-01 SelectionVectorRemover 05-02 Sort(sort0=[$1], dir0=[ASC]) 05-03 Project(type=[$0], uid=[$1], rms=[$2]) 05-04 HashToRandomExchange(dist0=[[$1]]) 06-01 UnorderedMuxExchange 07-01 Project(type=[$0], uid=[$1], rms=[$2], E_X_P_R_H_A_S_H_F_I_E_L_D=[hash32AsDouble($1, 1301011)]) 07-02 Flatten(flattenField=[$2]) 07-03 Project(type=[$0], uid=[$1], rms=[ITEM($2, 'rm')]) 07-04 Scan(groupscan=[ParquetGroupScan [entries=[ReadEntryWithPath [path=maprfs:///drill/testdata/resource-manager/nested_large]], selectionRoot=maprfs:/drill/testdata/resource-manager/nested_large, numFiles=1, usedMetadataFile=false, columns=[`type`, `uid`, `map`.`rm`]]]) {noformat} Here is a segment of the drillbit.log, starting at line 55890: {noformat} 2017-09-19 04:22:56,258 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:2] DEBUG o.a.d.e.t.g.SingleBatchSorterGen44 - Took 142 us to sort 1023 records 2017-09-19 04:22:56,265 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:4] DEBUG o.a.d.e.t.g.SingleBatchSorterGen44 - Took 105 us to sort 1023 records 2017-09-19 04:22:56,268 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:3:0] DEBUG o.a.d.e.p.i.p.PartitionSenderRootExec - Partitioner.next(): got next record batch with status OK 2017-09-19 04:22:56,275 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:7] DEBUG o.a.d.e.t.g.SingleBatchSorterGen44 - Took 145 us to sort 1023 records 2017-09-19 04:22:56,354 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:3:0] DEBUG o.a.d.e.p.i.p.PartitionSenderRootExec - Partitioner.next(): got next record batch with status OK 2017-09-19 04:22:56,357 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:2] DEBUG o.a.d.e.t.g.SingleBatchSorterGen44 - Took 143 us to sort 1023 records 2017-09-19 04:22:56,361 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:0] DEBUG o.a.d.exec.compile.ClassTransformer - Compiled and merged PriorityQueueCopierGen50: bytecode size = 11.0 KiB, time = 124 ms. 2017-09-19 04:22:56,365 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:4] DEBUG o.a.d.e.t.g.SingleBatchSorterGen44 - Took 108 us to sort 1023 records 2017-09-19 04:22:56,367 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:0] DEBUG o.a.d.e.p.i.x.m.PriorityQueueCopierWrapper - Copier setup complete 2017-09-19 04:22:56,375 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:7] DEBUG o.a.d.e.t.g.SingleBatchSorterGen44 - Took 144 us to sort 1023 records 2017-09-19 04:22:56,396 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:0] DEBUG o.a.drill.exec.vector.BigIntVector - Reallocating vector [$data$(BIGINT:REQUIRED)]. # of bytes: [0] -> [0] 2017-09-19 04:22:56,396 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:0] DEBUG o.a.drill.exec.vector.BigIntVector - Reallocating vector [$data$(BIGINT:REQUIRED)]. # of bytes: [0] -> [0] 2017-09-19 04:22:56,396 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:0] DEBUG o.a.drill.exec.vector.BigIntVector - Reallocating vector [$data$(BIGINT:REQUIRED)]. # of bytes: [0] -> [0] {noformat} >From here on out, the drillbit.log file is filled with "Reallocating vector" >messages. The log seems to be written as fast as Drill can write to disk. >The logs are filled within a minute. > External Sort times out, may be infinite loop > --------------------------------------------- > > Key: DRILL-5804 > URL: https://issues.apache.org/jira/browse/DRILL-5804 > Project: Apache Drill > Issue Type: Bug > Components: Execution - Relational Operators > Affects Versions: 1.11.0 > Reporter: Robert Hou > Assignee: Paul Rogers > Fix For: 1.12.0 > > Attachments: drillbit.log > > > Query is: > {noformat} > ALTER SESSION SET `exec.sort.disable_managed` = false; > select count(*) from ( > select * from ( > select s1.type type, flatten(s1.rms.rptd) rptds, s1.rms, s1.uid > from ( > select d.type type, d.uid uid, flatten(d.map.rm) rms from > dfs.`/drill/testdata/resource-manager/nested_large` d order by d.uid > ) s1 > ) s2 > order by s2.rms.mapid, s2.rptds.a, s2.rptds.do_not_exist > ); > {noformat} > Plan is: > {noformat} > | 00-00 Screen > 00-01 Project(EXPR$0=[$0]) > 00-02 StreamAgg(group=[{}], EXPR$0=[$SUM0($0)]) > 00-03 UnionExchange > 01-01 StreamAgg(group=[{}], EXPR$0=[COUNT()]) > 01-02 Project($f0=[0]) > 01-03 SingleMergeExchange(sort0=[4 ASC], sort1=[5 ASC], > sort2=[6 ASC]) > 02-01 SelectionVectorRemover > 02-02 Sort(sort0=[$4], sort1=[$5], sort2=[$6], dir0=[ASC], > dir1=[ASC], dir2=[ASC]) > 02-03 Project(type=[$0], rptds=[$1], rms=[$2], uid=[$3], > EXPR$4=[$4], EXPR$5=[$5], EXPR$6=[$6]) > 02-04 HashToRandomExchange(dist0=[[$4]], dist1=[[$5]], > dist2=[[$6]]) > 03-01 UnorderedMuxExchange > 04-01 Project(type=[$0], rptds=[$1], rms=[$2], > uid=[$3], EXPR$4=[$4], EXPR$5=[$5], EXPR$6=[$6], > E_X_P_R_H_A_S_H_F_I_E_L_D=[hash32AsDouble($6, hash32AsDouble($5, > hash32AsDouble($4, 1301011)))]) > 04-02 Project(type=[$0], rptds=[$1], rms=[$2], > uid=[$3], EXPR$4=[ITEM($2, 'mapid')], EXPR$5=[ITEM($1, 'a')], > EXPR$6=[ITEM($1, 'do_not_exist')]) > 04-03 Flatten(flattenField=[$1]) > 04-04 Project(type=[$0], rptds=[ITEM($2, > 'rptd')], rms=[$2], uid=[$1]) > 04-05 SingleMergeExchange(sort0=[1 ASC]) > 05-01 SelectionVectorRemover > 05-02 Sort(sort0=[$1], dir0=[ASC]) > 05-03 Project(type=[$0], uid=[$1], > rms=[$2]) > 05-04 > HashToRandomExchange(dist0=[[$1]]) > 06-01 UnorderedMuxExchange > 07-01 Project(type=[$0], > uid=[$1], rms=[$2], E_X_P_R_H_A_S_H_F_I_E_L_D=[hash32AsDouble($1, 1301011)]) > 07-02 > Flatten(flattenField=[$2]) > 07-03 Project(type=[$0], > uid=[$1], rms=[ITEM($2, 'rm')]) > 07-04 > Scan(groupscan=[ParquetGroupScan [entries=[ReadEntryWithPath > [path=maprfs:///drill/testdata/resource-manager/nested_large]], > selectionRoot=maprfs:/drill/testdata/resource-manager/nested_large, > numFiles=1, usedMetadataFile=false, columns=[`type`, `uid`, `map`.`rm`]]]) > {noformat} > Here is a segment of the drillbit.log, starting at line 55890: > {noformat} > 2017-09-19 04:22:56,258 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:2] DEBUG > o.a.d.e.t.g.SingleBatchSorterGen44 - Took 142 us to sort 1023 records > 2017-09-19 04:22:56,265 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:4] DEBUG > o.a.d.e.t.g.SingleBatchSorterGen44 - Took 105 us to sort 1023 records > 2017-09-19 04:22:56,268 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:3:0] DEBUG > o.a.d.e.p.i.p.PartitionSenderRootExec - Partitioner.next(): got next record > batch with status OK > 2017-09-19 04:22:56,275 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:7] DEBUG > o.a.d.e.t.g.SingleBatchSorterGen44 - Took 145 us to sort 1023 records > 2017-09-19 04:22:56,354 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:3:0] DEBUG > o.a.d.e.p.i.p.PartitionSenderRootExec - Partitioner.next(): got next record > batch with status OK > 2017-09-19 04:22:56,357 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:2] DEBUG > o.a.d.e.t.g.SingleBatchSorterGen44 - Took 143 us to sort 1023 records > 2017-09-19 04:22:56,361 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:0] DEBUG > o.a.d.exec.compile.ClassTransformer - Compiled and merged > PriorityQueueCopierGen50: bytecode size = 11.0 KiB, time = 124 ms. > 2017-09-19 04:22:56,365 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:4] DEBUG > o.a.d.e.t.g.SingleBatchSorterGen44 - Took 108 us to sort 1023 records > 2017-09-19 04:22:56,367 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:0] DEBUG > o.a.d.e.p.i.x.m.PriorityQueueCopierWrapper - Copier setup complete > 2017-09-19 04:22:56,375 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:7] DEBUG > o.a.d.e.t.g.SingleBatchSorterGen44 - Took 144 us to sort 1023 records > 2017-09-19 04:22:56,396 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:0] DEBUG > o.a.drill.exec.vector.BigIntVector - Reallocating vector > [$data$(BIGINT:REQUIRED)]. # of bytes: [0] -> [0] > 2017-09-19 04:22:56,396 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:0] DEBUG > o.a.drill.exec.vector.BigIntVector - Reallocating vector > [$data$(BIGINT:REQUIRED)]. # of bytes: [0] -> [0] > 2017-09-19 04:22:56,396 [263f0252-fc60-7f8d-a1b1-c075876d1bd2:frag:2:0] DEBUG > o.a.drill.exec.vector.BigIntVector - Reallocating vector > [$data$(BIGINT:REQUIRED)]. # of bytes: [0] -> [0] > {noformat} > From here on out, the drillbit.log file is filled with "Reallocating vector" > messages. The log seems to be written as fast as Drill can write to disk. > The logs are filled within a minute. > sing cln2 q40.q -- This message was sent by Atlassian JIRA (v6.4.14#64029)