Ansluter Go Profilering Med Spårning · Felix Geisendörfer

Publicerad: 11 februari 2022

Idag skulle jag vilja dela med mig av några tankar om några nya profileringsfunktioner som vi nyligen levererade hos Datadog. Jag ska förklara vad de gör, hur de fungerar och vilka Go 1.18-bidrag som behövdes för att saker och ting skulle fungera bra.

Feature Showcase

Låt oss börja med slutresultatet. Föreställ dig att du har ett spår på 100 ms där 10 ms spenderas på en databasfråga, men 90 ms förblir oförklarade.

När detta händer behöver du vanligtvis studera din kod för ledtrådar. Har du glömt några spårningsinstrument? Dags att lägga till det, distribuera om och vänta. Eller kanske du behöver optimera din Go-kod? Om ja, hur?

Detta arbetsflöde är hanterbart, men det visar sig att det finns ett bättre sätt – vi kan använda profileringsdata för att fylla i luckorna. Och det är precis vad vår nya Code Hotspots-funktion gör. Som du kan se nedan använde vår begäran 90ms On-CPU-tid. Detta är en stark signal som låter oss utesluta off-CPU-aktivitet som oinstrumenterade servicesamtal, mutex-konflikter, kanalväntningar, sovande etc.

Ännu bättre, när vi klickar på knappen “Visa profil”, kan vi se denna On-CPU-tid som ett flamdiagram per begäran. Här kan vi se att vår tid ägnades åt JSON-kodning.

Och eftersom våra HTTP-hanterarfunktioner inte visas i stackspåren, kan vi också indirekt dra slutsatsen att detta arbete gjordes i en bakgrundsgoroutin som skapades av den goroutine som hanterade begäran.

Förutom att bryta ned spårningsinformation med hjälp av profilering kan vi också göra tvärtom och bryta ner en profils CPU-tid efter slutpunkt som visas nedan. Kryssrutorna kan användas för att filtrera profilen efter slutpunkt.

Och för att göra det lättare att förstå förändringar över tid, t.ex. efter en implementering, kan vi rita upp dessa data.

Hur det fungerar

Funktionerna är byggda ovanpå en befintlig Go-funktion som kallas pprof-etiketter som gör att vi kan koppla godtyckliga nyckel/värdepar till den för närvarande pågående goroutinen. Dessa etiketter ärvas automatiskt när en ny goroutin skapas, så de når in i alla hörn av din kod. Av avgörande betydelse är dessa etiketter också integrerade i CPU-profilern, så att de automatiskt hamnar i de CPU-profiler som den producerar.

Så för att implementera den här funktionen modifierade vi spårningskoden i vårt dd-trace-go-bibliotek för att automatiskt tillämpa etiketter som t.ex. span id och endpoint när ett nytt spann skapas. Dessutom tar vi bort etiketterna när spännet är klart. Ett förenklat exempel på denna implementering kan ses nedan:

func StartSpan(ctx context.Context, endpoint string) *span {
	span := &span{id: rand.Uint64(), restoreCtx: ctx}
	labels := pprof.Labels(
		"span_id", fmt.Sprintf("%d", span.id),
		"endpoint", endpoint,
	)
	pprof.SetGoroutineLabels(pprof.WithLabels(ctx, labels))
	return span
}

type span struct {
	id         uint64
	restoreCtx context.Context
}

func (s *span) Finish() {
	pprof.SetGoroutineLabels(s.restoreCtx)
}

Vår faktiska implementering är lite mer komplex och minskar även risken för att läcka PII (Personally Identifiable Information). Den täcker automatiskt HTTP- och gRPC-omslagen i vårt bidragspaket, såväl som alla anpassade spår som din applikation kan implementera.

När vår backend väl tar emot spårnings- och profileringsinformationen kan vi utföra de sökningar som behövs för att driva funktionerna som visades upp tidigare i det här inlägget.

Profileringsförbättringar i Go 1.18

Som en del av implementeringen av dessa nya funktioner gjorde vi en hel del tester, inklusive enhetstester, mikrobenchmarks, makrobenchmarks och mer. Som väntat dök detta upp problem i vår kod och gjorde det möjligt för oss att snabbt fixa dem.

Något mindre förväntat upptäckte vi också flera problem i Go-körningstiden som påverkade pprof-etiketternas noggrannhet, såväl som CPU-profilering i allmänhet. Den goda nyheten är att med hjälp av communityn, Go-underhållarna och bidrag från vår sida – alla dessa problem har åtgärdats i den kommande Go 1.18-versionen.

Om du är intresserad av alla detaljer om detta, kolla in det kompletterande inlägget: Profiling Improvements in Go 1.18.

Med det sagt, om du inte använder mycket cgo borde de nya funktionerna redan fungera utmärkt för dig i Go 1.17.

Feedback önskas

Jag letar just nu efter personer som är intresserade av att ta de här nya funktionerna en sväng för att få feedback.

Det spelar ingen roll om du är en befintlig eller potentiell kund, skicka bara ett mejl till mig så kan vi ställa in en 30 min zoom. För att söta affären svarar jag också gärna på allmänna Go-profileringsfrågor längs vägen :).

Bilaga: Komma igång

Om du vill komma igång snabbt kan du helt enkelt kopiera koden nedan till din ansökan.

Dessutom kan du kolla in denna fullt fungerande dd-trace-go-demo-applikation som visar en integration inklusive HTTP och PostgreSQL.

package main

import (
	"time"

	"gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer"
	"gopkg.in/DataDog/dd-trace-go.v1/profiler"
)

func main() {
	const (
		env     = "dev"
		service = "example"
		version = "0.1"
	)

	tracer.Start(
		tracer.WithEnv(env),
		tracer.WithService(service),
		tracer.WithServiceVersion(version),
		tracer.WithProfilerCodeHotspots(true),
		tracer.WithProfilerEndpoints(true),
	)
	defer tracer.Stop()

	err := profiler.Start(
		profiler.WithService(service),
		profiler.WithEnv(env),
		profiler.WithVersion(version),

		// Enables CPU profiling 100% of the time to capture hotspot information
		// for all spans. Default is 25% right now, but this might change in the
		// next dd-trace-go release.
		profiler.CPUDuration(60*time.Second),
		profiler.WithPeriod(60*time.Second),
	)
	if err != nil {
		panic(err)
	}
	defer profiler.Stop()

	// 
}