inprocgrpc calls are not getting traced

[farcaller]

One of the interesting ideas for inprocgrpc is when an external grpc request is using a subset of the service APIs to do its job, calling into itself. If the call is done directly there's little visibility into which parts are slow and which RPCs are actually called too often so I tried using inprocgrpc to loopback into the service provider itself.

Unfortunately inprocgrpc initiated calls would be still missing from /x/net/trace dashboard. Is that an oversight, a bug, or something that inprocgrpc wasn't intended to solve?

[jhump]

I'm not familiar with x/net/trace dashboard. If there is some tracing built into the main *grpc.ClientConn, then it is indeed not built into inprocgrpc.Channel. And that might explain why only external RPCs show up there.

However, you can add an interceptor around the in-process channel to instrument those loopback RPCs and record everything you need.

[farcaller]

It's part of the grpc server: https://github.com/grpc/grpc-go/blob/master/server.go#L691

[farcaller]

Toyed with the interceptor and here's how you can instrument the internal "server" traces.

inproc := &inprocgrpc.Channel{}

inproc.WithServerUnaryInterceptor(func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp interface{}, err error) {
  methodFamily := func(m string) string {
    m = strings.TrimPrefix(m, "/") // remove leading slash
    if i := strings.Index(m, "/"); i >= 0 {
      m = m[:i] // remove everything from second slash
    }
    if i := strings.LastIndex(m, "."); i >= 0 {
      m = m[i+1:] // cut down to last dotted component
    }
    return m
  }

  tr := trace.New("grpcinmem.Recv."+methodFamily(info.FullMethod), info.FullMethod)
  ctx = trace.NewContext(ctx, tr)
  defer tr.Finish()
  return handler(ctx, req)
})

[farcaller]

Unfortunately I can't seem to be able to find a way to leave a trace at the call site. Can I suggest a following modification to Channel.Invoke:

    tr, ok := trace.FromContext(ctx)
    enableTracing = false
    if ok {
        enableTracing = true
    }
    if enableTracing {
        tr.LazyPrintf("inproc calling %s", method)
    }
    ...
    if enableTracing {
        tr.LazyPrintf("... inproc call:%v", err)
    }

[farcaller]

This way the original trace (on the grpc side) gets annotated with in-process calls, and those calls translate into dedicated in-process trace entries of their own.

[farcaller]

FWIW, grpc's tracer finalizer: https://github.com/grpc/grpc-go/blob/master/server.go#L855

[jhump]

@farcaller, for the client, you can use an interceptor for that, too:

inprocChan := inprocgrpc.Channel{}
clientChan := grpchan.InterceptChannel(inprocChan, unaryInterceptor, streamInterceptor)
// send RPCs through clientChan, not inprocChan

However, knowing when to call tr.Finish() for a streaming call is a pain. You have to wrap the stream (and have to do other tricks, like using runtime.Finalizer and possibly even spinning up a goroutine, to properly finish the trace in the face of a misbehaving/incorrectly written stream client).

[jhump]

I think this issue can be adequately worked around via interceptors, which keeps the RPC implementation simple. So I'm going to close this issue.