From eff0865be9d9fd44701338fb1c3edbe5c31985d2 Mon Sep 17 00:00:00 2001 From: Jeremy Asher Date: Fri, 9 Feb 2024 12:22:32 -0800 Subject: [PATCH 1/4] remove unnecessary test log lines --- lisp/x/profiler/longtest.lisp | 20 ++++++++------------ lisp/x/profiler/test.lisp | 6 +----- 2 files changed, 9 insertions(+), 17 deletions(-) diff --git a/lisp/x/profiler/longtest.lisp b/lisp/x/profiler/longtest.lisp index 49e860c..07520d7 100644 --- a/lisp/x/profiler/longtest.lisp +++ b/lisp/x/profiler/longtest.lisp @@ -1,6 +1,3 @@ -(defun print-it (x) - (debug-print x)) - (defun add-it (x y) (+ x y)) @@ -11,15 +8,14 @@ (foldl (lambda (a x) - (print-it - (add-it - (recurse-it - (foldl add-it - a - (vector - 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 2873 2 111 34 4555 22 12 - 93 83 12 12 2 2 3 845 83 3 2 4 59 92 1 34 888 38 2 8 4 2 8 4))) - x)) + (add-it + (recurse-it + (foldl add-it + a + (vector + 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 2873 2 111 34 4555 22 12 + 93 83 12 12 2 2 3 845 83 3 2 4 59 92 1 34 888 38 2 8 4 2 8 4))) + x) (foldl (lambda (m q) (foldl diff --git a/lisp/x/profiler/test.lisp b/lisp/x/profiler/test.lisp index 19580f1..b5f74ea 100644 --- a/lisp/x/profiler/test.lisp +++ b/lisp/x/profiler/test.lisp @@ -1,6 +1,3 @@ -(defun print-it (x) - (debug-print x)) - (defun add-it (x y) "@trace{ Add-It }" (+ x y)) @@ -10,8 +7,7 @@ (recurse-it (- x 1)) (add-it x 3))) -(print-it "Hello") -(print-it (add-it (add-it 3 (recurse-it 5)) 8)) ; span 1..3 +(add-it (add-it 3 (recurse-it 5)) 8) ; span 1..3 (labels ([add-it-again (x) From 9cdc240ed5a418afe7d3e09f35eedeb4318b6253 Mon Sep 17 00:00:00 2001 From: Jeremy Asher Date: Fri, 9 Feb 2024 14:25:48 -0800 Subject: [PATCH 2/4] improve source location tracing This improves the logic for looking up function source location and follows OTLP conventions more completely when tracing in that mode. --- lisp/x/profiler/callgrind.go | 16 +++++++++++----- lisp/x/profiler/opencensus_annotator.go | 10 ++++++---- lisp/x/profiler/opentelemetry_annotator.go | 22 +++++++++++++++++++--- lisp/x/profiler/profiler.go | 19 +++++++++---------- 4 files changed, 45 insertions(+), 22 deletions(-) diff --git a/lisp/x/profiler/callgrind.go b/lisp/x/profiler/callgrind.go index 846efed..a867a8e 100644 --- a/lisp/x/profiler/callgrind.go +++ b/lisp/x/profiler/callgrind.go @@ -180,9 +180,11 @@ func (p *callgrindProfiler) end(fun *lisp.LVal) { p.Lock() defer p.Unlock() fName, _ := p.prettyFunName(fun) - source, line := getSource(fun) + loc := getSourceLoc(fun) // Write what function we've been observing and where to find it - fmt.Fprintf(p.writer, "fl=%s\n", p.getRef(source)) + if loc != nil { + fmt.Fprintf(p.writer, "fl=%s\n", p.getRef(loc.File)) + } fmt.Fprintf(p.writer, "fn=%s\n", p.getRef(fName)) ref := p.getCallRefAndDecrement() ref.duration = time.Since(ref.start) @@ -195,11 +197,15 @@ func (p *callgrindProfiler) end(fun *lisp.LVal) { memory := ref.endMemory - ref.startMemory // Cache the location - we won't be able to get it again when we build the maps for // things that call this. - if ref.line == 0 && fun.Source != nil { - ref.line = fun.Source.Line - ref.file = fun.Source.File + if ref.line == 0 && loc != nil { + ref.line = loc.Line + ref.file = loc.File } // Output timing and line ref + line := 0 + if loc != nil { + line = loc.Line + } fmt.Fprintf(p.writer, "%d %d %d\n", line, ref.duration, memory) // Output the things we called for _, entry := range ref.children { diff --git a/lisp/x/profiler/opencensus_annotator.go b/lisp/x/profiler/opencensus_annotator.go index 5843c19..f1dcf99 100644 --- a/lisp/x/profiler/opencensus_annotator.go +++ b/lisp/x/profiler/opencensus_annotator.go @@ -49,12 +49,14 @@ func (p *ocAnnotator) Start(fun *lisp.LVal) func() { oldContext := p.currentContext prettyLabel, _ := p.prettyFunName(fun) p.currentContext, p.currentSpan = trace.StartSpan(p.currentContext, prettyLabel) - return func() { - file, line := getSource(fun) + loc := getSourceLoc(fun) + if loc != nil { p.currentSpan.Annotate([]trace.Attribute{ - trace.StringAttribute("file", file), - trace.Int64Attribute("line", int64(line)), + trace.StringAttribute("file", loc.File), + trace.Int64Attribute("line", int64(loc.Line)), }, "source") + } + return func() { p.currentSpan.End() // And pop the current context back p.currentContext = oldContext diff --git a/lisp/x/profiler/opentelemetry_annotator.go b/lisp/x/profiler/opentelemetry_annotator.go index 88e2744..f23775e 100644 --- a/lisp/x/profiler/opentelemetry_annotator.go +++ b/lisp/x/profiler/opentelemetry_annotator.go @@ -7,6 +7,7 @@ import ( "github.com/luthersystems/elps/lisp" "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/attribute" + semconv "go.opentelemetry.io/otel/semconv/v1.21.0" "go.opentelemetry.io/otel/trace" ) @@ -62,14 +63,29 @@ func (p *otelAnnotator) Start(fun *lisp.LVal) func() { return func() {} } oldContext := p.currentContext - prettyLabel, _ := p.prettyFunName(fun) + prettyLabel, funName := p.prettyFunName(fun) p.currentContext, p.currentSpan = contextTracer(p.currentContext).Start(p.currentContext, prettyLabel) + p.addCodeAttributes(fun, funName) return func() { - file, line := getSource(fun) - p.currentSpan.AddEvent("source", trace.WithAttributes(attribute.Key("file").String(file), attribute.Key("line").Int64(int64(line)))) p.currentSpan.End() // And pop the current context back p.currentContext = oldContext p.currentSpan = trace.SpanFromContext(p.currentContext) } } + +func (p *otelAnnotator) addCodeAttributes(fun *lisp.LVal, funName string) { + loc := getSourceLoc(fun) + attrs := []attribute.KeyValue{ + semconv.CodeNamespace(fun.Package()), + semconv.CodeFunction(funName), + } + if loc != nil { + attrs = append(attrs, + semconv.CodeColumn(loc.Col), + semconv.CodeFilepath(loc.File), + semconv.CodeLineNumber(loc.Line), + ) + } + p.currentSpan.SetAttributes(attrs...) +} diff --git a/lisp/x/profiler/profiler.go b/lisp/x/profiler/profiler.go index 44fbcdc..f2769f8 100644 --- a/lisp/x/profiler/profiler.go +++ b/lisp/x/profiler/profiler.go @@ -5,6 +5,7 @@ import ( "regexp" "github.com/luthersystems/elps/lisp" + "github.com/luthersystems/elps/parser/token" ) // profiler is a minimal lisp.Profiler @@ -95,16 +96,14 @@ func getFunNameFromFID(rt *lisp.Runtime, in string) string { return builtinRegex.FindStringSubmatch(in)[1] } -func getSource(function *lisp.LVal) (string, int) { - if function.Source != nil { - return function.Source.File, function.Source.Line +func getSourceLoc(fun *lisp.LVal) *token.Location { + if len(fun.Cells) > 0 { + if cell := fun.Cells[0]; cell.Source != nil { + return cell.Source + } } - - source := "no-source" - line := 0 - if cell := function.Cells[0]; cell != nil && cell.Source != nil { - source = cell.Source.File - line = cell.Source.Line + if fun.Source != nil { + return fun.Source } - return source, line + return nil } From 183c00b489a8a1d61c46356e9c5b1e9e5c88533f Mon Sep 17 00:00:00 2001 From: Jeremy Asher Date: Fri, 9 Feb 2024 12:53:29 -0800 Subject: [PATCH 3/4] go mod tidy --- go.mod | 1 - go.sum | 2 -- 2 files changed, 3 deletions(-) diff --git a/go.mod b/go.mod index a5ea5c0..71326a5 100644 --- a/go.mod +++ b/go.mod @@ -11,7 +11,6 @@ require ( github.com/stretchr/testify v1.8.4 go.opencensus.io v0.24.0 go.opentelemetry.io/otel v1.21.0 - go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.21.0 go.opentelemetry.io/otel/sdk v1.21.0 go.opentelemetry.io/otel/trace v1.21.0 ) diff --git a/go.sum b/go.sum index 999af97..ce6bebe 100644 --- a/go.sum +++ b/go.sum @@ -110,8 +110,6 @@ go.opencensus.io v0.24.0 h1:y73uSU6J157QMP2kn2r30vwW1A2W2WFwSCGnAVxeaD0= go.opencensus.io v0.24.0/go.mod h1:vNK8G9p7aAivkbmorf4v+7Hgx+Zs0yY+0fOtgBfjQKo= go.opentelemetry.io/otel v1.21.0 h1:hzLeKBZEL7Okw2mGzZ0cc4k/A7Fta0uoPgaJCr8fsFc= go.opentelemetry.io/otel v1.21.0/go.mod h1:QZzNPQPm1zLX4gZK4cMi+71eaorMSGT3A4znnUvNNEo= -go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.21.0 h1:VhlEQAPp9R1ktYfrPk5SOryw1e9LDDTZCbIPFrho0ec= -go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.21.0/go.mod h1:kB3ufRbfU+CQ4MlUcqtW8Z7YEOBeK2DJ6CmR5rYYF3E= go.opentelemetry.io/otel/metric v1.21.0 h1:tlYWfeo+Bocx5kLEloTjbcDwBuELRrIFxwdQ36PlJu4= go.opentelemetry.io/otel/metric v1.21.0/go.mod h1:o1p3CA8nNHW8j5yuQLdc1eeqEaPfzug24uvsyIEJRWM= go.opentelemetry.io/otel/sdk v1.21.0 h1:FTt8qirL1EysG6sTQRZ5TokkU8d0ugCj8htOgThZXQ8= From 7df45210073343ceafb970e69783955754bcdb60 Mon Sep 17 00:00:00 2001 From: Jeremy Asher Date: Fri, 9 Feb 2024 14:23:15 -0800 Subject: [PATCH 4/4] hold onto otel tracer, fixed tracer name --- lisp/x/profiler/opentelemetry_annotator.go | 17 +++-------------- 1 file changed, 3 insertions(+), 14 deletions(-) diff --git a/lisp/x/profiler/opentelemetry_annotator.go b/lisp/x/profiler/opentelemetry_annotator.go index f23775e..b8d1aa1 100644 --- a/lisp/x/profiler/opentelemetry_annotator.go +++ b/lisp/x/profiler/opentelemetry_annotator.go @@ -11,17 +11,13 @@ import ( "go.opentelemetry.io/otel/trace" ) -const ( - // ContextOpenTelemetryTracerKey looks up a parent tracer name from a context key. - ContextOpenTelemetryTracerKey = "otelParentTracer" -) - var _ lisp.Profiler = &otelAnnotator{} type otelAnnotator struct { profiler currentContext context.Context currentSpan trace.Span + tracer trace.Tracer } func NewOpenTelemetryAnnotator(runtime *lisp.Runtime, parentContext context.Context, opts ...Option) *otelAnnotator { @@ -30,6 +26,7 @@ func NewOpenTelemetryAnnotator(runtime *lisp.Runtime, parentContext context.Cont runtime: runtime, }, currentContext: parentContext, + tracer: otel.GetTracerProvider().Tracer("elps"), } p.profiler.applyConfigs(opts...) return p @@ -50,21 +47,13 @@ func (p *otelAnnotator) Complete() error { return nil } -func contextTracer(ctx context.Context) trace.Tracer { - tracerName, ok := ctx.Value(ContextOpenTelemetryTracerKey).(string) - if !ok { - tracerName = "elps" - } - return otel.GetTracerProvider().Tracer(tracerName) -} - func (p *otelAnnotator) Start(fun *lisp.LVal) func() { if p.skipTrace(fun) { return func() {} } oldContext := p.currentContext prettyLabel, funName := p.prettyFunName(fun) - p.currentContext, p.currentSpan = contextTracer(p.currentContext).Start(p.currentContext, prettyLabel) + p.currentContext, p.currentSpan = p.tracer.Start(p.currentContext, prettyLabel) p.addCodeAttributes(fun, funName) return func() { p.currentSpan.End()