[IMPALA-4608] Fragment instance completion times can be very wrong

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: Impala 2.8.0
• Fix Version/s: Impala 2.8.0
• Component/s: Backend
• Target Version: Impala 2.8.0
• Assignee: Henry Robinson
• Reporter: Henry Robinson
• Created: 07/Dec/16 00:46
• Updated: 09/Dec/16 02:54
• Resolved: 09/Dec/16 02:54

Description

(See IMPALA-4511 for the original report)

Fragment with table sink has incorrect timings as well. 14125_TableSinkProfile.txt

    Averaged Fragment F00:(Total: 38.946ms, non-child: 0.000ns, % non-child: 0.00%)
      split sizes:  min: 39.27 MB, max: 84.67 MB, avg: 47.67 MB, stddev: 15.36 MB
      completion times: min:2562047h47m  max:-9223372036854775808.000ns  mean: -nanns  stddev:0.000ns
      execution rates: min:8589934592.00 GB/sec  max:-9223372036854775808.00 B/sec  mean:-nan B/sec  stddev:0.00 /sec
      num instances: 13
       - AverageThreadTokens: 1.83 
       - BloomFilterBytes: 0
       - InvoluntaryContextSwitches: 397 (397)
       - PeakMemoryUsage: 133.62 MB (140110965)
       - PerHostPeakMemUsage: 133.62 MB (140110965)
       - RowsProduced: 923.08K (923076)
       - TotalNetworkReceiveTime: 0.000ns
       - TotalNetworkSendTime: 0.000ns
       - TotalStorageWaitTime: 53.426ms
       - TotalWallClockTime: 4s353ms
         - SysTime: 239.962ms
         - UserTime: 2s314ms
       - VoluntaryContextSwitches: 1.52K (1517)
      Fragment Instance Lifecycle Timings:
         - ExecTime: 2s294ms
           - ExecTreeExecTime: 74.614ms
         - OpenTime: 14.390ms
           - ExecTreeOpenTime: 37.820us
         - PrepareTime: 24.490ms
           - ExecTreePrepareTime: 149.684us
      BlockMgr:
         - BlockWritesOutstanding: 0 (0)
         - BlocksCreated: 0 (0)
         - BlocksRecycled: 0 (0)
         - BufferedPins: 0 (0)
         - BytesWritten: 0
         - MaxBlockSize: 8.00 MB (8388608)
         - MemoryLimit: 80.00 GB (85899345920)
         - PeakMemoryUsage: 0
         - ScratchFileUsedBytes: 0
         - TotalBufferWaitTime: 0.000ns
         - TotalEncryptionTime: 0.000ns
         - TotalReadBlockTime: 0.000ns
      HdfsTableSink:(Total: 2s169ms, non-child: 2s169ms, % non-child: 100.00%)
         - BytesWritten: 47.21 MB (49505546)
         - CompressTimer: 260.018ms
         - EncodeTimer: 1s680ms
         - FilesCreated: 1 (1)
         - FinalizePartitionFileTimer: 445.748ms
         - HdfsWriteTimer: 253.939ms
         - PartitionsCreated: 1 (1)
         - PeakMemoryUsage: 60.00 MB (62910135)
         - RowsInserted: 923.08K (923076)
         - TmpFileCreateTimer: 41.257ms