[IMPALA-6694] BufferPool appears misaligned in query profile

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: Impala 3.0, Impala 2.12.0
• Fix Version/s: Impala 3.0, Impala 2.12.0
• Component/s: Backend
• Target Version: Impala 2.12.0
• Epic Color: ghx-label-1
• Assignee: Tim Armstrong
• Reporter: Michael Ho
• Created: 17/Mar/18 01:47
• Updated: 31/Mar/18 23:35
• Resolved: 29/Mar/18 22:30

Description

It appears that the buffer pool statistics of exec node is sometimes misaligned in the profile. For instance, the aggregation node's buffer pool appears after the exchange node below:

AGGREGATION_NODE (id=101):(Total: 120.713ms, non-child: 7.815ms, % non-child: 6.47%)
           - BuildTime: 934.375us
           - GetResultsTime: 4.245ms
           - HTResizeTime: 2.644us
           - HashBuckets: 16.38K (16384)
           - LargestPartitionPercent: 7 (7)
           - MaxPartitionLevel: 0 (0)
           - NumRepartitions: 0 (0)
           - PartitionsCreated: 16 (16)
           - PeakMemoryUsage: 1.99 MB (2082944)
           - RowsRepartitioned: 0 (0)
           - RowsReturned: 399 (399)
           - RowsReturnedRate: 3.32 K/sec
           - SpilledPartitions: 0 (0)
        EXCHANGE_NODE (id=100):(Total: 112.897ms, non-child: 112.897ms, % non-child: 100.00%)
           - ConvertRowBatchTime: 69.267us
           - PeakMemoryUsage: 160.00 KB (163840)
           - RowsReturned: 421 (421)
           - RowsReturnedRate: 3.74 K/sec
          Buffer pool:
             - AllocTime: 37.231us
             - CumulativeAllocationBytes: 202.67 KB (207530)
             - CumulativeAllocations: 12 (12)
             - PeakReservation: 160.00 KB (163840)
             - PeakUnpinnedBytes: 0
             - PeakUsedReservation: 160.00 KB (163840)
             - ReadIoBytes: 0
             - ReadIoOps: 0 (0)
             - ReadIoWaitTime: 0.000ns
             - WriteIoBytes: 0
             - WriteIoOps: 0 (0)
             - WriteIoWaitTime: 0.000ns
          RecvrSide:
             - FirstBatchArrivalWaitTime: 64.009ms
             - TotalBytesReceived: 98.23 KB (100588)
             - TotalGetBatchTime: 112.773ms
               - DataArrivalTimer: 112.732ms
          SenderSide:
             - DeserializeRowBatchTime: 261.039us
             - NumBatchesArrived: 6 (6)
             - NumBatchesDeferred: 0 (0)
             - NumBatchesEnqueued: 6 (6)
             - NumBatchesReceived: 6 (6)
             - NumEarlySenders: 0 (0)
             - NumEosReceived: 3 (3)
          Buffer pool:
             - AllocTime: 28.534us
             - CumulativeAllocationBytes: 1.25 MB (1310720)
             - CumulativeAllocations: 20 (20)
             - PeakReservation: 1.94 MB (2031616)
             - PeakUnpinnedBytes: 0
             - PeakUsedReservation: 1.25 MB (1310720)
             - ReadIoBytes: 0
             - ReadIoOps: 0 (0)
             - ReadIoWaitTime: 0.000ns
             - WriteIoBytes: 0
             - WriteIoOps: 0 (0)
             - WriteIoWaitTime: 0.000ns
        AGGREGATION_NODE (id=111):(Total: 7.688ms, non-child: 7.587ms, % non-child: 98.68%)
           - BuildTime: 788.577us
           - GetResultsTime: 4.245ms
           - HTResizeTime: 959.000ns
           - HashBuckets: 16.38K (16384)
           - LargestPartitionPercent: 7 (7)
           - MaxPartitionLevel: 0 (0)
           - NumRepartitions: 0 (0)
           - PartitionsCreated: 16 (16)
           - PeakMemoryUsage: 1.97 MB (2065536)
           - RowsRepartitioned: 0 (0)
           - RowsReturned: 399 (399)
           - RowsReturnedRate: 53.59 K/sec
           - SpilledPartitions: 0 (0)
        EXCHANGE_NODE (id=110):(Total: 101.784us, non-child: 101.784us, % non-child: 100.00%)
           - ConvertRowBatchTime: 56.804us
           - PeakMemoryUsage: 186.67 KB (191146)
           - RowsReturned: 421 (421)
           - RowsReturnedRate: 4.40 M/sec
          Buffer pool:
             - AllocTime: 32.337us
             - CumulativeAllocationBytes: 186.67 KB (191146)
             - CumulativeAllocations: 12 (12)
             - PeakReservation: 186.67 KB (191146)
             - PeakUnpinnedBytes: 0
             - PeakUsedReservation: 186.67 KB (191146)
             - ReadIoBytes: 0
             - ReadIoOps: 0 (0)
             - ReadIoWaitTime: 0.000ns
             - WriteIoBytes: 0
             - WriteIoOps: 0 (0)
             - WriteIoWaitTime: 0.000ns
          RecvrSide:
             - FirstBatchArrivalWaitTime: 0.000ns
             - TotalBytesReceived: 85.93 KB (87989)
             - TotalGetBatchTime: 21.294us
               - DataArrivalTimer: 0.000ns
          SenderSide:
             - DeserializeRowBatchTime: 231.593us
             - NumBatchesArrived: 6 (6)
             - NumBatchesDeferred: 0 (0)
             - NumBatchesEnqueued: 6 (6)
             - NumBatchesReceived: 6 (6)
             - NumEarlySenders: 0 (0)
             - NumEosReceived: 3 (3)
          Buffer pool:
             - AllocTime: 28.224us
             - CumulativeAllocationBytes: 1.25 MB (1310720)
             - CumulativeAllocations: 20 (20)
             - PeakReservation: 1.94 MB (2031616)
             - PeakUnpinnedBytes: 0
             - PeakUsedReservation: 1.25 MB (1310720)
             - ReadIoBytes: 0
             - ReadIoOps: 0 (0)
             - ReadIoWaitTime: 0.000ns
             - WriteIoBytes: 0
             - WriteIoOps: 0 (0)
             - WriteIoWaitTime: 0.000ns

cc'ing [e-mail]], mmokhtar