Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add profiler span labeler #62

Merged
merged 4 commits into from
Jan 31, 2024
Merged
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
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, "_")
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This prefixing behavior seems a bit non-intuitive. Would it make sense to just drop leading junk we don't want to allow or reject the label entirely and fall back to the function name?

}

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