[kudu-CR] [rpc] add slow timing logging for WrapSaslCall
Alexey Serbin has submitted this change and it was merged. ( http://gerrit.cloudera.org:8080/16868 ) Change subject: [rpc] add slow timing logging for WrapSaslCall .. [rpc] add slow timing logging for WrapSaslCall In the context of KUDU-3217, this patch adds logging on slow SASL calls. The reason for setting threshold of 250ms is that 250ms is more than enough for a local call, and it should be long enough for a call to a robust KDC in the local network. Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece Reviewed-on: http://gerrit.cloudera.org:8080/16868 Reviewed-by: Grant Henke Reviewed-by: Bankim Bhavsar Tested-by: Kudu Jenkins --- M src/kudu/rpc/client_negotiation.cc M src/kudu/rpc/client_negotiation.h M src/kudu/rpc/sasl_common.cc M src/kudu/rpc/sasl_common.h M src/kudu/rpc/server_negotiation.cc M src/kudu/thrift/sasl_client_transport.cc 6 files changed, 64 insertions(+), 36 deletions(-) Approvals: Grant Henke: Looks good to me, approved Bankim Bhavsar: Looks good to me, approved Kudu Jenkins: Verified -- To view, visit http://gerrit.cloudera.org:8080/16868 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: kudu Gerrit-Branch: master Gerrit-MessageType: merged Gerrit-Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece Gerrit-Change-Number: 16868 Gerrit-PatchSet: 5 Gerrit-Owner: Alexey Serbin Gerrit-Reviewer: Alexey Serbin Gerrit-Reviewer: Bankim Bhavsar Gerrit-Reviewer: Grant Henke Gerrit-Reviewer: Kudu Jenkins (120) Gerrit-Reviewer: Tidy Bot (241)
[kudu-CR] [rpc] add slow timing logging for WrapSaslCall
Bankim Bhavsar has posted comments on this change. ( http://gerrit.cloudera.org:8080/16868 ) Change subject: [rpc] add slow timing logging for WrapSaslCall .. Patch Set 4: Code-Review+2 -- To view, visit http://gerrit.cloudera.org:8080/16868 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: kudu Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece Gerrit-Change-Number: 16868 Gerrit-PatchSet: 4 Gerrit-Owner: Alexey Serbin Gerrit-Reviewer: Alexey Serbin Gerrit-Reviewer: Bankim Bhavsar Gerrit-Reviewer: Grant Henke Gerrit-Reviewer: Kudu Jenkins (120) Gerrit-Reviewer: Tidy Bot (241) Gerrit-Comment-Date: Mon, 14 Dec 2020 18:46:05 + Gerrit-HasComments: No
[kudu-CR] [rpc] add slow timing logging for WrapSaslCall
Grant Henke has posted comments on this change. ( http://gerrit.cloudera.org:8080/16868 ) Change subject: [rpc] add slow timing logging for WrapSaslCall .. Patch Set 4: Code-Review+2 -- To view, visit http://gerrit.cloudera.org:8080/16868 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: kudu Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece Gerrit-Change-Number: 16868 Gerrit-PatchSet: 4 Gerrit-Owner: Alexey Serbin Gerrit-Reviewer: Alexey Serbin Gerrit-Reviewer: Bankim Bhavsar Gerrit-Reviewer: Grant Henke Gerrit-Reviewer: Kudu Jenkins (120) Gerrit-Reviewer: Tidy Bot (241) Gerrit-Comment-Date: Mon, 14 Dec 2020 18:35:34 + Gerrit-HasComments: No
[kudu-CR] [rpc] add slow timing logging for WrapSaslCall
Alexey Serbin has posted comments on this change. ( http://gerrit.cloudera.org:8080/16868 ) Change subject: [rpc] add slow timing logging for WrapSaslCall .. Patch Set 3: (1 comment) http://gerrit.cloudera.org:8080/#/c/16868/3/src/kudu/rpc/sasl_common.h File src/kudu/rpc/sasl_common.h: http://gerrit.cloudera.org:8080/#/c/16868/3/src/kudu/rpc/sasl_common.h@91 PS3, Line 91: description > Nit: 'description' Done -- To view, visit http://gerrit.cloudera.org:8080/16868 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: kudu Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece Gerrit-Change-Number: 16868 Gerrit-PatchSet: 3 Gerrit-Owner: Alexey Serbin Gerrit-Reviewer: Alexey Serbin Gerrit-Reviewer: Bankim Bhavsar Gerrit-Reviewer: Grant Henke Gerrit-Reviewer: Kudu Jenkins (120) Gerrit-Reviewer: Tidy Bot (241) Gerrit-Comment-Date: Mon, 14 Dec 2020 18:31:39 + Gerrit-HasComments: Yes
[kudu-CR] [rpc] add slow timing logging for WrapSaslCall
Hello Tidy Bot, Kudu Jenkins, Grant Henke, Bankim Bhavsar, I'd like you to reexamine a change. Please visit http://gerrit.cloudera.org:8080/16868 to look at the new patch set (#4). Change subject: [rpc] add slow timing logging for WrapSaslCall .. [rpc] add slow timing logging for WrapSaslCall In the context of KUDU-3217, this patch adds logging on slow SASL calls. The reason for setting threshold of 250ms is that 250ms is more than enough for a local call, and it should be long enough for a call to a robust KDC in the local network. Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece --- M src/kudu/rpc/client_negotiation.cc M src/kudu/rpc/client_negotiation.h M src/kudu/rpc/sasl_common.cc M src/kudu/rpc/sasl_common.h M src/kudu/rpc/server_negotiation.cc M src/kudu/thrift/sasl_client_transport.cc 6 files changed, 64 insertions(+), 36 deletions(-) git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/68/16868/4 -- To view, visit http://gerrit.cloudera.org:8080/16868 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: kudu Gerrit-Branch: master Gerrit-MessageType: newpatchset Gerrit-Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece Gerrit-Change-Number: 16868 Gerrit-PatchSet: 4 Gerrit-Owner: Alexey Serbin Gerrit-Reviewer: Alexey Serbin Gerrit-Reviewer: Bankim Bhavsar Gerrit-Reviewer: Grant Henke Gerrit-Reviewer: Kudu Jenkins (120) Gerrit-Reviewer: Tidy Bot (241)
[kudu-CR] [rpc] add slow timing logging for WrapSaslCall
Bankim Bhavsar has posted comments on this change. ( http://gerrit.cloudera.org:8080/16868 ) Change subject: [rpc] add slow timing logging for WrapSaslCall .. Patch Set 3: Code-Review+2 (1 comment) http://gerrit.cloudera.org:8080/#/c/16868/3/src/kudu/rpc/sasl_common.h File src/kudu/rpc/sasl_common.h: http://gerrit.cloudera.org:8080/#/c/16868/3/src/kudu/rpc/sasl_common.h@91 PS3, Line 91: description Nit: 'description' -- To view, visit http://gerrit.cloudera.org:8080/16868 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: kudu Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece Gerrit-Change-Number: 16868 Gerrit-PatchSet: 3 Gerrit-Owner: Alexey Serbin Gerrit-Reviewer: Alexey Serbin Gerrit-Reviewer: Bankim Bhavsar Gerrit-Reviewer: Grant Henke Gerrit-Reviewer: Kudu Jenkins (120) Gerrit-Reviewer: Tidy Bot (241) Gerrit-Comment-Date: Mon, 14 Dec 2020 18:11:18 + Gerrit-HasComments: Yes
[kudu-CR] [rpc] add slow timing logging for WrapSaslCall
Alexey Serbin has posted comments on this change. ( http://gerrit.cloudera.org:8080/16868 ) Change subject: [rpc] add slow timing logging for WrapSaslCall .. Patch Set 1: (2 comments) http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/sasl_common.cc File src/kudu/rpc/sasl_common.cc: http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/sasl_common.cc@323 PS1, Line 323: SCOPED_LOG_SLOW_EXECUTION(WARNING, 100, desc ? desc : "making SASL call"); > I think we should error on only logging when it could indicate a larger iss OK, thanks for the clarification. I guess a warning message if the call and lock/unlock take together longer than 250ms should be fine. http://gerrit.cloudera.org:8080/#/c/16868/2/src/kudu/rpc/sasl_common.cc File src/kudu/rpc/sasl_common.cc: http://gerrit.cloudera.org:8080/#/c/16868/2/src/kudu/rpc/sasl_common.cc@324 PS2, Line 324: // In many cases, the GSSAPI SASL plugin will generate a nice error > Is the CHECK_NOTNULL needed given the DCHECK above? It seems this was a remnant from another version. Removed. -- To view, visit http://gerrit.cloudera.org:8080/16868 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: kudu Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece Gerrit-Change-Number: 16868 Gerrit-PatchSet: 1 Gerrit-Owner: Alexey Serbin Gerrit-Reviewer: Alexey Serbin Gerrit-Reviewer: Grant Henke Gerrit-Reviewer: Kudu Jenkins (120) Gerrit-Reviewer: Tidy Bot (241) Gerrit-Comment-Date: Mon, 14 Dec 2020 17:49:23 + Gerrit-HasComments: Yes
[kudu-CR] [rpc] add slow timing logging for WrapSaslCall
Hello Tidy Bot, Kudu Jenkins, Grant Henke, I'd like you to reexamine a change. Please visit http://gerrit.cloudera.org:8080/16868 to look at the new patch set (#3). Change subject: [rpc] add slow timing logging for WrapSaslCall .. [rpc] add slow timing logging for WrapSaslCall In the context of KUDU-3217, this patch adds logging on slow SASL calls. The reason for setting threshold of 250ms is that 250ms is more than enough for a local call, and it should be long enough for a call to a robust KDC in the local network. Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece --- M src/kudu/rpc/client_negotiation.cc M src/kudu/rpc/client_negotiation.h M src/kudu/rpc/sasl_common.cc M src/kudu/rpc/sasl_common.h M src/kudu/rpc/server_negotiation.cc M src/kudu/thrift/sasl_client_transport.cc 6 files changed, 63 insertions(+), 36 deletions(-) git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/68/16868/3 -- To view, visit http://gerrit.cloudera.org:8080/16868 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: kudu Gerrit-Branch: master Gerrit-MessageType: newpatchset Gerrit-Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece Gerrit-Change-Number: 16868 Gerrit-PatchSet: 3 Gerrit-Owner: Alexey Serbin Gerrit-Reviewer: Alexey Serbin Gerrit-Reviewer: Grant Henke Gerrit-Reviewer: Kudu Jenkins (120) Gerrit-Reviewer: Tidy Bot (241)
[kudu-CR] [rpc] add slow timing logging for WrapSaslCall
Grant Henke has posted comments on this change. (
http://gerrit.cloudera.org:8080/16868 )
Change subject: [rpc] add slow timing logging for WrapSaslCall
..
Patch Set 2: Code-Review+2
(4 comments)
http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/client_negotiation.h
File src/kudu/rpc/client_negotiation.h:
http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/client_negotiation.h@20
PS1, Line 20: #include
> I think it's possible to move this back, but then we would need to ignore I
nah, that's okay. I was just curious why.
http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/sasl_common.cc
File src/kudu/rpc/sasl_common.cc:
http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/sasl_common.cc@322
PS1, Line 322: const char* description) {
> I was thinking to have more lenient approach to the description, allowing f
Given we control all the call sites I think that makes sense.
http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/sasl_common.cc@323
PS1, Line 323: DCHECK(description);
> 100ms is more than enough for a local call, and it's also long enough for
I think we should error on only logging when it could indicate a larger issue
or impact Kudu directly. A more conservative 250ms sounds good.
http://gerrit.cloudera.org:8080/#/c/16868/2/src/kudu/rpc/sasl_common.cc
File src/kudu/rpc/sasl_common.cc:
http://gerrit.cloudera.org:8080/#/c/16868/2/src/kudu/rpc/sasl_common.cc@324
PS2, Line 324: SCOPED_LOG_SLOW_EXECUTION(WARNING, 250,
CHECK_NOTNULL(description));
Is the CHECK_NOTNULL needed given the DCHECK above?
--
To view, visit http://gerrit.cloudera.org:8080/16868
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece
Gerrit-Change-Number: 16868
Gerrit-PatchSet: 2
Gerrit-Owner: Alexey Serbin
Gerrit-Reviewer: Alexey Serbin
Gerrit-Reviewer: Grant Henke
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Tidy Bot (241)
Gerrit-Comment-Date: Mon, 14 Dec 2020 14:52:01 +
Gerrit-HasComments: Yes
[kudu-CR] [rpc] add slow timing logging for WrapSaslCall
Alexey Serbin has posted comments on this change. ( http://gerrit.cloudera.org:8080/16868 ) Change subject: [rpc] add slow timing logging for WrapSaslCall .. Patch Set 1: (1 comment) http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/client_negotiation.h File src/kudu/rpc/client_negotiation.h: http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/client_negotiation.h@20 PS1, Line 20: #include > That's what IWYU did. I guess it thinks sasl.h belongs to the system-wide I think it's possible to move this back, but then we would need to ignore IWYU's complaint. -- To view, visit http://gerrit.cloudera.org:8080/16868 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: kudu Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece Gerrit-Change-Number: 16868 Gerrit-PatchSet: 1 Gerrit-Owner: Alexey Serbin Gerrit-Reviewer: Alexey Serbin Gerrit-Reviewer: Grant Henke Gerrit-Reviewer: Kudu Jenkins (120) Gerrit-Reviewer: Tidy Bot (241) Gerrit-Comment-Date: Mon, 14 Dec 2020 07:05:14 + Gerrit-HasComments: Yes
[kudu-CR] [rpc] add slow timing logging for WrapSaslCall
Alexey Serbin has posted comments on this change. (
http://gerrit.cloudera.org:8080/16868 )
Change subject: [rpc] add slow timing logging for WrapSaslCall
..
Patch Set 1:
(3 comments)
http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/client_negotiation.h
File src/kudu/rpc/client_negotiation.h:
http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/client_negotiation.h@20
PS1, Line 20: #include
> Why does this belong at the top of the file?
That's what IWYU did. I guess it thinks sasl.h belongs to the system-wide
libraries.
http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/sasl_common.cc
File src/kudu/rpc/sasl_common.cc:
http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/sasl_common.cc@322
PS1, Line 322: const char* desc) {
> Should we DCHECK to ensure description isn't null? otherwise "making SASL c
I was thinking to have more lenient approach to the description, allowing for
nullptr. But since you asked, I guess you'd rather see it strict.
Done.
http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/sasl_common.cc@323
PS1, Line 323: SCOPED_LOG_SLOW_EXECUTION(WARNING, 100, desc ? desc : "making
SASL call");
> How did you pick 100ms?
100ms is more than enough for a local call, and it's also long enough for a
call to a KDC in a local network. In my test server, it takes about 7ms to get
a TGT from the KDC given a keytab.
Do you think we should set it to something higher? I guess we might set it to
250ms, or use INFO log here if you are concerned with too much log lines in
cluster with somewhat slow KDC. Just in case, I put changed it to 250ms if
100ms seems a bit risky.
--
To view, visit http://gerrit.cloudera.org:8080/16868
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece
Gerrit-Change-Number: 16868
Gerrit-PatchSet: 1
Gerrit-Owner: Alexey Serbin
Gerrit-Reviewer: Alexey Serbin
Gerrit-Reviewer: Grant Henke
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Tidy Bot (241)
Gerrit-Comment-Date: Mon, 14 Dec 2020 06:56:34 +
Gerrit-HasComments: Yes
[kudu-CR] [rpc] add slow timing logging for WrapSaslCall
Hello Tidy Bot, Kudu Jenkins, Grant Henke, I'd like you to reexamine a change. Please visit http://gerrit.cloudera.org:8080/16868 to look at the new patch set (#2). Change subject: [rpc] add slow timing logging for WrapSaslCall .. [rpc] add slow timing logging for WrapSaslCall In the context of KUDU-3217, this patch adds logging on slow SASL calls. The reason for setting threshold of 250ms is that 250ms is more than enough for a local call, and it should be long enough for a call to a robust KDC in the local network. Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece --- M src/kudu/rpc/client_negotiation.cc M src/kudu/rpc/client_negotiation.h M src/kudu/rpc/sasl_common.cc M src/kudu/rpc/sasl_common.h M src/kudu/rpc/server_negotiation.cc M src/kudu/thrift/sasl_client_transport.cc 6 files changed, 63 insertions(+), 36 deletions(-) git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/68/16868/2 -- To view, visit http://gerrit.cloudera.org:8080/16868 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: kudu Gerrit-Branch: master Gerrit-MessageType: newpatchset Gerrit-Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece Gerrit-Change-Number: 16868 Gerrit-PatchSet: 2 Gerrit-Owner: Alexey Serbin Gerrit-Reviewer: Grant Henke Gerrit-Reviewer: Kudu Jenkins (120) Gerrit-Reviewer: Tidy Bot (241)
[kudu-CR] [rpc] add slow timing logging for WrapSaslCall
Grant Henke has posted comments on this change. (
http://gerrit.cloudera.org:8080/16868 )
Change subject: [rpc] add slow timing logging for WrapSaslCall
..
Patch Set 1:
(3 comments)
http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/client_negotiation.h
File src/kudu/rpc/client_negotiation.h:
http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/client_negotiation.h@20
PS1, Line 20: #include
Why does this belong at the top of the file?
http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/sasl_common.cc
File src/kudu/rpc/sasl_common.cc:
http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/sasl_common.cc@322
PS1, Line 322: const char* desc) {
Should we DCHECK to ensure description isn't null? otherwise "making SASL call"
isn't super helpful.
http://gerrit.cloudera.org:8080/#/c/16868/1/src/kudu/rpc/sasl_common.cc@323
PS1, Line 323: SCOPED_LOG_SLOW_EXECUTION(WARNING, 100, desc ? desc : "making
SASL call");
How did you pick 100ms?
--
To view, visit http://gerrit.cloudera.org:8080/16868
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece
Gerrit-Change-Number: 16868
Gerrit-PatchSet: 1
Gerrit-Owner: Alexey Serbin
Gerrit-Reviewer: Grant Henke
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Tidy Bot (241)
Gerrit-Comment-Date: Mon, 14 Dec 2020 04:24:45 +
Gerrit-HasComments: Yes
[kudu-CR] [rpc] add slow timing logging for WrapSaslCall
Alexey Serbin has uploaded this change for review. ( http://gerrit.cloudera.org:8080/16868 Change subject: [rpc] add slow timing logging for WrapSaslCall .. [rpc] add slow timing logging for WrapSaslCall In the context of KUDU-3217, this patch adds logging on slow SASL calls. Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece --- M src/kudu/rpc/client_negotiation.cc M src/kudu/rpc/client_negotiation.h M src/kudu/rpc/sasl_common.cc M src/kudu/rpc/sasl_common.h M src/kudu/rpc/server_negotiation.cc M src/kudu/thrift/sasl_client_transport.cc 6 files changed, 60 insertions(+), 35 deletions(-) git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/68/16868/1 -- To view, visit http://gerrit.cloudera.org:8080/16868 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: kudu Gerrit-Branch: master Gerrit-MessageType: newchange Gerrit-Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece Gerrit-Change-Number: 16868 Gerrit-PatchSet: 1 Gerrit-Owner: Alexey Serbin
