[Impala-ASF-CR] IMPALA-9128: part 1: log on slow data stream RPCs
Impala Public Jenkins has submitted this change and it was merged. (
http://gerrit.cloudera.org:8080/14662 )
Change subject: IMPALA-9128: part 1: log on slow data stream RPCs
..
IMPALA-9128: part 1: log on slow data stream RPCs
Allows modifying the threshold for KRPC's server-side slow
RPC logging (which is enabled for all KRPCs).
Added additional logging for data stream RPCs TransmitData
and EndDataStream, and for slow waits that delay the query.
Adds statistics for RPC time to provide some clues if there
are slow data stream RPCs.
I tested this with a low threshold and delays added:
start-impala-cluster.py \
--impalad_args=--impala_slow_rpc_threshold_ms=1 \
--impalad_args=--debug_actions=END_DATA_STREAM_DELAY:JITTER@3000@1.0
Example Profile output:
- NetworkThroughput: (Avg: 102.98 MB/sec ; Min: 5.58 MB/sec ; Max: 171.79
MB/sec ; Number of samples: 296)
- RpcNetworkTime: (Avg: 13.468ms ; Min: 91.309us ; Max: 2s395ms ; Number of
samples: 299)
- RpcRecvrTime: (Avg: 13.406ms ; Min: 83.160us ; Max: 2s395ms ; Number of
samples: 299)
Example log output (with log threshold of 1ms):
I1107 14:33:50.487251 24933 krpc-data-stream-sender.cc:363]
ad4fa70619170ace:b58b2eba0006] Long delay waiting for RPC to
127.0.1.1:27000 (fragment_instance_id=ad4fa70619170ace:b58b2eba): took
451.036ms
I1107 14:33:51.295518 21361 rpcz_store.cc:265] Call
impala.DataStreamService.EndDataStream from 127.0.0.1:43952 (request call id
82) took 1259ms. Request Metrics: {}
I1107 14:33:44.843204 21332 krpc-data-stream-sender.cc:342] Slow TransmitData
RPC to 127.0.1.1:27000
(fragment_instance_id=ad4fa70619170ace:b58b2eba0006): took 2.194ms.
Receiver time: 457.902us Network time: 1.736ms
I1107 14:33:45.139068 21333 krpc-data-stream-sender.cc:342] Slow EndDataStream
RPC to 127.0.1.1:27001
(fragment_instance_id=ad4fa70619170ace:b58b2eba0004): took 61.340ms.
Receiver time: 81.908us Network time: 61.259ms
Change-Id: I258ac91b9fbbdbc86d0e8091c34f511f8957c4cd
Reviewed-on: http://gerrit.cloudera.org:8080/14662
Reviewed-by: Impala Public Jenkins
Tested-by: Impala Public Jenkins
---
M be/src/common/global-flags.cc
M be/src/rpc/rpc-mgr.cc
M be/src/runtime/krpc-data-stream-sender.cc
M be/src/runtime/krpc-data-stream-sender.h
4 files changed, 87 insertions(+), 4 deletions(-)
Approvals:
Impala Public Jenkins: Looks good to me, approved; Verified
--
To view, visit http://gerrit.cloudera.org:8080/14662
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: merged
Gerrit-Change-Id: I258ac91b9fbbdbc86d0e8091c34f511f8957c4cd
Gerrit-Change-Number: 14662
Gerrit-PatchSet: 6
Gerrit-Owner: Tim Armstrong
Gerrit-Reviewer: Impala Public Jenkins
Gerrit-Reviewer: Lars Volker
Gerrit-Reviewer: Thomas Tauber-Marshall
Gerrit-Reviewer: Tim Armstrong
Gerrit-Reviewer: Todd Lipcon
[Impala-ASF-CR] IMPALA-9128: part 1: log on slow data stream RPCs
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/14662 ) Change subject: IMPALA-9128: part 1: log on slow data stream RPCs .. Patch Set 5: Verified+1 -- To view, visit http://gerrit.cloudera.org:8080/14662 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I258ac91b9fbbdbc86d0e8091c34f511f8957c4cd Gerrit-Change-Number: 14662 Gerrit-PatchSet: 5 Gerrit-Owner: Tim Armstrong Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Lars Volker Gerrit-Reviewer: Thomas Tauber-Marshall Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Todd Lipcon Gerrit-Comment-Date: Tue, 12 Nov 2019 23:36:31 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-9128: part 1: log on slow data stream RPCs
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/14662 ) Change subject: IMPALA-9128: part 1: log on slow data stream RPCs .. Patch Set 5: Code-Review+2 -- To view, visit http://gerrit.cloudera.org:8080/14662 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I258ac91b9fbbdbc86d0e8091c34f511f8957c4cd Gerrit-Change-Number: 14662 Gerrit-PatchSet: 5 Gerrit-Owner: Tim Armstrong Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Lars Volker Gerrit-Reviewer: Thomas Tauber-Marshall Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Todd Lipcon Gerrit-Comment-Date: Tue, 12 Nov 2019 19:05:41 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-9128: part 1: log on slow data stream RPCs
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/14662 ) Change subject: IMPALA-9128: part 1: log on slow data stream RPCs .. Patch Set 5: Build started: https://jenkins.impala.io/job/gerrit-verify-dryrun/5202/ DRY_RUN=false -- To view, visit http://gerrit.cloudera.org:8080/14662 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I258ac91b9fbbdbc86d0e8091c34f511f8957c4cd Gerrit-Change-Number: 14662 Gerrit-PatchSet: 5 Gerrit-Owner: Tim Armstrong Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Lars Volker Gerrit-Reviewer: Thomas Tauber-Marshall Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Todd Lipcon Gerrit-Comment-Date: Tue, 12 Nov 2019 19:05:42 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-9128: part 1: log on slow data stream RPCs
Thomas Tauber-Marshall has posted comments on this change. (
http://gerrit.cloudera.org:8080/14662 )
Change subject: IMPALA-9128: part 1: log on slow data stream RPCs
..
Patch Set 4:
(1 comment)
http://gerrit.cloudera.org:8080/#/c/14662/4/be/src/runtime/krpc-data-stream-sender.cc
File be/src/runtime/krpc-data-stream-sender.cc:
http://gerrit.cloudera.org:8080/#/c/14662/4/be/src/runtime/krpc-data-stream-sender.cc@374
PS4, Line 374: if (IsSlowRpc(elapsed_time_ns)) {
> I don't think so, I was thinking that it might be useful to directly track
Got it. I think its probably fine - if we're triggering this logging, something
is probably going on that needs to be addressed anyways, so a little extra
noise in the logs isn't necessary a bad thing
--
To view, visit http://gerrit.cloudera.org:8080/14662
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I258ac91b9fbbdbc86d0e8091c34f511f8957c4cd
Gerrit-Change-Number: 14662
Gerrit-PatchSet: 4
Gerrit-Owner: Tim Armstrong
Gerrit-Reviewer: Impala Public Jenkins
Gerrit-Reviewer: Lars Volker
Gerrit-Reviewer: Thomas Tauber-Marshall
Gerrit-Reviewer: Tim Armstrong
Gerrit-Reviewer: Todd Lipcon
Gerrit-Comment-Date: Tue, 12 Nov 2019 19:01:08 +
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-9128: part 1: log on slow data stream RPCs
Tim Armstrong has posted comments on this change. (
http://gerrit.cloudera.org:8080/14662 )
Change subject: IMPALA-9128: part 1: log on slow data stream RPCs
..
Patch Set 4:
(1 comment)
http://gerrit.cloudera.org:8080/#/c/14662/4/be/src/runtime/krpc-data-stream-sender.cc
File be/src/runtime/krpc-data-stream-sender.cc:
http://gerrit.cloudera.org:8080/#/c/14662/4/be/src/runtime/krpc-data-stream-sender.cc@374
PS4, Line 374: if (IsSlowRpc(elapsed_time_ns)) {
> Are there rpcs that this will log for that we wouldn't have noticed were sl
I don't think so, I was thinking that it might be useful to directly track the
amount of time spent waiting, since if this triggers it proves that it blocked
the sender thread (in theory a slow RPC might not block the sender if the
sender if running very slow). But I guess that's probably not super-useful,
since a slow RPC is likely to be a symptom of something regardless - I can
remove it if you think it's not worth the extra noise.
--
To view, visit http://gerrit.cloudera.org:8080/14662
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I258ac91b9fbbdbc86d0e8091c34f511f8957c4cd
Gerrit-Change-Number: 14662
Gerrit-PatchSet: 4
Gerrit-Owner: Tim Armstrong
Gerrit-Reviewer: Impala Public Jenkins
Gerrit-Reviewer: Lars Volker
Gerrit-Reviewer: Thomas Tauber-Marshall
Gerrit-Reviewer: Tim Armstrong
Gerrit-Reviewer: Todd Lipcon
Gerrit-Comment-Date: Tue, 12 Nov 2019 18:56:56 +
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-9128: part 1: log on slow data stream RPCs
Thomas Tauber-Marshall has posted comments on this change. (
http://gerrit.cloudera.org:8080/14662 )
Change subject: IMPALA-9128: part 1: log on slow data stream RPCs
..
Patch Set 4: Code-Review+2
(2 comments)
http://gerrit.cloudera.org:8080/#/c/14662/1/be/src/runtime/krpc-data-stream-sender.h
File be/src/runtime/krpc-data-stream-sender.h:
http://gerrit.cloudera.org:8080/#/c/14662/1/be/src/runtime/krpc-data-stream-sender.h@225
PS1, Line 225: RuntimeProfile::SummaryStatsCounter* recvr_time_stats_ =
nullptr;
> I think you're right on that one - it looks like the timer starts when the
Looks like you've decided to tackle this by leaving 'receiver_latency_ns' alone
and doing the tracing in a follow up patch? That works for me
http://gerrit.cloudera.org:8080/#/c/14662/4/be/src/runtime/krpc-data-stream-sender.cc
File be/src/runtime/krpc-data-stream-sender.cc:
http://gerrit.cloudera.org:8080/#/c/14662/4/be/src/runtime/krpc-data-stream-sender.cc@374
PS4, Line 374: if (IsSlowRpc(elapsed_time_ns)) {
Are there rpcs that this will log for that we wouldn't have noticed were slow
in ...CompleteCB?
--
To view, visit http://gerrit.cloudera.org:8080/14662
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I258ac91b9fbbdbc86d0e8091c34f511f8957c4cd
Gerrit-Change-Number: 14662
Gerrit-PatchSet: 4
Gerrit-Owner: Tim Armstrong
Gerrit-Reviewer: Impala Public Jenkins
Gerrit-Reviewer: Lars Volker
Gerrit-Reviewer: Thomas Tauber-Marshall
Gerrit-Reviewer: Tim Armstrong
Gerrit-Reviewer: Todd Lipcon
Gerrit-Comment-Date: Tue, 12 Nov 2019 18:48:02 +
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-9128: part 1: log on slow data stream RPCs
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/14662 ) Change subject: IMPALA-9128: part 1: log on slow data stream RPCs .. Patch Set 4: Build Successful https://jenkins.impala.io/job/gerrit-code-review-checks/4991/ : Initial code review checks passed. Use gerrit-verify-dryrun-external or gerrit-verify-dryrun to run full precommit tests. -- To view, visit http://gerrit.cloudera.org:8080/14662 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I258ac91b9fbbdbc86d0e8091c34f511f8957c4cd Gerrit-Change-Number: 14662 Gerrit-PatchSet: 4 Gerrit-Owner: Tim Armstrong Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Lars Volker Gerrit-Reviewer: Thomas Tauber-Marshall Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Todd Lipcon Gerrit-Comment-Date: Fri, 08 Nov 2019 21:31:02 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-9128: part 1: log on slow data stream RPCs
Hello Thomas Tauber-Marshall, Lars Volker, Todd Lipcon, Impala Public Jenkins,
I'd like you to reexamine a change. Please visit
http://gerrit.cloudera.org:8080/14662
to look at the new patch set (#4).
Change subject: IMPALA-9128: part 1: log on slow data stream RPCs
..
IMPALA-9128: part 1: log on slow data stream RPCs
Allows modifying the threshold for KRPC's server-side slow
RPC logging (which is enabled for all KRPCs).
Added additional logging for data stream RPCs TransmitData
and EndDataStream, and for slow waits that delay the query.
Adds statistics for RPC time to provide some clues if there
are slow data stream RPCs.
I tested this with a low threshold and delays added:
start-impala-cluster.py \
--impalad_args=--impala_slow_rpc_threshold_ms=1 \
--impalad_args=--debug_actions=END_DATA_STREAM_DELAY:JITTER@3000@1.0
Example Profile output:
- NetworkThroughput: (Avg: 102.98 MB/sec ; Min: 5.58 MB/sec ; Max: 171.79
MB/sec ; Number of samples: 296)
- RpcNetworkTime: (Avg: 13.468ms ; Min: 91.309us ; Max: 2s395ms ; Number of
samples: 299)
- RpcRecvrTime: (Avg: 13.406ms ; Min: 83.160us ; Max: 2s395ms ; Number of
samples: 299)
Example log output (with log threshold of 1ms):
I1107 14:33:50.487251 24933 krpc-data-stream-sender.cc:363]
ad4fa70619170ace:b58b2eba0006] Long delay waiting for RPC to
127.0.1.1:27000 (fragment_instance_id=ad4fa70619170ace:b58b2eba): took
451.036ms
I1107 14:33:51.295518 21361 rpcz_store.cc:265] Call
impala.DataStreamService.EndDataStream from 127.0.0.1:43952 (request call id
82) took 1259ms. Request Metrics: {}
I1107 14:33:44.843204 21332 krpc-data-stream-sender.cc:342] Slow TransmitData
RPC to 127.0.1.1:27000
(fragment_instance_id=ad4fa70619170ace:b58b2eba0006): took 2.194ms.
Receiver time: 457.902us Network time: 1.736ms
I1107 14:33:45.139068 21333 krpc-data-stream-sender.cc:342] Slow EndDataStream
RPC to 127.0.1.1:27001
(fragment_instance_id=ad4fa70619170ace:b58b2eba0004): took 61.340ms.
Receiver time: 81.908us Network time: 61.259ms
Change-Id: I258ac91b9fbbdbc86d0e8091c34f511f8957c4cd
---
M be/src/common/global-flags.cc
M be/src/rpc/rpc-mgr.cc
M be/src/runtime/krpc-data-stream-sender.cc
M be/src/runtime/krpc-data-stream-sender.h
4 files changed, 87 insertions(+), 4 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/62/14662/4
--
To view, visit http://gerrit.cloudera.org:8080/14662
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I258ac91b9fbbdbc86d0e8091c34f511f8957c4cd
Gerrit-Change-Number: 14662
Gerrit-PatchSet: 4
Gerrit-Owner: Tim Armstrong
Gerrit-Reviewer: Impala Public Jenkins
Gerrit-Reviewer: Lars Volker
Gerrit-Reviewer: Thomas Tauber-Marshall
Gerrit-Reviewer: Tim Armstrong
Gerrit-Reviewer: Todd Lipcon
[Impala-ASF-CR] IMPALA-9128: part 1: log on slow data stream RPCs
Hello Thomas Tauber-Marshall, Lars Volker, Todd Lipcon, Impala Public Jenkins,
I'd like you to reexamine a change. Please visit
http://gerrit.cloudera.org:8080/14662
to look at the new patch set (#3).
Change subject: IMPALA-9128: part 1: log on slow data stream RPCs
..
IMPALA-9128: part 1: log on slow data stream RPCs
Allows modifying the threshold for KRPC's server-side slow
RPC logging (which is enabled for all KRPCs).
Added additional logging for data stream RPCs TransmitData
and EndDataStream, and for slow waits that delay the query.
Adds statistics for RPC time to provide some clues if there
are slow data stream RPCs.
I tested this with a low threshold and delays added:
start-impala-cluster.py \
--impalad_args=--impala_slow_rpc_threshold_ms=1 \
--impalad_args=--debug_actions=END_DATA_STREAM_DELAY:JITTER@3000@1.0
Example Profile output:
- NetworkThroughput: (Avg: 102.98 MB/sec ; Min: 5.58 MB/sec ; Max: 171.79
MB/sec ; Number of samples: 296)
- RpcNetworkTime: (Avg: 13.468ms ; Min: 91.309us ; Max: 2s395ms ; Number of
samples: 299)
- RpcRecvrTime: (Avg: 13.406ms ; Min: 83.160us ; Max: 2s395ms ; Number of
samples: 299)
Example log output (with log threshold of 1ms):
I1107 14:33:50.487251 24933 krpc-data-stream-sender.cc:363]
ad4fa70619170ace:b58b2eba0006] Long delay waiting for RPC to
127.0.1.1:27000 (fragment_instance_id=ad4fa70619170ace:b58b2eba): took
451.036ms
I1107 14:33:51.295518 21361 rpcz_store.cc:265] Call
impala.DataStreamService.EndDataStream from 127.0.0.1:43952 (request call id
82) took 1259ms. Request Metrics: {}
I1107 14:33:44.843204 21332 krpc-data-stream-sender.cc:342] Slow TransmitData
RPC to 127.0.1.1:27000
(fragment_instance_id=ad4fa70619170ace:b58b2eba0006): took 2.194ms.
Receiver time: 457.902us Network time: 1.736ms
I1107 14:33:45.139068 21333 krpc-data-stream-sender.cc:342] Slow EndDataStream
RPC to 127.0.1.1:27001
(fragment_instance_id=ad4fa70619170ace:b58b2eba0004): took 61.340ms.
Receiver time: 81.908us Network time: 61.259ms
Change-Id: I258ac91b9fbbdbc86d0e8091c34f511f8957c4cd
---
M be/src/common/global-flags.cc
M be/src/rpc/rpc-mgr.cc
M be/src/runtime/krpc-data-stream-sender.cc
M be/src/runtime/krpc-data-stream-sender.h
4 files changed, 87 insertions(+), 4 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/62/14662/3
--
To view, visit http://gerrit.cloudera.org:8080/14662
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I258ac91b9fbbdbc86d0e8091c34f511f8957c4cd
Gerrit-Change-Number: 14662
Gerrit-PatchSet: 3
Gerrit-Owner: Tim Armstrong
Gerrit-Reviewer: Impala Public Jenkins
Gerrit-Reviewer: Lars Volker
Gerrit-Reviewer: Thomas Tauber-Marshall
Gerrit-Reviewer: Tim Armstrong
Gerrit-Reviewer: Todd Lipcon
