[
https://issues.apache.org/jira/browse/IMPALA-6754?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16708058#comment-16708058
]
Michael Ho commented on IMPALA-6754:
------------------------------------
Things have definitely improved with KRPC. Please find a sample excerpt below:
{noformat}
Operator #Hosts Avg Time Max Time #Rows Est. #Rows Peak Mem
Est. Peak Mem Detail
------------------------------------------------------------------------------------------------------------------------
09:AGGREGATE 1 249.568us 249.568us 1 1 16.00 KB
10.00 MB FINALIZE
08:EXCHANGE 1 45.272us 45.272us 3 1 32.00 KB
16.00 KB UNPARTITIONED
04:AGGREGATE 3 114.728us 140.725us 3 1 16.00 KB
10.00 MB
07:AGGREGATE 3 1.954ms 2.181ms 10 10 1.95 MB
10.00 MB
06:EXCHANGE 3 16.369us 17.213us 10 10 16.00 KB
16.00 KB HASH(a.int_col)
03:AGGREGATE 3 998.326us 1.110ms 10 10 2.09 MB
10.00 MB STREAMING
02:HASH JOIN 3 5s036ms 6s042ms 100 7.30K 1.99 MB
1.94 MB INNER JOIN, BROADCAST
|--05:EXCHANGE 3 63.364us 81.605us 100 100 48.00 KB
16.00 KB BROADCAST
| 01:SCAN HDFS 3 4.197ms 4.988ms 100 100 50.00 KB
32.00 MB functional.alltypessmall b
00:SCAN HDFS 3 35.649ms 44.940ms 7.30K 7.30K 419.00 KB
128.00 MB functional.alltypes a
{noformat}
The exchange node shows a much higher total time, mostly due to the long
arrival time of the first batch.
{noformat}
EXCHANGE_NODE (id=6):(Total: 6s074ms, non-child: 16.886us, % non-child:
0.00%)
- ConvertRowBatchTime: 2.564us
- PeakMemoryUsage: 16.00 KB (16384)
- RowsReturned: 2 (2)
- RowsReturnedRate: 0
Buffer pool:
- AllocTime: 2.118us
- CumulativeAllocationBytes: 16.00 KB (16384)
- CumulativeAllocations: 2 (2)
- PeakReservation: 16.00 KB (16384)
- PeakUnpinnedBytes: 0
- PeakUsedReservation: 16.00 KB (16384)
- ReadIoBytes: 0
- ReadIoOps: 0 (0)
- ReadIoWaitTime: 0.000ns
- WriteIoBytes: 0
- WriteIoOps: 0 (0)
- WriteIoWaitTime: 0.000ns
Dequeue:
BytesDequeued(500.000ms): 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
- FirstBatchWaitTime: 6s074ms
- TotalBytesDequeued: 26.00 B (26)
- TotalGetBatchTime: 6s074ms
- DataWaitTime: 6s074ms
{noformat}
> Exchange node includes FirstBatchArrivalWaitTime in summary
> -----------------------------------------------------------
>
> Key: IMPALA-6754
> URL: https://issues.apache.org/jira/browse/IMPALA-6754
> Project: IMPALA
> Issue Type: Bug
> Components: Backend
> Affects Versions: Impala 2.11.0
> Reporter: Balazs Jeszenszky
> Assignee: Michael Ho
> Priority: Minor
> Labels: observability
>
> In the following execution summary:
> {code:java}
> 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
> [...]
> {code}
> 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:
> {code:java}
> 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
> {code}
> 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.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
