Add tracer for handshakers. #15090

markdroth · 2018-04-17T22:01:18Z

This adds some logging needed to debug a handshaker problem being reported internally.

Note that this will require adding the name field to the handshaker vtables in internal code before we import this. Once this PR is ready to merge, I'll prepare the necessary internal change.

grpc-testing · 2018-04-17T22:04:32Z

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

libgrpc.so

     VM SIZE                                            FILE SIZE
 ++++++++++++++ GROWING                              ++++++++++++++
  +0.2% +1.12Ki [None]                               +2.64Ki  +0.0%
      +0.2% +1.03Ki [Unmapped]                           +2.62Ki  +0.0%
      +3.4%     +40 [None]                                     0  [ = ]
      [NEW]     +24 grpc_handshaker_trace                      0  [ = ]
       +33%      +8 fail_handshaker_vtable                    +8   +33%
       +33%      +8 security_handshaker_vtable                +8   +33%
       +33%      +8 http_connect_handshaker_vtable            +8   +33%
   +30%    +512 src/core/lib/channel/handshaker.cc      +512   +30%
      +183%    +372 call_next_handshaker_locked             +372  +183%
       +63%     +83 grpc_handshake_manager_add               +83   +63%
      [NEW]     +48 _GLOBAL__sub_I_handshaker.cc             +48  [NEW]
      [NEW]      +8 grpc_handshaker_name                      +8  [NEW]
      +0.9%      +1 [Unmapped]                                +1  +0.9%
  +8.6%    +322 src/core/lib/channel/channel_args.cc    +322  +8.6%
      [NEW]    +312 grpc_channel_args_string                +312  [NEW]
      +5.7%     +10 [Unmapped]                               +10  +5.7%

  +0.1% +1.93Ki TOTAL                                +3.45Ki  +0.0%


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

libgrpc++.so

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

 -------------- SHRINK --------------
  [ = ]       0 [None]     -40  -0.0%

  [ = ]       0 TOTAL      -40  -0.0%

yashykt · 2018-04-17T22:27:43Z

src/core/lib/channel/handshaker.cc

 #include "src/core/lib/iomgr/timer.h"

+grpc_core::TraceFlag grpc_handshaker_trace(false, "handshaker");


I'm guessing the DebugOnlyTraceFlag will not work?

I'm sure it would work, but I don't know why it would be necessary. In general, DebugOnlyTraceFlag is for cases where enabling the tracer imposes a large amount of overhead that we don't want in opt builds (e.g., things like ref-count tracing, which occurs a lot). That's not the case here, so there's no reason not to allow this tracer even in opt builds.

I agree that the overhead would not be much but I would prefer to not add unnecessary overhead.

By that logic, why would we support any tracer in opt mode? I don't understand why this particular tracer would be different than any other.

Note that there is no additional overhead unless the tracer is actually enabled.

Mark, is there a specific reason to want this tracer in opt builds ? We have seen a general downward drift in performance benchmarks, so I would lean towards avoiding this overhead unless there is a specific need.

