Merge pull request #64 from luthersystems/tracing-fixes

Tracing fixes

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
 )

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=

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 {

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

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

lisp/x/profiler/opentelemetry_annotator.go

@@ -7,20 +7,17 @@ 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"
 )
 
-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 {
@@ -29,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
@@ -49,27 +47,34 @@ 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, _ := p.prettyFunName(fun)
-	p.currentContext, p.currentSpan = contextTracer(p.currentContext).Start(p.currentContext, prettyLabel)
+	prettyLabel, funName := p.prettyFunName(fun)
+	p.currentContext, p.currentSpan = p.tracer.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...)
+}

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
 }

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)