Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

grpclb: Improved logging #13332

Merged
merged 4 commits into from
Nov 10, 2017
Merged

Conversation

dgquintas
Copy link
Contributor

No description provided.

Copy link
Member

@markdroth markdroth left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Comments are all cosmetic. Feel free to merge after addressing.

@@ -175,6 +175,9 @@ typedef struct wrapped_rr_closure_arg {
/* The RR instance related to the closure */
grpc_lb_policy* rr_policy;

/* The grpclb instance that created the wrapping */
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Might be a good idea to note that we're not holding a ref to the LB policy; the field is just here to provide the pointer value for log messages.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

@@ -647,7 +654,7 @@ static bool pick_from_internal_rr_locked(
if (server->drop) {
// Not using the RR policy, so unref it.
if (GRPC_TRACER_ON(grpc_lb_glb_trace)) {
gpr_log(GPR_INFO, "Unreffing RR for drop (0x%" PRIxPTR ")",
gpr_log(GPR_INFO, "[grpclb %p] Unreffing RR %p for drop", glb_policy,
(intptr_t)wc_arg->rr_policy);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think we need the intptr_t cast here.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

(unsigned long)glb_policy->serverlist->num_servers,
(void*)glb_policy->rr_policy);
"[grpclb %p] Failure creating a RoundRobin policy for serverlist "
"update with %lu entries. The previous RR instance (%p), if any, "
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggest using PRIuPTR here to avoid the cast.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

@@ -1708,10 +1726,11 @@ static void lb_on_server_status_received_locked(grpc_exec_ctx* exec_ctx,
char* status_details =
grpc_slice_to_c_string(glb_policy->lb_call_status_details);
gpr_log(GPR_INFO,
"Status from LB server received. Status = %d, Details = '%s', "
"[grpclb %p] Status from LB server received. Status = %d, Details "
"= '%s', "
"(call: %p), error %p",
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Logging the address of the error doesn't seem very useful. Why not log grpc_error_string(error) instead?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

@@ -213,7 +217,8 @@ static void wrapped_rr_closure(grpc_exec_ctx* exec_ctx, void* arg,
grpc_grpclb_client_stats_unref(wc_arg->client_stats);
}
if (GRPC_TRACER_ON(grpc_lb_glb_trace)) {
gpr_log(GPR_INFO, "Unreffing RR %p", (void*)wc_arg->rr_policy);
gpr_log(GPR_INFO, "[grpclb %p] Unreffing RR %p", wc_arg->glb_policy,
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think that all of the gpr_log() calls inside of a if (GRPC_TRACER_ON(grpc_lb_glb_trace)) block should use GPR_DEBUG instead of GPR_INFO.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we have any guideline about this? I think those concerns are independent.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think we've historically paid enough attention to this, but in general I think trace information belongs at the debug log level. But we certainly don't need to hold up this PR for that if you don't want to.

@@ -1261,8 +1270,7 @@ static void lb_call_on_retry_timer_locked(grpc_exec_ctx* exec_ctx, void* arg,
glb_policy->retry_timer_active = false;
if (!glb_policy->shutting_down && error == GRPC_ERROR_NONE) {
if (GRPC_TRACER_ON(grpc_lb_glb_trace)) {
gpr_log(GPR_INFO, "Restaring call to LB server (grpclb %p)",
(void*)glb_policy);
gpr_log(GPR_INFO, "[grpclb %p] Restaring call to LB server", glb_policy);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

typo: "Restaring" instead of "Restarting"

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

@@ -175,7 +175,8 @@ typedef struct wrapped_rr_closure_arg {
/* The RR instance related to the closure */
grpc_lb_policy* rr_policy;

/* The grpclb instance that created the wrapping */
/* The grpclb instance that created the wrapping. This instance is not owned,
* reference counts are untouched. Its used only for logging purposes. */
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

s/Its/It's/

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Uuuugh, one of my pet peeves. The shame... fixed.

@@ -213,7 +217,8 @@ static void wrapped_rr_closure(grpc_exec_ctx* exec_ctx, void* arg,
grpc_grpclb_client_stats_unref(wc_arg->client_stats);
}
if (GRPC_TRACER_ON(grpc_lb_glb_trace)) {
gpr_log(GPR_INFO, "Unreffing RR %p", (void*)wc_arg->rr_policy);
gpr_log(GPR_INFO, "[grpclb %p] Unreffing RR %p", wc_arg->glb_policy,
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think we've historically paid enough attention to this, but in general I think trace information belongs at the debug log level. But we certainly don't need to hold up this PR for that if you don't want to.

"to be used. Future updates from the LB will attempt to create new "
"[grpclb %p] Failure creating a RoundRobin policy for serverlist "
"update with %" PRIuPTR
" entries. The previous RR instance (%p), if any, will continue to "
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nit: This line can be moved up to the end of the previous line.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I tried. Clang-format insists on putting it there :/

@grpc-testing
Copy link

****************************************************************

libgrpc.so

     VM SIZE                                                                                            FILE SIZE
 ++++++++++++++ GROWING                                                                              ++++++++++++++
  +1.3%    +192 src/core/ext/filters/client_channel/lb_policy/grpclb/grpclb.cc                          +192  +1.3%
      [NEW]    +834 build_lb_channel_args(grpc_exec_ctx*, grpc_lb_addresses const*, grpc_fake_resolver_r    +834  [NEW]
      +9.8%     +63 pick_from_internal_rr_locked                                                             +63  +9.8%
      +1.7%     +27 rr_handover_locked(grpc_exec_ctx*, glb_lb_policy*) [clone .part.5]                       +27  +1.7%
      +2.0%     +27 lb_on_response_received_locked                                                           +27  +2.0%
      +4.2%     +17 wrapped_rr_closure                                                                       +17  +4.2%
      +2.3%     +16 glb_pick_locked                                                                          +16  +2.3%
      +3.9%     +16 lb_on_server_status_received_locked                                                      +16  +3.9%
      +5.3%     +16 update_lb_connectivity_status_locked                                                     +16  +5.3%
      +1.1%      +4 [Unmapped]                                                                                +4  +1.1%
      +0.3%      +3 glb_create                                                                                +3  +0.3%
      +0.5%      +3 send_client_load_report_locked                                                            +3  +0.5%

 -+-+-+-+-+-+-+ MIXED                                                                                +-+-+-+-+-+-+-
  +0.1%    +296 [None]                                                                                  -432  -0.0%

  +0.0%    +488 TOTAL                                                                                   -240  -0.0%


****************************************************************

libgrpc++.so

     VM SIZE        FILE SIZE
 ++++++++++++++  ++++++++++++++

  [ = ]       0        0  [ = ]



@grpc-testing
Copy link

[trickle] No significant performance differences

@grpc-testing
Copy link

Corrupt JSON data (indicates timeout or crash): 
    bm_fullstack_streaming_pump.BM_PumpStreamClientToServer_InProcessCHTTP2__16777216.counters.new: 1


[microbenchmarks] No significant performance differences

@dgquintas
Copy link
Contributor Author

Issues: #13149 #13124 #13122 #13330

@dgquintas dgquintas merged commit c0ec3cc into grpc:master Nov 10, 2017
@lock lock bot locked as resolved and limited conversation to collaborators Jan 21, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

6 participants