drill-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Robert Hou (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (DRILL-5804) External Sort times out, may be infinite loop
Date Tue, 19 Sep 2017 20:34:00 GMT

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

Mime
View raw message