Uploaded image for project: 'Apache Drill'
  1. Apache Drill
  2. DRILL-4851

TPCDS Query 64 just hang there at "starting" state

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Duplicate
    • 1.8.0
    • None
    • Functions - Drill
    • None
    • REL 6.0

    Description

      TPC-DS Query 64 on SF100 (views on parquet files) hung there at "starting" state. drillbit.log on the foreman node show the following info:
      2016-08-17 14:26:00,785 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.drill.exec.work.foreman.Foreman - Query text for query id 284b2996-d25a-d9af-178c-143b32ea6969: WITH cs_ui AS (SELECT cs_item_sk, Sum(cs_ext_list_price) AS sale, Sum(cr_refunded_cash + cr_reversed_charge + cr_store_credit) AS refund FROM catalog_sales, catalog_returns WHERE cs_item_sk = cr_item_sk AND cs_order_number = cr_order_number GROUP BY cs_item_sk HAVING Sum(cs_ext_list_price) > 2 * Sum( cr_refunded_cash + cr_reversed_charge + cr_store_credit)), cross_sales AS (SELECT i_product_name product_name, i_item_sk item_sk, s_store_name store_name, s_zip store_zip, ad1.ca_street_number b_street_number, ad1.ca_street_name b_streen_name, ad1.ca_city b_city, ad1.ca_zip b_zip, ad2.ca_street_number c_street_number, ad2.ca_street_name c_street_name, ad2.ca_city c_city, ad2.ca_zip c_zip, d1.d_year AS syear, d2.d_year AS fsyear, d3.d_year s2year, Count cnt, Sum(ss_wholesale_cost) s1, Sum(ss_list_price) s2, Sum(ss_coupon_amt) s3 FROM store_sales, store_returns, cs_ui, date_dim d1, date_dim d2, date_dim d3, store, customer, customer_dd

      emographics cd1, customer_demographics cd2, promotion, household_demographics hd1, household_demographics hd2, customer_address ad1, customer_address ad2, income_band ib1, income_band ib2, item WHERE ss_store_sk = s_stt
      ore_sk AND ss_sold_date_sk = d1.d_date_sk AND ss_customer_sk = c_customer_sk AND ss_cdemo_sk = cd1.cd_demo_sk AND ss_hdemo_sk = hd1.hd_demo_sk AND ss_addr_sk = ad1.ca_address_sk AND ss_item_sk = i_item_sk AND ss_item_skk
      = sr_item_sk AND ss_ticket_number = sr_ticket_number AND ss_item_sk = cs_ui.cs_item_sk AND c_current_cdemo_sk = cd2.cd_demo_sk AND c_current_hdemo_sk = hd2.hd_demo_sk AND c_current_addr_sk = ad2.ca_address_sk AND c_firr
      st_sales_date_sk = d2.d_date_sk AND c_first_shipto_date_sk = d3.d_date_sk AND ss_promo_sk = p_promo_sk AND hd1.hd_income_band_sk = ib1.ib_income_band_sk AND hd2.hd_income_band_sk = ib2.ib_income_band_sk AND cd1.cd_maritt
      al_status <> cd2.cd_marital_status AND i_color IN ( 'cyan', 'peach', 'blush', 'frosted', 'powder', 'orange' ) AND i_current_price BETWEEN 58 AND 58 + 10 AND i_current_price BETWEEN 58 + 1 AND 58 + 15 GROUP BY i_productt
      _name, i_item_sk, s_store_name, s_zip, ad1.ca_street_number, ad1.ca_street_name, ad1.ca_city, ad1.ca_zip, ad2.ca_street_number, ad2.ca_street_name, ad2.ca_city, ad2.ca_zip, d1.d_year, d2.d_year, d3.d_year) SELECT cs1.prr
      oduct_name, cs1.store_name, cs1.store_zip, cs1.b_street_number, cs1.b_streen_name, cs1.b_city, cs1.b_zip, cs1.c_street_number, cs1.c_street_name, cs1.c_city, cs1.c_zip, cs1.syear, cs1.cnt, cs1.s1, cs1.s2, cs1.s3, cs2.s11
      , cs2.s2, cs2.s3, cs2.syear, cs2.cnt FROM cross_sales cs1, cross_sales cs2 WHERE cs1.item_sk = cs2.item_sk AND cs1.syear = 2001 AND cs2.syear = 2001 + 1 AND cs2.cnt <= cs1.cnt AND cs1.store_name = cs2.store_name AND
      cs1.store_zip = cs2.store_zip ORDER BY cs1.product_name, cs1.store_name, cs2.cnt
      2016-08-17 14:26:04,045 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 1 ms to get file statuses
      2016-08-17 14:26:04,051 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1 using 1 threads. Time: 4ms total, 4.753323mm
      s avg, 4ms max.
      2016-08-17 14:26:04,051 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1 using 1 threads. Earliest start: 12.261000
      μs, Latest start: 12.261000 μs, Average start: 12.261000 μs .
      2016-08-17 14:26:04,051 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 6 ms to read file metadata
      2016-08-17 14:26:04,064 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 1 ms to get file statuses
      2016-08-17 14:26:04,068 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1 using 1 threads. Time: 4ms total, 4.302719mm
      s avg, 4ms max.
      2016-08-17 14:26:04,069 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1 using 1 threads. Earliest start: 0.542000 μ
      s, Latest start: 0.542000 μs, Average start: 0.542000 μs .
      2016-08-17 14:26:04,069 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 4 ms to read file metadata
      2016-08-17 14:26:04,704 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 0 ms to get file statuses
      2016-08-17 14:26:04,708 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1 using 1 threads. Time: 3ms total, 3.859318mm
      s avg, 3ms max.
      2016-08-17 14:26:04,708 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1 using 1 threads. Earliest start: 1.152000 μ
      s, Latest start: 1.152000 μs, Average start: 1.152000 μs .
      2016-08-17 14:26:04,708 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 4 ms to read file metadata
      2016-08-17 14:26:05,095 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 1 ms to get file statuses
      2016-08-17 14:26:05,099 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1 using 1 threads. Time: 3ms total, 3.865957mm
      s avg, 3ms max.
      2016-08-17 14:26:05,100 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1 using 1 threads. Earliest start: 1.019000 μ
      s, Latest start: 1.019000 μs, Average start: 1.019000 μs .
      2016-08-17 14:26:05,100 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 4 ms to read file metadata
      2016-08-17 14:26:05,442 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 1 ms to get file statuses
      2016-08-17 14:26:05,446 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1 using 1 threads. Time: 4ms total, 4.249519mm
      s avg, 4ms max.
      2016-08-17 14:26:05,446 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1 using 1 threads. Earliest start: 1.138000 μ
      s, Latest start: 1.138000 μs, Average start: 1.138000 μs .
      2016-08-17 14:26:05,446 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 4 ms to read file metadata
      2016-08-17 14:26:05,795 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 1 ms to get file statuses
      2016-08-17 14:26:05,799 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1 using 1 threads. Time: 3ms total, 3.221330mm
      s avg, 3ms max.
      2016-08-17 14:26:05,799 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1 using 1 threads. Earliest start: 1.054000 μ
      s, Latest start: 1.054000 μs, Average start: 1.054000 μs .
      2016-08-17 14:26:05,799 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 3 ms to read file metadata
      2016-08-17 14:26:06,080 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 1 ms to get file statuses
      239953,1 99%
      2016-08-17 14:26:06,085 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1 using 1 threads. Earliest start: 1.105000 μs, Latest start: 1.105000 μs, Average start: 1.105000 μs .
      2016-08-17 14:26:06,085 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 4 ms to read file metadata
      2016-08-17 14:26:06,216 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 1 ms to get file statuses
      2016-08-17 14:26:06,220 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1 using 1 threads. Time: 3ms total, 3.710791ms avg, 3ms max.
      2016-08-17 14:26:06,220 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1 using 1 threads. Earliest start: 1.153000 μs, Latest start: 1.153000 μs, Average start: 1.153000 μs .
      2016-08-17 14:26:06,220 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 4 ms to read file metadata
      2016-08-17 14:26:06,364 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 2 ms to get file statuses
      2016-08-17 14:26:06,369 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1 using 1 threads. Time: 4ms total, 4.268899ms avg, 4ms max.
      2016-08-17 14:26:06,369 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1 using 1 threads. Earliest start: 1.132000 μs, Latest start: 1.132000 μs, Average start: 1.132000 μs .
      2016-08-17 14:26:06,369 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 4 ms to read file metadata
      2016-08-17 14:26:07,157 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 8 ms to get file statuses
      2016-08-17 14:26:07,188 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 30 out of 30 using 16 threads. Time: 29ms total, 11.629212ms avg, 14ms max.
      2016-08-17 14:26:07,188 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 30 out of 30 using 16 threads. Earliest start: 2437.982000 μs, Latest start: 22245.100000 μs, Average start: 10261.659633 μs .
      2016-08-17 14:26:07,188 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 30 ms to read file metadata
      2016-08-17 14:26:07,233 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 25 ms to get file statuses
      2016-08-17 14:26:07,348 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 166 out of 166 using 16 threads. Time: 114ms total, 10.513099ms avg, 15ms max.
      2016-08-17 14:26:07,349 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 166 out of 166 using 16 threads. Earliest start: 377.260000 μs, Latest start: 107621.105000 μs, Average start: 52540.837259 μs .
      2016-08-17 14:26:07,349 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 115 ms to read file metadata
      2016-08-17 14:26:07,880 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 4 ms to get file statuses
      2016-08-17 14:26:07,911 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 15 out of 15 using 15 threads. Time: 30ms total, 13.056295ms avg, 28ms max.
      2016-08-17 14:26:07,911 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 15 out of 15 using 15 threads. Earliest start: 496.446000 μs, Latest start: 2997.867000 μs, Average start: 2783.290533 μs .
      2016-08-17 14:26:07,911 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 31 ms to read file metadata
      2016-08-17 14:26:07,942 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 21 ms to get file statuses
      2016-08-17 14:26:08,002 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 120 out of 120 using 16 threads. Time: 59ms total, 7.314891ms avg, 11ms max.
      2016-08-17 14:26:08,003 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 120 out of 120 using 16 threads. Earliest start: 377.841000 μs, Latest start: 53615.160000 μs, Average start: 26594.183183 μs .
      2016-08-17 14:26:08,003 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.exec.store.parquet.Metadata - Took 60 ms to read file metadata
      2016-08-17 14:26:08,443 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - Beginning partition pruning, pruning class: org.apache.drill.exec.planner.logical.partition.PruneScanRule$DirPruneScanFilterOnScanRule
      2016-08-17 14:26:08,446 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - No partition columns are projected from the scan..continue. Total pruning elapsed time: 2 ms
      2016-08-17 14:26:08,446 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - Beginning partition pruning, pruning class: org.apache.drill.exec.planner.logical.partition.PruneScanRule$DirPruneScanFilterOnScanRule
      2016-08-17 14:26:08,446 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - No partition columns are projected from the scan..continue. Total pruning elapsed time: 0 ms
      2016-08-17 14:26:08,446 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - Beginning partition pruning, pruning class: org.apache.drill.exec.planner.logical.partition.PruneScanRule$DirPruneScanFilterOnScanRule
      2016-08-17 14:26:08,446 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - No partition columns are projected from the scan..continue. Total pruning elapsed time: 0 ms
      2016-08-17 14:26:08,447 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - Beginning partition pruning, pruning class: org.apache.drill.exec.planner.logical.partition.PruneScanRule$DirPruneScanFilterOnScanRule
      2016-08-17 14:26:08,447 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - No partition columns are projected from the scan..continue. Total pruning elapsed time: 0 ms
      2016-08-17 14:26:08,448 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - Beginning partition pruning, pruning class: org.apache.drill.exec.planner.logical.partition.ParquetPruneScanRule$2
      2016-08-17 14:26:08,448 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - No partition columns are projected from the scan..continue. Total pruning elapsed time: 0 ms
      2016-08-17 14:26:08,448 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - Beginning partition pruning, pruning class: org.apache.drill.exec.planner.logical.partition.ParquetPruneScanRule$2
      2016-08-17 14:26:08,449 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - No partition columns are projected from the scan..continue. Total pruning elapsed time: 0 ms
      2016-08-17 14:26:08,449 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - Beginning partition pruning, pruning class: org.apache.drill.exec.planner.logical.partition.ParquetPruneScanRule$2
      2016-08-17 14:26:08,449 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - No partition columns are projected from the scan..continue. Total pruning elapsed time: 0 ms
      2016-08-17 14:26:08,449 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - Beginning partition pruning, pruning class: org.apache.drill.exec.planner.logical.partition.ParquetPruneScanRule$2
      2016-08-17 14:26:08,449 ucs-node4.perf.lab [284b2996-d25a-d9af-178c-143b32ea6969:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - No partition columns are projected from the scan..continue. Total pruning elapsed time: 0 ms

      This is on 1.8.0 master
      commit id: 0a4c21cc15329c063f256f6fbf2c4c69a90d9fa1

      The same query runs fine on the same database, using Drill 1.6.0 release

      Attachments

        Issue Links

          Activity

            People

              jni Jinfeng Ni
              dechanggu Dechang Gu
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: