diff --git a/lisp/x/profiler/callgrind.go b/lisp/x/profiler/callgrind.go index 8c76ed3..e772fdb 100644 --- a/lisp/x/profiler/callgrind.go +++ b/lisp/x/profiler/callgrind.go @@ -130,7 +130,7 @@ func (p *callgrindProfiler) Start(fun *lisp.LVal) func() { } // Mark the time and point of entry. It feels like we're building the call stack in Runtime // again, but we're not - it's called, not callers. - p.incrementCallRef(prettyFunName(p.runtime, fun), fun.Source) + p.incrementCallRef(p.prettyFunName(fun), fun.Source) return func() { p.end(fun) @@ -178,7 +178,7 @@ func (p *callgrindProfiler) end(fun *lisp.LVal) { } p.Lock() defer p.Unlock() - fName := prettyFunName(p.runtime, fun) + fName := p.prettyFunName(fun) source, line := getSource(fun) // Write what function we've been observing and where to find it fmt.Fprintf(p.writer, "fl=%s\n", p.getRef(source)) diff --git a/lisp/x/profiler/funlabeler.go b/lisp/x/profiler/funlabeler.go new file mode 100644 index 0000000..9711e23 --- /dev/null +++ b/lisp/x/profiler/funlabeler.go @@ -0,0 +1,75 @@ +package profiler + +import ( + "fmt" + "regexp" + "strings" + "unicode" + + "github.com/luthersystems/elps/lisp" + "github.com/luthersystems/elps/lisp/lisplib/libhelp" +) + +// FunLabeler provides an alternative name for a function label in the trace. +type FunLabeler func(runtime *lisp.Runtime, fun *lisp.LVal) string + +// WithELPSDocLabeler labels spans using elps doc magic strings. +func WithELPSDocLabeler() Option { + return WithFunLabeler(elpsDocFunLabeler) +} + +// WithFunLabeler sets the labeler for tracing spans. +func WithFunLabeler(funLabeler FunLabeler) Option { + return func(p *profiler) { + p.funLabeler = funLabeler + } +} + +// defaultFunName constructs a pretty canonical name using the function name. +func defaultFunName(runtime *lisp.Runtime, fun *lisp.LVal) string { + if fun.Type != lisp.LFun { + return "" + } + funData := fun.FunData() + if funData == nil { + return "" + } + return fmt.Sprintf("%s:%s", funData.Package, getFunNameFromFID(runtime, funData.FID)) +} + +// ELPSDocLabel is a magic string used to extract function labels. +const ELPSDocLabel = `@trace{([^}]+)}` + +var elpsDocLabelRegExp = regexp.MustCompile(ELPSDocLabel) + +var sanitizeRegExp = regexp.MustCompile(`[\W_]+`) + +func sanatizeLabel(userLabel string) string { + if userLabel == "" { + return "" + } + userLabel = strings.TrimSpace(userLabel) + userLabel = sanitizeRegExp.ReplaceAllString(userLabel, "_") + // Ensure the label doesn't start with a digit or special character + if len(userLabel) > 0 && !unicode.IsLetter(rune(userLabel[0])) { + userLabel = "label_" + userLabel + } + return userLabel +} + +func elpsDocFunLabeler(runtime *lisp.Runtime, fun *lisp.LVal) string { + docStr := libhelp.FunDocstring(fun) + if docStr == "" { + return "" + } + matches := elpsDocLabelRegExp.FindAllStringSubmatch(docStr, -1) + label := "" + for _, match := range matches { + if len(match) > 1 { + label = match[1] + break + } + } + + return sanatizeLabel(label) +} diff --git a/lisp/x/profiler/go_annotator.go b/lisp/x/profiler/go_annotator.go index 4ca8229..1a4d2eb 100644 --- a/lisp/x/profiler/go_annotator.go +++ b/lisp/x/profiler/go_annotator.go @@ -53,7 +53,7 @@ func (p *pprofAnnotator) Start(fun *lisp.LVal) func() { // if we always ran inside a context, or a whole conditional code path and the added complication that brings // if we did it that way. oldContext := p.currentContext - p.currentContext = pprof.WithLabels(p.currentContext, pprof.Labels("function", prettyFunName(p.runtime, fun))) + p.currentContext = pprof.WithLabels(p.currentContext, pprof.Labels("function", p.prettyFunName(fun))) // apply the selected labels to the current goroutine (NB this will propagate if the code branches further down... pprof.SetGoroutineLabels(p.currentContext) diff --git a/lisp/x/profiler/opencensus_annotator.go b/lisp/x/profiler/opencensus_annotator.go index 2f20347..201fd46 100644 --- a/lisp/x/profiler/opencensus_annotator.go +++ b/lisp/x/profiler/opencensus_annotator.go @@ -47,7 +47,7 @@ func (p *ocAnnotator) Start(fun *lisp.LVal) func() { return func() {} } oldContext := p.currentContext - p.currentContext, p.currentSpan = trace.StartSpan(p.currentContext, prettyFunName(p.runtime, fun)) + p.currentContext, p.currentSpan = trace.StartSpan(p.currentContext, p.prettyFunName(fun)) return func() { file, line := getSource(fun) p.currentSpan.Annotate([]trace.Attribute{ diff --git a/lisp/x/profiler/opentelemetry_annotator.go b/lisp/x/profiler/opentelemetry_annotator.go index 91e69d7..6d91227 100644 --- a/lisp/x/profiler/opentelemetry_annotator.go +++ b/lisp/x/profiler/opentelemetry_annotator.go @@ -62,7 +62,7 @@ func (p *otelAnnotator) Start(fun *lisp.LVal) func() { return func() {} } oldContext := p.currentContext - p.currentContext, p.currentSpan = contextTracer(p.currentContext).Start(p.currentContext, prettyFunName(p.runtime, fun)) + p.currentContext, p.currentSpan = contextTracer(p.currentContext).Start(p.currentContext, p.prettyFunName(fun)) return func() { file, line := getSource(fun) p.currentSpan.AddEvent("source", trace.WithAttributes(attribute.Key("file").String(file), attribute.Key("line").Int64(int64(line)))) diff --git a/lisp/x/profiler/opentelemetry_annotator_test.go b/lisp/x/profiler/opentelemetry_annotator_test.go index eb4d587..fc7b7c4 100644 --- a/lisp/x/profiler/opentelemetry_annotator_test.go +++ b/lisp/x/profiler/opentelemetry_annotator_test.go @@ -57,7 +57,9 @@ func TestNewOpenTelemetryAnnotatorSkip(t *testing.T) { env := lisp.NewEnv(nil) env.Runtime.Reader = parser.NewReader() - ppa := profiler.NewOpenTelemetryAnnotator(env.Runtime, context.Background(), profiler.WithELPSDocFilter()) + ppa := profiler.NewOpenTelemetryAnnotator(env.Runtime, context.Background(), + profiler.WithELPSDocFilter(), + profiler.WithELPSDocLabeler()) assert.NoError(t, ppa.Enable()) lerr := lisp.InitializeUserEnv(env) assert.NoError(t, lisp.GoError(lerr)) @@ -68,4 +70,5 @@ func TestNewOpenTelemetryAnnotatorSkip(t *testing.T) { spans := exporter.GetSpans() assert.LessOrEqual(t, len(spans), 3, "Expected selective spans") + assert.Equal(t, spans[0].Name, "Add", "Expected custom label") } diff --git a/lisp/x/profiler/profiler.go b/lisp/x/profiler/profiler.go index 680af49..904d9dc 100644 --- a/lisp/x/profiler/profiler.go +++ b/lisp/x/profiler/profiler.go @@ -12,6 +12,7 @@ type profiler struct { runtime *lisp.Runtime enabled bool skipFilter SkipFilter + funLabeler FunLabeler } var _ lisp.Profiler = &profiler{} @@ -40,6 +41,17 @@ func (p *profiler) Start(fun *lisp.LVal) func() { return func() {} } +func (p *profiler) prettyFunName(fun *lisp.LVal) string { + label := "" + if p.funLabeler != nil { + label = p.funLabeler(p.runtime, fun) + } + if label == "" { + label = defaultFunName(p.runtime, fun) + } + return label +} + // skipTrace is a helper function to decide whether to skip tracing. func (p *profiler) skipTrace(v *lisp.LVal) bool { return !p.enabled || defaultSkipFilter(v) || p.skipFilter != nil && p.skipFilter(v) @@ -60,18 +72,6 @@ func getFunNameFromFID(rt *lisp.Runtime, in string) string { return builtinRegex.FindStringSubmatch(in)[1] } -// prettyFunName constructs a pretty canonical name. -func prettyFunName(runtime *lisp.Runtime, fun *lisp.LVal) string { - if fun.Type != lisp.LFun { - return "" - } - funData := fun.FunData() - if funData == nil { - return "" - } - return fmt.Sprintf("%s:%s", funData.Package, getFunNameFromFID(runtime, funData.FID)) -} - func getSource(function *lisp.LVal) (string, int) { if function.Source != nil { return function.Source.File, function.Source.Line diff --git a/lisp/x/profiler/test.lisp b/lisp/x/profiler/test.lisp index f3f54a7..17329cc 100644 --- a/lisp/x/profiler/test.lisp +++ b/lisp/x/profiler/test.lisp @@ -2,7 +2,7 @@ (debug-print x)) (defun add-it (x y) - "@trace" + "@trace{Add}" (+ x y)) (defun recurse-it (x)