feat: add basic gateway tracing #8595

guseggert · 2021-12-08T17:54:39Z

@lidel's blurb for Release Notes (wip)

see copy text in tracing/doc.go

Added spans

The root span for gateway request is named Rateway.Request
- http.target has "original" request
- ResolvedPath has immutable IPFS path behind the original request (matters when /ipns/)
Each response format type has its own span:
- Gateway.ServeRawBlock
- Gateway.ServeCar
- Gateway.ServeUnixFs
  - Gateway.ServeFile
  - Gateway.ServeDirectory

How to use Jaeger UI

One can use the jaegertracing/all-in-one Docker image to run a full Jaeger
stack and configure go-ipfs to publish traces to it (here, in an ephemeral
container):

$ docker run --rm -it --name jaeger \
    -e COLLECTOR_ZIPKIN_HOST_PORT=:9411 \
    -p 5775:5775/udp \
    -p 6831:6831/udp \
    -p 6832:6832/udp \
    -p 5778:5778 \
    -p 16686:16686 \
    -p 14268:14268 \
    -p 14250:14250 \
    -p 9411:9411 \
    jaegertracing/all-in-one

Then, in other terminal, start go-ipfs with Jaeger tracing enabled:

$ IPFS_TRACING=1 IPFS_TRACING_JAEGER=1 ipfs daemon

Finally, the Jaeger UI is available at http://localhost:16686

Demo

CAR	Block	File	Directory

cmd/ipfs/main.go

core/coreapi/path.go

core/corehttp/gateway_handler.go

frrist

Good stuff!

frrist · 2021-12-16T21:30:27Z

core/coreapi/unixfs.go

 	settings, prefix, err := options.UnixfsAddOptions(opts...)
 	if err != nil {
 		return nil, err
 	}

