profiler.go

Documentation: github.com/dop251/goja

     1  package goja
     2  
     3  import (
     4  	"errors"
     5  	"io"
     6  	"strconv"
     7  	"sync"
     8  	"sync/atomic"
     9  	"time"
    10  
    11  	"github.com/google/pprof/profile"
    12  )
    13  
    14  const profInterval = 10 * time.Millisecond
    15  const profMaxStackDepth = 64
    16  
    17  const (
    18  	profReqNone int32 = iota
    19  	profReqDoSample
    20  	profReqSampleReady
    21  	profReqStop
    22  )
    23  
    24  type _globalProfiler struct {
    25  	p profiler
    26  	w io.Writer
    27  
    28  	enabled int32
    29  }
    30  
    31  var globalProfiler _globalProfiler
    32  
    33  type profTracker struct {
    34  	req, finished int32
    35  	start, stop   time.Time
    36  	numFrames     int
    37  	frames        [profMaxStackDepth]StackFrame
    38  }
    39  
    40  type profiler struct {
    41  	mu       sync.Mutex
    42  	trackers []*profTracker
    43  	buf      *profBuffer
    44  	running  bool
    45  }
    46  
    47  type profFunc struct {
    48  	f    profile.Function
    49  	locs map[int32]*profile.Location
    50  }
    51  
    52  type profSampleNode struct {
    53  	loc      *profile.Location
    54  	sample   *profile.Sample
    55  	parent   *profSampleNode
    56  	children map[*profile.Location]*profSampleNode
    57  }
    58  
    59  type profBuffer struct {
    60  	funcs map[*Program]*profFunc
    61  	root  profSampleNode
    62  }
    63  
    64  func (pb *profBuffer) addSample(pt *profTracker) {
    65  	sampleFrames := pt.frames[:pt.numFrames]
    66  	n := &pb.root
    67  	for j := len(sampleFrames) - 1; j >= 0; j-- {
    68  		frame := sampleFrames[j]
    69  		if frame.prg == nil {
    70  			continue
    71  		}
    72  		var f *profFunc
    73  		if f = pb.funcs[frame.prg]; f == nil {
    74  			f = &profFunc{
    75  				locs: make(map[int32]*profile.Location),
    76  			}
    77  			if pb.funcs == nil {
    78  				pb.funcs = make(map[*Program]*profFunc)
    79  			}
    80  			pb.funcs[frame.prg] = f
    81  		}
    82  		var loc *profile.Location
    83  		if loc = f.locs[int32(frame.pc)]; loc == nil {
    84  			loc = &profile.Location{}
    85  			f.locs[int32(frame.pc)] = loc
    86  		}
    87  		if nn := n.children[loc]; nn == nil {
    88  			if n.children == nil {
    89  				n.children = make(map[*profile.Location]*profSampleNode, 1)
    90  			}
    91  			nn = &profSampleNode{
    92  				parent: n,
    93  				loc:    loc,
    94  			}
    95  			n.children[loc] = nn
    96  			n = nn
    97  		} else {
    98  			n = nn
    99  		}
   100  	}
   101  	smpl := n.sample
   102  	if smpl == nil {
   103  		locs := make([]*profile.Location, 0, len(sampleFrames))
   104  		for n1 := n; n1.loc != nil; n1 = n1.parent {
   105  			locs = append(locs, n1.loc)
   106  		}
   107  		smpl = &profile.Sample{
   108  			Location: locs,
   109  			Value:    make([]int64, 2),
   110  		}
   111  		n.sample = smpl
   112  	}
   113  	smpl.Value[0]++
   114  	smpl.Value[1] += int64(pt.stop.Sub(pt.start))
   115  }
   116  
   117  func (pb *profBuffer) profile() *profile.Profile {
   118  	pr := profile.Profile{}
   119  	pr.SampleType = []*profile.ValueType{
   120  		{Type: "samples", Unit: "count"},
   121  		{Type: "cpu", Unit: "nanoseconds"},
   122  	}
   123  	pr.PeriodType = pr.SampleType[1]
   124  	pr.Period = int64(profInterval)
   125  	mapping := &profile.Mapping{
   126  		ID:   1,
   127  		File: "[ECMAScript code]",
   128  	}
   129  	pr.Mapping = make([]*profile.Mapping, 1, len(pb.funcs)+1)
   130  	pr.Mapping[0] = mapping
   131  
   132  	pr.Function = make([]*profile.Function, 0, len(pb.funcs))
   133  	funcNames := make(map[string]struct{})
   134  	var funcId, locId uint64
   135  	for prg, f := range pb.funcs {
   136  		fileName := prg.src.Name()
   137  		funcId++
   138  		f.f.ID = funcId
   139  		f.f.Filename = fileName
   140  		var funcName string
   141  		if prg.funcName != "" {
   142  			funcName = prg.funcName.String()
   143  		} else {
   144  			funcName = "<anonymous>"
   145  		}
   146  		// Make sure the function name is unique, otherwise the graph display merges them into one node, even
   147  		// if they are in different mappings.
   148  		if _, exists := funcNames[funcName]; exists {
   149  			funcName += "." + strconv.FormatUint(f.f.ID, 10)
   150  		} else {
   151  			funcNames[funcName] = struct{}{}
   152  		}
   153  		f.f.Name = funcName
   154  		pr.Function = append(pr.Function, &f.f)
   155  		for pc, loc := range f.locs {
   156  			locId++
   157  			loc.ID = locId
   158  			pos := prg.src.Position(prg.sourceOffset(int(pc)))
   159  			loc.Line = []profile.Line{
   160  				{
   161  					Function: &f.f,
   162  					Line:     int64(pos.Line),
   163  				},
   164  			}
   165  
   166  			loc.Mapping = mapping
   167  			pr.Location = append(pr.Location, loc)
   168  		}
   169  	}
   170  	pb.addSamples(&pr, &pb.root)
   171  	return &pr
   172  }
   173  
   174  func (pb *profBuffer) addSamples(p *profile.Profile, n *profSampleNode) {
   175  	if n.sample != nil {
   176  		p.Sample = append(p.Sample, n.sample)
   177  	}
   178  	for _, child := range n.children {
   179  		pb.addSamples(p, child)
   180  	}
   181  }
   182  
   183  func (p *profiler) run() {
   184  	ticker := time.NewTicker(profInterval)
   185  	counter := 0
   186  
   187  	for ts := range ticker.C {
   188  		p.mu.Lock()
   189  		left := len(p.trackers)
   190  		if left == 0 {
   191  			break
   192  		}
   193  		for {
   194  			// This loop runs until either one of the VMs is signalled or all of the VMs are scanned and found
   195  			// busy or deleted.
   196  			if counter >= len(p.trackers) {
   197  				counter = 0
   198  			}
   199  			tracker := p.trackers[counter]
   200  			req := atomic.LoadInt32(&tracker.req)
   201  			if req == profReqSampleReady {
   202  				p.buf.addSample(tracker)
   203  			}
   204  			if atomic.LoadInt32(&tracker.finished) != 0 {
   205  				p.trackers[counter] = p.trackers[len(p.trackers)-1]
   206  				p.trackers[len(p.trackers)-1] = nil
   207  				p.trackers = p.trackers[:len(p.trackers)-1]
   208  			} else {
   209  				counter++
   210  				if req != profReqDoSample {
   211  					// signal the VM to take a sample
   212  					tracker.start = ts
   213  					atomic.StoreInt32(&tracker.req, profReqDoSample)
   214  					break
   215  				}
   216  			}
   217  			left--
   218  			if left <= 0 {
   219  				// all VMs are busy
   220  				break
   221  			}
   222  		}
   223  		p.mu.Unlock()
   224  	}
   225  	ticker.Stop()
   226  	p.running = false
   227  	p.mu.Unlock()
   228  }
   229  
   230  func (p *profiler) registerVm() *profTracker {
   231  	pt := new(profTracker)
   232  	p.mu.Lock()
   233  	if p.buf != nil {
   234  		p.trackers = append(p.trackers, pt)
   235  		if !p.running {
   236  			go p.run()
   237  			p.running = true
   238  		}
   239  	} else {
   240  		pt.req = profReqStop
   241  	}
   242  	p.mu.Unlock()
   243  	return pt
   244  }
   245  
   246  func (p *profiler) start() error {
   247  	p.mu.Lock()
   248  	if p.buf != nil {
   249  		p.mu.Unlock()
   250  		return errors.New("profiler is already active")
   251  	}
   252  	p.buf = new(profBuffer)
   253  	p.mu.Unlock()
   254  	return nil
   255  }
   256  
   257  func (p *profiler) stop() *profile.Profile {
   258  	p.mu.Lock()
   259  	trackers, buf := p.trackers, p.buf
   260  	p.trackers, p.buf = nil, nil
   261  	p.mu.Unlock()
   262  	if buf != nil {
   263  		k := 0
   264  		for i, tracker := range trackers {
   265  			req := atomic.LoadInt32(&tracker.req)
   266  			if req == profReqSampleReady {
   267  				buf.addSample(tracker)
   268  			} else if req == profReqDoSample {
   269  				// In case the VM is requested to do a sample, there is a small chance of a race
   270  				// where we set profReqStop in between the read and the write, so that the req
   271  				// ends up being set to profReqSampleReady. It's no such a big deal if we do nothing,
   272  				// it just means the VM remains in tracing mode until it finishes the current run,
   273  				// but we do an extra cleanup step later just in case.
   274  				if i != k {
   275  					trackers[k] = trackers[i]
   276  				}
   277  				k++
   278  			}
   279  			atomic.StoreInt32(&tracker.req, profReqStop)
   280  		}
   281  
   282  		if k > 0 {
   283  			trackers = trackers[:k]
   284  			go func() {
   285  				// Make sure all VMs are requested to stop tracing.
   286  				for {
   287  					k := 0
   288  					for i, tracker := range trackers {
   289  						req := atomic.LoadInt32(&tracker.req)
   290  						if req != profReqStop {
   291  							atomic.StoreInt32(&tracker.req, profReqStop)
   292  							if i != k {
   293  								trackers[k] = trackers[i]
   294  							}
   295  							k++
   296  						}
   297  					}
   298  
   299  					if k == 0 {
   300  						return
   301  					}
   302  					trackers = trackers[:k]
   303  					time.Sleep(100 * time.Millisecond)
   304  				}
   305  			}()
   306  		}
   307  		return buf.profile()
   308  	}
   309  	return nil
   310  }
   311  
   312  /*
   313  StartProfile enables execution time profiling for all Runtimes within the current process.
   314  This works similar to pprof.StartCPUProfile and produces the same format which can be consumed by `go tool pprof`.
   315  There are, however, a few notable differences. Firstly, it's not a CPU profile, rather "execution time" profile.
   316  It measures the time the VM spends executing an instruction. If this instruction happens to be a call to a
   317  blocking Go function, the waiting time will be measured. Secondly, the 'cpu' sample isn't simply `count*period`,
   318  it's the time interval between when sampling was requested and when the instruction has finished. If a VM is still
   319  executing the same instruction when the time comes for the next sample, the sampling is skipped (i.e. `count` doesn't
   320  grow).
   321  
   322  If there are multiple functions with the same name, their names get a '.N' suffix, where N is a unique number,
   323  because otherwise the graph view merges them together (even if they are in different mappings). This includes
   324  "<anonymous>" functions.
   325  
   326  The sampling period is set to 10ms.
   327  
   328  It returns an error if profiling is already active.
   329  */
   330  func StartProfile(w io.Writer) error {
   331  	err := globalProfiler.p.start()
   332  	if err != nil {
   333  		return err
   334  	}
   335  	globalProfiler.w = w
   336  	atomic.StoreInt32(&globalProfiler.enabled, 1)
   337  	return nil
   338  }
   339  
   340  /*
   341  StopProfile stops the current profile initiated by StartProfile, if any.
   342  */
   343  func StopProfile() {
   344  	atomic.StoreInt32(&globalProfiler.enabled, 0)
   345  	pr := globalProfiler.p.stop()
   346  	if pr != nil {
   347  		_ = pr.Write(globalProfiler.w)
   348  	}
   349  	globalProfiler.w = nil
   350  }
   351
View as plain text