[IMPALA-6754] Exchange node includes FirstBatchArrivalWaitTime in summary

• Type: Bug
• Status: Resolved
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: Impala 2.11.0
• Fix Version/s: Impala 2.12.0, Impala 3.1.0
• Component/s: Backend
• Labels: observability
• Epic Color: ghx-label-3
• Assignee: Michael Ho
• Reporter: Balazs Jeszenszky
• Created: 28/Mar/18 09:23
• Updated: 04/Dec/18 01:42
• Resolved: 04/Dec/18 01:42

Description

In the following execution summary:

Operator          #Hosts   Avg Time   Max Time  #Rows  Est. #Rows   Peak Mem  Est. Peak Mem  Detail
-----------------------------------------------------------------------------------------------------------------------------------
15:AGGREGATE           1  141.556us  141.556us      1           1   20.00 KB       10.00 MB  FINALIZE
14:EXCHANGE            1      2h46m      2h46m      1           1          0              0  UNPARTITIONED
09:AGGREGATE           1   16s442ms   16s442ms      1           1  768.00 KB       10.00 MB
08:HASH JOIN           1      1h38m      1h38m  2.63B          -1  122.64 MB        2.00 GB  LEFT OUTER JOIN, BROADCAST
[...]

the timer for the EXCHANGE node is misleading. It's unlikely that sending a single row across network took so long, and individual counters confirm:

      EXCHANGE_NODE (id=14):(Total: 2h46m, non-child: 2h46m, % non-child: 100.00%)
         - ConvertRowBatchTime: 901.000ns
         - PeakMemoryUsage: 0
         - RowsReturned: 1 (1)
         - RowsReturnedRate: 0
        DataStreamReceiver:
           - BytesReceived: 16.00 B (16)
           - DeserializeRowBatchTimer: 4.965us
           - FirstBatchArrivalWaitTime: 2h46m
           - PeakMemoryUsage: 4.01 KB (4104)
           - SendersBlockedTimer: 0.000ns
           - SendersBlockedTotalTimer(*): 0.000ns

In this case, the underlying joins took long (which is correctly reported in the rest of the profile).
Exchange timers should reflect the time it took to transfer rows across network.