Implemented "cpu" profiler for ECMAScript code (similar to pprof.StartCPUProfile)

compiler.go

@@ -1314,7 +1314,9 @@ func (c *compiler) enterDummyMode() (leaveFunc func()) {
 			breaking: savedBlock.breaking,
 		}
 	}
-	c.p = &Program{}
+	c.p = &Program{
+		src: c.p.src,
+	}
 	c.newScope()
 	return func() {
 		c.block, c.p = savedBlock, savedProgram

compiler_expr.go

@@ -1372,8 +1372,9 @@ func (e *compiledFunctionLiteral) compile() (prg *Program, name unistring.String
 	savedPrg := e.c.p
 	preambleLen := 8 // enter, boxThis, loadStack(0), initThis, createArgs, set, loadCallee, init
 	e.c.p = &Program{
-		src:  e.c.p.src,
-		code: e.c.newCode(preambleLen, 16),
+		src:    e.c.p.src,
+		code:   e.c.newCode(preambleLen, 16),
+		srcMap: []srcMapItem{{srcPos: e.offset}},
 	}
 	e.c.newScope()
 	s := e.c.scope
@@ -1731,6 +1732,7 @@ func (e *compiledFunctionLiteral) compile() (prg *Program, name unistring.String
 		}
 	}
 	code[delta] = enter
+	e.c.p.srcMap[0].pc = delta
 	s.trimCode(delta)
 
 	strict = s.strict
@@ -2481,7 +2483,9 @@ func (c *compiler) evalConst(expr compiledExpr) (Value, *Exception) {
 	var savedPrg *Program
 	createdPrg := false
 	if c.evalVM.prg == nil {
-		c.evalVM.prg = &Program{}
+		c.evalVM.prg = &Program{
+			src: c.p.src,
+		}
 		savedPrg = c.p
 		c.p = c.evalVM.prg
 		createdPrg = true

go.mod

@@ -6,6 +6,7 @@ require (
 	github.com/dlclark/regexp2 v1.7.0
 	github.com/dop251/goja_nodejs v0.0.0-20211022123610-8dd9abb0616d
 	github.com/go-sourcemap/sourcemap v2.1.3+incompatible
+	github.com/google/pprof v0.0.0-20230207041349-798e818bf904
 	github.com/kr/pretty v0.3.0 // indirect
 	golang.org/x/text v0.3.7
 	gopkg.in/yaml.v2 v2.4.0

go.sum

@@ -1,3 +1,6 @@
+github.com/chzyer/logex v1.2.0/go.mod h1:9+9sk7u7pGNWYMkh0hdiL++6OeibzJccyQU4p4MedaY=
+github.com/chzyer/readline v1.5.0/go.mod h1:x22KAscuvRqlLoK9CsoYsmxoXZMMFVyOl86cAH8qUic=
+github.com/chzyer/test v0.0.0-20210722231415-061457976a23/go.mod h1:Q3SI9o4m/ZMnBNeIyt5eFwwo7qiLfzFZmjNmxjkiQlU=
 github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E=
 github.com/dlclark/regexp2 v1.4.1-0.20201116162257-a2a8dda75c91/go.mod h1:2pZnwuY/m+8K6iRw6wQdMtk+rH5tNGR1i55kozfMjCc=
 github.com/dlclark/regexp2 v1.7.0 h1:7lJfhqlPssTb1WQx4yvTHN0uElPEv52sbaECrAQxjAo=
@@ -8,6 +11,9 @@ github.com/dop251/goja_nodejs v0.0.0-20211022123610-8dd9abb0616d h1:W1n4DvpzZGOI
 github.com/dop251/goja_nodejs v0.0.0-20211022123610-8dd9abb0616d/go.mod h1:DngW8aVqWbuLRMHItjPUyqdj+HWPvnQe8V8y1nDpIbM=
 github.com/go-sourcemap/sourcemap v2.1.3+incompatible h1:W1iEw64niKVGogNgBN3ePyLFfuisuzeidWPMPWmECqU=
 github.com/go-sourcemap/sourcemap v2.1.3+incompatible/go.mod h1:F8jJfvm2KbVjc5NqelyYJmf/v5J0dwNLS2mL4sNA1Jg=
+github.com/google/pprof v0.0.0-20230207041349-798e818bf904 h1:4/hN5RUoecvl+RmJRE2YxKWtnnQls6rQjjW5oV7qg2U=
+github.com/google/pprof v0.0.0-20230207041349-798e818bf904/go.mod h1:uglQLonpP8qtYCYyzA+8c/9qtqgA3qsXGYqCPKARAFg=
+github.com/ianlancetaylor/demangle v0.0.0-20220319035150-800ac71e25c2/go.mod h1:aYm2/VgdVmcIU8iMfdMvDMsRAQjcfZSKFby6HOFvi/w=
 github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
 github.com/kr/pretty v0.2.1/go.mod h1:ipq/a2n7PKx3OHsz4KJII5eveXtPO4qwEXGdVfWzfnI=
 github.com/kr/pretty v0.3.0 h1:WgNl7dwNpEZ6jJ9k1snq4pZsg7DOEN8hP9Xw0Tsjwk0=
@@ -18,6 +24,7 @@ github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY=
 github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE=
 github.com/rogpeppe/go-internal v1.6.1 h1:/FiVV8dS/e+YqF2JvO3yXRFbBLTIuSDkuC7aBOAvL+k=
 github.com/rogpeppe/go-internal v1.6.1/go.mod h1:xXDCJY+GAPziupqXw64V24skbSoqbTEfhy4qGm1nDQc=
+golang.org/x/sys v0.0.0-20220310020820-b874c991c1a5/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/text v0.3.6/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=
 golang.org/x/text v0.3.7 h1:olpwvP2KacW1ZWvsR7uQhoyTYvKAupfQrRGBFM352Gk=
 golang.org/x/text v0.3.7/go.mod h1:u+2+/6zg+i71rQMx5EYifcz6MCKuco9NR6JIITiCfzQ=

profiler.go

@@ -0,0 +1,308 @@
+package goja
+
+import (
+	"errors"
+	"io"
+	"strconv"
+	"sync"
+	"sync/atomic"
+	"time"
+
+	"github.com/google/pprof/profile"
+)
+
+const profInterval = 10 * time.Millisecond
+const profMaxStackDepth = 64
+
+const (
+	profReqNone int32 = iota
+	profReqDoSample
+	profReqSampleReady
+	profReqStop
+)
+
+type _globalProfiler struct {
+	p profiler
+	w io.Writer
+
+	enabled int32
+}
+
+var globalProfiler _globalProfiler
+
+type profTracker struct {
+	req, finished int32
+	start, stop   time.Time
+	numFrames     int
+	frames        [profMaxStackDepth]StackFrame
+}
+
+type profiler struct {
+	mu       sync.Mutex
+	trackers []*profTracker
+	buf      *profBuffer
+	running  bool
+}
+
+type profFunc struct {
+	f    profile.Function
+	locs map[int32]*profile.Location
+}
+
+type profSampleNode struct {
+	loc      *profile.Location
+	sample   *profile.Sample
+	parent   *profSampleNode
+	children map[*profile.Location]*profSampleNode
+}
+
+type profBuffer struct {
+	funcs map[*Program]*profFunc
+	root  profSampleNode
+}
+
+func (pb *profBuffer) addSample(pt *profTracker) {
+	sampleFrames := pt.frames[:pt.numFrames]
+	n := &pb.root
+	for j := len(sampleFrames) - 1; j >= 0; j-- {
+		frame := sampleFrames[j]
+		if frame.prg == nil {
+			continue
+		}
+		var f *profFunc
+		if f = pb.funcs[frame.prg]; f == nil {
+			f = &profFunc{
+				locs: make(map[int32]*profile.Location),
+			}
+			if pb.funcs == nil {
+				pb.funcs = make(map[*Program]*profFunc)
+			}
+			pb.funcs[frame.prg] = f
+		}
+		var loc *profile.Location
+		if loc = f.locs[int32(frame.pc)]; loc == nil {
+			loc = &profile.Location{}
+			f.locs[int32(frame.pc)] = loc
+		}
+		if nn := n.children[loc]; nn == nil {
+			if n.children == nil {
+				n.children = make(map[*profile.Location]*profSampleNode, 1)
+			}
+			nn = &profSampleNode{
+				parent: n,
+				loc:    loc,
+			}
+			n.children[loc] = nn
+			n = nn
+		} else {
+			n = nn
+		}
+	}
+	smpl := n.sample
+	if smpl == nil {
+		locs := make([]*profile.Location, 0, len(sampleFrames))
+		for n1 := n; n1.loc != nil; n1 = n1.parent {
+			locs = append(locs, n1.loc)
+		}
+		smpl = &profile.Sample{
+			Location: locs,
+			Value:    make([]int64, 2),
+		}
+		n.sample = smpl
+	}
+	smpl.Value[0]++
+	smpl.Value[1] += int64(pt.stop.Sub(pt.start))
+}
+
+func (pb *profBuffer) profile() *profile.Profile {
+	pr := profile.Profile{}
+	pr.SampleType = []*profile.ValueType{
+		{Type: "samples", Unit: "count"},
+		{Type: "cpu", Unit: "nanoseconds"},
+	}
+	pr.PeriodType = pr.SampleType[1]
+	pr.Period = int64(profInterval)
+	mapping := &profile.Mapping{
+		ID:   1,
+		File: "[ECMAScript code]",
+	}
+	pr.Mapping = make([]*profile.Mapping, 1, len(pb.funcs)+1)
+	pr.Mapping[0] = mapping
+
+	pr.Function = make([]*profile.Function, 0, len(pb.funcs))
+	funcNames := make(map[string]struct{})
+	var funcId, locId uint64
+	for prg, f := range pb.funcs {
+		fileName := prg.src.Name()
+		funcId++
+		f.f.ID = funcId
+		f.f.Filename = fileName
+		var funcName string
+		if prg.funcName != "" {
+			funcName = prg.funcName.String()
+		} else {
+			funcName = "<anonymous>"
+		}
+		// Make sure the function name is unique, otherwise the graph display merges them into one node, even
+		// if they are in different mappings.
+		if _, exists := funcNames[funcName]; exists {
+			funcName += "." + strconv.FormatUint(f.f.ID, 10)
+		} else {
+			funcNames[funcName] = struct{}{}
+		}
+		f.f.Name = funcName
+		pr.Function = append(pr.Function, &f.f)
+		for pc, loc := range f.locs {
+			locId++
+			loc.ID = locId
+			pos := prg.src.Position(prg.sourceOffset(int(pc)))
+			loc.Line = []profile.Line{
+				{
+					Function: &f.f,
+					Line:     int64(pos.Line),
+				},
+			}
+
+			loc.Mapping = mapping
+			pr.Location = append(pr.Location, loc)
+		}
+	}
+	pb.addSamples(&pr, &pb.root)
+	return &pr
+}
+
+func (pb *profBuffer) addSamples(p *profile.Profile, n *profSampleNode) {
+	if n.sample != nil {
+		p.Sample = append(p.Sample, n.sample)
+	}
+	for _, child := range n.children {
+		pb.addSamples(p, child)
+	}
+}
+
+func (p *profiler) run() {
+	ticker := time.NewTicker(profInterval)
+	counter := 0
+L:
+	for ts := range ticker.C {
+		p.mu.Lock()
+		left := len(p.trackers)
+		for {
+			// This loop runs until either one of the VMs is signalled or all of the VMs are scanned and found
+			// busy or deleted.
+			if counter >= len(p.trackers) {
+				counter = 0
+			}
+			tracker := p.trackers[counter]
+			req := atomic.LoadInt32(&tracker.req)
+			if req == profReqSampleReady {
+				if p.buf != nil {
+					p.buf.addSample(tracker)
+				}
+			}
+			if atomic.LoadInt32(&tracker.finished) != 0 {
+				p.trackers[counter] = p.trackers[len(p.trackers)-1]
+				p.trackers[len(p.trackers)-1] = nil
+				p.trackers = p.trackers[:len(p.trackers)-1]
+				if len(p.trackers) == 0 {
+					break L
+				}
+			} else {
+				counter++
+				if p.buf != nil {
+					if req != profReqDoSample {
+						// signal the VM to take a sample
+						tracker.start = ts
+						atomic.StoreInt32(&tracker.req, profReqDoSample)
+						break
+					}
+				} else {
+					atomic.StoreInt32(&tracker.req, profReqStop)
+				}
+			}
+			left--
+			if left <= 0 {
+				// all VMs are busy
+				break
+			}
+		}
+		p.mu.Unlock()
+	}
+	ticker.Stop()
+	p.running = false
+	p.mu.Unlock()
+}
+
+func (p *profiler) registerVm() *profTracker {
+	pt := new(profTracker)
+	p.mu.Lock()
+	p.trackers = append(p.trackers, pt)
+	if !p.running {
+		go p.run()
+		p.running = true
+	}
+	p.mu.Unlock()
+	return pt
+}
+
+func (p *profiler) start() error {
+	p.mu.Lock()
+	if p.buf != nil {
+		p.mu.Unlock()
+		return errors.New("profiler is already active")
+	}
+	p.buf = new(profBuffer)
+	p.mu.Unlock()
+	return nil
+}
+
+func (p *profiler) stop() *profile.Profile {
+	p.mu.Lock()
+	buf := p.buf
+	p.buf = nil
+	p.mu.Unlock()
+	if buf != nil {
+		return buf.profile()
+	}
+	return nil
+}
+
+/*
+StartProfile enables execution time profiling for all Runtimes within the current process.
+This works similar to pprof.StartCPUProfile and produces the same format which can be consumed by `go tool pprof`.
+There are, however, a few notable differences. Firstly, it's not a CPU profile, rather "execution time" profile.
+It measures the time the VM spends executing an instruction. If this instruction happens to be a call to a
+blocking Go function, the waiting time will be measured. Secondly, the 'cpu' sample isn't simply `count*period`,
+it's the time interval between when sampling was requested and when the instruction has finished. If a VM is still
+executing the same instruction when the time comes for the next sample, the sampling is skipped (i.e. `count` doesn't
+grow).
+
+If there are multiple functions with the same name, their names get a '.N' suffix, where N is a unique number,
+because otherwise the graph view merges them together (even if they are in different mappings). This includes
+"<anonymous>" functions.
+
+The sampling period is set to 10ms.
+
+It returns an error if profiling is already active.
+*/
+func StartProfile(w io.Writer) error {
+	err := globalProfiler.p.start()
+	if err != nil {
+		return err
+	}
+	globalProfiler.w = w
+	atomic.StoreInt32(&globalProfiler.enabled, 1)
+	return nil
+}
+
+/*
+StopProfile stops the current profile initiated by StartProfile, if any.
+*/
+func StopProfile() {
+	atomic.StoreInt32(&globalProfiler.enabled, 0)
+	pr := globalProfiler.p.stop()
+	if pr != nil {
+		_ = pr.Write(globalProfiler.w)
+	}
+	globalProfiler.w = nil
+}

profiler_test.go

@@ -0,0 +1,55 @@
+package goja
+
+import (
+	"sync/atomic"
+	"testing"
+	"time"
+)
+
+func TestProfiler(t *testing.T) {
+
+	err := StartProfile(nil)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	vm := New()
+	go func() {
+		_, err := vm.RunScript("test123.js", `
+			const a = 2 + 2;
+			function loop() {
+				for(;;) {}
+			}
+			loop();
+		`)
+		if err != nil {
+			if _, ok := err.(*InterruptedError); !ok {
+				panic(err)
+			}
+		}
+	}()
+
+	time.Sleep(200 * time.Millisecond)
+
+	atomic.StoreInt32(&globalProfiler.enabled, 0)
+	pr := globalProfiler.p.stop()
+
+	if len(pr.Sample) == 0 {
+		t.Fatal("No samples were recorded")
+	}
+
+	var running bool
+	for i := 0; i < 10; i++ {
+		time.Sleep(100 * time.Millisecond)
+		globalProfiler.p.mu.Lock()
+		running = globalProfiler.p.running
+		globalProfiler.p.mu.Unlock()
+		if !running {
+			break
+		}
+	}
+	if running {
+		t.Fatal("The profiler is still running")
+	}
+	vm.Interrupt(nil)
+}

vm.go

@@ -7,6 +7,7 @@ import (
 	"strings"
 	"sync"
 	"sync/atomic"
+	"time"
 
 	"github.com/dop251/goja/unistring"
 )
@@ -330,6 +331,8 @@ type vm struct {
 	interruptLock sync.Mutex
 
 	curAsyncRunner *asyncRunner
+
+	profTracker *profTracker
 }
 
 type instruction interface {
@@ -555,8 +558,20 @@ func (vm *vm) halted() bool {
 }
 
 func (vm *vm) run() {
+	if vm.profTracker != nil && !vm.runWithProfiler() {
+		return
+	}
+	count := 0
 	interrupted := false
 	for {
+		if count == 0 {
+			if atomic.LoadInt32(&globalProfiler.enabled) == 1 && !vm.runWithProfiler() {
+				return
+			}
+			count = 100
+		} else {
+			count--
+		}
 		if interrupted = atomic.LoadUint32(&vm.interrupted) != 0; interrupted {
 			break
 		}
@@ -578,6 +593,42 @@ func (vm *vm) run() {
 	}
 }
 
+func (vm *vm) runWithProfiler() bool {
+	pt := vm.profTracker
+	if pt == nil {
+		pt = globalProfiler.p.registerVm()
+		vm.profTracker = pt
+		defer func() {
+			atomic.StoreInt32(&vm.profTracker.finished, 1)
+			vm.profTracker = nil
+		}()
+	}
+	interrupted := false
+	for {
+		if interrupted = atomic.LoadUint32(&vm.interrupted) != 0; interrupted {
+			return true
+		}
+		pc := vm.pc
+		if pc < 0 || pc >= len(vm.prg.code) {
+			break
+		}
+		vm.prg.code[pc].exec(vm)
+		req := atomic.LoadInt32(&pt.req)
+		if req == profReqStop {
+			return true
+		}
+		if req == profReqDoSample {
+			pt.stop = time.Now()
+
+			pt.numFrames = len(vm.r.CaptureCallStack(len(pt.frames), pt.frames[:0]))
+			pt.frames[0].pc = pc
+			atomic.StoreInt32(&pt.req, profReqSampleReady)
+		}
+	}
+
+	return false
+}
+
 func (vm *vm) Interrupt(v interface{}) {
 	vm.interruptLock.Lock()
 	vm.interruptVal = v

vm_test.go

@@ -1,6 +1,7 @@
 package goja
 
 import (
+	"github.com/dop251/goja/file"
 	"github.com/dop251/goja/parser"
 	"github.com/dop251/goja/unistring"
 	"testing"
@@ -21,6 +22,7 @@ func TestVM1(t *testing.T) {
 	vm := r.vm
 
 	vm.prg = &Program{
+		src:    file.NewFile("dummy", "", 1),
 		values: []Value{valueInt(2), valueInt(3), asciiString("test")},
 		code: []instruction{
 			&bindGlobal{vars: []unistring.String{"v"}},