+	span.SetAttributes(


Allocations can be avoided here (and elsewhere when attributes are used) by only setting them when the span is recording. e.g.

if span.IsRecording() { // set stuffs }

Admittedly, this is tedious for some of the one-liners that start a span and set attributes together; I wonder if there is an alternative...

I also wonder if it's worth adding an Attributes method to some of these types like settings, for example. It may be more appropriate for a follow-on.

My thought process here was that we already know we have way bigger fish to fry in terms of memory allocations, so I wasn't too concerned with this. Hopefully one day we get to the point where these matter...in the meantime, we can enjoy the simpler code

iand

Looks good and I've been using this branch to study gateway performance characteristics.

iand · 2022-03-31T10:52:07Z

tracing/tracing.go

+
+// Span starts a new span using the standard IPFS tracing conventions.
+func Span(ctx context.Context, componentName string, spanName string, opts ...traceapi.SpanStartOption) (context.Context, traceapi.Span) {
+	return otel.Tracer("go-ipfs").Start(ctx, fmt.Sprintf("%s.%s", componentName, spanName), opts...)


I think the argument to otel.Tracer should be an empty string to use the default instrumentating library name as per the documentaion. Note the distinction made between Instrumented Library and Instrumenting Library

My understanding is that this tracer name ("instrumentation name") is similar to our logging "subsystems", in that the application can use these to know which component a span comes from, and use that to decide things like whether to record the span at all (see e.g. https://opentelemetry.io/docs/instrumentation/java/automatic/agent-config/#suppressing-specific-agent-instrumentation and https://github.com/open-telemetry/opentelemetry-go/blob/main/sdk/trace/span_processor_filter_example_test.go#L53 ). E.g. if an application uses this repo as a library, it can decide to drop all spans from go-ipfs using this instrumentation name. If we use empty string here, the default go.opentelemetry.io/otel/sdk/tracer will be used. See also https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/trace/api.md#get-a-tracer .

I think it is intended that the default tracer is used since we aren't changing the format of the traces. We already record the name of the system and the software used to record the trace in the Resource section. See, for example, this section of one trace. The otel documentation is not super clear but I feel that the presence of Version and SchemaURL fields in the InstrumentationLibrary object imply that this is related to the type of trace that has been produced.

"Resource": [ { "Key": "service.name", "Value": { "Type": "STRING", "Value": "go-ipfs" } }, { "Key": "service.version", "Value": { "Type": "STRING", "Value": "0.13.0-dev" } }, { "Key": "telemetry.sdk.language", "Value": { "Type": "STRING", "Value": "go" } }, { "Key": "telemetry.sdk.name", "Value": { "Type": "STRING", "Value": "opentelemetry" } }, { "Key": "telemetry.sdk.version", "Value": { "Type": "STRING", "Value": "1.6.1" } } ], "InstrumentationLibrary": { "Name": "go-ipfs", "Version": "", "SchemaURL": "" }

I think the service is more at the "application" scope, so that we can tell from which system the spans of a distributed trace originate.

I'm also new to these concepts, so I've generally been mimicking the provided examples, which seem to use the same distinction: https://github.com/open-telemetry/opentelemetry-go/tree/main/example

Fair enough. I don't feel strongly about it. It's possible that the SchemaURL/Version fields are intended to describe the schema of the tags that the library is writing.

Yeah I'm not sure what those are for. This is all clearly communicated as experimental so that we have some wiggle room to adjust these over time as we learn more.

iand · 2022-03-31T11:01:37Z

tracing/tracing.go

+}
+
+// Span starts a new span using the standard IPFS tracing conventions.
+func Span(ctx context.Context, componentName string, spanName string, opts ...traceapi.SpanStartOption) (context.Context, traceapi.Span) {


This is a candidate for moving to a new library package. As we add tracing to more base libraries we will repeat this multiple times and we can add more helpers to keep things consistent and to reduce the number of imports needed to start a span.

I started one here https://github.com/iand/go-ipfs-tracing as part of my experiments with this branch and instrumenting other related libraries.

Yeah that makes sense, I was waiting to create something like this until I used OpenTelemetry in a few repos to understand our usage patterns better. I'm also hesitant to make a tracing "kitchen sink", since it seems like a place that would accumulate dependencies over time and significantly contribute to our dependency hell.

iand · 2022-03-31T15:12:10Z

tracing/doc.go

+// Span names follow a convention of <Component>.<Span>, some examples:
+//
+//  - component=Gateway + span=Request -> Gateway.Request
+//  - component=CoreAPI.PinAPI + span=Verify.CheckPin -> CoreAPI.PinAPI.Verify.CheckPin


Can we tighten this convention up? I think we need to define what a component is and what convention we have for naming the span - is it the type name and method, or should it include the package somehow? We'll need this as soon as we start adding tracing to other ipfs libraries.

One convention could be that the component is the repo name go-ipfs/go-blockservice/go-namesys and the Span name is the function name, prefixed by the typename if it's a method. Additional spans within a function would use a name derived from this base. The convention would lead to names like:

go-ipfs.PinAPI.Add

go-blockservice.Session.GetBlock

go-namesys.ResolveIPNS

We could include package name but it would make the names much longer for no great benefit, go-ipfs.PinAPI.Add could be ``go-ipfs.core.coreapi.PinAPI.Add` (would also be extra maintenance burden to keep names in sync when refactoring)

This convention is not the prettiest but it would work consistently across all our libraries and gives signposts for developers looking for where a particular span was created.

This would need to be modified if we keep the library name in the Instrumentation Library field (although I don't know how/if that surfaces in the Jaeger UI for example)

I'd like to protect our ability to refactor repos, modules, and packages without breaking tracing consumers, so I'd like to avoid coupling it to those as much as possible. Much like we do with logging subsystems (I toyed with the idea of coupling these with logging subsystems but gave up.) The downside though is that it makes it harder to find the code origin of traces, but I still don't think that's very hard with a quick GitHub search. Or we could add some middleware that adds an attribute to all spans with the source file + line info of where the span originated?

lidel

Took it for a spin, works as expected 👍

Added more Gateway.* spans in #8841 (needs to be merged into this PR) + small asks below.

tracing/doc.go

test/sharness/t0310-tracing.sh

BigLep · 2022-04-01T16:07:17Z

2022-04-01: @lidel will incorporate feedback in #8841, then merge it here, review PR as a whole, merge!

Adds more visibility into how long generic lookup takes vs producing specific response type.

lidel · 2022-04-04T17:20:55Z

The only CI test that fails is go-ipfs-http-client, which is unrelated to changes from this PR and being fixed in #8838

Resolved conflicts, merging to avoid doing this again.

lidel

LGTM, we can adjust / add more spans in future PRs.

Added Jaeger UI instruction to docs/environment-variables.md, should be really useful for newcomers / gateway admins.
Drafted a blurb for go-ipfs 0.13 Release Notes in feat: add basic gateway tracing #8595 (comment)

guseggert requested review from frrist and coryschwartz December 8, 2021 17:54

guseggert linked an issue Dec 8, 2021 that may be closed by this pull request

Add comprehensive tracing #8578

Open

9 tasks

guseggert removed a link to an issue Dec 8, 2021

Add comprehensive tracing #8578

Open

9 tasks

guseggert mentioned this pull request Dec 8, 2021

Add comprehensive tracing #8578

Open

9 tasks

guseggert force-pushed the feat/tracing branch from 66b4fe3 to 5d08759 Compare December 8, 2021 18:01

whyrusleeping reviewed Dec 8, 2021

View reviewed changes

cmd/ipfs/main.go Outdated Show resolved Hide resolved

whyrusleeping reviewed Dec 8, 2021

View reviewed changes

core/coreapi/path.go Outdated Show resolved Hide resolved

whyrusleeping reviewed Dec 8, 2021

View reviewed changes

core/coreapi/path.go Outdated Show resolved Hide resolved

whyrusleeping reviewed Dec 8, 2021

View reviewed changes

core/corehttp/gateway_handler.go Outdated Show resolved Hide resolved

guseggert force-pushed the feat/tracing branch 4 times, most recently from 5cab996 to 9b9691c Compare December 16, 2021 16:17

BigLep linked an issue Dec 16, 2021 that may be closed by this pull request

Add comprehensive tracing #8578

Open

9 tasks

guseggert force-pushed the feat/tracing branch 4 times, most recently from 791c811 to 2a4398d Compare December 16, 2021 20:35

frrist reviewed Dec 16, 2021

View reviewed changes

guseggert force-pushed the feat/tracing branch from 2a4398d to ca46ca5 Compare March 24, 2022 14:30

guseggert added 4 commits March 24, 2022 10:31

feat: add basic gateway tracing

809863f

Add deprecation warning when tracer plugins are loaded

bf5d8f9

add response format attribute to span in gateway handler

c1ce763

add note about tracing's experimental status in godoc

fbcbe30

guseggert force-pushed the feat/tracing branch from ca46ca5 to fbcbe30 Compare March 24, 2022 14:31

guseggert added 4 commits March 25, 2022 11:00

add nil check for TTL when adding name span attrs

ea51027

add basic sharness test for integration with otel collector

fc165f5

add nil check in UnixFSAPI.processLink

28268c6

tracing sharness test: check all json objs for swarm span

a334329

guseggert marked this pull request as ready for review March 26, 2022 14:05

guseggert self-assigned this Mar 26, 2022

guseggert added the kind/feature A new feature label Mar 26, 2022

guseggert added this to the go-ipfs 0.13 milestone Mar 26, 2022

guseggert requested a review from lidel March 28, 2022 20:54

iand reviewed Mar 31, 2022

View reviewed changes

lidel mentioned this pull request Apr 1, 2022

feat(gw): tracing spans per response type #8841

Merged

lidel requested changes Apr 1, 2022

View reviewed changes

tracing/doc.go Show resolved Hide resolved

test/sharness/t0310-tracing.sh Outdated Show resolved Hide resolved

guseggert added 2 commits April 1, 2022 08:00

add env var docs to docs/environment-variables.md

b27f463

pin the otel collector version

3e3f7d5

guseggert force-pushed the feat/tracing branch from a4edab3 to 3e3f7d5 Compare April 1, 2022 14:55

guseggert removed the request for review from coryschwartz April 1, 2022 14:56

lidel added 2 commits April 4, 2022 17:13

feat(gw): tracing spans per response type (#8841)

60b3809

Adds more visibility into how long generic lookup takes vs producing specific response type.

Merge branch 'master' into feat/tracing

4319420

lidel force-pushed the feat/tracing branch from 87913bd to 4319420 Compare April 4, 2022 15:38

docs: tracing with jaeger-ui

7c56ac0

lidel approved these changes Apr 4, 2022

View reviewed changes

lidel merged commit f855bfe into master Apr 4, 2022

lidel deleted the feat/tracing branch April 4, 2022 17:24

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: add basic gateway tracing #8595

feat: add basic gateway tracing #8595

guseggert commented Dec 8, 2021 •

edited by lidel

Loading

frrist left a comment

frrist Dec 16, 2021

frrist Dec 16, 2021

frrist Dec 16, 2021 •

edited

Loading

guseggert Dec 16, 2021

iand left a comment

iand Mar 31, 2022

guseggert Mar 31, 2022

iand Mar 31, 2022

guseggert Mar 31, 2022

iand Mar 31, 2022

guseggert Apr 1, 2022

iand Mar 31, 2022

guseggert Mar 31, 2022

iand Mar 31, 2022

iand Mar 31, 2022

guseggert Apr 1, 2022 •

edited

Loading

lidel left a comment

BigLep commented Apr 1, 2022

lidel commented Apr 4, 2022

lidel left a comment •

edited

Loading

feat: add basic gateway tracing #8595

feat: add basic gateway tracing #8595

Conversation

guseggert commented Dec 8, 2021 • edited by lidel Loading

@lidel's blurb for Release Notes (wip)

Added spans

How to use Jaeger UI

Demo

frrist left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

frrist Dec 16, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

iand left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

guseggert Apr 1, 2022 • edited Loading

Choose a reason for hiding this comment

lidel left a comment

Choose a reason for hiding this comment

BigLep commented Apr 1, 2022

lidel commented Apr 4, 2022

lidel left a comment • edited Loading

Choose a reason for hiding this comment

guseggert commented Dec 8, 2021 •

edited by lidel

Loading

frrist Dec 16, 2021 •

edited

Loading

guseggert Apr 1, 2022 •

edited

Loading

lidel left a comment •

edited

Loading