Add profiler skip filter

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()
 }

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.
+annotations.

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")
 }

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