From 4c0b8501e380f40baf6bd31dc46e65374e48cb2d Mon Sep 17 00:00:00 2001 From: sam-at-luther Date: Tue, 2 Jan 2024 19:51:35 -0800 Subject: [PATCH 1/3] Add profiler skip filter --- lisp/profiler.go | 8 -- lisp/x/profiler/Readme.md | 31 ++-- lisp/x/profiler/callgrind.go | 133 +++++++----------- lisp/x/profiler/callgrind_test.go | 21 +-- lisp/x/profiler/go_annotator.go | 59 +++----- lisp/x/profiler/go_annotator_test.go | 69 +-------- lisp/x/profiler/longtest.lisp | 47 +++++++ lisp/x/profiler/opencensus_annotator.go | 70 ++------- lisp/x/profiler/opencensus_annotator_test.go | 51 +++---- lisp/x/profiler/opentelemetry_annotator.go | 70 +++------ .../profiler/opentelemetry_annotator_test.go | 85 +++++------ lisp/x/profiler/profiler.go | 85 +++++++++++ lisp/x/profiler/profiler_test.go | 11 ++ lisp/x/profiler/shared.go | 21 --- lisp/x/profiler/skipfilter.go | 50 +++++++ lisp/x/profiler/test.lisp | 14 ++ 16 files changed, 378 insertions(+), 447 deletions(-) create mode 100644 lisp/x/profiler/longtest.lisp create mode 100644 lisp/x/profiler/profiler.go create mode 100644 lisp/x/profiler/profiler_test.go delete mode 100644 lisp/x/profiler/shared.go create mode 100644 lisp/x/profiler/skipfilter.go create mode 100644 lisp/x/profiler/test.lisp diff --git a/lisp/profiler.go b/lisp/profiler.go index cf0560d..6d03ab6 100644 --- a/lisp/profiler.go +++ b/lisp/profiler.go @@ -4,14 +4,6 @@ const ElpsVersion = "1.7" // Interface for a profiler type Profiler interface { - // IsEnabled determines if the profiler enabled. - IsEnabled() bool - // Enable enables the profiler - Enable() error - // SetFile sets the file to output to - SetFile(filename string) error - // Complete ends the profiling session and output summary lines - Complete() error // Start the process, and returns a function to stop. Start(function *LVal) func() } diff --git a/lisp/x/profiler/Readme.md b/lisp/x/profiler/Readme.md index fbf5577..3243b9b 100644 --- a/lisp/x/profiler/Readme.md +++ b/lisp/x/profiler/Readme.md @@ -2,20 +2,20 @@ >_Note_ The profilers in this directory are experimental code and may not always works as anticipated. -Hooks are provided on the `lisp.Runtime` to contain a profiler implementing -the interface defined in `lisp.Profiler`. +Hooks are provided on the `lisp.Runtime` to contain a profiler implementing +the interface defined in `lisp.Profiler`. ## Profilers available ### Callgrind profiler -This profiler produces output in callgrind/cachegrind format which can be read -using [KCachegrind](http://kcachegrind.sourceforge.net/html/Home.html), -[QCachegrind](https://sourceforge.net/projects/qcachegrindwin/) and similar programs. +This profiler produces output in callgrind/cachegrind format which can be read +using [KCachegrind](http://kcachegrind.sourceforge.net/html/Home.html), +[QCachegrind](https://sourceforge.net/projects/qcachegrindwin/) and similar programs. It captures source, call, time and memory information from every LISP call made. This profiler is probably the most useful for locating problems whilst developing code in ELPS at present. -To enable this profiler, it needs to be linked to the ELPS runtime and it must be instructed +To enable this profiler, it needs to be linked to the ELPS runtime and it must be instructed to complete the profile and close the file before the profile can be read. ```go package a @@ -45,7 +45,7 @@ func runLispStuff() { } ``` You can then open the resulting profile in KCachegrind or similar. - + ### Opencensus annotator This profiler appends [OpenCensus](https://opencensus.io/) tracing spans to an input context for each LISP call made. It may be useful for adding production metrics to non-performant code, especially if using @@ -77,19 +77,6 @@ func runLispStuff(ctx context.Context) { // and then tell the profiler to wrap up and close the file when you're done ocp.Complete() } -``` -It is also possible to pass the profiler a new base context between runs without spinning up a -new ELPS runtime. To do this, pass the context to the `EnableWithContext` function. -```go -env := lisp.NewEnv(nil) -ocp := profiler.NewOpenCensusAnnotator(env.Runtime, ctx1) -lisp.InitializeUserEnv(env) -ocp.Enable() -// do some stuff -ocp.Complete() -ocp.EnableWithContext(ctx2) -// do some more stuff -ocp.Complete() ``` ### pprof annotator This profiler appends tags for called functions to a CPU profile generated by the standard @@ -132,7 +119,7 @@ func runLispStuff(ctx context.Context) { } ``` -It would also be possible to use this within a process profiled using the `pprof` http interface. To +It would also be possible to use this within a process profiled using the `pprof` http interface. To do so, you could simply omit the lines starting profiling above as long as your imports in `main` were set up correctly. @@ -141,4 +128,4 @@ The overhead of running profiling is small but not insignificant. This overhead by the overhead of the systems profiled to rather than the profiler itself, but should be taken into account when deciding when to use these interfaces. However, the overhead of running the OpenCensus and `pprof` annotators is not markedly greater than running those systems without the ELPS -annotations. \ No newline at end of file +annotations. diff --git a/lisp/x/profiler/callgrind.go b/lisp/x/profiler/callgrind.go index 4e34cff..8c76ed3 100644 --- a/lisp/x/profiler/callgrind.go +++ b/lisp/x/profiler/callgrind.go @@ -17,21 +17,24 @@ import ( // I like PHP but because XDebug is very light // The resulting files can be opened in KCacheGrind or QCacheGrind. type callgrindProfiler struct { + profiler sync.Mutex writer *os.File - runtime *lisp.Runtime - enabled bool startTime time.Time refs map[string]int refCounter int callRefs map[int32]*callRef } +var _ lisp.Profiler = &callgrindProfiler{} + // Returns a new Callgrind processor -func NewCallgrindProfiler(runtime *lisp.Runtime) lisp.Profiler { +func NewCallgrindProfiler(runtime *lisp.Runtime, opts ...Option) *callgrindProfiler { p := new(callgrindProfiler) p.runtime = runtime runtime.Profiler = p + + p.profiler.applyConfigs(opts...) return p } @@ -48,15 +51,8 @@ type callRef struct { line int } -func (p *callgrindProfiler) IsEnabled() bool { - return p.enabled -} - func (p *callgrindProfiler) Enable() error { p.Lock() - if p.enabled { - return errors.New("profiler already enabled") - } if p.writer == nil { return errors.New("no output set in profiler") } @@ -67,7 +63,6 @@ func (p *callgrindProfiler) Enable() error { p.startTime = time.Now() p.refs = make(map[string]int) p.refCounter = 0 - p.enabled = true p.Unlock() p.incrementCallRef("ENTRYPOINT", &token.Location{ File: "-", @@ -76,7 +71,7 @@ func (p *callgrindProfiler) Enable() error { Line: 0, Col: 0, }) - return nil + return p.profiler.Enable() } func (p *callgrindProfiler) SetFile(filename string) error { @@ -114,7 +109,10 @@ func (p *callgrindProfiler) Complete() error { ms := &runtime.MemStats{} runtime.ReadMemStats(ms) fmt.Fprintf(p.writer, "summary %d %d\n\n", duration.Nanoseconds(), ms.TotalAlloc) - return p.writer.Close() + if err := p.writer.Close(); err != nil { + return err + } + return nil } func (p *callgrindProfiler) getRef(name string) string { @@ -126,25 +124,16 @@ func (p *callgrindProfiler) getRef(name string) string { return fmt.Sprintf("(%d) %s", p.refCounter, name) } -func (p *callgrindProfiler) Start(function *lisp.LVal) func() { - if !p.enabled { +func (p *callgrindProfiler) Start(fun *lisp.LVal) func() { + if p.skipTrace(fun) { return func() {} } - switch function.Type { - case lisp.LInt, lisp.LString, lisp.LFloat, lisp.LBytes, lisp.LError, lisp.LArray, lisp.LQuote, lisp.LNative, lisp.LQSymbol, lisp.LSortMap: - // We don't need to profile these types. We could, but we're not that LISP :D - return func() {} - case lisp.LFun, lisp.LSymbol, lisp.LSExpr: - // 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. - _, _, name := p.getFunctionParameters(function) - p.incrementCallRef(name, function.Source) - default: - panic(fmt.Sprintf("Missing type %d", function.Type)) - } + // 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) return func() { - p.end(function) + p.end(fun) } } @@ -183,67 +172,41 @@ func (p *callgrindProfiler) getCallRefAndDecrement() *callRef { panic(fmt.Sprintf("Unset thread ref %d", *thread)) } -// Gets file parameters from the LVal -func (p *callgrindProfiler) getFunctionParameters(function *lisp.LVal) (string, int, string) { - var source string - line := 0 - if function.Source == nil { - if cell := function.Cells[0]; cell != nil && cell.Source != nil { - source = cell.Source.File - line = cell.Source.Line - } else { - source = "no-source" - } - } else { - source = function.Source.File - line = function.Source.Line - } - fName := fmt.Sprintf("%s:%s", function.FunData().Package, getFunNameFromFID(p.runtime, function.FunData().FID)) - return source, line, fName -} - -func (p *callgrindProfiler) end(function *lisp.LVal) { +func (p *callgrindProfiler) end(fun *lisp.LVal) { if !p.enabled { return } p.Lock() defer p.Unlock() - switch function.Type { - case lisp.LInt, lisp.LString, lisp.LFloat, lisp.LBytes, lisp.LError, lisp.LArray, lisp.LQuote, lisp.LNative, lisp.LSortMap: - // Again, we can ignore these as we never put them on the stack - return - case lisp.LFun, lisp.LSymbol, lisp.LSExpr, lisp.LQSymbol: - source, line, fName := p.getFunctionParameters(function) - // Write what function we've been observing and where to find it - fmt.Fprintf(p.writer, "fl=%s\n", p.getRef(source)) - fmt.Fprintf(p.writer, "fn=%s\n", p.getRef(fName)) - ref := p.getCallRefAndDecrement() - ref.duration = time.Since(ref.start) - if ref.duration == 0 { - ref.duration = 1 - } - ms := &runtime.MemStats{} - runtime.ReadMemStats(ms) - ref.endMemory = ms.TotalAlloc - 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 && function.Source != nil { - ref.line = function.Source.Line - ref.file = function.Source.File - } - // Output timing and line ref - fmt.Fprintf(p.writer, "%d %d %d\n", line, ref.duration, memory) - // Output the things we called - for _, entry := range ref.children { - fmt.Fprintf(p.writer, "cfl=%s\n", p.getRef(entry.file)) - fmt.Fprintf(p.writer, "cfn=%s\n", p.getRef(entry.name)) - fmt.Fprint(p.writer, "calls=1 0 0\n") - fmt.Fprintf(p.writer, "%d %d %d\n", entry.line, entry.duration, memory) - } - // and end the entry - fmt.Fprint(p.writer, "\n") - default: - panic(fmt.Sprintf("Missing type %d", function.Type)) + fName := prettyFunName(p.runtime, 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)) + fmt.Fprintf(p.writer, "fn=%s\n", p.getRef(fName)) + ref := p.getCallRefAndDecrement() + ref.duration = time.Since(ref.start) + if ref.duration == 0 { + ref.duration = 1 + } + ms := &runtime.MemStats{} + runtime.ReadMemStats(ms) + ref.endMemory = ms.TotalAlloc + 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 } + // Output timing and line ref + fmt.Fprintf(p.writer, "%d %d %d\n", line, ref.duration, memory) + // Output the things we called + for _, entry := range ref.children { + fmt.Fprintf(p.writer, "cfl=%s\n", p.getRef(entry.file)) + fmt.Fprintf(p.writer, "cfn=%s\n", p.getRef(entry.name)) + fmt.Fprint(p.writer, "calls=1 0 0\n") + fmt.Fprintf(p.writer, "%d %d %d\n", entry.line, entry.duration, memory) + } + // and end the entry + fmt.Fprint(p.writer, "\n") } diff --git a/lisp/x/profiler/callgrind_test.go b/lisp/x/profiler/callgrind_test.go index 75c0852..0f09853 100644 --- a/lisp/x/profiler/callgrind_test.go +++ b/lisp/x/profiler/callgrind_test.go @@ -26,26 +26,7 @@ func TestNewCallgrind(t *testing.T) { if lisp.GoError(lerr) != nil { t.Fatal(lisp.GoError(lerr)) } - // Some spurious functions to check we get a profile out - testsrc := env.LoadString("test.lisp", ` -(defun print-it - ('x) - (debug-print x) -) -(defun add-it - ('x 'y) - (+ x y) -) -(defun recurse-it - ('x) - (if - (< x 4) - (recurse-it (- x 1)) - (add-it x 3) - ) -) -(print-it "Hello") -(print-it (add-it (add-it 3 (recurse-it 5)) 8))`) + testsrc := env.LoadString("test.lisp", testLisp) lerr = env.Eval(testsrc) assert.NotEqual(t, lisp.LError, lerr.Type) // Mark the profile as complete and dump the rest of the profile diff --git a/lisp/x/profiler/go_annotator.go b/lisp/x/profiler/go_annotator.go index 41a1bbf..4ca8229 100644 --- a/lisp/x/profiler/go_annotator.go +++ b/lisp/x/profiler/go_annotator.go @@ -2,8 +2,6 @@ package profiler import ( "context" - "errors" - "fmt" "runtime/pprof" "github.com/luthersystems/elps/lisp" @@ -15,33 +13,29 @@ import ( // Unfortunately, due to the decision of the writers of pprof to fix the sampling rate at 100Hz // this is now less useful than might be expected. type pprofAnnotator struct { - runtime *lisp.Runtime - enabled bool + profiler currentContext context.Context } -func NewPprofAnnotator(runtime *lisp.Runtime, parentContext context.Context) lisp.Profiler { - return &pprofAnnotator{ - runtime: runtime, +var _ lisp.Profiler = &pprofAnnotator{} + +func NewPprofAnnotator(runtime *lisp.Runtime, parentContext context.Context, opts ...Option) *pprofAnnotator { + p := &pprofAnnotator{ + profiler: profiler{ + runtime: runtime, + }, currentContext: parentContext, } -} - -func (p *pprofAnnotator) IsEnabled() bool { - return p.enabled + p.profiler.applyConfigs(opts...) + return p } func (p *pprofAnnotator) Enable() error { p.runtime.Profiler = p - p.enabled = true if p.currentContext == nil { p.currentContext = context.Background() } - return nil -} - -func (p *pprofAnnotator) SetFile(filename string) error { - return errors.New("no need to set a file for this profiler type") + return p.profiler.Enable() } func (p *pprofAnnotator) Complete() error { @@ -49,30 +43,19 @@ func (p *pprofAnnotator) Complete() error { return nil } -func (p *pprofAnnotator) Start(function *lisp.LVal) func() { - if !p.enabled { +func (p *pprofAnnotator) Start(fun *lisp.LVal) func() { + if p.skipTrace(fun) { return func() {} } + // We're keeping the context on a stack here rather than using the pprof.Do function for the simple + // reason that I would have had to make more changes to the lisp.EvalSExpr function to accommodate that, + // and doing so would have a negative effect on users not profiling - it would either be an extra stack entry + // 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 - switch function.Type { - case lisp.LInt, lisp.LString, lisp.LFloat, lisp.LBytes, lisp.LError, lisp.LArray, lisp.LQuote, lisp.LNative, lisp.LQSymbol, lisp.LSortMap: - // We don't need to profile these types. We could, but we're not that LISP :D - return func() {} - case lisp.LFun, lisp.LSymbol, lisp.LSExpr: - // We're keeping the context on a stack here rather than using the pprof.Do function for the simple - // reason that I would have had to make more changes to the lisp.EvalSExpr function to accommodate that, - // and doing so would have a negative effect on users not profiling - it would either be an extra stack entry - // 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. - fName := fmt.Sprintf("%s:%s", function.FunData().Package, getFunNameFromFID(p.runtime, function.FunData().FID)) - labels := pprof.Labels("function", fName) - oldContext = p.currentContext - p.currentContext = pprof.WithLabels(p.currentContext, labels) - // apply the selected labels to the current goroutine (NB this will propagate if the code branches further down... - pprof.SetGoroutineLabels(p.currentContext) - default: - panic(fmt.Sprintf("missing type %d", function.Type)) - } + p.currentContext = pprof.WithLabels(p.currentContext, pprof.Labels("function", prettyFunName(p.runtime, fun))) + // apply the selected labels to the current goroutine (NB this will propagate if the code branches further down... + pprof.SetGoroutineLabels(p.currentContext) return func() { p.currentContext = oldContext diff --git a/lisp/x/profiler/go_annotator_test.go b/lisp/x/profiler/go_annotator_test.go index 793ebc7..9cd967b 100644 --- a/lisp/x/profiler/go_annotator_test.go +++ b/lisp/x/profiler/go_annotator_test.go @@ -23,79 +23,12 @@ func TestNewPprofAnnotator(t *testing.T) { assert.NoError(t, pprof.StartCPUProfile(file)) defer pprof.StopCPUProfile() assert.NoError(t, ppa.Enable()) - assert.Error(t, ppa.SetFile("./pprofout")) lerr := lisp.InitializeUserEnv(env) if lisp.GoError(lerr) != nil { t.Fatal(lisp.GoError(lerr)) } // Some spurious functions to check we get a profile out - testsrc := env.LoadString("test.lisp", ` -(defun print-it - ('x) - (debug-print x) -) -(defun add-it - ('x 'y) - (+ x y) -) -(defun recurse-it - ('x) - (if - (< x 4) - (recurse-it (- x 1)) - (add-it x 3) - ) -) -( - 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 - ) - ) - (foldl - (lambda - ('m 'q) - (foldl - (lambda - ('j 'b) - (* j b) - ) - a - (vector 83 764 2 37 34 2 1 88 7 6 3 22 1) - ) - ) - a - (vector a a a a a a a a a a a a a a a a a a a a a) - ) - ) - 0 - (vector - 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 - 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 - 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 - 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 - 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 - 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 - 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 - 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 - 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 - 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 - 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 - 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 - 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 - 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 - ) -) -`) + testsrc := env.LoadString("test.lisp", longTestLisp) lerr = env.Eval(testsrc) assert.NotEqual(t, lisp.LError, lerr.Type, lerr.Str) // Mark the profile as complete and dump the rest of the profile diff --git a/lisp/x/profiler/longtest.lisp b/lisp/x/profiler/longtest.lisp new file mode 100644 index 0000000..49e860c --- /dev/null +++ b/lisp/x/profiler/longtest.lisp @@ -0,0 +1,47 @@ +(defun print-it (x) + (debug-print x)) + +(defun add-it (x y) + (+ x y)) + +(defun recurse-it (x) + (if (< x 4) + (recurse-it (- x 1)) + (add-it x 3))) + +(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)) + (foldl + (lambda (m q) + (foldl + (lambda (j b) + (* j b)) + a + (vector 83 764 2 37 34 2 1 88 7 6 3 22 1))) + a + (vector a a a a a a a a a a a a a a a a a a a a a))) + 0 + (vector + 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 + 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 + 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 + 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 + 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 + 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 + 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 + 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 + 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 + 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 + 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 + 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 + 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4 + 9 7 8 6 5 4 3 2 8 36 73 83 3 82 2 1 334 3 82 1 32 3 8 0 1 2 83 4 9 0 11 3 4)) diff --git a/lisp/x/profiler/opencensus_annotator.go b/lisp/x/profiler/opencensus_annotator.go index 5ba9550..2f20347 100644 --- a/lisp/x/profiler/opencensus_annotator.go +++ b/lisp/x/profiler/opencensus_annotator.go @@ -3,51 +3,36 @@ package profiler import ( "context" "errors" - "fmt" "github.com/luthersystems/elps/lisp" "go.opencensus.io/trace" ) type ocAnnotator struct { - runtime *lisp.Runtime - enabled bool + profiler currentContext context.Context currentSpan *trace.Span } -func NewOpenCensusAnnotator(runtime *lisp.Runtime, parentContext context.Context) lisp.Profiler { - return &ocAnnotator{ - runtime: runtime, - currentContext: parentContext, - } -} - -func (p *ocAnnotator) IsEnabled() bool { - return p.enabled -} +var _ lisp.Profiler = &ocAnnotator{} -func (p *ocAnnotator) EnableWithContext(ctx context.Context) error { - p.runtime.Profiler = p - p.enabled = true - if ctx == nil { - return errors.New("set a context to use this function") +func NewOpenCensusAnnotator(runtime *lisp.Runtime, parentContext context.Context, opts ...Option) *ocAnnotator { + p := &ocAnnotator{ + profiler: profiler{ + runtime: runtime, + }, + currentContext: parentContext, } - p.currentContext = ctx - return nil + p.profiler.applyConfigs(opts...) + return p } func (p *ocAnnotator) Enable() error { p.runtime.Profiler = p - p.enabled = true if p.currentContext == nil { return errors.New("we can only append spans to a context that is linked to opencensus") } - return nil -} - -func (p *ocAnnotator) SetFile(filename string) error { - return errors.New("no need to set a file for this profiler type") + return p.profiler.Enable() } func (p *ocAnnotator) Complete() error { @@ -57,24 +42,14 @@ func (p *ocAnnotator) Complete() error { return nil } -func (p *ocAnnotator) Start(function *lisp.LVal) func() { - if !p.enabled { +func (p *ocAnnotator) Start(fun *lisp.LVal) func() { + if p.skipTrace(fun) { return func() {} } oldContext := p.currentContext - switch function.Type { - case lisp.LInt, lisp.LString, lisp.LFloat, lisp.LBytes, lisp.LError, lisp.LArray, lisp.LQuote, lisp.LNative, lisp.LQSymbol, lisp.LSortMap: - // We don't need to profile these types. We could, but we're not that LISP :D - return func() {} - case lisp.LFun, lisp.LSymbol, lisp.LSExpr: - fName := fmt.Sprintf("%s:%s", function.FunData().Package, getFunNameFromFID(p.runtime, function.FunData().FID)) - p.currentContext, p.currentSpan = trace.StartSpan(p.currentContext, fName) - default: - panic(fmt.Sprintf("missing type %d", function.Type)) - } - + p.currentContext, p.currentSpan = trace.StartSpan(p.currentContext, prettyFunName(p.runtime, fun)) return func() { - file, line := p.getSource(function) + file, line := getSource(fun) p.currentSpan.Annotate([]trace.Attribute{ trace.StringAttribute("file", file), trace.Int64Attribute("line", int64(line)), @@ -85,18 +60,3 @@ func (p *ocAnnotator) Start(function *lisp.LVal) func() { p.currentSpan = trace.FromContext(p.currentContext) } } - -func (p *ocAnnotator) getSource(function *lisp.LVal) (source string, line int) { - if function.Source == nil { - if cell := function.Cells[0]; cell != nil && cell.Source != nil { - source = cell.Source.File - line = cell.Source.Line - } else { - source = "no-source" - } - return - } - source = function.Source.File - line = function.Source.Line - return -} diff --git a/lisp/x/profiler/opencensus_annotator_test.go b/lisp/x/profiler/opencensus_annotator_test.go index e770431..e8067df 100644 --- a/lisp/x/profiler/opencensus_annotator_test.go +++ b/lisp/x/profiler/opencensus_annotator_test.go @@ -2,7 +2,6 @@ package profiler_test import ( "context" - "log" "testing" "github.com/luthersystems/elps/lisp" @@ -12,48 +11,32 @@ import ( "go.opencensus.io/trace" ) +type inMemoryExporter struct { + spans []*trace.SpanData +} + +func (e *inMemoryExporter) ExportSpan(sd *trace.SpanData) { + e.spans = append(e.spans, sd) +} + func TestNewOpenCensusAnnotator(t *testing.T) { env := lisp.NewEnv(nil) env.Runtime.Reader = parser.NewReader() - // Let's sample at 100% for the purposes of this test... trace.ApplyConfig(trace.Config{DefaultSampler: trace.AlwaysSample()}) - trace.RegisterExporter(new(customExporter)) + exporter := &inMemoryExporter{} + trace.RegisterExporter(exporter) + t.Cleanup(func() { + trace.UnregisterExporter(exporter) + }) + ppa := profiler.NewOpenCensusAnnotator(env.Runtime, context.Background()) assert.NoError(t, ppa.Enable()) lerr := lisp.InitializeUserEnv(env) - if lisp.GoError(lerr) != nil { - t.Fatal(lisp.GoError(lerr)) - } - testsrc := env.LoadString("test.lisp", ` -(defun print-it - ('x) - (debug-print x) -) -(defun add-it - ('x 'y) - (+ x y) -) -(defun recurse-it - ('x) - (if - (< x 4) - (recurse-it (- x 1)) - (add-it x 3) - ) -) -(print-it "Hello") -(print-it (add-it (add-it 3 (recurse-it 5)) 8))`) + assert.NoError(t, lisp.GoError(lerr)) + testsrc := env.LoadString("test.lisp", testLisp) lerr = env.Eval(testsrc) assert.NotEqual(t, lisp.LError, lerr.Type) - // Mark the profile as complete and dump the rest of the profile assert.NoError(t, ppa.Complete()) -} - -// a simple exporter that prints to the screen - in the real world, you'd go to one of the -// myriad exporters supported by opencensus https://opencensus.io/exporters/supported-exporters/go/ -type customExporter struct{} -func (cse *customExporter) ExportSpan(sd *trace.SpanData) { - log.Printf("Name: %s\n\tTraceID: %x\n\tSpanID: %x\n\tParentSpanID: %x\n\tStartTime: %s\n\tEndTime: %s\n\tAnnotations: %+v\n", - sd.Name, sd.TraceID, sd.SpanID, sd.ParentSpanID, sd.StartTime, sd.EndTime, sd.Annotations) + assert.GreaterOrEqual(t, len(exporter.spans), 1, "Expected at least one span") } diff --git a/lisp/x/profiler/opentelemetry_annotator.go b/lisp/x/profiler/opentelemetry_annotator.go index fea2d9d..91e69d7 100644 --- a/lisp/x/profiler/opentelemetry_annotator.go +++ b/lisp/x/profiler/opentelemetry_annotator.go @@ -3,7 +3,6 @@ package profiler import ( "context" "errors" - "fmt" "github.com/luthersystems/elps/lisp" "go.opentelemetry.io/otel" @@ -16,45 +15,31 @@ const ( ContextOpenTelemetryTracerKey = "otelParentTracer" ) +var _ lisp.Profiler = &otelAnnotator{} + type otelAnnotator struct { - runtime *lisp.Runtime - enabled bool + profiler currentContext context.Context currentSpan trace.Span } -func NewOpenTelemetryAnnotator(runtime *lisp.Runtime, parentContext context.Context) lisp.Profiler { - return &otelAnnotator{ - runtime: runtime, +func NewOpenTelemetryAnnotator(runtime *lisp.Runtime, parentContext context.Context, opts ...Option) *otelAnnotator { + p := &otelAnnotator{ + profiler: profiler{ + runtime: runtime, + }, currentContext: parentContext, } -} - -func (p *otelAnnotator) IsEnabled() bool { - return p.enabled -} - -func (p *otelAnnotator) EnableWithContext(ctx context.Context) error { - p.runtime.Profiler = p - p.enabled = true - if ctx == nil { - return errors.New("set a context to use this function") - } - p.currentContext = ctx - return nil + p.profiler.applyConfigs(opts...) + return p } func (p *otelAnnotator) Enable() error { p.runtime.Profiler = p - p.enabled = true if p.currentContext == nil { return errors.New("we can only append spans to a context that is linked to opentelemetry") } - return nil -} - -func (p *otelAnnotator) SetFile(filename string) error { - return errors.New("no need to set a file for this profiler type") + return p.profiler.Enable() } func (p *otelAnnotator) Complete() error { @@ -72,41 +57,18 @@ func contextTracer(ctx context.Context) trace.Tracer { return otel.GetTracerProvider().Tracer(tracerName) } -func (p *otelAnnotator) Start(function *lisp.LVal) func() { - if !p.enabled { +func (p *otelAnnotator) Start(fun *lisp.LVal) func() { + if p.skipTrace(fun) { return func() {} } oldContext := p.currentContext - switch function.Type { - case lisp.LInt, lisp.LString, lisp.LFloat, lisp.LBytes, lisp.LError, lisp.LArray, lisp.LQuote, lisp.LNative, lisp.LQSymbol, lisp.LSortMap: - // We don't need to profile these types. We could, but we're not that LISP :D - return func() {} - case lisp.LFun, lisp.LSymbol, lisp.LSExpr: - fName := fmt.Sprintf("%s:%s", function.FunData().Package, getFunNameFromFID(p.runtime, function.FunData().FID)) - p.currentContext, p.currentSpan = contextTracer(p.currentContext).Start(p.currentContext, fName) - default: - panic(fmt.Sprintf("missing type %d", function.Type)) - } + p.currentContext, p.currentSpan = contextTracer(p.currentContext).Start(p.currentContext, prettyFunName(p.runtime, fun)) return func() { - file, line := p.getSource(function) + 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) getSource(function *lisp.LVal) (source string, line int) { - if function.Source == nil { - if cell := function.Cells[0]; cell != nil && cell.Source != nil { - source = cell.Source.File - line = cell.Source.Line - } else { - source = "no-source" - } - return - } - source = function.Source.File - line = function.Source.Line - return -} diff --git a/lisp/x/profiler/opentelemetry_annotator_test.go b/lisp/x/profiler/opentelemetry_annotator_test.go index ca28cfe..eb4d587 100644 --- a/lisp/x/profiler/opentelemetry_annotator_test.go +++ b/lisp/x/profiler/opentelemetry_annotator_test.go @@ -2,7 +2,7 @@ package profiler_test import ( "context" - "log" + _ "embed" "testing" "github.com/luthersystems/elps/lisp" @@ -10,61 +10,62 @@ import ( "github.com/luthersystems/elps/parser" "github.com/stretchr/testify/assert" "go.opentelemetry.io/otel" - "go.opentelemetry.io/otel/exporters/stdout/stdouttrace" - sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" ) func TestNewOpenTelemetryAnnotator(t *testing.T) { - // Configure a stdout exporter to log the tracing data. - exporter, err := stdouttrace.New(stdouttrace.WithPrettyPrint()) - if err != nil { - log.Fatalf("failed to initialize stdout export pipeline: %v", err) - } + exporter := tracetest.NewInMemoryExporter() - tp := sdktrace.NewTracerProvider( - // Use the custom exporter - sdktrace.WithBatcher(exporter), - // Always sample - sdktrace.WithSampler(sdktrace.AlwaysSample()), + tp := trace.NewTracerProvider( + trace.WithSyncer(exporter), + trace.WithSampler(trace.AlwaysSample()), ) - // Register the tracer provider using global API. + t.Cleanup(func() { + err := tp.Shutdown(context.Background()) + assert.NoError(t, err, "TracerProvider shutdown") + }) otel.SetTracerProvider(tp) - // Ensure we're using the OpenTelemetry Annotator. env := lisp.NewEnv(nil) env.Runtime.Reader = parser.NewReader() ppa := profiler.NewOpenTelemetryAnnotator(env.Runtime, context.Background()) assert.NoError(t, ppa.Enable()) lerr := lisp.InitializeUserEnv(env) - if lisp.GoError(lerr) != nil { - t.Fatal(lisp.GoError(lerr)) - } - testsrc := env.LoadString("test.lisp", ` -(defun print-it - ('x) - (debug-print x) -) -(defun add-it - ('x 'y) - (+ x y) -) -(defun recurse-it - ('x) - (if - (< x 4) - (recurse-it (- x 1)) - (add-it x 3) + assert.NoError(t, lisp.GoError(lerr)) + testsrc := env.LoadString("test.lisp", testLisp) + lerr = env.Eval(testsrc) + assert.NotEqual(t, lisp.LError, lerr.Type, lerr.Str) + assert.NoError(t, ppa.Complete()) + + spans := exporter.GetSpans() + assert.GreaterOrEqual(t, len(spans), 3, "Expected at least three spans") +} + +func TestNewOpenTelemetryAnnotatorSkip(t *testing.T) { + exporter := tracetest.NewInMemoryExporter() + + tp := trace.NewTracerProvider( + trace.WithSyncer(exporter), + trace.WithSampler(trace.AlwaysSample()), ) -) -(print-it "Hello") -(print-it (add-it (add-it 3 (recurse-it 5)) 8))`) + t.Cleanup(func() { + err := tp.Shutdown(context.Background()) + assert.NoError(t, err, "TracerProvider shutdown") + }) + otel.SetTracerProvider(tp) + + env := lisp.NewEnv(nil) + env.Runtime.Reader = parser.NewReader() + ppa := profiler.NewOpenTelemetryAnnotator(env.Runtime, context.Background(), profiler.WithELPSDocFilter()) + assert.NoError(t, ppa.Enable()) + lerr := lisp.InitializeUserEnv(env) + assert.NoError(t, lisp.GoError(lerr)) + testsrc := env.LoadString("test.lisp", testLisp) lerr = env.Eval(testsrc) - assert.NotEqual(t, lisp.LError, lerr.Type) - // Mark the profile as complete and dump the rest of the profile + assert.NotEqual(t, lisp.LError, lerr.Type, lerr.Str) assert.NoError(t, ppa.Complete()) - err = tp.Shutdown(context.Background()) - if err != nil { - t.Errorf("Error during TracerProvider shutdown: %v", err) - } + spans := exporter.GetSpans() + assert.LessOrEqual(t, len(spans), 3, "Expected selective spans") } diff --git a/lisp/x/profiler/profiler.go b/lisp/x/profiler/profiler.go new file mode 100644 index 0000000..3de5887 --- /dev/null +++ b/lisp/x/profiler/profiler.go @@ -0,0 +1,85 @@ +package profiler + +import ( + "fmt" + "regexp" + + "github.com/luthersystems/elps/lisp" +) + +// profiler is a minimal lisp.Profiler +type profiler struct { + runtime *lisp.Runtime + enabled bool + skipFilter SkipFilter +} + +var _ lisp.Profiler = &profiler{} + +func (p *profiler) IsEnabled() bool { + return p.enabled +} + +type Option func(*profiler) + +func (p *profiler) applyConfigs(opts ...Option) { + for _, opt := range opts { + opt(p) + } +} + +func (p *profiler) Enable() error { + if p.enabled { + return fmt.Errorf("profiler already enabled") + } + p.enabled = true + return nil +} + +func (p *profiler) Start(fun *lisp.LVal) func() { + return func() {} +} + +// 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) +} + +var builtinRegex = regexp.MustCompile("\\<(?:builtin|special)-[a-z]+ \\`\\`(.*)\\'\\'\\>") + +// Gets a canonical version of the function name suitable for viewing in KCacheGrind +func getFunNameFromFID(rt *lisp.Runtime, in string) string { + // Most of the time we can just look this up in FunNames + if name, ok := rt.Package.FunNames[in]; ok { + return name + } + // but sometimes something doesn't match - so we'll try to regexp it out + if !builtinRegex.MatchString(in) { + return in + } + return builtinRegex.FindStringSubmatch(in)[1] +} + +// prettyFunName constructs a pretty canonical name. +// IMPORTANT: must be type with FunData() +func prettyFunName(runtime *lisp.Runtime, fun *lisp.LVal) string { + 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 + } + + source := "no-source" + line := 0 + if cell := function.Cells[0]; cell != nil && cell.Source != nil { + source = cell.Source.File + line = cell.Source.Line + } + return source, line +} diff --git a/lisp/x/profiler/profiler_test.go b/lisp/x/profiler/profiler_test.go new file mode 100644 index 0000000..8d6883c --- /dev/null +++ b/lisp/x/profiler/profiler_test.go @@ -0,0 +1,11 @@ +package profiler_test + +import ( + _ "embed" +) + +//go:embed test.lisp +var testLisp string + +//go:embed longtest.lisp +var longTestLisp string diff --git a/lisp/x/profiler/shared.go b/lisp/x/profiler/shared.go deleted file mode 100644 index c752137..0000000 --- a/lisp/x/profiler/shared.go +++ /dev/null @@ -1,21 +0,0 @@ -package profiler - -import ( - "github.com/luthersystems/elps/lisp" - "regexp" -) - -var builtinRegex = regexp.MustCompile("\\<(?:builtin|special)-[a-z]+ \\`\\`(.*)\\'\\'\\>") - -// Gets a canonical version of the function name suitable for viewing in KCacheGrind -func getFunNameFromFID(rt *lisp.Runtime, in string) string { - // Most of the time we can just look this up in FunNames - if name, ok := rt.Package.FunNames[in]; ok { - return name - } - // but sometimes something doesn't match - so we'll try to regexp it out - if !builtinRegex.MatchString(in) { - return in - } - return builtinRegex.FindStringSubmatch(in)[1] -} diff --git a/lisp/x/profiler/skipfilter.go b/lisp/x/profiler/skipfilter.go new file mode 100644 index 0000000..2ec7fb5 --- /dev/null +++ b/lisp/x/profiler/skipfilter.go @@ -0,0 +1,50 @@ +package profiler + +import ( + "regexp" + + "github.com/luthersystems/elps/lisp" + "github.com/luthersystems/elps/lisp/lisplib/libhelp" +) + +type SkipFilter func(fun *lisp.LVal) bool + +func defaultSkipFilter(fun *lisp.LVal) bool { + switch fun.Type { + case lisp.LFun, lisp.LSymbol, lisp.LSExpr: + return false + case lisp.LInt, lisp.LString, lisp.LFloat, lisp.LBytes, lisp.LError, lisp.LArray, lisp.LQuote, lisp.LNative, lisp.LQSymbol, lisp.LSortMap: + return true + default: + return true + } +} + +// WithELPSDocFilter filters to only include spans for functions with elps +// docs that denote tracing. +func WithELPSDocFilter() Option { + return WithSkipFilter(elpsDocSkipFilter) +} + +// WithSkipFilter sets the filter for tracing spans. +func WithSkipFilter(skipFilter SkipFilter) Option { + return func(p *profiler) { + p.skipFilter = skipFilter + } +} + +// ELPSDocTrace is a magic string used to enable tracing in a profiler +// configured WithELPSDocFilter. All functions with an elps doc comment that +// contains this string will be traced. +const ELPSDocTrace = "@trace" + +var elpsDocTraceRegExp = regexp.MustCompile(ELPSDocTrace) + +func elpsDocSkipFilter(fun *lisp.LVal) bool { + docStr := libhelp.FunDocstring(fun) + if docStr == "" { + return true + } + // do not skip elps docs that include trace constant + return !elpsDocTraceRegExp.MatchString(docStr) +} diff --git a/lisp/x/profiler/test.lisp b/lisp/x/profiler/test.lisp new file mode 100644 index 0000000..f3f54a7 --- /dev/null +++ b/lisp/x/profiler/test.lisp @@ -0,0 +1,14 @@ +(defun print-it (x) + (debug-print x)) + +(defun add-it (x y) + "@trace" + (+ x y)) + +(defun recurse-it (x) + (if (< x 4) + (recurse-it (- x 1)) + (add-it x 3))) + +(print-it "Hello") +(print-it (add-it (add-it 3 (recurse-it 5)) 8)) From 763d1a0a2860157a6d1ff6abe0cbc84bb1288324 Mon Sep 17 00:00:00 2001 From: sam-at-luther Date: Wed, 3 Jan 2024 14:45:50 -0800 Subject: [PATCH 2/3] Fix test, comments --- lisp/x/profiler/go_annotator_test.go | 2 +- lisp/x/profiler/profiler.go | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/lisp/x/profiler/go_annotator_test.go b/lisp/x/profiler/go_annotator_test.go index 9cd967b..43d6ce3 100644 --- a/lisp/x/profiler/go_annotator_test.go +++ b/lisp/x/profiler/go_annotator_test.go @@ -28,7 +28,7 @@ func TestNewPprofAnnotator(t *testing.T) { t.Fatal(lisp.GoError(lerr)) } // Some spurious functions to check we get a profile out - testsrc := env.LoadString("test.lisp", longTestLisp) + testsrc := env.LoadString("longtest.lisp", longTestLisp) lerr = env.Eval(testsrc) assert.NotEqual(t, lisp.LError, lerr.Type, lerr.Str) // Mark the profile as complete and dump the rest of the profile diff --git a/lisp/x/profiler/profiler.go b/lisp/x/profiler/profiler.go index 3de5887..061e64d 100644 --- a/lisp/x/profiler/profiler.go +++ b/lisp/x/profiler/profiler.go @@ -47,7 +47,7 @@ func (p *profiler) skipTrace(v *lisp.LVal) bool { var builtinRegex = regexp.MustCompile("\\<(?:builtin|special)-[a-z]+ \\`\\`(.*)\\'\\'\\>") -// Gets a canonical version of the function name suitable for viewing in KCacheGrind +// Gets a canonical version of the function name suitable for human viewing. func getFunNameFromFID(rt *lisp.Runtime, in string) string { // Most of the time we can just look this up in FunNames if name, ok := rt.Package.FunNames[in]; ok { From ee40ea3458efa6cbc4fcef41587fb12f15bf1d83 Mon Sep 17 00:00:00 2001 From: sam-at-luther Date: Wed, 3 Jan 2024 15:23:22 -0800 Subject: [PATCH 3/3] Avoid panic in profiler --- lisp/x/profiler/profiler.go | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/lisp/x/profiler/profiler.go b/lisp/x/profiler/profiler.go index 061e64d..680af49 100644 --- a/lisp/x/profiler/profiler.go +++ b/lisp/x/profiler/profiler.go @@ -61,8 +61,10 @@ func getFunNameFromFID(rt *lisp.Runtime, in string) string { } // prettyFunName constructs a pretty canonical name. -// IMPORTANT: must be type with FunData() func prettyFunName(runtime *lisp.Runtime, fun *lisp.LVal) string { + if fun.Type != lisp.LFun { + return "" + } funData := fun.FunData() if funData == nil { return ""