grpc connection time metric in the middleware

user_10697430 0
Viewed 178

This is my previous question grpc middleware(interceptors) for metric

I want to use middleware. That's what I have now.

func RequestTimeStream(mtr *metrics.Metrics) grpc.StreamServerInterceptor {
    return grpc.StreamServerInterceptor(func(srv interface{}, stream grpc.ServerStream, info *grpc.StreamServerInfo,
        handler grpc.StreamHandler) error {
        beginTime := time.Now()
        label, err := getLabel(info.FullMethod)
        if err != nil {
            return errors.Errorf("Unknown method name: %s", info.FullMethod)
        }
        defer mtr.RequestTime.With(metrics.MakeLabels(label)).Observe(time.Since(beginTime).Seconds())
        if err := handler(srv, stream); err != nil {
            return err
        }
        return nil
    })
}

Creating grpc server

    streamInterceptors := grpc_middleware.ChainStreamServer(
        middleware.RecoveryStream(logger, metrics.InternalGRPCPanicErrors),
        identifyMdw.IdentifyStream,
        middleware.AuthenticateStream(logger, metrics, authService),
        middleware.LimitStream(logger, metrics, limiters),
        middleware.RequestTimeStream(metrics),
    )

    opts := []grpc.ServerOption{grpc.UnaryInterceptor(unaryInterceptors), grpc.StreamInterceptor(streamInterceptors)}

    grpcServer, err := ggrpc.NewServer(cfg.ServerConfig, opts...)

My code is not working properly. The metrics are too small ~30,000 nanoseconds.

prometheus go middleware
1 Answers

Assuming I'm understanding your issue correctly I believe the problem is with:

defer mtr.RequestTime.With(metrics.MakeLabels(label)).Observe(time.Since(beginTime).Seconds())

It appears that you expect this to be run at the time the function exits and calculate the time elapsed as at that time. However as per the language spec:

Each time a "defer" statement executes, the function value and parameters to the call are evaluated as usual and saved anew but the actual function is not invoked.

So the parameters are evaluated when the defer statement executes NOT when the surrounding function exits (and the deferred function runs). This can be demonstrated with a simple program:

beginTime := time.Now()
defer fmt.Println("defer", time.Since(beginTime).Seconds())
time.Sleep(2 * time.Second)
fmt.Println("non-defer", time.Since(beginTime).Seconds())

This will output something like:

non-defer 2
defer 0

There are a few possible solutions; the simplest is probably to use a closure e.g.

defer func() { fmt.Println("defer", time.Since(beginTime).Seconds()) }()

or in your case:

defer func() { mtr.RequestTime.With(metrics.MakeLabels(label)).Observe(time.Since(beginTime).Seconds())}()
user_118109460
Related