[IMPALA-5682] Freeing memory from other plan nodes in RowBatch::Reset() results in confusing execution time breakdown

• Type: Improvement
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: Impala 2.9.0
• Component/s: Perf Investigation
• Target Version: Product Backlog
• Epic Color: ghx-label-4
• Assignee: Unassigned
• Reporter: Alan Choi
• Created: 19/Jul/17 16:53
• Updated: 06/Mar/18 18:50

Description

Even after IMPALA-4923 is fixed, query execution time is unaccounted for in an extremely selective query. See this query profile extract:

SORT_NODE (id=1):(Total: 1s436ms, non-child: 416.017ms, % non-child: 28.96%)
ExecOption: Codegen Enabled

• InMemorySortTime: 165.000ns
• InitialRunsCreated: 1 (1)
• PeakMemoryUsage: 32.07 MB (33626999)
• RowsReturned: 0 (0)
• RowsReturnedRate: 0
• SortDataSize: 0
• SpilledRuns: 0 (0)
• TotalMergesPerformed: 0 (0)
  HDFS_SCAN_NODE (id=0):(Total: 1s020ms, non-child: 1s020ms, % non-child: 100.00%)
  Hdfs split stats (<volume id>:<# splits>/<split lengths>): 2:9/2.25 GB 0:3/600.90 MB 1:4/685.12 MB
  ExecOption: PARQUET Codegen Enabled, Codegen enabled: 16 out of 16
  Hdfs Read Thread Concurrency Bucket: 0:100% 1:0% 2:0% 3:0% 4:0% 5:0% 6:0%
  File Formats: PARQUET/SNAPPY:16
  BytesRead(500.000ms): 0, 1.37 GB, 2.70 GB
• FooterProcessingTime: (Avg: 3.065ms ; Min: 712.185us ; Max: 12.901ms ; Number of samples: 16)
• AverageHdfsReadThreadConcurrency: 0.00
• AverageScannerThreadConcurrency: 7.50
• BytesRead: 3.51 GB (3763724319)
• BytesReadDataNodeCache: 0
• BytesReadLocal: 3.51 GB (3763724319)
• BytesReadRemoteUnexpected: 0
• BytesReadShortCircuit: 3.51 GB (3763724319)
• DecompressionTime: 7s321ms
• MaxCompressedTextFileLength: 0
• NumColumns: 1 (1)
• NumDictFilteredRowGroups: 0 (0)
• NumDisksAccessed: 3 (3)
• NumRowGroups: 16 (16)
• NumScannerThreadsStarted: 8 (8)
• NumScannersWithNoReads: 0 (0)
• NumStatsFilteredRowGroups: 0 (0)
• PeakMemoryUsage: 361.49 MB (379053770)
• PerReadThreadRawHdfsThroughput: 2.25 GB/sec
• RemoteScanRanges: 0 (0)
• RowBatchQueueGetWaitTime: 1s016ms
• RowBatchQueuePutWaitTime: 0.000ns
• RowsRead: 103.96M (103960000)
• RowsReturned: 0 (0)
• RowsReturnedRate: 0
• ScanRangesComplete: 16 (16)
• ScannerThreadsInvoluntaryContextSwitches: 2.80K (2797)
• ScannerThreadsTotalWallClockTime: 9s918ms
• MaterializeTupleTime: 1s773ms
• ScannerThreadsSysTime: 724.000ms
• ScannerThreadsUserTime: 7s536ms
• ScannerThreadsVoluntaryContextSwitches: 395 (395)
• TotalRawHdfsReadTime: 1s555ms
• TotalReadThroughput: 1.80 GB/sec

The sort node has processed zero rows but still spent ~500ms.