18. Metricas

Cuando tu aplicación está en funcionamiento en producción con tráfico real, o si estás llevando a cabo pruebas de carga dirigidas, es posible que desees tener una visión detallada de cómo está funcionando y qué recursos está utilizando. Por ejemplo, es posible que desees responder preguntas como:

• ¿Cuánta memoria está utilizando mi aplicación? ¿Cómo está cambiando esto con el tiempo?
• ¿Cuántas goroutines están en uso actualmente? ¿Cómo está cambiando esto con el tiempo?
• ¿Cuántas conexiones de base de datos están en uso y cuántas están inactivas? ¿Necesito cambiar la configuración del grupo de conexiones?`
• ¿Cuál es la proporción de respuestas HTTP exitosas en comparación con los errores tanto del cliente como del servidor? ¿Los índices de error están elevados por encima de lo normal?

Tener perspicacia sobre estas cosas puede ayudar a informar tus elecciones de hardware y configuración, y actuar como una señal de advertencia temprana de posibles problemas (como fugas de memoria).

Para ayudar con esto, la biblioteca estándar de Go incluye el paquete expvar que facilita la recopilación y visualización de diferentes métricas de aplicación en tiempo de ejecución.

En esta sección aprenderás:

• Cómo usar el paquete expvar para ver métricas de aplicación en formato JSON a través de un manejador HTTP.
• Qué métricas de aplicación predeterminadas están disponibles y cómo crear tus propias métricas de aplicación personalizadas para monitorear el número de goroutines activas y el pool de conexiones de la base de datos.
• Cómo usar middleware para monitorear métricas de aplicación a nivel de solicitud, incluidos los recuentos de diferentes códigos de estado de respuesta HTTP.

18.1 Exponiendo Métricas con Expvar

Ver las métricas de nuestra aplicación se facilita por el hecho de que el paquete expvar proporciona una función expvar.Handler() que devuelve un manejador HTTP que expone las métricas de tu aplicación. Por defecto, este manejador muestra información sobre el uso de memoria, junto con un recordatorio de qué banderas de línea de comandos utilizaste al iniciar la aplicación, todo ello en formato JSON. Así que lo primero que vamos a hacer es montar este manejador en un nuevo punto final GET /debug/vars, así:

package main

import (
	"expvar" // Nuevo import
	"net/http"
	"github.com/julienschmidt/httprouter"
)

func (app *application) routes() http.Handler {
	router := httprouter.New()
	router.NotFound = http.HandlerFunc(app.notFoundResponse)
	router.MethodNotAllowed = http.HandlerFunc(app.methodNotAllowedResponse)
	router.HandlerFunc(http.MethodGet, "/v1/healthcheck", app.healthcheckHandler)
	router.HandlerFunc(http.MethodGet, "/v1/movies", app.requirePermission("movies:read", app.listMoviesHandler))
	router.HandlerFunc(http.MethodPost, "/v1/movies", app.requirePermission("movies:write", app.createMovieHandler))
	router.HandlerFunc(http.MethodGet, "/v1/movies/:id", app.requirePermission("movies:read", app.showMovieHandler))
	router.HandlerFunc(http.MethodPatch, "/v1/movies/:id", app.requirePermission("movies:write", app.updateMovieHandler))
	router.HandlerFunc(http.MethodDelete, "/v1/movies/:id", app.requirePermission("movies:write", app.deleteMovieHandler))
	router.HandlerFunc(http.MethodPost, "/v1/users", app.registerUserHandler)
	router.HandlerFunc(http.MethodPut, "/v1/users/activated", app.activateUserHandler)
	router.HandlerFunc(http.MethodPost, "/v1/tokens/authentication", app.createAuthenticationTokenHandler)
	// Registrar un nuevo punto final GET /debug/vars que apunte al manejador expvar.
	router.Handler(http.MethodGet, "/debug/vars", expvar.Handler())
	return app.recoverPanic(app.enableCORS(app.rateLimit(app.authenticate(router))))
}

Nota: Utilizar el punto final GET /debug/vars para el manejador expvar es convencional pero ciertamente no necesario. Si prefieres, está perfectamente bien registrarlo en un punto final alternativo como GET /v1/metrics en su lugar.

De acuerdo, vamos a probar esto. Ve y reinicia la API, pasando un par de banderas de línea de comandos con fines de demostración. Así:

$ go run ./cmd/api -limiter-enabled=false -port=4000

time=2023-09-10T10:59:13.722+02:00 level=INFO msg="base de datos conexión de pool establecido"
time=2023-09-10T10:59:13.722+02:00 level=INFO msg="iniciando servidor" addr=:4000 env=desarrollo

Y si visitas http://localhost:4000/debug/vars en tu navegador web, deberías ver una respuesta JSON que contiene información sobre tu aplicación en ejecución. En mi caso, la respuesta se ve así:

Podemos ver que el JSON aquí contiene actualmente dos elementos de nivel superior: “cmdline” y “memstats”. Vamos a hablar rápidamente sobre lo que representan estos elementos.

El elemento “cmdline” contiene una matriz de los argumentos de la línea de comandos utilizados para ejecutar la aplicación, comenzando con el nombre del programa. Esto es esencialmente una representación JSON de la variable os.Args, y es útil si deseas ver exactamente qué configuraciones no predeterminadas se usaron al iniciar la aplicación.

El elemento “memstats” contiene una instantánea ‘momento en el tiempo’ del uso de memoria, como lo devuelve la función runtime.MemStats(). La documentación y las descripciones de todos los valores se pueden encontrar aquí, pero los más importantes son:

• TotalAlloc: Bytes acumulativos asignados en el montón (no disminuirá).
• HeapAlloc: Número actual de bytes en el montón.
• HeapObjects: Número actual de objetos en el montón.
• Sys: Bytes totales de memoria obtenidos del sistema operativo (es decir, la memoria total reservada por el tiempo de ejecución de Go para el montón, las pilas y otras estructuras de datos internas).
• NumGC: Número de ciclos completados del recolector de basura.
• NextGC: El tamaño de montón objetivo del próximo ciclo del recolector de basura (Go tiene como objetivo mantener HeapAlloc ≤ NextGC).

Sugerencia: Si alguno de los términos anteriores te resulta desconocido, te recomiendo encarecidamente que leas el artículo Understanding Allocations in Go, que ofrece una excelente introducción sobre cómo Go asigna memoria y los conceptos del montón (heap) y la pila (stack).

18.2 Creando metricas personalizadas

La información predeterminada expuesta por el manejador expvar es un buen comienzo, pero podemos hacerla aún más útil al exponer algunas métricas personalizadas adicionales en la respuesta JSON.

Para ilustrar esto, comenzaremos realmente simple y primero expondremos el número de versión de nuestra aplicación en el JSON. Si no lo recuerdas, el número de versión está actualmente definido como la constante de cadena “1.0.0” en nuestro archivo main.go.

El código para hacer esto se descompone en dos pasos básicos: primero necesitamos registrar una variable personalizada con el paquete expvar, y luego necesitamos establecer el valor para la variable en sí. En una línea, el código se ve aproximadamente así:

expvar.NewString("version").Set(version)

La primera parte de esto — expvar.NewString("version") — crea un nuevo tipo expvar.String, luego lo publica para que aparezca en la respuesta JSON del manejador expvar con el nombre “version”, y luego devuelve un puntero a él. Luego usamos el método Set() en él para asignar un valor real al puntero.

Dos cosas más para tener en cuenta:

• El tipo expvar.String es seguro para uso concurrente. Entonces — si quieres — está bien manipular este valor en tiempo de ejecución desde los manejadores de tu aplicación.

• Si intentas registrar dos variables expvar con el mismo nombre, obtendrás un pánico en tiempo de ejecución cuando se registre la variable duplicada.

Adelante, integremos este código en nuestra función main(), así:

package main

import (
	"context"
	"database/sql"
	"expvar" // Nuevo import
	"flag"
	"log/slog"
	"os"
	"strings"
	"sync"
	"time"
	"greenlight.alexedwards.net/internal/data"
	"greenlight.alexedwards.net/internal/mailer"
	_ "github.com/lib/pq"
)

// Recuerda, nuestro número de versión es simplemente una cadena constante (por ahora).
const version = "1.0.0"

...

func main() {
	...

	// Publica una nueva variable "version" en el manejador expvar que contiene el número de versión de nuestra aplicación (actualmente la constante "1.0.0").
	expvar.NewString("version").Set(version)

	app := &application{
		config: cfg,
		logger: logger,
		models: data.NewModels(db),
		mailer: mailer.New(cfg.smtp.host, cfg.smtp.port, cfg.smtp.username, cfg.smtp.password, cfg.smtp.sender),
	}

	err = app.serve()
	if err != nil {
		logger.Error(err.Error())
		os.Exit(1)
	}
}
...

Si reinicias la API y visitas nuevamente http://localhost:4000/debug/vars en tu navegador web, ahora deberías ver un elemento “version”: “1.0.0” en el JSON.

Nota: En el código anterior, usamos la función expvar.NewString() para registrar y publicar una cadena en el manejador expvar. Pero Go también proporciona funciones para algunos otros tipos de datos comunes: NewFloat(), NewInt() y NewMap(). Todos estos funcionan de manera muy similar, y los utilizaremos en el próximo capítulo.

18.2 Metricas dinamicas

Ocasionalmente, es posible que desees publicar métricas que requieran llamar a otro código, o realizar algún tipo de preprocesamiento, para generar la información necesaria. Para ayudar con esto, existe la función expvar.Publish(), que te permite publicar el resultado de una función en la salida JSON.

Por ejemplo, si deseas publicar el número de goroutines activas actualmente utilizando la función runtime.NumGoroutine() de Go, podrías escribir el siguiente código:

expvar.Publish("goroutines", expvar.Func(func() interface{} {
    return runtime.NumGoroutine()
}))

Es importante señalar aquí que cualquier valor devuelto por esta función debe poder ser codificado en JSON sin errores. Si no se puede codificar en JSON, se omitirá de la salida expvar y la respuesta del punto final GET /debug/vars será incorrecta. Cualquier error será descartado silenciosamente.

En el caso del fragmento de código anterior, runtime.NumGoroutine() devuelve un tipo int regular, que se codificará como un número JSON. Así que no hay ningún problema con eso aquí.

Bien, agreguemos este código a nuestra función main(), junto con otras dos funciones que:

1. Publiquen información sobre el estado de nuestro pool de conexiones de la base de datos (como el número de conexiones inactivas y en uso) a través del método db.Stats().
2. Publiquen la marca de tiempo Unix actual con precisión de segundos.

package main

import (
	"context"
	"database/sql"
	"expvar"
	"flag"
	"log/slog"
	"os"
	"runtime" // Nuevo import
	"strings"
	"sync"
	"time"
	"greenlight.alexedwards.net/internal/data"
	"greenlight.alexedwards.net/internal/mailer"
	_ "github.com/lib/pq"
)

...

func main() {
	...

	expvar.NewString("version").Set(version)

	// Publicar el número de goroutines activas.
	expvar.Publish("goroutines", expvar.Func(func() interface{} {
		return runtime.NumGoroutine()
	}))

	// Publicar las estadísticas del pool de conexiones de la base de datos.
	expvar.Publish("database", expvar.Func(func() interface{} {
		return db.Stats()
	}))

	// Publicar la marca de tiempo Unix actual.
	expvar.Publish("timestamp", expvar.Func(func() interface{} {
		return time.Now().Unix()
	}))

	app := &application{
		config: cfg,
		logger: logger,
		models: data.NewModels(db),
		mailer: mailer.New(cfg.smtp.host, cfg.smtp.port, cfg.smtp.username, cfg.smtp.password, cfg.smtp.sender),
	}

	err = app.serve()
	if err != nil {
		logger.Error(err.Error())
		os.Exit(1)
	}
}

...

Si reinicias la API y abres nuevamente el punto final GET /debug/vars en tu navegador, ahora deberías ver los elementos adicionales “database”, “goroutines” y “timestamp” en el JSON.

En mi caso, puedo ver que la aplicación actualmente tiene 8 goroutines activas, y el pool de conexiones de la base de datos está en su estado ‘inicial’ con solo una conexión actualmente inactiva (que se creó cuando nuestro código llamó a db.PingContext() al iniciar).

Si lo deseas, puedes usar una herramienta como hey para generar algunas solicitudes a tu aplicación y ver cómo cambian estas cifras bajo carga. Por ejemplo, puedes enviar un lote de solicitudes al punto final POST /v1/tokens/authentication (que es lento y costoso porque verifica una contraseña hashada con bcrypt) de la siguiente manera:

$ BODY='{"email": "alice@example.com", "password": "pa55word"}'
$ hey -d "$BODY" -m "POST" http://localhost:4000/v1/tokens/authentication
Summary:
Total:8.0979 secs
Slowest:2.4612 secs
Fastest:1.6169 secs
Average:1.9936 secs
Requests/sec: 24.6977
Total data:
24975 bytes
Size/request: 124 bytes
Response time histogram:
1.617 [1]|■
1.701 [6]|■■■■■
1.786 [10] |■■■■■■■■■
1.870 [26] |■■■■■■■■■■■■■■■■■■■■■■■
1.955 [36] |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
2.039 [46] |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
2.123 [36] |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
2.208 [21] |■■■■■■■■■■■■■■■■■■
2.292 [12] |■■■■■■■■■■
2.377 [4]|■■■
2.461 [2]|■■
Latency distribution:
10% in 1.8143 secs
25% in 1.8871 secs
50% in 1.9867 secs
75% in 2.1000 secs
90% in 2.2017 secs
95% in 2.2642 secs
99% in 2.3799 secs
Details (average, fastest, slowest):
DNS+dialup: 0.0009 secs, 1.6169 secs, 2.4612 secs
DNS-lookup: 0.0005 secs, 0.0000 secs, 0.0030 secs
req write: 0.0002 secs, 0.0000 secs, 0.0051 secs
resp wait: 1.9924 secs, 1.6168 secs, 2.4583 secs
resp read: 0.0000 secs, 0.0000 secs, 0.0001 secs
Status code distribution:
[201] 200 responses

Importante: Asegúrate de que tu API tenga el limitador de velocidad desactivado con la bandera de línea de comandos -limiter-enabled=false antes de ejecutar esto, de lo contrario, la herramienta hey recibirá muchas respuestas 429 Too Many Requests.

Si visitas el punto final GET /debug/vars mientras la herramienta hey está en ejecución, deberías ver que las métricas de tu aplicación ahora lucen bastante diferentes.

En el momento en que tomé esta captura de pantalla, podemos ver que mi aplicación de API tenía 118 goroutines activas, con 11 conexiones de base de datos en uso y 14 conexiones inactivas.

Hay un par de cosas interesantes que señalar también. La cifra de WaitCount de la base de datos de 25 es el número total de veces que nuestra aplicación tuvo que esperar a que una conexión de base de datos estuviera disponible en nuestro pool de sql.DB (porque todas las conexiones estaban en uso). Del mismo modo, WaitCountDuration es la cantidad acumulativa de tiempo (en nanosegundos) que se pasó esperando una conexión. A partir de estos datos, es posible calcular que cuando nuestra aplicación tuvo que esperar una conexión de base de datos, el tiempo de espera promedio fue de aproximadamente 98 milisegundos. Idealmente, quieres ver ceros o números muy bajos para estas dos cosas bajo carga normal en producción.

Además, la cifra de MaxIdleTimeClosed es el recuento total del número de conexiones que se han cerrado porque alcanzaron su límite de ConnMaxIdleTime (que en nuestro caso está configurado en 15 minutos de forma predeterminada). Si dejas la aplicación en funcionamiento pero no la usas, y vuelves en 15 minutos, deberías ver que el número de conexiones abiertas ha disminuido a cero y el recuento de MaxIdleTimeClosed ha aumentado en consecuencia.

Quizás te gustaría experimentar un poco con esto y probar cambiar algunos de los parámetros de configuración del pool de conexiones para ver cómo afecta el comportamiento de estas cifras bajo carga. Por ejemplo:

$ go run ./cmd/api -limiter-enabled=false -db-max-open-conns=50 -db-max-idle-conns=50 -db-max-idle-time=20s -port=4000

18.2 información adicional

18.2 Protegiendo endopoint de métricas

Es importante tener en cuenta que estas métricas proporcionan información muy útil a cualquier persona que desee realizar un ataque de denegación de servicio contra tu aplicación, y que los valores de “cmdline” también pueden exponer información potencialmente sensible (como un DSN de base de datos).

Por lo tanto, debes asegurarte de restringir el acceso al punto final GET /debug/vars cuando se ejecuta en un entorno de producción.

Existen varias formas diferentes de hacer esto. Una opción es aprovechar nuestro proceso de autenticación existente y crear un permiso metrics:view para que solo ciertos usuarios de confianza puedan acceder al punto final. Otra opción sería utilizar la Autenticación Básica HTTP para restringir el acceso al punto final.

En nuestro caso, cuando despleguemos nuestra aplicación en producción más adelante, la ejecutaremos detrás de Caddy como un proxy inverso. Como parte de nuestra configuración de Caddy, restringiremos el acceso al punto final GET /debug/vars para que solo se pueda acceder a través de conexiones desde la máquina local, en lugar de estar expuesto en Internet.

18.2 Eliminar métricas por defecto

Actualmente no es posible eliminar los elementos predeterminados “cmdline” y “memstats” del manejador expvar, incluso si lo deseas. Existe un problema abierto al respecto, y con suerte será posible omitirlos en una versión futura de Go.

18.3 Request-level metrics

Capítulo 18.3. Métricas a nivel de solicitud

En este capítulo vamos a crear un nuevo middleware para registrar métricas personalizadas a nivel de solicitud para nuestra aplicación. Comenzaremos registrando las siguientes tres cosas:

1. El número total de solicitudes recibidas.
2. El número total de respuestas enviadas.
3. El tiempo total (acumulativo) necesario para procesar todas las solicitudes en microsegundos.

Todos estos valores serán enteros, por lo que podremos registrar estas métricas con el paquete expvar utilizando la función expvar.NewInt().

Vamos a pasar directamente al código y crear un nuevo método de middleware llamado metrics(), que inicializa las variables expvar necesarias y luego las actualiza cada vez que procesamos una solicitud. Así:

package main

import (
    "errors"
    "expvar" // Nuevo import
    "fmt"
    "net"
    "net/http"
    "strings"
    "sync"
    "time"
    
    "greenlight.alexedwards.net/internal/data"
    "greenlight.alexedwards.net/internal/validator"
    "golang.org/x/time/rate"
)

// ...

func (app *application) metrics(next http.Handler) http.Handler {
    // Inicializar las nuevas variables expvar cuando la cadena de middleware se construye por primera vez.
    var (
        totalRequestsReceived          = expvar.NewInt("total_requests_received")
        totalResponsesSent            = expvar.NewInt("total_responses_sent")
        totalProcessingTimeMicroseconds = expvar.NewInt("total_processing_time_μs")
    )

    // El siguiente código se ejecutará para cada solicitud...
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        // Registrar el momento en que comenzamos a procesar la solicitud.
        start := time.Now()
        
        // Usar el método Add() para incrementar el número de solicitudes recibidas en 1.
        totalRequestsReceived.Add(1)
        
        // Llamar al siguiente manejador en la cadena.
        next.ServeHTTP(w, r)
        
        // En el camino de vuelta de la cadena de middleware, incrementar el número de respuestas enviadas en 1.
        totalResponsesSent.Add(1)
        
        // Calcular el número de microsegundos desde que comenzamos a procesar la solicitud,
        // luego incrementar el tiempo total de procesamiento por esta cantidad.
        duration := time.Since(start).Microseconds()
        totalProcessingTimeMicroseconds.Add(duration)
    })
}

Una vez hecho eso, necesitamos actualizar el archivo cmd/api/routes.go para incluir el nuevo middleware metrics(), justo al principio de la cadena. De esta manera:

package main

...

func (app *application) routes() http.Handler {
    router := httprouter.New()
    router.NotFound = http.HandlerFunc(app.notFoundResponse)
    router.MethodNotAllowed = http.HandlerFunc(app.methodNotAllowedResponse)
    router.HandlerFunc(http.MethodGet, "/v1/healthcheck", app.healthcheckHandler)
    router.HandlerFunc(http.MethodGet, "/v1/movies", app.requirePermission("movies:read", app.listMoviesHandler))
    router.HandlerFunc(http.MethodPost, "/v1/movies", app.requirePermission("movies:write", app.createMovieHandler))
    router.HandlerFunc(http.MethodGet, "/v1/movies/:id", app.requirePermission("movies:read", app.showMovieHandler))
    router.HandlerFunc(http.MethodPatch, "/v1/movies/:id", app.requirePermission("movies:write", app.updateMovieHandler))
    router.HandlerFunc(http.MethodDelete, "/v1/movies/:id", app.requirePermission("movies:write", app.deleteMovieHandler))
    router.HandlerFunc(http.MethodPost, "/v1/users", app.registerUserHandler)
    router.HandlerFunc(http.MethodPut, "/v1/users/activated", app.activateUserHandler)
    router.HandlerFunc(http.MethodPost, "/v1/tokens/authentication", app.createAuthenticationTokenHandler)
    router.Handler(http.MethodGet, "/debug/vars", expvar.Handler())

    // Use the new metrics() middleware at the start of the chain.
    return app.metrics(app.recoverPanic(app.enableCORS(app.rateLimit(app.authenticate(router)))))
}

De acuerdo, vamos a probar esto. Adelante y ejecuta la API nuevamente con la limitación de velocidad desactivada:

$ go run ./cmd/api -limiter-enabled=false

Cuando visites localhost:4000/debug/vars en tu navegador, ahora deberías ver que la respuesta JSON incluye elementos para total_requests_received (solicitudes totales recibidas), total_responses_sent (respuestas totales enviadas) y total_processing_time_μs (tiempo total de procesamiento en microsegundos).

En este punto, podemos ver que nuestra API ha recibido una solicitud y enviado cero respuestas. Tiene sentido si lo piensas: en el momento en que se generó esta respuesta JSON, aún no se había enviado realmente. Si actualizas la página, deberías ver que estos números incrementan, incluido un aumento en el valor de total_processing_time_μs.

Intentemos esto bajo carga y usemos hey para hacer algunas solicitudes al endpoint POST /v1/tokens/authentication nuevamente. Primero reinicia la API:

$ go run ./cmd/api -limiter-enabled=false

Y luego usa hey para generar la carga de la siguiente manera:

$ BODY='{"email": "alice@example.com", "password": "pa55word"}'
$ hey -d "$BODY" -m "POST" http://localhost:4000/v1/tokens/authentication
Summary:
Total: 9.9141 secs
Slowest: 3.0333 secs
Fastest: 1.6788 secs
Average: 2.4302 secs
Requests/sec: 20.1732
Total data: 24987 bytes
Size/request: 124 bytes
Response time histogram:
1.679 [1] |■
1.814 [1] |■
1.950 [3] |■■■
2.085 [8] |■■■■■■■
2.221 [28] |■■■■■■■■■■■■■■■■■■■■■■■■
2.356 [39] |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
2.491 [46] |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
2.627 [34] |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
2.762 [20] |■■■■■■■■■■■■■■■■■
2.898 [9] |■■■■■■■■
3.033 [11] |■■■■■■■■■■
Latency distribution:
10% in 2.1386 secs
25% in 2.2678 secs
50% in 2.4197 secs
75% in 2.5769 secs
90% in 2.7718 secs
95% in 2.9125 secs
99% in 3.0220 secs
Details (average, fastest, slowest):
DNS+dialup: 0.0007 secs, 1.6788 secs, 3.0333 secs
DNS-lookup: 0.0005 secs, 0.0000 secs, 0.0047 secs
req write: 0.0001 secs, 0.0000 secs, 0.0012 secs
resp wait: 2.4293 secs, 1.6787 secs, 3.0293 secs
resp read: 0.0000 secs, 0.0000 secs, 0.0001 secs
Status code distribution:
[201] 200 responses

Una vez que haya completado, si actualizas localhost:4000/debug/vars en tu navegador, tus métricas deberían haber cambiado

Basándonos en los valores de total_processing_time_μs y total_responses_sent, podemos calcular que el tiempo promedio de procesamiento por solicitud fue aproximadamente de 2.4 segundos (recuerda, este endpoint es deliberadamente lento y costoso computacionalmente ya que necesitamos verificar la contraseña del usuario encriptada con bcrypt).

481455830 μs / 201 reqs = 2395303 μs/req = 2.4 s/req

Esto se alinea con los datos que estamos viendo en el resumen de resultados de hey, que da el tiempo promedio de respuesta como 2.4302 segundos. La cifra de hey es el tiempo para el viaje completo, por lo que siempre será un poco mayor ya que incluye la latencia de red y el tiempo que toma para que http.Server maneje la solicitud.

18.3 información adicional

18.3 Calculando metricas adicionales

Basándonos en esta información en la respuesta de GET /debug/vars, también podemos derivar algunas métricas adicionales interesantes. Tales como…

• El número de solicitudes ‘activas’ en vuelo: total_requests_received - total_responses_sent

• El número promedio de solicitudes recibidas por segundo (entre las llamadas A y B al punto final GET /debug/vars): (total_requests_received_B - total_requests_received_A) / (timestamp_B - timestamp_A)

• El tiempo promedio de procesamiento por solicitud (entre las llamadas A y B al punto final GET /debug/vars): (total_processing_time_μs_B - total_processing_time_μs_A) / (total_requests_received_B - total_requests_received_A

18.4 Grabación de Códigos de Estado http

Además de registrar el recuento total de respuestas enviadas, podemos llevar esto más lejos y ampliar nuestro middleware metrics() para comenzar a contar exactamente qué códigos de estado HTTP tenían nuestras respuestas.

La parte complicada de hacer esto es averiguar qué código de estado HTTP tiene una respuesta en nuestro middleware metrics(). Desafortunadamente, Go no admite esto de forma nativa; no hay una manera incorporada de examinar un http.ResponseWriter para ver qué código de estado se va a enviar a un cliente.

Para capturar el código de estado de la respuesta, en su lugar necesitaremos crear nuestro propio http.ResponseWriter personalizado que registre una copia del código de estado HTTP para acceso futuro.

Antes de que se lanzara Go 1.20, hacer esto era frágil y difícil de hacer correctamente. Pero ahora, con el nuevo tipo http.ResponseController de Go con soporte para desenrollar http.ResponseWriter, de repente se ha vuelto mucho más sencillo implementarlo por uno mismo.

Sugerencia: Si necesitas trabajar con una versión anterior de Go, te recomiendo encarecidamente que uses el paquete de terceros httpsnoop en lugar de implementar tu propio http.ResponseWriter personalizado.

Efectivamente, lo que queremos hacer es crear una estructura que envuelva un http.ResponseWriter existente y tenga los métodos Write() y WriteHeader() personalizados implementados en ella, los cuales registren el código de estado de la respuesta. Es importante también implementar un método Unwrap() en ella, que devuelva el valor original envuelto de http.ResponseWriter. El código que queremos escribir se ve así:

// El tipo metricsResponseWriter envuelve un http.ResponseWriter existente y también
// contiene un campo para registrar el código de estado de la respuesta, y un indicador booleano para
// indicar si los encabezados de respuesta ya han sido escritos.
type metricsResponseWriter struct {
    wrapped       http.ResponseWriter
    statusCode    int
    headerWritten bool
}

// Esta función devuelve una nueva instancia de metricsResponseWriter que envuelve un
// http.ResponseWriter dado y tiene un código de estado de 200 (que es el estado
// código que Go enviará en una respuesta HTTP de forma predeterminada).
func newMetricsResponseWriter(w http.ResponseWriter) *metricsResponseWriter {
    return &metricsResponseWriter{
        wrapped:    w,
        statusCode: http.StatusOK,
    }
}

// El método Header() es un 'paso a través' simple al método Header() del
// http.ResponseWriter envuelto.
func (mw *metricsResponseWriter) Header() http.Header {
    return mw.wrapped.Header()
}

// Nuevamente, el método WriteHeader() hace un 'paso a través' al método WriteHeader()
// del http.ResponseWriter envuelto. Pero después de que esto devuelve,
// también registramos el código de estado de la respuesta (si aún no se ha registrado)
// y establecemos el campo headerWritten en verdadero para indicar que la respuesta HTTP
// encabezados ya han sido escritos.
func (mw *metricsResponseWriter) WriteHeader(statusCode int) {
    mw.wrapped.WriteHeader(statusCode)
    if !mw.headerWritten {
        mw.statusCode = statusCode
        mw.headerWritten = true
    }
}

// Del mismo modo, el método Write() hace un 'paso a través' al método Write() del
// http.ResponseWriter envuelto. Llamar a esto escribirá automáticamente cualquier
// encabezados de respuesta, así que establecemos el campo headerWritten en verdadero.
func (mw *metricsResponseWriter) Write(b []byte) (int, error) {
    mw.headerWritten = true
    return mw.wrapped.Write(b)
}

// También necesitamos un método Unwrap() que devuelva el http.ResponseWriter envuelto existente.
func (mw *metricsResponseWriter) Unwrap() http.ResponseWriter {
    return mw.wrapped
}

Lo importante de darse cuenta es que nuestro tipo metricsResponseWriter satisface la interfaz http.ResponseWriter. Tiene los métodos Header(), WriteHeader() y Write() con la firma apropiada, por lo que podemos usarlo en nuestros controladores como si fuera normal.

Además, nota que no registramos el código de estado hasta después de la llamada de ‘paso a través’ en el método WriteHeader(). Esto se debe a que un pánico en esa operación (potencialmente debido a un código de estado inválido) puede significar que se envíe un código de estado diferente al cliente en última instancia.

Por último, también establecemos un código de estado predeterminado de 200 OK en la función newMetricsResponseWriter(). Es importante que establezcamos este valor predeterminado aquí, en caso de que un controlador nunca llame a Write() o WriteHeader().

Pero en última instancia, nuestro metricsResponseWriter es realmente solo una capa ligera sobre un valor existente de http.ResponseWriter.

Sigamos adelante y adaptemos nuestro middleware metrics() para usar esto. También necesitaremos publicar una nueva variable total_responses_sent_by_status utilizando la función expvar.NewMap(). Esto nos dará un mapa en el que podemos almacenar los diferentes códigos de estado HTTP, junto con un recuento acumulativo de respuestas para cada estado.

Continúa y actualiza el archivo cmd/api/middleware.go de la siguiente manera:

package main

import (
    "errors"
    "expvar"
    "fmt"
    "net"
    "net/http"
    "strconv" // Nuevo import
    "strings"
    "sync"
    "time"
    
    "greenlight.alexedwards.net/internal/data"
    "greenlight.alexedwards.net/internal/validator"
    "golang.org/x/time/rate"
)

type metricsResponseWriter struct {
    wrapped       http.ResponseWriter
    statusCode    int
    headerWritten bool
}

func newMetricsResponseWriter(w http.ResponseWriter) *metricsResponseWriter {
    return &metricsResponseWriter{
        wrapped:    w,
        statusCode: http.StatusOK,
    }
}

func (mw *metricsResponseWriter) Header() http.Header {
    return mw.wrapped.Header()
}

func (mw *metricsResponseWriter) WriteHeader(statusCode int) {
    mw.wrapped.WriteHeader(statusCode)
    if !mw.headerWritten {
        mw.statusCode = statusCode
        mw.headerWritten = true
    }
}

func (mw *metricsResponseWriter) Write(b []byte) (int, error) {
    mw.headerWritten = true
    return mw.wrapped.Write(b)
}

func (mw *metricsResponseWriter) Unwrap() http.ResponseWriter {
    return mw.wrapped
}

func (app *application) metrics(next http.Handler) http.Handler {
    var (
        totalRequestsReceived           = expvar.NewInt("total_requests_received")
        totalResponsesSent             = expvar.NewInt("total_responses_sent")
        totalProcessingTimeMicroseconds = expvar.NewInt("total_processing_time_μs")
        // Declara un nuevo mapa expvar para mantener el recuento de respuestas para cada código de estado HTTP.
        totalResponsesSentByStatus      = expvar.NewMap("total_responses_sent_by_status")
    )

    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        start := time.Now()
        totalRequestsReceived.Add(1)

        // Crea un nuevo metricsResponseWriter, que envuelve el valor original
        // http.ResponseWriter que el middleware de métricas recibió.
        mw := newMetricsResponseWriter(w)

        // Llama al siguiente manejador en la cadena usando el nuevo metricsResponseWriter
        // como el valor http.ResponseWriter.
        next.ServeHTTP(mw, r)

        totalResponsesSent.Add(1)

        // En este punto, el código de estado de la respuesta debería estar almacenado en el
        // campo mw.statusCode. Ten en cuenta que el mapa expvar es indexado por cadena, así que
        // necesitamos usar la función strconv.Itoa() para convertir el código de estado
        // (que es un entero) a una cadena. Luego usamos el método Add() en
        // nuestro nuevo mapa totalResponsesSentByStatus para incrementar el recuento para el
        // código de estado dado en 1.
        totalResponsesSentByStatus.Add(strconv.Itoa(mw.statusCode), 1)

        duration := time.Since(start).Microseconds()
        totalProcessingTimeMicroseconds.Add(duration)
    })
}

Bien, vamos a probar esto. Ejecuta la API nuevamente, pero esta vez deja el limitador de velocidad activado. De la siguiente manera:

$ go run ./cmd/api
time=2023-09-10T10:59:13.722+02:00 level=INFO msg="database connection pool established"
time=2023-09-10T10:59:13.722+02:00 level=INFO msg="starting server" addr=:4000 env=development

Luego, utiliza hey nuevamente para generar algo de carga contra el punto final POST /v1/tokens/authentication. Esto debería resultar en un pequeño número de respuestas exitosas 201 Created, pero muchas más respuestas 429 Too Many Requests debido a que se alcanza el límite de velocidad.

$ BODY='{"email": "alice@example.com", "password": "pa55word"}'
$ hey -d "$BODY" -m "POST" http://localhost:4000/v1/tokens/authentication
Summary:
Total: 0.3351 secs
Slowest: 0.3334 secs
Fastest: 0.0001 secs
Average: 0.0089 secs
Requests/sec: 596.9162
Total data: 7556 bytes
Size/request: 37 bytes
Response time histogram:
0.000 [1] |
0.033 [195] |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
0.067 [0] |
0.100 [0] |
0.133 [0] |
0.167 [0] |
0.200 [0] |
0.233 [0] |
0.267 [0] |
0.300 [0] |
0.333 [4] |■
Latency distribution:
10% in 0.0002 secs
25% in 0.0002 secs
50% in 0.0014 secs
75% in 0.0047 secs
90% in 0.0075 secs
95% in 0.0088 secs
99% in 0.3311 secs
Details (average, fastest, slowest):
DNS+dialup: 0.0008 secs, 0.0001 secs, 0.3334 secs
DNS-lookup: 0.0006 secs, 0.0000 secs, 0.0041 secs
req write: 0.0002 secs, 0.0000 secs, 0.0033 secs
resp wait: 0.0078 secs, 0.0001 secs, 0.3291 secs
resp read: 0.0000 secs, 0.0000 secs, 0.0015 secs
Status code distribution:
[201] 4 responses
[429] 196 responses

Y si echas un vistazo a las métricas en tu navegador, ahora deberías ver los mismos recuentos correspondientes para cada código de estado bajo el elemento total_responses_sent_by_status.

18.4 información adicional

18.4 Visualizando y analizanndo metricas

Ahora que tenemos algunas métricas de nivel de aplicación registradas, surge toda la pregunta de qué debes hacer con ellas. La respuesta a esto será diferente de proyecto a proyecto. Para algunas aplicaciones de bajo valor, podría ser suficiente revisar manualmente las métricas de vez en cuando, o solo cuando sospeches un problema, y asegurarte de que nada parezca inusual o fuera de lugar.

En otros proyectos, es posible que desees escribir un script para recuperar periódicamente los datos JSON del punto final GET /debug/vars y llevar a cabo un análisis adicional. Esto podría incluir funcionalidades para alertarte si algo parece ser anormal. En el otro extremo del espectro, es posible que desees utilizar una herramienta como Prometheus para recuperar y visualizar los datos del punto final, y mostrar gráficos de las métricas en tiempo real.

Hay muchas opciones diferentes, y lo correcto realmente depende de las necesidades de tu proyecto y negocio. Pero en todos los casos, utilizar el paquete expvar para recopilar y publicar las métricas te proporciona una excelente plataforma desde la cual puedes integrar cualquier herramienta externa de monitoreo, alerta o visualización.

Ahora que tenemos algunas métricas de nivel de aplicación registradas, surge toda la pregunta de qué debes hacer con ellas. La respuesta a esto será diferente de proyecto a proyecto. Para algunas aplicaciones de bajo valor, podría ser suficiente revisar manualmente las métricas de vez en cuando, o solo cuando sospeches un problema, y asegurarte de que nada parezca inusual o fuera de lugar.

En otros proyectos, es posible que desees escribir un script para recuperar periódicamente los datos JSON del punto final GET /debug/vars`` y llevar a cabo un análisis adicional. Esto podría incluir funcionalidades para alertartesi algo parece seranormal. En el otro extremo del espectro, es posible que desees utilizar una herramienta como [Prometheus](https://prometheus.io/) para recuperar y visualizar los datos del punto final, y mostrar gráficosde las métricas entiempo real`.