As per our discussion, it is very useful to support tracers in opt mode, because this allows customers to enable them without pushing a debug binary (which they often can't for performance reasons). This makes it easier to gather useful debugging information when a customer runs into a problem.

If we're really worried about the branch-prediction performance impact of a few if statements checking whether the tracer is enabled, I would suggest that we find a structural way to make use of the GPR_UNLIKELY macro that @yashykt recently added in #15009. For example, perhaps we could use that in the TraceFlag::enabled() method.

Based on offline discussion, we will explore adding compiler hints to the tracers to avoid perf impact.

yashykt

LGTM if the DebugOnlyTraceFlag will not be enough

grpc-testing · 2018-04-17T22:56:17Z

[microbenchmarks] Performance differences noted:
Benchmark                                                                                 cpu_time    real_time
----------------------------------------------------------------------------------------  ----------  -----------
BM_ErrorGetPresentInt                                                                     -10%        -10%
BM_ErrorGetStatusCode<SimpleError>                                                        -4%         -4%
BM_ErrorHttpError<ErrorWithGrpcStatus>                                                    -5%         -5%
BM_ErrorHttpError<SimpleError>                                                            -7%         -7%
BM_PumpStreamClientToServer<InProcess>/262144                                             +10%        +10%
BM_StreamingPingPongWithCoalescingApi<MinInProcess, NoOpMutator, NoOpMutator>/262144/2/1  -4%         -4%

markdroth · 2018-04-18T16:11:17Z

Known failures: #14969 #15102 #15103

a11r

Looks good overall.

markdroth · 2018-04-18T19:54:55Z

@AspirinSJL, I need an owners approval for this. Thanks!

grpc-testing · 2018-04-18T21:22:22Z

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

libgrpc.so

     VM SIZE                                            FILE SIZE
 ++++++++++++++ GROWING                              ++++++++++++++
  +0.2% +1.13Ki [None]                               +2.92Ki  +0.0%
      +0.2% +1.04Ki [Unmapped]                           +2.89Ki  +0.0%
      +3.4%     +40 [None]                                     0  [ = ]
      [NEW]     +24 grpc_handshaker_trace                      0  [ = ]
       +33%      +8 fail_handshaker_vtable                    +8   +33%
       +33%      +8 security_handshaker_vtable                +8   +33%
       +33%      +8 http_connect_handshaker_vtable            +8   +33%
   +33%    +560 src/core/lib/channel/handshaker.cc      +560   +33%
      +204%    +415 call_next_handshaker_locked             +415  +204%
       +63%     +83 grpc_handshake_manager_add               +83   +63%
      [NEW]     +48 _GLOBAL__sub_I_handshaker.cc             +48  [NEW]
      [NEW]      +8 grpc_handshaker_name                      +8  [NEW]
      +5.1%      +6 [Unmapped]                                +6  +5.1%
  +8.7%    +326 src/core/lib/channel/channel_args.cc    +326  +8.7%
      [NEW]    +316 grpc_channel_args_string                +316  [NEW]
      +5.7%     +10 [Unmapped]                               +10  +5.7%

  +0.1% +1.99Ki TOTAL                                +3.78Ki  +0.0%


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

libgrpc++.so

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

 -------------- SHRINK --------------
  [ = ]       0 [None]     -40  -0.0%

  [ = ]       0 TOTAL      -40  -0.0%

grpc-testing · 2018-04-18T22:14:19Z

[microbenchmarks] No significant performance differences

Add tracer for handshakers.

dc4d01f

markdroth added the disposition/Needs Internal Changes label Apr 17, 2018

markdroth requested a review from yashykt April 17, 2018 22:01

markdroth requested review from a11r and dgquintas as code owners April 17, 2018 22:01

yashykt reviewed Apr 17, 2018

View reviewed changes

yashykt approved these changes Apr 17, 2018

View reviewed changes

a11r approved these changes Apr 18, 2018

View reviewed changes

markdroth requested a review from AspirinSJL April 18, 2018 19:54

AspirinSJL approved these changes Apr 18, 2018

View reviewed changes

Don't crash on null channel args or read buffer.

344634c

markdroth merged commit 8892c08 into grpc:master Apr 19, 2018

markdroth deleted the handshaker_trace branch April 19, 2018 17:34

lock bot locked as resolved and limited conversation to collaborators Jan 19, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add tracer for handshakers. #15090

Add tracer for handshakers. #15090

markdroth commented Apr 17, 2018

grpc-testing commented Apr 17, 2018

yashykt Apr 17, 2018

markdroth Apr 18, 2018

yashykt Apr 18, 2018

markdroth Apr 18, 2018

a11r Apr 18, 2018

markdroth Apr 18, 2018

a11r Apr 18, 2018

yashykt left a comment

grpc-testing commented Apr 17, 2018

markdroth commented Apr 18, 2018

a11r left a comment

markdroth commented Apr 18, 2018

grpc-testing commented Apr 18, 2018

grpc-testing commented Apr 18, 2018

		#include "src/core/lib/iomgr/timer.h"

		grpc_core::TraceFlag grpc_handshaker_trace(false, "handshaker");

Add tracer for handshakers. #15090

Add tracer for handshakers. #15090

Conversation

markdroth commented Apr 17, 2018

grpc-testing commented Apr 17, 2018

yashykt Apr 17, 2018

Choose a reason for hiding this comment

markdroth Apr 18, 2018

Choose a reason for hiding this comment

yashykt Apr 18, 2018

Choose a reason for hiding this comment

markdroth Apr 18, 2018

Choose a reason for hiding this comment

a11r Apr 18, 2018

Choose a reason for hiding this comment

markdroth Apr 18, 2018

Choose a reason for hiding this comment

a11r Apr 18, 2018

Choose a reason for hiding this comment

yashykt left a comment

Choose a reason for hiding this comment

grpc-testing commented Apr 17, 2018

markdroth commented Apr 18, 2018

a11r left a comment

Choose a reason for hiding this comment

markdroth commented Apr 18, 2018

grpc-testing commented Apr 18, 2018

grpc-testing commented Apr 18, 2018