[IMPALA-4667] Incorrect timeline reported for queries with long running coordinator fragment

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Not A Problem
• Affects Version/s: Impala 2.8.0
• Component/s: Backend
• Labels: profile supportability
• Assignee: Unassigned
• Reporter: Mostafa Mokhtar
• Created: 15/Dec/16 08:07
• Updated: 02/Oct/18 01:33
• Resolved: 02/Oct/18 01:33

Description

Query profile shows that "Unregister query" ran for 7 seconds

Query

 select *
FROM   (SELECT Rank()
                 OVER( partition by l_linenumber
                   ORDER BY  l_orderkey) AS rank
        FROM   lineitem
        WHERE  l_shipdate < '1992-05-09') a
WHERE  rank < 10

Plan

PLAN-ROOT SINK
|
05:EXCHANGE [UNPARTITIONED]
|  hosts=7 per-host-mem=unavailable
|  tuple-ids=6,5 row-size=50B cardinality=17999891
|
03:SELECT
|  predicates: rank() < 10
|  hosts=7 per-host-mem=0B
|  tuple-ids=6,5 row-size=50B cardinality=17999891
|
02:ANALYTIC
|  functions: rank()
|  partition by: l_linenumber
|  order by: l_orderkey ASC
|  window: RANGE BETWEEN UNBOUNDED PRECEDING AND CURRENT ROW
|  hosts=7 per-host-mem=0B
|  tuple-ids=6,5 row-size=50B cardinality=179998909
|
01:SORT
|  order by: l_linenumber ASC NULLS FIRST, l_orderkey ASC
|  hosts=7 per-host-mem=352.00MB
|  tuple-ids=6 row-size=42B cardinality=179998909
|
04:EXCHANGE [HASH(l_linenumber)]
|  hosts=7 per-host-mem=0B
|  tuple-ids=0 row-size=42B cardinality=179998909
|
00:SCAN HDFS [tpch_300_parquet.lineitem, RANDOM]
   partitions=1/1 files=259 size=63.71GB
   predicates: l_shipdate < '1992-05-09'
   table stats: 1799989091 rows total
   column stats: all
   hosts=7 per-host-mem=264.00MB
   tuple-ids=0 row-size=42B cardinality=179998909

ExecSummary:

Operator       #Hosts   Avg Time   Max Time   #Rows  Est. #Rows   Peak Mem  Est. Peak Mem  Detail                    
---------------------------------------------------------------------------------------------------------------------
05:EXCHANGE         1  156.063us  156.063us      63      18.00M          0        -1.00 B  UNPARTITIONED             
03:SELECT           7   63.424ms  126.486ms      63      18.00M    9.02 MB              0                            
02:ANALYTIC         7    1s582ms    3s140ms  50.88M     180.00M   25.03 MB              0                            
01:SORT             7    4s099ms    8s368ms  50.88M     180.00M  616.07 MB      352.00 MB                            
04:EXCHANGE         7  497.343ms    1s304ms  50.88M     180.00M          0              0  HASH(l_linenumber)        
00:SCAN HDFS        7   89.198ms   94.103ms  50.88M     180.00M    1.21 GB      264.00 MB  tpch_300_parquet.lineitem 

Query timeline

    Planner Timeline: 14.041ms
       - Analysis finished: 2.081ms (2.081ms)
       - Equivalence classes computed: 2.286ms (205.178us)
       - Single node plan created: 8.255ms (5.968ms)
       - Runtime filters computed: 8.308ms (52.728us)
       - Distributed plan created: 8.455ms (147.135us)
       - Lineage info computed: 8.650ms (195.300us)
       - Planning finished: 14.041ms (5.390ms)
    Query Timeline: 13s183ms
       - Query submitted: 37.469us (37.469us)
       - Planning finished: 18.856ms (18.819ms)
       - Submit for admission: 20.020ms (1.163ms)
       - Completed admission: 20.794ms (773.463us)
       - Ready to start 15 fragment instances: 21.443ms (648.888us)
       - All 15 fragment instances started: 33.322ms (11.879ms)
       - Rows available: 5s904ms (5s871ms)
       - First row fetched: 5s985ms (80.483ms)
       - Unregister query: 13s137ms (7s152ms)

This query has the same issue

select l_orderkey from lineitem ORDER BY  l_orderkey limit 1000000

Profile snippet

PLAN-ROOT SINK
|
02:MERGING-EXCHANGE [UNPARTITIONED]
|  order by: l_orderkey ASC
|  limit: 1000000
|  hosts=7 per-host-mem=unavailable
|  tuple-ids=1 row-size=8B cardinality=1000000
|
01:TOP-N [LIMIT=1000000]
|  order by: l_orderkey ASC
|  hosts=7 per-host-mem=7.63MB
|  tuple-ids=1 row-size=8B cardinality=1000000
|
00:SCAN HDFS [tpch_300_parquet.lineitem, RANDOM]
   partitions=1/1 files=259 size=63.71GB
   table stats: 1799989091 rows total
   column stats: all
   hosts=7 per-host-mem=88.00MB
   tuple-ids=0 row-size=8B cardinality=1799989091
----------------
    Estimated Per-Host Mem: 100274688
    Estimated Per-Host VCores: 1
    Request Pool: root.mmokhtar
    Admission result: Admitted immediately
    ExecSummary: 
Operator              #Hosts   Avg Time   Max Time  #Rows  Est. #Rows   Peak Mem  Est. Peak Mem  Detail                    
---------------------------------------------------------------------------------------------------------------------------
02:MERGING-EXCHANGE        1   84.179ms   84.179ms  1.00M       1.00M          0        -1.00 B  UNPARTITIONED             
01:TOP-N                   7    4s215ms    4s352ms  7.00M       1.00M   16.31 MB        7.63 MB                            
00:SCAN HDFS               7  852.720ms  926.640ms  1.80B       1.80B  469.33 MB       88.00 MB  tpch_300_parquet.lineitem 
    Planner Timeline: 17.455ms
       - Analysis finished: 11.134ms (11.134ms)
       - Equivalence classes computed: 11.307ms (173.177us)
       - Single node plan created: 15.293ms (3.986ms)
       - Runtime filters computed: 15.335ms (41.815us)
       - Distributed plan created: 15.434ms (98.882us)
       - Lineage info computed: 15.548ms (113.722us)
       - Planning finished: 17.455ms (1.907ms)
    Query Timeline: 35s420ms
       - Query submitted: 36.365us (36.365us)
       - Planning finished: 21.088ms (21.051ms)
       - Submit for admission: 22.219ms (1.131ms)
       - Completed admission: 22.960ms (740.344us)
       - Ready to start 8 fragment instances: 23.535ms (575.355us)
       - All 8 fragment instances started: 27.952ms (4.416ms)
       - Rows available: 5s388ms (5s360ms)
       - First row fetched: 5s474ms (86.011ms)
       - Unregister query: 35s411ms (29s937ms)
     - ComputeScanRangeAssignmentTimer: 507.269us
  ImpalaServer:
     - ClientFetchWaitTimer: 28s068ms
     - RowMaterializationTimer: 1s953ms