Skip to content

Commit

Permalink
Add profiler span labeler
Browse files Browse the repository at this point in the history
  • Loading branch information
sam-at-luther committed Jan 4, 2024
1 parent 21f69bb commit 1206d25
Show file tree
Hide file tree
Showing 9 changed files with 175 additions and 19 deletions.
4 changes: 2 additions & 2 deletions lisp/x/profiler/callgrind.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -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))
Expand Down
85 changes: 85 additions & 0 deletions lisp/x/profiler/funlabeler.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,85 @@
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 sanitizeLabel(userLabel string) string {
userLabel = strings.TrimSpace(userLabel)
if userLabel == "" {
return ""
}

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
}

// Eliminate duplicate underscores
parts := strings.Split(userLabel, "_")
var nonEmptyParts []string
for _, part := range parts {
if part != "" {
nonEmptyParts = append(nonEmptyParts, part)
}
}
return strings.Join(nonEmptyParts, "_")
}

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 sanitizeLabel(label)
}
68 changes: 68 additions & 0 deletions lisp/x/profiler/funlabeler_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,68 @@
package profiler

import (
"testing"

"github.com/stretchr/testify/assert"
)

func TestSanitizeLabel(t *testing.T) {
tests := []struct {
name string
label string
expected string
}{
{
name: "normal case",
label: "NormalLabel",
expected: "NormalLabel",
},
{
name: "contains spaces",
label: "Label With Spaces",
expected: "Label_With_Spaces",
},
{
name: "contains special characters",
label: "Label@#$%^&",
expected: "Label",
},
{
name: "starts with a digit",
label: "123Label",
expected: "label_123Label",
},
{
name: "empty string",
label: "",
expected: "",
},
{
name: "starts with a digit",
label: "123Label",
expected: "label_123Label",
},
{
name: "starts with an underscore",
label: "_Label",
expected: "label_Label",
},
{
name: "starts with a special character",
label: "@Label",
expected: "label_Label",
},
{
name: "starts with a space",
label: " Label",
expected: "Label",
},
}

for _, tc := range tests {
t.Run(tc.name, func(t *testing.T) {
actual := sanitizeLabel(tc.label)
assert.Equal(t, tc.expected, actual, "sanitizeLabel(%s)", tc.label)
})
}
}
2 changes: 1 addition & 1 deletion lisp/x/profiler/go_annotator.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)

Expand Down
2 changes: 1 addition & 1 deletion lisp/x/profiler/opencensus_annotator.go
Original file line number Diff line number Diff line change
Expand Up @@ -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{
Expand Down
2 changes: 1 addition & 1 deletion lisp/x/profiler/opentelemetry_annotator.go
Original file line number Diff line number Diff line change
Expand Up @@ -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))))
Expand Down
5 changes: 4 additions & 1 deletion lisp/x/profiler/opentelemetry_annotator_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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))
Expand All @@ -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_It", "Expected custom label")
}
24 changes: 12 additions & 12 deletions lisp/x/profiler/profiler.go
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@ type profiler struct {
runtime *lisp.Runtime
enabled bool
skipFilter SkipFilter
funLabeler FunLabeler
}

var _ lisp.Profiler = &profiler{}
Expand Down Expand Up @@ -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)
Expand All @@ -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
Expand Down
2 changes: 1 addition & 1 deletion lisp/x/profiler/test.lisp
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
(debug-print x))

(defun add-it (x y)
"@trace"
"@trace{ Add-It }"
(+ x y))

(defun recurse-it (x)
Expand Down

0 comments on commit 1206d25

Please sign in to comment.