Uploaded image for project: 'IMPALA'
  2. IMPALA-5285

Account for missing significant contributors to query time in exec summary



    • Type: Bug
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: Backend
    • Epic Color:


      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
      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
          - 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



              • Assignee:
                mkempanna Mala Chikka Kempanna
              • Votes:
                0 Vote for this issue
                3 Start watching this issue


                • Created: