[
https://issues.apache.org/jira/browse/DRILL-4785?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15383276#comment-15383276
]
Dechang Gu commented on DRILL-4785:
-----------------------------------
Reproduced the issue with TPCH data and query.
Commit id 10afc708600ea9f4cb0e7c2cd981b5b1001fea0d: the query takes 1.864 secs
drillbit.log:
2016-07-18 15:31:18,480 ucs-node5.perf.lab
[2872a749-2a71-a4ad-ae64-5539c681ec34:foreman] INFO
o.a.drill.exec.work.foreman.Foreman - Query text for query id
2872a749-2a71-a4ad-ae64-5539c681ec34: SELECT * FROM
(
select
sum(l_extendedprice * l_discount) as revenue
from
lineitem
where
l_shipdate >= date '1997-01-01'
and l_shipdate < date '1997-01-01' + interval '1' year
and
l_discount between 0.03 - 0.01 and 0.03 + 0.01
and l_quantity < 24
)
LZT
LIMIT 0
2016-07-18 15:31:19,141 ucs-node5.perf.lab
[2872a749-2a71-a4ad-ae64-5539c681ec34:foreman] INFO
o.a.d.exec.store.parquet.Metadata - Took 431 ms to read metadata from cache file
2016-07-18 15:31:19,296 ucs-node5.perf.lab
[2872a749-2a71-a4ad-ae64-5539c681ec34:foreman] INFO
o.a.d.exec.store.parquet.Metadata - Took 153 ms to read metadata from cache file
2016-07-18 15:31:19,968 ucs-node5.perf.lab
[2872a749-2a71-a4ad-ae64-5539c681ec34:frag:0:0] INFO
o.a.d.e.w.fragment.FragmentExecutor - 2872a749-2a71-a4ad-ae64-5539c681ec34:0:0:
State change requested AWAITING_ALLOCATION --> RUNNING
2016-07-18 15:31:19,969 ucs-node5.perf.lab
[2872a749-2a71-a4ad-ae64-5539c681ec34:frag:0:0] INFO
o.a.d.e.w.f.FragmentStatusReporter - 2872a749-2a71-a4ad-ae64-5539c681ec34:0:0:
State to report: RUNNING
commit id 9f4fff800d128878094ae70b454201f79976135d: the query takes
0.286 secs
drillbit.log:
2016-07-18 15:42:59,618 ucs-node5.perf.lab
[2872a48c-1221-bef1-32f0-4445a69ef580:foreman] INFO
o.a.drill.exec.work.foreman.Foreman - Query text for query id
2872a48c-1221-bef1-32f0-4445a69ef580: SELECT * FROM
(
select
sum(l_extendedprice * l_discount) as revenue
from
lineitem
where
l_shipdate >= date '1997-01-01'
and l_shipdate < date '1997-01-01' + interval '1' year
and
l_discount between 0.03 - 0.01 and 0.03 + 0.01
and l_quantity < 24
)
LZT
LIMIT 0
2016-07-18 15:42:59,841 ucs-node5.perf.lab
[2872a48c-1221-bef1-32f0-4445a69ef580:frag:0:0] INFO
o.a.d.e.w.fragment.FragmentExecutor - 2872a48c-1221-bef1-32f0-4445a69ef580:0:0:
State change requested AWAITING_ALLOCATION --> RUNNING
2016-07-18 15:42:59,841 ucs-node5.perf.lab
[2872a48c-1221-bef1-32f0-4445a69ef580:frag:0:0] INFO
o.a.d.e.w.f.FragmentStatusReporter - 2872a48c-1221-bef1-32f0-4445a69ef580:0:0:
State to report: RUNNING
2016-07-18 15:42:59,852 ucs-node5.perf.lab
[2872a48c-1221-bef1-32f0-4445a69ef580:frag:0:0] INFO
o.a.d.e.w.fragment.FragmentExecutor - 2872a48c-1221-bef1-32f0-4445a69ef580:0:0:
State change requested RUNNING --> FINISHED
2016-07-18 15:42:59,852 ucs-node5.perf.lab
[2872a48c-1221-bef1-32f0-4445a69ef580:frag:0:0] INFO
o.a.d.e.w.f.FragmentStatusReporter - 2872a48c-1221-bef1-32f0-4445a69ef580:0:0:
State to report: FINISHED
Note that "read metadata from cache file " is where the extra time spent.
> Limit 0 queries regressed in Drill 1.7.0
> -----------------------------------------
>
> Key: DRILL-4785
> URL: https://issues.apache.org/jira/browse/DRILL-4785
> Project: Apache Drill
> Issue Type: Bug
> Components: Functions - Drill
> Affects Versions: 1.7.0
> Environment: Redhat EL6
> Reporter: Dechang Gu
> Assignee: Venki Korukanti
> Fix For: 1.8.0
>
>
> We noticed a bunch of limit 0 queries regressed quite a bit: +2500ms, while
> the same queries took ~400ms in Apache Drill 1.6.0. 5-6X regression. Further
> investigation indicates that most likely the root cause of the regression is
> in the commit:
> vkorukanti committed with vkorukanti DRILL-4446: Support mandatory work
> assignment to endpoint requirement…
> commit id: 10afc708600ea9f4cb0e7c2cd981b5b1001fea0d
> With drill build on this commit, query takes 3095ms
> and in the drillbit.log:
> 2016-07-15 17:27:55,048 ucs-node2.perf.lab
> [28768074-4ed6-a70a-2e6a-add3201ab801:foreman] INFO
> o.a.drill.exec.work.foreman.Foreman - Query text for query id
> 28768074-4ed6-a70a-2e6a-add3201ab801: SELECT * FROM (SELECT
> CAST(EXTRACT(MONTH FROM CAST(`rfm_sales`.`business_date` AS DATE)) AS
> INTEGER) AS `mn_business_date_ok`,AVG((CASE WHEN ((CAST(EXTRACT(YEAR FROM
> CAST(`rfm_sales`.`business_date` AS DATE)) AS INTEGER) = 2014) AND
> (CAST((EXTRACT(MONTH FROM CAST(`rfm_sales`.`business_date` AS DATE)) - 1) / 3
> + 1 AS INTEGER) <= 4)) THEN `rfm_sales`.`pos_netsales` ELSE NULL END)) AS
> `avg_Calculation_CIDBACJBCCCBHDGB_ok`,SUM((CASE WHEN ((CAST(EXTRACT(YEAR FROM
> CAST(`rfm_sales`.`business_date` AS DATE)) AS INTEGER) = 2014) AND
> (CAST((EXTRACT(MONTH FROM CAST(`rfm_sales`.`business_date` AS DATE)) - 1) / 3
> + 1 AS INTEGER) <= 4)) THEN `rfm_sales`.`pos_netsales` ELSE NULL END)) AS
> `sum_Calculation_CIDBACJBCCCBHDGB_ok`,SUM((CASE WHEN ((CAST(EXTRACT(YEAR FROM
> CAST(`rfm_sales`.`business_date` AS DATE)) AS INTEGER) = 2014) AND
> (CAST((EXTRACT(MONTH FROM CAST(`rfm_sales`.`business_date` AS DATE)) - 1) / 3
> + 1 AS INTEGER) <= 4)) THEN 1 ELSE NULL END)) AS
> `sum_Calculation_CJEBBAEBBFADBDFJ_ok`,SUM((CASE WHEN ((CAST(EXTRACT(YEAR FROM
> CAST(`rfm_sales`.`business_date` AS DATE)) AS INTEGER) = 2014) AND
> (CAST((EXTRACT(MONTH FROM CAST(`rfm_sales`.`business_date` AS DATE)) - 1) / 3
> + 1 AS INTEGER) <= 4)) THEN (`rfm_sales`.`pos_comps` +
> `rfm_sales`.`pos_promos`) ELSE NULL END)) AS `sum_Net_Sales__YTD___copy__ok`
> FROM `dfs.xxx`.`views/rfm_sales` `rfm_sales` GROUP BY CAST(EXTRACT(MONTH FROM
> CAST(`rfm_sales`.`business_date` AS DATE)) AS INTEGER)) T LIMIT 0
> 2016-07-15 17:27:55,664 ucs-node2.perf.lab
> [28768074-4ed6-a70a-2e6a-add3201ab801:foreman] INFO
> o.a.d.exec.store.parquet.Metadata - Took 208 ms to read metadata from cache
> file
> 2016-07-15 17:27:56,783 ucs-node2.perf.lab
> [28768074-4ed6-a70a-2e6a-add3201ab801:foreman] INFO
> o.a.d.exec.store.parquet.Metadata - Took 129 ms to read metadata from cache
> file
> 2016-07-15 17:27:57,960 ucs-node2.perf.lab
> [28768074-4ed6-a70a-2e6a-add3201ab801:frag:0:0] INFO
> o.a.d.e.w.fragment.FragmentExecutor -
> 28768074-4ed6-a70a-2e6a-add3201ab801:0:0: State change requested
> AWAITING_ALLOCATION --> RUNNING
> 2016-07-15 17:27:57,961 ucs-node2.perf.lab
> [28768074-4ed6-a70a-2e6a-add3201ab801:frag:0:0] INFO
> o.a.d.e.w.f.FragmentStatusReporter -
> 28768074-4ed6-a70a-2e6a-add3201ab801:0:0: State to report: RUNNING
> 2016-07-15 17:27:57,989 ucs-node2.perf.lab
> [28768074-4ed6-a70a-2e6a-add3201ab801:frag:0:0] INFO
> o.a.d.e.w.fragment.FragmentExecutor -
> 28768074-4ed6-a70a-2e6a-add3201ab801:0:0: State change requested RUNNING -->
> FINISHED
> 2016-07-15 17:27:57,989 ucs-node2.perf.lab
> [28768074-4ed6-a70a-2e6a-add3201ab801:frag:0:0] INFO
> o.a.d.e.w.f.FragmentStatusReporter -
> 28768074-4ed6-a70a-2e6a-add3201ab801:0:0: State to report: FINISHED
> while running the same query on the parent commit (commit id
> 9f4fff800d128878094ae70b454201f79976135d), it only takes 492ms.
> and in the drillbit.log:
> 2016-07-15 17:19:27,309 ucs-node7.perf.lab
> [2876826f-ee19-9466-0c0c-869f47c409f8:foreman] INFO
> o.a.drill.exec.work.foreman.Foreman - Query text for query id
> 2876826f-ee19-9466-0c0c-869f47c409f8: SELECT * FROM (SELECT
> CAST(EXTRACT(MONTH FROM CAST(`rfm_sales`.`business_date` AS DATE)) AS
> INTEGER) AS `mn_business_date_ok`,AVG((CASE WHEN ((CAST(EXTRACT(YEAR FROM
> CAST(`rfm_sales`.`business_date` AS DATE)) AS INTEGER) = 2014) AND
> (CAST((EXTRACT(MONTH FROM CAST(`rfm_sales`.`business_date` AS DATE)) - 1) / 3
> + 1 AS INTEGER) <= 4)) THEN `rfm_sales`.`pos_netsales` ELSE NULL END)) AS
> `avg_Calculation_CIDBACJBCCCBHDGB_ok`,SUM((CASE WHEN ((CAST(EXTRACT(YEAR FROM
> CAST(`rfm_sales`.`business_date` AS DATE)) AS INTEGER) = 2014) AND
> (CAST((EXTRACT(MONTH FROM CAST(`rfm_sales`.`business_date` AS DATE)) - 1) / 3
> + 1 AS INTEGER) <= 4)) THEN `rfm_sales`.`pos_netsales` ELSE NULL END)) AS
> `sum_Calculation_CIDBACJBCCCBHDGB_ok`,SUM((CASE WHEN ((CAST(EXTRACT(YEAR FROM
> CAST(`rfm_sales`.`business_date` AS DATE)) AS INTEGER) = 2014) AND
> (CAST((EXTRACT(MONTH FROM CAST(`rfm_sales`.`business_date` AS DATE)) - 1) / 3
> + 1 AS INTEGER) <= 4)) THEN 1 ELSE NULL END)) AS
> `sum_Calculation_CJEBBAEBBFADBDFJ_ok`,SUM((CASE WHEN ((CAST(EXTRACT(YEAR FROM
> CAST(`rfm_sales`.`business_date` AS DATE)) AS INTEGER) = 2014) AND
> (CAST((EXTRACT(MONTH FROM CAST(`rfm_sales`.`business_date` AS DATE)) - 1) / 3
> + 1 AS INTEGER) <= 4)) THEN (`rfm_sales`.`pos_comps` +
> `rfm_sales`.`pos_promos`) ELSE NULL END)) AS `sum_Net_Sales__YTD___copy__ok`
> FROM `dfs.xxx`.`views/rfm_sales` `rfm_sales` GROUP BY CAST(EXTRACT(MONTH FROM
> CAST(`rfm_sales`.`business_date` AS DATE)) AS INTEGER)) T LIMIT 0
> 2016-07-15 17:19:27,619 ucs-node7.perf.lab
> [2876826f-ee19-9466-0c0c-869f47c409f8:frag:0:0] INFO
> o.a.d.e.w.fragment.FragmentExecutor -
> 2876826f-ee19-9466-0c0c-869f47c409f8:0:0: State change requested
> AWAITING_ALLOCATION --> RUNNING
> 2016-07-15 17:19:27,619 ucs-node7.perf.lab
> [2876826f-ee19-9466-0c0c-869f47c409f8:frag:0:0] INFO
> o.a.d.e.w.f.FragmentStatusReporter -
> 2876826f-ee19-9466-0c0c-869f47c409f8:0:0: State to report: RUNNING
> 2016-07-15 17:19:27,643 ucs-node7.perf.lab
> [2876826f-ee19-9466-0c0c-869f47c409f8:frag:0:0] INFO
> o.a.d.e.w.fragment.FragmentExecutor -
> 2876826f-ee19-9466-0c0c-869f47c409f8:0:0: State change requested RUNNING -->
> FINISHED
> 2016-07-15 17:19:27,644 ucs-node7.perf.lab
> [2876826f-ee19-9466-0c0c-869f47c409f8:frag:0:0] INFO
> o.a.d.e.w.f.FragmentStatusReporter -
> 2876826f-ee19-9466-0c0c-869f47c409f8:0:0: State to report: FINISHED
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
