[IMPALA-5285] Account for missing significant contributors to query time in exec summary

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Component/s: Backend
• Labels: resource-management
• Epic Color: ghx-label-1
• Assignee: Unassigned
• Reporter: Mala Chikka Kempanna
• Created: 05/May/17 20:44
• Updated: 07/Dec/18 15:52

Description

Entire time of query begin-end duration is not accounted for in summary(This is excluding client fetch wait timer)

For eg
1) Start end time is
Start Time: 2017-03-24 09:23:03.131144000
End Time: 2017-03-24 10:54:57.702228000

2) Query exec summary and timelines look like below

    Admission result: Admitted immediately
    ExecSummary: 
Operator       #Hosts  Avg Time  Max Time  #Rows  Est. #Rows   Peak Mem  Est. Peak Mem  Detail                       
---------------------------------------------------------------------------------------------------------------------
04:EXCHANGE         1  17.320us  17.320us      0       1.18B          0        -1.00 B  UNPARTITIONED                
03:AGGREGATE       18     4m35s     5m54s      0       1.18B    5.01 GB        5.99 GB  FINALIZE                     
02:EXCHANGE        18   5s530ms   7s483ms  1.18B       1.18B          0              0  HASH(TRADEDATE,SYMB,EVENTID) 
01:AGGREGATE       18  39s865ms  59s336ms  1.18B       1.18B  170.09 MB       56.95 GB  STREAMING                    
00:SCAN HDFS       18   7s721ms  18s678ms  1.18B       1.18B  213.28 MB      264.00 MB  cif20.dlereference           
    - ComputeScanRangeAssignmentTimer: 835228
    - InactiveTotalTime: 0
    - TotalTime: 0
    Planner Timeline
      Analysis finished: 1768171
      Equivalence classes computed: 1953496
      Single node plan created: 2636132
      Runtime filters computed: 2764237
      Distributed plan created: 3178894
      Lineage info computed: 3297595
      Planning finished: 4567814
    Query Timeline
      Query submitted: 315704
      Planning finished: 8032272
      Submit for admission: 10787376
      Completed admission: 11053424
      Ready to start 37 fragment instances: 12622968
      All 37 fragment instances started: 591275200
      Rows available: 5514496400348
      First row fetched: 5514558703092
      Unregister query: 5514571011444
  ImpalaServer
    - ClientFetchWaitTimer: 68269916
    - InactiveTotalTime: 0
    - RowMaterializationTimer: 6332212
    - TotalTime: 0

I want to call attention to large discrepancy in total time accounted for in summary and timeline to one recorded ad start-end time

This I believe is happening due to not recording fragment receive time in query profiles, which will remove the confusion when reading such profiles.

This large time is listed under each fragment completion times in same profile

    Averaged Fragment F01
      split sizes:  min: 0, max: 0, avg: 0, stddev: 0
      completion times: min:1h31m  max:1h31m  mean: 1h31m  stddev:2s911ms
      execution rates: min:0.00 /sec  max:0.00 /sec  mean:0.00 /sec  stddev:0.00 /sec
      num instances: 18
 
    Averaged Fragment F00
      split sizes:  min: 628.43 MB, max: 1.00 GB, avg: 827.75 MB, stddev: 104.93 MB
      completion times: min:35m18s  max:1h31m  mean: 1h4m  stddev:13m10s
      execution rates: min:184.88 KB/sec  max:303.77 KB/sec  mean:224.86 KB/sec  stddev:30.22 KB/sec
      num instances: 18

Issue Links

• relates to: IMPALA-5397 Set "End Time" earlier rather than on unregistration.
• relates to: IMPALA-1048 Data sinks do not show up in the exec summary