From 60b38090b6e11b700932867dc5470b17e01de6b0 Mon Sep 17 00:00:00 2001 From: Marcin Rataj Date: Mon, 4 Apr 2022 17:13:48 +0200 Subject: [PATCH] feat(gw): tracing spans per response type (#8841) Adds more visibility into how long generic lookup takes vs producing specific response type. --- core/corehttp/gateway_handler.go | 5 +++-- core/corehttp/gateway_handler_block.go | 11 ++++++++--- core/corehttp/gateway_handler_car.go | 11 +++++++++-- core/corehttp/gateway_handler_unixfs.go | 9 +++++++-- core/corehttp/gateway_handler_unixfs_dir.go | 11 ++++++++--- core/corehttp/gateway_handler_unixfs_file.go | 10 +++++++--- docs/debug-guide.md | 6 ++++++ mk/golang.mk | 2 +- 8 files changed, 49 insertions(+), 16 deletions(-) diff --git a/core/corehttp/gateway_handler.go b/core/corehttp/gateway_handler.go index f168c84c305..e7dd77169ef 100644 --- a/core/corehttp/gateway_handler.go +++ b/core/corehttp/gateway_handler.go @@ -352,6 +352,7 @@ func (i *gatewayHandler) getOrHeadHandler(w http.ResponseWriter, r *http.Request // Detect when explicit Accept header or ?format parameter are present responseFormat := customResponseFormat(r) trace.SpanFromContext(r.Context()).SetAttributes(attribute.String("ResponseFormat", responseFormat)) + trace.SpanFromContext(r.Context()).SetAttributes(attribute.String("ResolvedPath", resolvedPath.String())) // Finish early if client already has matching Etag if r.Header.Get("If-None-Match") == getEtag(r, resolvedPath.Cid()) { @@ -390,11 +391,11 @@ func (i *gatewayHandler) getOrHeadHandler(w http.ResponseWriter, r *http.Request return case "application/vnd.ipld.raw": logger.Debugw("serving raw block", "path", contentPath) - i.serveRawBlock(w, r, resolvedPath.Cid(), contentPath, begin) + i.serveRawBlock(w, r, resolvedPath, 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, begin) + i.serveCar(w, r, resolvedPath, contentPath, begin) return default: // catch-all for unsuported application/vnd.* err := fmt.Errorf("unsupported format %q", responseFormat) diff --git a/core/corehttp/gateway_handler_block.go b/core/corehttp/gateway_handler_block.go index 13d7ebefd9f..891c418c87a 100644 --- a/core/corehttp/gateway_handler_block.go +++ b/core/corehttp/gateway_handler_block.go @@ -6,13 +6,18 @@ import ( "net/http" "time" - cid "github.com/ipfs/go-cid" + "github.com/ipfs/go-ipfs/tracing" ipath "github.com/ipfs/interface-go-ipfs-core/path" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/trace" ) // serveRawBlock returns bytes behind a raw block -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) +func (i *gatewayHandler) serveRawBlock(w http.ResponseWriter, r *http.Request, resolvedPath ipath.Resolved, contentPath ipath.Path, begin time.Time) { + ctx, span := tracing.Span(r.Context(), "Gateway", "ServeRawBlock", trace.WithAttributes(attribute.String("path", resolvedPath.String()))) + defer span.End() + blockCid := resolvedPath.Cid() + blockReader, err := i.api.Block().Get(ctx, resolvedPath) if err != nil { webError(w, "ipfs block get "+blockCid.String(), err, http.StatusInternalServerError) return diff --git a/core/corehttp/gateway_handler_car.go b/core/corehttp/gateway_handler_car.go index 5f0f2117fc7..de618e47cf4 100644 --- a/core/corehttp/gateway_handler_car.go +++ b/core/corehttp/gateway_handler_car.go @@ -7,17 +7,24 @@ import ( blocks "github.com/ipfs/go-block-format" cid "github.com/ipfs/go-cid" + "github.com/ipfs/go-ipfs/tracing" coreiface "github.com/ipfs/interface-go-ipfs-core" ipath "github.com/ipfs/interface-go-ipfs-core/path" gocar "github.com/ipld/go-car" selectorparse "github.com/ipld/go-ipld-prime/traversal/selector/parse" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/trace" ) // 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, begin time.Time) { - ctx, cancel := context.WithCancel(r.Context()) +func (i *gatewayHandler) serveCar(w http.ResponseWriter, r *http.Request, resolvedPath ipath.Resolved, contentPath ipath.Path, begin time.Time) { + ctx, span := tracing.Span(r.Context(), "Gateway", "ServeCar", trace.WithAttributes(attribute.String("path", resolvedPath.String()))) + defer span.End() + ctx, cancel := context.WithCancel(ctx) defer cancel() + rootCid := resolvedPath.Cid() + // Set Content-Disposition name := rootCid.String() + ".car" setContentDispositionHeader(w, name, "attachment") diff --git a/core/corehttp/gateway_handler_unixfs.go b/core/corehttp/gateway_handler_unixfs.go index ed15f41393b..2252b3891c6 100644 --- a/core/corehttp/gateway_handler_unixfs.go +++ b/core/corehttp/gateway_handler_unixfs.go @@ -7,13 +7,18 @@ import ( "time" files "github.com/ipfs/go-ipfs-files" + "github.com/ipfs/go-ipfs/tracing" ipath "github.com/ipfs/interface-go-ipfs-core/path" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/trace" "go.uber.org/zap" ) func (i *gatewayHandler) serveUnixFs(w http.ResponseWriter, r *http.Request, resolvedPath ipath.Resolved, contentPath ipath.Path, begin time.Time, logger *zap.SugaredLogger) { + ctx, span := tracing.Span(r.Context(), "Gateway", "ServeUnixFs", trace.WithAttributes(attribute.String("path", resolvedPath.String()))) + defer span.End() // Handling UnixFS - dr, err := i.api.Unixfs().Get(r.Context(), resolvedPath) + dr, err := i.api.Unixfs().Get(ctx, resolvedPath) if err != nil { webError(w, "ipfs cat "+html.EscapeString(contentPath.String()), err, http.StatusNotFound) return @@ -23,7 +28,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, begin) + i.serveFile(w, r, resolvedPath, contentPath, f, begin) return } diff --git a/core/corehttp/gateway_handler_unixfs_dir.go b/core/corehttp/gateway_handler_unixfs_dir.go index 87708159e8e..e458e803076 100644 --- a/core/corehttp/gateway_handler_unixfs_dir.go +++ b/core/corehttp/gateway_handler_unixfs_dir.go @@ -10,9 +10,12 @@ import ( "github.com/dustin/go-humanize" files "github.com/ipfs/go-ipfs-files" "github.com/ipfs/go-ipfs/assets" + "github.com/ipfs/go-ipfs/tracing" path "github.com/ipfs/go-path" "github.com/ipfs/go-path/resolver" ipath "github.com/ipfs/interface-go-ipfs-core/path" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/trace" "go.uber.org/zap" ) @@ -20,6 +23,8 @@ import ( // // 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, begin time.Time, logger *zap.SugaredLogger) { + ctx, span := tracing.Span(r.Context(), "Gateway", "ServeDirectory", trace.WithAttributes(attribute.String("path", resolvedPath.String()))) + defer span.End() // HostnameOption might have constructed an IPNS/IPFS path using the Host header. // In this case, we need the original path for constructing redirects @@ -35,7 +40,7 @@ func (i *gatewayHandler) serveDirectory(w http.ResponseWriter, r *http.Request, // Check if directory has index.html, if so, serveFile idxPath := ipath.Join(resolvedPath, "index.html") - idx, err := i.api.Unixfs().Get(r.Context(), idxPath) + idx, err := i.api.Unixfs().Get(ctx, idxPath) switch err.(type) { case nil: cpath := contentPath.String() @@ -63,7 +68,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, begin) + i.serveFile(w, r, resolvedPath, idxPath, f, begin) return case resolver.ErrNoLink: logger.Debugw("no index.html; noop", "path", idxPath) @@ -111,7 +116,7 @@ func (i *gatewayHandler) serveDirectory(w http.ResponseWriter, r *http.Request, size = humanize.Bytes(uint64(s)) } - resolved, err := i.api.ResolvePath(r.Context(), ipath.Join(resolvedPath, dirit.Name())) + resolved, err := i.api.ResolvePath(ctx, ipath.Join(resolvedPath, dirit.Name())) if err != nil { internalWebError(w, err) return diff --git a/core/corehttp/gateway_handler_unixfs_file.go b/core/corehttp/gateway_handler_unixfs_file.go index 9807969fee0..e8a3718fc16 100644 --- a/core/corehttp/gateway_handler_unixfs_file.go +++ b/core/corehttp/gateway_handler_unixfs_file.go @@ -10,17 +10,21 @@ import ( "time" "github.com/gabriel-vasile/mimetype" - cid "github.com/ipfs/go-cid" files "github.com/ipfs/go-ipfs-files" + "github.com/ipfs/go-ipfs/tracing" ipath "github.com/ipfs/interface-go-ipfs-core/path" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/trace" ) // 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, begin time.Time) { +func (i *gatewayHandler) serveFile(w http.ResponseWriter, r *http.Request, resolvedPath ipath.Resolved, contentPath ipath.Path, file files.File, begin time.Time) { + _, span := tracing.Span(r.Context(), "Gateway", "ServeFile", trace.WithAttributes(attribute.String("path", resolvedPath.String()))) + defer span.End() // Set Cache-Control and read optional Last-Modified time - modtime := addCacheControlHeaders(w, r, contentPath, fileCid) + modtime := addCacheControlHeaders(w, r, contentPath, resolvedPath.Cid()) // Set Content-Disposition name := addContentDispositionHeader(w, r, contentPath) diff --git a/docs/debug-guide.md b/docs/debug-guide.md index 07439c37cfe..5bb39eee564 100644 --- a/docs/debug-guide.md +++ b/docs/debug-guide.md @@ -7,6 +7,7 @@ This is a document for helping debug go-ipfs. Please add to it if you can! - [Analyzing the stack dump](#analyzing-the-stack-dump) - [Analyzing the CPU Profile](#analyzing-the-cpu-profile) - [Analyzing vars and memory statistics](#analyzing-vars-and-memory-statistics) +- [Tracing](#tracing) - [Other](#other) ### Beginning @@ -95,6 +96,11 @@ the quickest way to easily point out where the hot spots in the code are. The output is JSON formatted and includes badger store statistics, the command line run, and the output from Go's [runtime.ReadMemStats](https://golang.org/pkg/runtime/#ReadMemStats). The [MemStats](https://golang.org/pkg/runtime/#MemStats) has useful information about memory allocation and garbage collection. +### Tracing + +Experimental tracing via OpenTelemetry suite of tools is available. +See `tracing/doc.go` for more details. + ### Other If you have any questions, or want us to analyze some weird go-ipfs behaviour, diff --git a/mk/golang.mk b/mk/golang.mk index 0b2a2c55ae2..7ede944637f 100644 --- a/mk/golang.mk +++ b/mk/golang.mk @@ -70,7 +70,7 @@ test_go_fmt: TEST_GO += test_go_fmt test_go_lint: test/bin/golangci-lint - golangci-lint run ./... + golangci-lint run --timeout=3m ./... .PHONY: test_go_lint test_go: $(TEST_GO)