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.

Sign up for GitHub

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

Jump to bottom

BAAS-28253: Add optional tick tracking at the function level #115

Merged
merged 18 commits into from
Feb 12, 2024
Merged

BAAS-28253: Add optional tick tracking at the function level #115

Show file tree
Hide file tree
Changes from 5 commits
Commits
Show all changes
18 commits
Select commit Hold shift + click to select a range
b14fe92
BAAS-28253: Add optional tick tracking at the function level
Calvinnix Jan 31, 2024
5a636fa
improve variable name
Calvinnix Jan 31, 2024
ebff8e5
improve performance by sampling 10% of ticks, a better approach might…
Calvinnix Jan 31, 2024
d9a1535
optimize function tick tracking
Calvinnix Jan 31, 2024
aae390a
undo map key optimization
Calvinnix Jan 31, 2024
cb34f32
clean up code
Calvinnix Jan 31, 2024
5f52315
add nil check
Calvinnix Feb 1, 2024
6dcfbe8
rename variable for clarity
Calvinnix Feb 1, 2024
3a14fee
default function tick tracking to false, add comments
Calvinnix Feb 1, 2024
7e6ac5f
improve comment
Calvinnix Feb 1, 2024
a4e34da
replace setPrg pattern to avoid diverging from goja as much
Calvinnix Feb 2, 2024
608e641
Adhere to best practices, simplify profileTicks
Calvinnix Feb 2, 2024
6f9d567
add tests for tick tracking
Calvinnix Feb 2, 2024
c47f607
use reflect to check map equality
Calvinnix Feb 2, 2024
f02d9b0
update tests and update variable names/location
Calvinnix Feb 2, 2024
0ff8462
add additional test scenarios
Calvinnix Feb 2, 2024
c0ed032
update tick metric key formatting and add docs
Calvinnix Feb 5, 2024
4fe0248
add error test scenario and more docs
Calvinnix Feb 12, 2024
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
2 changes: 1 addition & 1 deletion compiler_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -156,7 +156,7 @@ func testLibX() *Program {

func (r *Runtime) testPrg(p *Program, expectedResult Value, t *testing.T) {
vm := r.vm
vm.prg = p
vm.setPrg(p)
Calvinnix marked this conversation as resolved.
Show resolved Hide resolved
vm.pc = 0
vm.prg.dumpCode(t.Logf)
vm.result = _undefined
Expand Down
6 changes: 3 additions & 3 deletions func.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -227,7 +227,7 @@ func (f *classFuncObject) _initFields(instance *Object) {
if f.initFields != nil {
vm := f.val.runtime.vm
vm.pushCtx()
vm.prg = f.initFields
vm.setPrg(f.initFields)
vm.stash = f.stash
vm.privEnv = f.privEnv
vm.newTarget = nil
Expand Down Expand Up @@ -319,7 +319,7 @@ func (f *baseJsFuncObject) _call(ctx context.Context, args []Value, newTarget, t
vm.pushCtx()
}
vm.args = len(args)
vm.prg = f.prg
vm.setPrg(f.prg)
vm.stash = f.stash
vm.privEnv = f.privEnv
vm.newTarget = newTarget
Expand Down Expand Up @@ -433,7 +433,7 @@ func (f *nativeFuncObject) Call(call FunctionCall) Value {
func (f *nativeFuncObject) vmCall(vm *vm, n int) {
if f.f != nil {
vm.pushCtx()
vm.prg = nil
vm.setPrg(nil)
vm.sb = vm.sp - n // so that [sb-1] points to the callee
ret := f.f(FunctionCall{
Arguments: vm.stack[vm.sp-n : vm.sp],
Expand Down
21 changes: 18 additions & 3 deletions runtime.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -204,12 +204,19 @@
limiter *rate.Limiter
limiterTicksLeft int
ticks uint64

disableTickMetrics bool
Calvinnix marked this conversation as resolved.
Show resolved Hide resolved
functionTickMetrics map[string]uint64
}

func (self *Runtime) Ticks() uint64 {
return self.ticks
}

func (self *Runtime) GetFunctionTickMetrics() map[string]uint64 {
Calvinnix marked this conversation as resolved.
Show resolved Hide resolved
Calvinnix marked this conversation as resolved.
Show resolved Hide resolved
return self.functionTickMetrics
}

// SetStackTraceLimit sets an upper limit to the number of stack frames that
// goja will use when formatting an error's stack trace. By default, the limit
// is 10. This is consistent with V8 and SpiderMonkey.
Expand Down Expand Up @@ -489,7 +496,7 @@
}
r.vm.init()

r.SetRateLimiter(rate.NewLimiter(rate.Inf, maxInt))

Check failure on line 499 in runtime.go

View workflow job for this annotation

GitHub Actions / test (1.16.x, ubuntu-latest, 386) 

constant 9007199254740992 overflows int
}

func (r *Runtime) typeErrorResult(throw bool, args ...interface{}) {
Expand Down Expand Up @@ -971,7 +978,7 @@
panic(err)
}

vm.prg = p
vm.setPrg(p)
vm.pc = 0
vm.args = 0
vm.result = _undefined
Expand Down Expand Up @@ -1513,7 +1520,7 @@
vm.stash = &r.global.stash
vm.sb = vm.sp - 1
}
vm.prg = p
vm.setPrg(p)
Copy link

Choose a reason for hiding this comment

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

[q] We calculate the ticks before vm.runTry() or vm.run()where ticks is ticking(vm.r.ticks++). Would it return 0 in some case? Correct me. I may be lost somewhere.
[q] can we add some tests to see if we're able to get the ticks metrics correctly?e.g. creating a vm to run a function and return this metrics. It may be not easy because we need to know the expected ticks(lol).

Copy link
Author

Choose a reason for hiding this comment

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

For some background I had a previous iteration of this that tracked ticks at the exec call but that came with a ~20-30% performance hit.

		} else {
                         // tick tracking occurred here
			vm.prg.code[vm.pc].exec(vm)
		}

[q] We calculate the ticks before vm.runTry() or vm.run()where ticks is ticking(vm.r.ticks++). Would it return 0 in some case? Correct me. I may be lost somewhere.

Yes there may be some scenarios on initial setup where this gets hit and no new ticks have been calculated yet. I think for the run and runTry scenario you are referencing it would probably get handled by the existing vm.prg being nil (i.e. this check in setPrg if vm.prg != nil {)

I like your idea to add tests, I originally compared the setPrg solution against the results of the verbose solution I referenced above and did not see any discrepancies, but I'll add a few tests to solidify that check.

Copy link

Choose a reason for hiding this comment

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

[q1] yes, I believe in some cases the ticks could be 0, but I believe that's fine. I'll let Calvin confirm that thought :)

[q2] agreed. Now that we're closer to a solution we should start adding some tests. We don't need to check exact ticks, but we should make sure that the metrics contain the correct functions and that the ticks of an expensive JS function are higher than the ticks of trivial functions. It might also be worth testing that executing a function X times generates X times more ticks than executing the same function once.

vm.pc = 0
vm.result = _undefined
ex := vm.runTry(r.vm.ctx)
Expand All @@ -1528,7 +1535,7 @@
vm.clearStack()
} else {
vm.stack = nil
vm.prg = nil
vm.setPrg(nil)
vm.setFuncName("")
r.leave()
}
Expand Down Expand Up @@ -3229,3 +3236,11 @@
}
return defProto
}

func (self *Runtime) DisableFunctionTickTracking() {
Calvinnix marked this conversation as resolved.
Show resolved Hide resolved
self.disableTickMetrics = true
}

func (self *Runtime) EnableFunctionTickTracking() {
self.disableTickMetrics = false
}
Calvinnix marked this conversation as resolved.
Show resolved Hide resolved
33 changes: 26 additions & 7 deletions vm.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -306,12 +306,29 @@ type vm struct {
interrupted uint32
interruptVal interface{}
interruptLock sync.Mutex

lastFunctionTicks uint64
}

type instruction interface {
exec(*vm)
}

func (vm *vm) setPrg(prg *Program) {
Calvinnix marked this conversation as resolved.
Show resolved Hide resolved
if !vm.r.disableTickMetrics {
currentTicks := vm.r.Ticks()
if vm.prg != nil {
Copy link

Choose a reason for hiding this comment

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

What I mean by the situation of returning 0 is when vm.prg != nil. In an extreme case, in the very beginning, vm.r.Ticks() should return 0 because ticks is not ticking yet. vm.lastFunctionTicks is also 0. So line 328 will plus 0 at that time.

Copy link
Author

Choose a reason for hiding this comment

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

Yeah I think that edge case is ok.

Copy link
Author

Choose a reason for hiding this comment

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

I say that because I think I prefer the noop (adding 0) over the logic it would take to avoid that scenario.

Let me know if you disagree though!

Copy link

Choose a reason for hiding this comment

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

I also think this is fine, but @LijieZhang1998 let me know if you disagree/if I'm misunderstanding your comment. We don't care too much about these metrics being 100% accurate. We just want to figure out which are the top 10 or so functions we should be focusing on improving.

if vm.r.functionTickMetrics == nil {
vm.r.functionTickMetrics = make(map[string]uint64)
}
Calvinnix marked this conversation as resolved.
Show resolved Hide resolved
functionName := vm.prg.src.Name() + "_" + string(vm.prg.funcName)
Calvinnix marked this conversation as resolved.
Show resolved Hide resolved
vm.r.functionTickMetrics[functionName] += currentTicks - vm.lastFunctionTicks
}
vm.lastFunctionTicks = currentTicks
}
vm.prg = prg
}

func (vm *vm) getFuncName() unistring.String {
vm.funcNameLock.RLock()
s := vm.funcName
Expand Down Expand Up @@ -585,6 +602,7 @@ func (vm *vm) init() {
func (vm *vm) run() {
vm.halt = false
interrupted := false

Calvinnix marked this conversation as resolved.
Show resolved Hide resolved
for !vm.halt {
// NOTE: we should try to avoid making expensive operations within this
// loop since it gets called millions of times per second.
Expand Down Expand Up @@ -866,8 +884,9 @@ func (vm *vm) pushCtx() {
}

func (vm *vm) restoreCtx(ctx *vmContext) {
vm.prg, vm.stash, vm.privEnv, vm.newTarget, vm.result, vm.pc, vm.sb, vm.args =
ctx.prg, ctx.stash, ctx.privEnv, ctx.newTarget, ctx.result, ctx.pc, ctx.sb, ctx.args
vm.stash, vm.privEnv, vm.newTarget, vm.result, vm.pc, vm.sb, vm.args =
ctx.stash, ctx.privEnv, ctx.newTarget, ctx.result, ctx.pc, ctx.sb, ctx.args
vm.setPrg(ctx.prg)

vm.ctx = ctx.ctx
vm.setFuncName(ctx.funcName)
Expand Down Expand Up @@ -3394,7 +3413,7 @@ func (numargs call) exec(vm *vm) {
vm.pc++
vm.pushCtx()
vm.args = n
vm.prg = f.prg
vm.setPrg(f.prg)
vm.stash = f.stash
vm.privEnv = f.privEnv
vm.pc = 0
Expand All @@ -3404,7 +3423,7 @@ func (numargs call) exec(vm *vm) {
vm.pc++
vm.pushCtx()
vm.args = n
vm.prg = f.prg
vm.setPrg(f.prg)
vm.stash = f.stash
vm.privEnv = f.privEnv
vm.pc = 0
Expand All @@ -3414,7 +3433,7 @@ func (numargs call) exec(vm *vm) {
vm.pc++
vm.pushCtx()
vm.args = n
vm.prg = f.prg
vm.setPrg(f.prg)
vm.stash = f.stash
vm.privEnv = f.privEnv
vm.pc = 0
Expand All @@ -3429,7 +3448,7 @@ func (numargs call) exec(vm *vm) {
vm._nativeCall(&f.nativeFuncObject, n)
case *proxyObject:
vm.pushCtx()
vm.prg = nil
vm.setPrg(nil)
vm.setFuncName("proxy")
ret := f.apply(FunctionCall{ctx: vm.ctx, This: vm.stack[vm.sp-n-2], Arguments: vm.stack[vm.sp-n : vm.sp]})
if ret == nil {
Expand All @@ -3449,7 +3468,7 @@ func (numargs call) exec(vm *vm) {
func (vm *vm) _nativeCall(f *nativeFuncObject, n int) {
if f.f != nil {
vm.pushCtx()
vm.prg = nil
vm.setPrg(nil)
vm.setFuncName(nilSafe(f.getStr("name", nil)).string())
ret := f.f(FunctionCall{
ctx: vm.ctx,
Expand Down
Loading