feat: add gateway histogram metrics (#8443)

* feat(gw): response type histogram metrics

- response-type agnostic firstContentBlockGetMetric which counts the
  latency til the first content block.

- car/block/file/gen-dir-index duration histogram metrics that show how
  long each response type takes

* docs: improve metrics descriptions
* feat: more gw histogram buckets

0.05, 0.1, 0.25, 0.5, 1, 2, 5, 10, 30, 60 secs
as suggested in reviews at ipfs/kubo#8443

Co-authored-by: Marcin Rataj <lidel@lidel.org>
Co-authored-by: Gus Eggert <gus@gus.dev>

This commit was moved from ipfs/kubo@beaa8fc

gateway/core/corehttp/gateway_handler.go

@@ -62,7 +62,15 @@ type gatewayHandler struct {
 	config GatewayConfig
 	api    coreiface.CoreAPI
 
-	unixfsGetMetric *prometheus.SummaryVec
+	// generic metrics
+	firstContentBlockGetMetric *prometheus.HistogramVec
+	unixfsGetMetric            *prometheus.SummaryVec // deprecated, use firstContentBlockGetMetric
+
+	// response type metrics
+	unixfsFileGetMetric   *prometheus.HistogramVec
+	unixfsGenDirGetMetric *prometheus.HistogramVec
+	carStreamGetMetric    *prometheus.HistogramVec
+	rawBlockGetMetric     *prometheus.HistogramVec
 }
 
 // StatusResponseWriter enables us to override HTTP Status Code passed to
@@ -85,29 +93,93 @@ func (sw *statusResponseWriter) WriteHeader(code int) {
 	sw.ResponseWriter.WriteHeader(code)
 }
 
-func newGatewayHandler(c GatewayConfig, api coreiface.CoreAPI) *gatewayHandler {
-	unixfsGetMetric := prometheus.NewSummaryVec(
-		// TODO: deprecate and switch to content type agnostic metrics: https://github.com/ipfs/go-ipfs/issues/8441
+func newGatewaySummaryMetric(name string, help string) *prometheus.SummaryVec {
+	summaryMetric := prometheus.NewSummaryVec(
 		prometheus.SummaryOpts{
 			Namespace: "ipfs",
 			Subsystem: "http",
-			Name:      "unixfs_get_latency_seconds",
-			Help:      "The time till the first block is received when 'getting' a file from the gateway.",
+			Name:      name,
+			Help:      help,
+		},
+		[]string{"gateway"},
+	)
+	if err := prometheus.Register(summaryMetric); err != nil {
+		if are, ok := err.(prometheus.AlreadyRegisteredError); ok {
+			summaryMetric = are.ExistingCollector.(*prometheus.SummaryVec)
+		} else {
+			log.Errorf("failed to register ipfs_http_%s: %v", name, err)
+		}
+	}
+	return summaryMetric
+}
+
+func newGatewayHistogramMetric(name string, help string) *prometheus.HistogramVec {
+	// We can add buckets as a parameter in the future, but for now using static defaults
+	// suggested in https://github.com/ipfs/go-ipfs/issues/8441
+	defaultBuckets := []float64{0.05, 0.1, 0.25, 0.5, 1, 2, 5, 10, 30, 60}
+	histogramMetric := prometheus.NewHistogramVec(
+		prometheus.HistogramOpts{
+			Namespace: "ipfs",
+			Subsystem: "http",
+			Name:      name,
+			Help:      help,
+			Buckets:   defaultBuckets,
 		},
 		[]string{"gateway"},
 	)
-	if err := prometheus.Register(unixfsGetMetric); err != nil {
+	if err := prometheus.Register(histogramMetric); err != nil {
 		if are, ok := err.(prometheus.AlreadyRegisteredError); ok {
-			unixfsGetMetric = are.ExistingCollector.(*prometheus.SummaryVec)
+			histogramMetric = are.ExistingCollector.(*prometheus.HistogramVec)
 		} else {
-			log.Errorf("failed to register unixfsGetMetric: %v", err)
+			log.Errorf("failed to register ipfs_http_%s: %v", name, err)
 		}
 	}
+	return histogramMetric
+}
 
+func newGatewayHandler(c GatewayConfig, api coreiface.CoreAPI) *gatewayHandler {
 	i := &gatewayHandler{
-		config:          c,
-		api:             api,
-		unixfsGetMetric: unixfsGetMetric,
+		config: c,
+		api:    api,
+		// Improved Metrics
+		// ----------------------------
+		// Time till the first content block (bar in /ipfs/cid/foo/bar)
+		// (format-agnostic, across all response types)
+		firstContentBlockGetMetric: newGatewayHistogramMetric(
+			"gw_first_content_block_get_latency_seconds",
+			"The time till the first content block is received on GET from the gateway.",
+		),
+
+		// Response-type specific metrics
+		// ----------------------------
+		// UnixFS: time it takes to return a file
+		unixfsFileGetMetric: newGatewayHistogramMetric(
+			"gw_unixfs_file_get_duration_seconds",
+			"The time to serve an entire UnixFS file from the gateway.",
+		),
+		// UnixFS: time it takes to generate static HTML with directory listing
+		unixfsGenDirGetMetric: newGatewayHistogramMetric(
+			"gw_unixfs_gen_dir_listing_get_duration_seconds",
+			"The time to serve a generated UnixFS HTML directory listing from the gateway.",
+		),
+		// CAR: time it takes to return requested CAR stream
+		carStreamGetMetric: newGatewayHistogramMetric(
+			"gw_car_stream_get_duration_seconds",
+			"The time to GET an entire CAR stream from the gateway.",
+		),
+		// Block: time it takes to return requested Block
+		rawBlockGetMetric: newGatewayHistogramMetric(
+			"gw_raw_block_get_duration_seconds",
+			"The time to GET an entire raw Block from the gateway.",
+		),
+
+		// Legacy Metrics
+		// ----------------------------
+		unixfsGetMetric: newGatewaySummaryMetric( // TODO: remove?
+			// (deprecated, use firstContentBlockGetMetric instead)
+			"unixfs_get_latency_seconds",
+			"The time to receive the first UnixFS node on a GET from the gateway.",
+		),
 	}
 	return i
 }
@@ -291,7 +363,10 @@ func (i *gatewayHandler) getOrHeadHandler(w http.ResponseWriter, r *http.Request
 		webError(w, "ipfs block get "+resolvedPath.Cid().String(), err, http.StatusInternalServerError)
 		return
 	}
-	i.unixfsGetMetric.WithLabelValues(contentPath.Namespace()).Observe(time.Since(begin).Seconds())
+	ns := contentPath.Namespace()
+	timeToGetFirstContentBlock := time.Since(begin).Seconds()
+	i.unixfsGetMetric.WithLabelValues(ns).Observe(timeToGetFirstContentBlock) // deprecated, use firstContentBlockGetMetric instead
+	i.firstContentBlockGetMetric.WithLabelValues(ns).Observe(timeToGetFirstContentBlock)
 
 	// HTTP Headers
 	i.addUserHeaders(w) // ok, _now_ write user's headers.
@@ -308,15 +383,15 @@ func (i *gatewayHandler) getOrHeadHandler(w http.ResponseWriter, r *http.Request
 	switch responseFormat {
 	case "": // The implicit response format is UnixFS
 		logger.Debugw("serving unixfs", "path", contentPath)
-		i.serveUnixFs(w, r, resolvedPath, contentPath, logger)
+		i.serveUnixFs(w, r, resolvedPath, contentPath, begin, logger)
 		return
 	case "application/vnd.ipld.raw":
 		logger.Debugw("serving raw block", "path", contentPath)
-		i.serveRawBlock(w, r, resolvedPath.Cid(), contentPath)
+		i.serveRawBlock(w, r, resolvedPath.Cid(), contentPath, begin)
 		return
 	case "application/vnd.ipld.car", "application/vnd.ipld.car; version=1":
 		logger.Debugw("serving car stream", "path", contentPath)
-		i.serveCar(w, r, resolvedPath.Cid(), contentPath)
+		i.serveCar(w, r, resolvedPath.Cid(), contentPath, begin)
 		return
 	default: // catch-all for unsuported application/vnd.*
 		err := fmt.Errorf("unsupported format %q", responseFormat)

gateway/core/corehttp/gateway_handler_block.go

@@ -4,13 +4,14 @@ import (
 	"bytes"
 	"io/ioutil"
 	"net/http"
+	"time"
 
 	cid "github.com/ipfs/go-cid"
 	ipath "github.com/ipfs/interface-go-ipfs-core/path"
 )
 
 // serveRawBlock returns bytes behind a raw block
-func (i *gatewayHandler) serveRawBlock(w http.ResponseWriter, r *http.Request, blockCid cid.Cid, contentPath ipath.Path) {
+func (i *gatewayHandler) serveRawBlock(w http.ResponseWriter, r *http.Request, blockCid cid.Cid, contentPath ipath.Path, begin time.Time) {
 	blockReader, err := i.api.Block().Get(r.Context(), contentPath)
 	if err != nil {
 		webError(w, "ipfs block get "+blockCid.String(), err, http.StatusInternalServerError)
@@ -35,4 +36,7 @@ func (i *gatewayHandler) serveRawBlock(w http.ResponseWriter, r *http.Request, b
 	// Done: http.ServeContent will take care of
 	// If-None-Match+Etag, Content-Length and range requests
 	http.ServeContent(w, r, name, modtime, content)
+
+	// Update metrics
+	i.rawBlockGetMetric.WithLabelValues(contentPath.Namespace()).Observe(time.Since(begin).Seconds())
 }

gateway/core/corehttp/gateway_handler_car.go

@@ -3,6 +3,7 @@ package corehttp
 import (
 	"context"
 	"net/http"
+	"time"
 
 	blocks "github.com/ipfs/go-block-format"
 	cid "github.com/ipfs/go-cid"
@@ -13,7 +14,7 @@ import (
 )
 
 // serveCar returns a CAR stream for specific DAG+selector
-func (i *gatewayHandler) serveCar(w http.ResponseWriter, r *http.Request, rootCid cid.Cid, contentPath ipath.Path) {
+func (i *gatewayHandler) serveCar(w http.ResponseWriter, r *http.Request, rootCid cid.Cid, contentPath ipath.Path, begin time.Time) {
 	ctx, cancel := context.WithCancel(r.Context())
 	defer cancel()
 
@@ -59,6 +60,9 @@ func (i *gatewayHandler) serveCar(w http.ResponseWriter, r *http.Request, rootCi
 		w.Header().Set("X-Stream-Error", err.Error())
 		return
 	}
+
+	// Update metrics
+	i.carStreamGetMetric.WithLabelValues(contentPath.Namespace()).Observe(time.Since(begin).Seconds())
 }
 
 type dagStore struct {

gateway/core/corehttp/gateway_handler_unixfs.go

@@ -4,13 +4,14 @@ import (
 	"fmt"
 	"html"
 	"net/http"
+	"time"
 
 	files "github.com/ipfs/go-ipfs-files"
 	ipath "github.com/ipfs/interface-go-ipfs-core/path"
 	"go.uber.org/zap"
 )
 
-func (i *gatewayHandler) serveUnixFs(w http.ResponseWriter, r *http.Request, resolvedPath ipath.Resolved, contentPath ipath.Path, logger *zap.SugaredLogger) {
+func (i *gatewayHandler) serveUnixFs(w http.ResponseWriter, r *http.Request, resolvedPath ipath.Resolved, contentPath ipath.Path, begin time.Time, logger *zap.SugaredLogger) {
 	// Handling UnixFS
 	dr, err := i.api.Unixfs().Get(r.Context(), resolvedPath)
 	if err != nil {
@@ -22,7 +23,7 @@ func (i *gatewayHandler) serveUnixFs(w http.ResponseWriter, r *http.Request, res
 	// Handling Unixfs file
 	if f, ok := dr.(files.File); ok {
 		logger.Debugw("serving unixfs file", "path", contentPath)
-		i.serveFile(w, r, contentPath, resolvedPath.Cid(), f)
+		i.serveFile(w, r, contentPath, resolvedPath.Cid(), f, begin)
 		return
 	}
 
@@ -33,5 +34,5 @@ func (i *gatewayHandler) serveUnixFs(w http.ResponseWriter, r *http.Request, res
 		return
 	}
 	logger.Debugw("serving unixfs directory", "path", contentPath)
-	i.serveDirectory(w, r, resolvedPath, contentPath, dir, logger)
+	i.serveDirectory(w, r, resolvedPath, contentPath, dir, begin, logger)
 }

gateway/core/corehttp/gateway_handler_unixfs_dir.go

@@ -5,6 +5,7 @@ import (
 	"net/url"
 	gopath "path"
 	"strings"
+	"time"
 
 	"github.com/dustin/go-humanize"
 	files "github.com/ipfs/go-ipfs-files"
@@ -18,7 +19,7 @@ import (
 // serveDirectory returns the best representation of UnixFS directory
 //
 // It will return index.html if present, or generate directory listing otherwise.
-func (i *gatewayHandler) serveDirectory(w http.ResponseWriter, r *http.Request, resolvedPath ipath.Resolved, contentPath ipath.Path, dir files.Directory, logger *zap.SugaredLogger) {
+func (i *gatewayHandler) serveDirectory(w http.ResponseWriter, r *http.Request, resolvedPath ipath.Resolved, contentPath ipath.Path, dir files.Directory, begin time.Time, logger *zap.SugaredLogger) {
 
 	// HostnameOption might have constructed an IPNS/IPFS path using the Host header.
 	// In this case, we need the original path for constructing redirects
@@ -62,7 +63,7 @@ func (i *gatewayHandler) serveDirectory(w http.ResponseWriter, r *http.Request,
 
 		logger.Debugw("serving index.html file", "path", idxPath)
 		// write to request
-		i.serveFile(w, r, idxPath, resolvedPath.Cid(), f)
+		i.serveFile(w, r, idxPath, resolvedPath.Cid(), f, begin)
 		return
 	case resolver.ErrNoLink:
 		logger.Debugw("no index.html; noop", "path", idxPath)
@@ -194,4 +195,7 @@ func (i *gatewayHandler) serveDirectory(w http.ResponseWriter, r *http.Request,
 		internalWebError(w, err)
 		return
 	}
+
+	// Update metrics
+	i.unixfsGenDirGetMetric.WithLabelValues(contentPath.Namespace()).Observe(time.Since(begin).Seconds())
 }

gateway/core/corehttp/gateway_handler_unixfs_file.go

@@ -7,6 +7,7 @@ import (
 	"net/http"
 	gopath "path"
 	"strings"
+	"time"
 
 	"github.com/gabriel-vasile/mimetype"
 	cid "github.com/ipfs/go-cid"
@@ -16,7 +17,7 @@ import (
 
 // serveFile returns data behind a file along with HTTP headers based on
 // the file itself, its CID and the contentPath used for accessing it.
-func (i *gatewayHandler) serveFile(w http.ResponseWriter, r *http.Request, contentPath ipath.Path, fileCid cid.Cid, file files.File) {
+func (i *gatewayHandler) serveFile(w http.ResponseWriter, r *http.Request, contentPath ipath.Path, fileCid cid.Cid, file files.File, begin time.Time) {
 
 	// Set Cache-Control and read optional Last-Modified time
 	modtime := addCacheControlHeaders(w, r, contentPath, fileCid)
@@ -80,4 +81,7 @@ func (i *gatewayHandler) serveFile(w http.ResponseWriter, r *http.Request, conte
 	// Done: http.ServeContent will take care of
 	// If-None-Match+Etag, Content-Length and range requests
 	http.ServeContent(w, r, name, modtime, content)
+
+	// Update metrics
+	i.unixfsFileGetMetric.WithLabelValues(contentPath.Namespace()).Observe(time.Since(begin).Seconds())
 }