grpc connection time metric in the middleware

This is my previous question https://stackoverflow.com/questions/70240557/grpc-middlewareinterceptors-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.

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())}()