You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@drill.apache.org by "Rahul Challapalli (JIRA)" <ji...@apache.org> on 2016/12/20 01:08:58 UTC
[jira] [Commented] (DRILL-5138) TopN operator on top of ~110 GB
data set is very slow
[ https://issues.apache.org/jira/browse/DRILL-5138?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15762832#comment-15762832 ]
Rahul Challapalli commented on DRILL-5138:
------------------------------------------
There is constant activity in the logs and I see repeated messages like below
{code}
2016-12-19 17:08:24,668 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:7] DEBUG o.a.d.e.t.g.PriorityQueueGen25 - Took 236 us to add 1023 records
2016-12-19 17:08:24,669 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 1871512714
2016-12-19 17:08:24,688 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:2:0] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 1570308547
2016-12-19 17:08:24,716 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:9] DEBUG o.a.d.e.physical.impl.TopN.TopNBatch - Took 805818 us to get next
2016-12-19 17:08:24,719 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:2:0] DEBUG o.a.d.e.p.i.p.PartitionSenderRootExec - Partitioner.next(): got next record batch with status OK
2016-12-19 17:08:24,730 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:9] DEBUG o.a.d.e.t.g.PriorityQueueGen25 - Took 236 us to add 1023 records
2016-12-19 17:08:24,730 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:5] DEBUG o.a.d.e.physical.impl.TopN.TopNBatch - Took 891630 us to get next
2016-12-19 17:08:24,740 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 1829342356
2016-12-19 17:08:24,744 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 1979723182
2016-12-19 17:08:24,744 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:5] DEBUG o.a.d.e.t.g.PriorityQueueGen25 - Took 233 us to add 1023 records
2016-12-19 17:08:24,748 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 245261008
2016-12-19 17:08:24,751 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 806549589
2016-12-19 17:08:24,755 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 236042074
2016-12-19 17:08:24,759 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 1163285245
2016-12-19 17:08:24,763 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 1698900068
2016-12-19 17:08:24,766 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 1120699103
2016-12-19 17:08:24,769 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 2140745363
2016-12-19 17:08:24,804 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:2:0] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 711698891
2016-12-19 17:08:24,834 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:2:0] DEBUG o.a.d.e.p.i.p.PartitionSenderRootExec - Partitioner.next(): got next record batch with status OK
2016-12-19 17:08:24,839 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:16] DEBUG o.a.d.e.physical.impl.TopN.TopNBatch - Took 801665 us to get next
2016-12-19 17:08:24,842 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:2:0] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 1004715717
2016-12-19 17:08:24,854 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 1000960965
2016-12-19 17:08:24,856 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:6] DEBUG o.a.d.e.physical.impl.TopN.TopNBatch - Took 903870 us to get next
2016-12-19 17:08:24,858 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 381309402
2016-12-19 17:08:24,862 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:2] DEBUG o.a.d.e.physical.impl.TopN.TopNBatch - Took 912326 us to get next
2016-12-19 17:08:24,862 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 355745746
2016-12-19 17:08:24,862 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:16] DEBUG o.a.d.e.t.g.PriorityQueueGen25 - Took 369 us to add 1023 records
2016-12-19 17:08:24,865 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 1384689655
2016-12-19 17:08:24,870 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 747388677
2016-12-19 17:08:24,871 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:2:0] DEBUG o.a.d.e.p.i.p.PartitionSenderRootExec - Partitioner.next(): got next record batch with status OK
2016-12-19 17:08:24,873 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 1600619927
2016-12-19 17:08:24,879 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:6] DEBUG o.a.d.e.t.g.PriorityQueueGen25 - Took 373 us to add 1023 records
2016-12-19 17:08:24,882 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:2] DEBUG o.a.d.e.t.g.PriorityQueueGen25 - Took 226 us to add 1023 records
2016-12-19 17:08:24,924 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:1] DEBUG o.a.d.e.physical.impl.TopN.TopNBatch - Took 906193 us to get next
2016-12-19 17:08:24,941 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:1] DEBUG o.a.d.e.t.g.PriorityQueueGen25 - Took 232 us to add 1023 records
2016-12-19 17:08:24,952 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 1762056906
2016-12-19 17:08:24,955 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 772585445
2016-12-19 17:08:24,969 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 83456029
2016-12-19 17:08:24,975 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:2:0] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 1541738540
2016-12-19 17:08:25,000 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:2:0] DEBUG o.a.d.e.p.i.p.PartitionSenderRootExec - Partitioner.next(): got next record batch with status OK
2016-12-19 17:08:25,002 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:11] DEBUG o.a.d.e.physical.impl.TopN.TopNBatch - Took 875187 us to get next
2016-12-19 17:08:25,015 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:3] DEBUG o.a.d.e.physical.impl.TopN.TopNBatch - Took 871961 us to get next
2016-12-19 17:08:25,016 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:11] DEBUG o.a.d.e.t.g.PriorityQueueGen25 - Took 225 us to add 1023 records
2016-12-19 17:08:25,021 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:12] DEBUG o.a.d.e.physical.impl.TopN.TopNBatch - Took 772870 us to get next
2016-12-19 17:08:25,030 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:3] DEBUG o.a.d.e.t.g.PriorityQueueGen25 - Took 225 us to add 1023 records
2016-12-19 17:08:25,036 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:12] DEBUG o.a.d.e.t.g.PriorityQueueGen25 - Took 231 us to add 1023 records
2016-12-19 17:08:25,051 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 1333687504
2016-12-19 17:08:25,076 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 733542911
2016-12-19 17:08:25,079 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:2:0] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 1347610764
2016-12-19 17:08:25,097 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:4] DEBUG o.a.d.e.physical.impl.TopN.TopNBatch - Took 910390 us to get next
2016-12-19 17:08:25,097 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:2:0] DEBUG o.a.d.e.p.i.p.PartitionSenderRootExec - Partitioner.next(): got next record batch with status OK
2016-12-19 17:08:25,111 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:4] DEBUG o.a.d.e.t.g.PriorityQueueGen25 - Took 227 us to add 1023 records
2016-12-19 17:08:25,137 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 213954063
2016-12-19 17:08:25,149 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:0] DEBUG o.a.d.e.physical.impl.TopN.TopNBatch - Took 745343 us to get next
2016-12-19 17:08:25,150 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 945662070
2016-12-19 17:08:25,195 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:2:0] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 1973365277
2016-12-19 17:08:25,197 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:0] DEBUG o.a.d.e.t.g.PriorityQueueGen25 - Took 328 us to add 1023 records
2016-12-19 17:08:25,214 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:2:0] DEBUG o.a.d.e.p.i.p.PartitionSenderRootExec - Partitioner.next(): got next record batch with status OK
2016-12-19 17:08:25,224 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:14] DEBUG o.a.d.e.physical.impl.TopN.TopNBatch - Took 823658 us to get next
2016-12-19 17:08:25,226 [DATA-rpc-event-queue] DEBUG o.a.drill.exec.rpc.data.DataServer - Sending response with Sender 1301599879
2016-12-19 17:08:25,235 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:8] DEBUG o.a.d.e.physical.impl.TopN.TopNBatch - Took 825192 us to get next
2016-12-19 17:08:25,238 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:14] DEBUG o.a.d.e.t.g.PriorityQueueGen25 - Took 249 us to add 1023 records
2016-12-19 17:08:25,250 [27a7c888-76ad-fbf8-9d8e-79d20935f2ba:frag:1:8] DEBUG o.a.d.e.t.g.PriorityQueueGen25 - Took 227 us to add 1023 records
{code}
> TopN operator on top of ~110 GB data set is very slow
> -----------------------------------------------------
>
> Key: DRILL-5138
> URL: https://issues.apache.org/jira/browse/DRILL-5138
> Project: Apache Drill
> Issue Type: Bug
> Components: Execution - Relational Operators
> Reporter: Rahul Challapalli
>
> git.commit.id.abbrev=cf2b7c7
> No of cores : 23
> No of disks : 5
> DRILL_MAX_DIRECT_MEMORY="24G"
> DRILL_MAX_HEAP="12G"
> The below query ran for more than 4 hours and did not complete. The table is ~110 GB
> {code}
> select * from catalog_sales order by cs_quantity, cs_wholesale_cost limit 1;
> {code}
> Physical Plan :
> {code}
> 00-00 Screen : rowType = RecordType(ANY *): rowcount = 1.0, cumulative cost = {1.00798629141E10 rows, 4.17594320691E10 cpu, 0.0 io, 4.1287118487552E13 network, 0.0 memory}, id = 352
> 00-01 Project(*=[$0]) : rowType = RecordType(ANY *): rowcount = 1.0, cumulative cost = {1.0079862914E10 rows, 4.1759432069E10 cpu, 0.0 io, 4.1287118487552E13 network, 0.0 memory}, id = 351
> 00-02 Project(T0¦¦*=[$0]) : rowType = RecordType(ANY T0¦¦*): rowcount = 1.0, cumulative cost = {1.0079862914E10 rows, 4.1759432069E10 cpu, 0.0 io, 4.1287118487552E13 network, 0.0 memory}, id = 350
> 00-03 SelectionVectorRemover : rowType = RecordType(ANY T0¦¦*, ANY cs_quantity, ANY cs_wholesale_cost): rowcount = 1.0, cumulative cost = {1.0079862914E10 rows, 4.1759432069E10 cpu, 0.0 io, 4.1287118487552E13 network, 0.0 memory}, id = 349
> 00-04 Limit(fetch=[1]) : rowType = RecordType(ANY T0¦¦*, ANY cs_quantity, ANY cs_wholesale_cost): rowcount = 1.0, cumulative cost = {1.0079862913E10 rows, 4.1759432068E10 cpu, 0.0 io, 4.1287118487552E13 network, 0.0 memory}, id = 348
> 00-05 SingleMergeExchange(sort0=[1 ASC], sort1=[2 ASC]) : rowType = RecordType(ANY T0¦¦*, ANY cs_quantity, ANY cs_wholesale_cost): rowcount = 1.439980416E9, cumulative cost = {1.0079862912E10 rows, 4.1759432064E10 cpu, 0.0 io, 4.1287118487552E13 network, 0.0 memory}, id = 347
> 01-01 SelectionVectorRemover : rowType = RecordType(ANY T0¦¦*, ANY cs_quantity, ANY cs_wholesale_cost): rowcount = 1.439980416E9, cumulative cost = {8.639882496E9 rows, 3.0239588736E10 cpu, 0.0 io, 2.3592639135744E13 network, 0.0 memory}, id = 346
> 01-02 TopN(limit=[1]) : rowType = RecordType(ANY T0¦¦*, ANY cs_quantity, ANY cs_wholesale_cost): rowcount = 1.439980416E9, cumulative cost = {7.19990208E9 rows, 2.879960832E10 cpu, 0.0 io, 2.3592639135744E13 network, 0.0 memory}, id = 345
> 01-03 Project(T0¦¦*=[$0], cs_quantity=[$1], cs_wholesale_cost=[$2]) : rowType = RecordType(ANY T0¦¦*, ANY cs_quantity, ANY cs_wholesale_cost): rowcount = 1.439980416E9, cumulative cost = {5.759921664E9 rows, 2.879960832E10 cpu, 0.0 io, 2.3592639135744E13 network, 0.0 memory}, id = 344
> 01-04 HashToRandomExchange(dist0=[[$1]], dist1=[[$2]]) : rowType = RecordType(ANY T0¦¦*, ANY cs_quantity, ANY cs_wholesale_cost, ANY E_X_P_R_H_A_S_H_F_I_E_L_D): rowcount = 1.439980416E9, cumulative cost = {5.759921664E9 rows, 2.879960832E10 cpu, 0.0 io, 2.3592639135744E13 network, 0.0 memory}, id = 343
> 02-01 UnorderedMuxExchange : rowType = RecordType(ANY T0¦¦*, ANY cs_quantity, ANY cs_wholesale_cost, ANY E_X_P_R_H_A_S_H_F_I_E_L_D): rowcount = 1.439980416E9, cumulative cost = {4.319941248E9 rows, 1.1519843328E10 cpu, 0.0 io, 0.0 network, 0.0 memory}, id = 342
> 03-01 Project(T0¦¦*=[$0], cs_quantity=[$1], cs_wholesale_cost=[$2], E_X_P_R_H_A_S_H_F_I_E_L_D=[hash32AsDouble($2, hash32AsDouble($1))]) : rowType = RecordType(ANY T0¦¦*, ANY cs_quantity, ANY cs_wholesale_cost, ANY E_X_P_R_H_A_S_H_F_I_E_L_D): rowcount = 1.439980416E9, cumulative cost = {2.879960832E9 rows, 1.0079862912E10 cpu, 0.0 io, 0.0 network, 0.0 memory}, id = 341
> 03-02 Project(T0¦¦*=[$0], cs_quantity=[$1], cs_wholesale_cost=[$2]) : rowType = RecordType(ANY T0¦¦*, ANY cs_quantity, ANY cs_wholesale_cost): rowcount = 1.439980416E9, cumulative cost = {1.439980416E9 rows, 4.319941248E9 cpu, 0.0 io, 0.0 network, 0.0 memory}, id = 340
> 03-03 Scan(groupscan=[ParquetGroupScan [entries=[ReadEntryWithPath [path=maprfs:///drill/testdata/tpcds/parquet/sf1000/catalog_sales]], selectionRoot=maprfs:/drill/testdata/tpcds/parquet/sf1000/catalog_sales, numFiles=1, usedMetadataFile=false, columns=[`*`]]]) : rowType = (DrillRecordRow[*, cs_quantity, cs_wholesale_cost]): rowcount = 1.439980416E9, cumulative cost = {1.439980416E9 rows, 4.319941248E9 cpu, 0.0 io, 0.0 network, 0.0 memory}, id = 339
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)