grpc timing logging

gistfile1.diff

diff --git a/google.golang.org/grpc/call.go b/google.golang.org/grpc/call.go
index c1588c63..e1286dda 100644
--- a/google.golang.org/grpc/call.go
+++ b/google.golang.org/grpc/call.go
@@ -35,6 +35,7 @@ package grpc

 import (
        "bytes"
+       "fmt"
        "io"
        "time"

@@ -148,6 +149,8 @@ func Invoke(ctx context.Context, method string, args, reply interface{}, cc *Cli

 func invoke(ctx context.Context, method string, args, reply interface{}, cc *ClientConn, opts ...CallOption) (e error) {
        c := defaultCallInfo
+       start := time.Now()
+       restarts := 0
        if mc, ok := cc.getMethodConfig(method); ok {
                c.failFast = !mc.WaitForReady
                if mc.Timeout > 0 {
@@ -156,6 +159,7 @@ func invoke(ctx context.Context, method string, args, reply interface{}, cc *Cli
                        defer cancel()
                }
        }
+       getMethodConfig := time.Now()
        for _, o := range opts {
                if err := o.before(&c); err != nil {
                        return toRPCErr(err)
@@ -202,6 +206,7 @@ func invoke(ctx context.Context, method string, args, reply interface{}, cc *Cli
                        sh.HandleRPC(ctx, end)
                }
        }()
+       statsAndTracing := time.Now()
        topts := &transport.Options{
                Last:  true,
                Delay: false,
@@ -228,6 +233,7 @@ func invoke(ctx context.Context, method string, args, reply interface{}, cc *Cli
                        BlockingWait: !c.failFast,
                }
                t, put, err = cc.getTransport(ctx, gopts)
+               getTransport := time.Now()
                if err != nil {
                        // TODO(zhaoq): Probably revisit the error handling.
                        if _, ok := err.(*rpcError); ok {
@@ -246,6 +252,7 @@ func invoke(ctx context.Context, method string, args, reply interface{}, cc *Cli
                        c.traceInfo.tr.LazyLog(&payload{sent: true, msg: args}, true)
                }
                stream, err = sendRequest(ctx, cc.dopts, cc.dopts.cp, callHdr, t, args, topts)
+               sendRequest := time.Now()
                if err != nil {
                        if put != nil {
                                put()
@@ -263,6 +270,7 @@ func invoke(ctx context.Context, method string, args, reply interface{}, cc *Cli
                        return toRPCErr(err)
                }
                err = recvResponse(ctx, cc.dopts, t, &c, stream, reply)
+               recvResponse := time.Now()
                if err != nil {
                        if put != nil {
                                put()
@@ -280,10 +288,15 @@ func invoke(ctx context.Context, method string, args, reply interface{}, cc *Cli
                        c.traceInfo.tr.LazyLog(&payload{sent: false, msg: reply}, true)
                }
                t.CloseStream(stream, nil)
+               closeStream := time.Now()
                if put != nil {
                        put()
                        put = nil
                }
+               if method == "/cockroach.rpc.Heartbeat/Ping" {
+                       fmt.Printf("ping latencies (%d restarts, %v total): getMethodConfig %v; statsAndTracing %v; getTransport %v; sendRequest %v; recvResponse %v; closeStream %v\n",
+                               restarts, time.Now().Sub(start), getMethodConfig.Sub(start), statsAndTracing.Sub(getMethodConfig), getTransport.Sub(statsAndTracing), sendRequest.Sub(getTransport), recvResponse.Sub(sendRequest), closeStream.Sub(recvResponse))
+               }
                return Errorf(stream.StatusCode(), "%s", stream.StatusDesc())
        }
 }