Hay muchas opciones diferentes, y lo correcto realmente depende de las necesidades de tu proyecto y negocio. Pero en todos los casos, utilizar el paquete expvar para recopilar y publicar las métricas te proporciona una excelente plataforma desde la cual puedes integrar cualquier herramienta externa de monitoreo, alerta o visualización.

18.Embedded http.ResponseWriter

type metricsResponseWriter struct {
    http.ResponseWriter
    statusCode    int
    headerWritten bool
}

func newMetricsResponseWriter(w http.ResponseWriter) *metricsResponseWriter {
    return &metricsResponseWriter{
        ResponseWriter: w,
        statusCode:     http.StatusOK,
    }
}

func (mw *metricsResponseWriter) WriteHeader(statusCode int) {
    mw.ResponseWriter.WriteHeader(statusCode)
    if !mw.headerWritten {
        mw.statusCode = statusCode
        mw.headerWritten = true
    }
}

func (mw *metricsResponseWriter) Write(b []byte) (int, error) {
    mw.headerWritten = true
    return mw.ResponseWriter.Write(b)
}

func (mw *metricsResponseWriter) Unwrap() http.ResponseWriter {
    return mw.ResponseWriter
}

Esto te dará el mismo resultado final que el enfoque original. Sin embargo, la ventaja es que no necesitas escribir un método Header() para la estructura metricsResponseWriter (se promociona automáticamente desde el http.ResponseWriter incrustado). Mientras que la desventaja, al menos desde mi punto de vista, es que es un poco menos claro y explícito que usar un campo envuelto. Cualquiera de los enfoques está bien, realmente es solo cuestión de gusto personal cuál prefieres.