From 0ae652c225f7447ab0274bc2a7b6d18cf4406cfb Mon Sep 17 00:00:00 2001 From: Calvin Nix Date: Tue, 13 Feb 2024 13:44:16 -0500 Subject: [PATCH 01/13] BAAS-28597: Add counter for limiter wait calls --- runtime.go | 5 +++++ vm.go | 1 + 2 files changed, 6 insertions(+) diff --git a/runtime.go b/runtime.go index a8a3ecc9..f4e2e1d1 100644 --- a/runtime.go +++ b/runtime.go @@ -203,6 +203,7 @@ type Runtime struct { limiter *rate.Limiter limiterTicksLeft int + limiterWaitCount uint64 ticks uint64 tickMetricTrackingEnabled bool @@ -213,6 +214,10 @@ func (self *Runtime) Ticks() uint64 { return self.ticks } +func (self *Runtime) LimiterWaitCount() uint64 { + return self.limiterWaitCount +} + // 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. diff --git a/vm.go b/vm.go index cc974c78..49871cab 100644 --- a/vm.go +++ b/vm.go @@ -617,6 +617,7 @@ func (vm *vm) run() { ctx = context.Background() } + vm.r.limiterWaitCount++ if waitErr := vm.r.limiter.WaitN(ctx, vm.r.limiterTicksLeft); waitErr != nil { if vm.r.vm.ctx == nil { panic(waitErr) From ea92633ccde9ab3118a5dbeed9eb047af831fde2 Mon Sep 17 00:00:00 2001 From: Calvin Nix Date: Tue, 13 Feb 2024 14:02:06 -0500 Subject: [PATCH 02/13] add doc for LimiterWaitCount --- runtime.go | 2 ++ 1 file changed, 2 insertions(+) diff --git a/runtime.go b/runtime.go index f4e2e1d1..ae981c8a 100644 --- a/runtime.go +++ b/runtime.go @@ -214,6 +214,8 @@ func (self *Runtime) Ticks() uint64 { return self.ticks } +// LimiterWaitCount is a counter that tracks the amount of times WaitN was called.This happens when limiterTicksLeft +// hits 0, and we throttle the function execution. func (self *Runtime) LimiterWaitCount() uint64 { return self.limiterWaitCount } From 9824c33c0d5bc081ec8378eb40f906193e3614fa Mon Sep 17 00:00:00 2001 From: Calvin Nix Date: Tue, 13 Feb 2024 14:02:49 -0500 Subject: [PATCH 03/13] formatting --- runtime.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/runtime.go b/runtime.go index ae981c8a..29b6e788 100644 --- a/runtime.go +++ b/runtime.go @@ -214,7 +214,7 @@ func (self *Runtime) Ticks() uint64 { return self.ticks } -// LimiterWaitCount is a counter that tracks the amount of times WaitN was called.This happens when limiterTicksLeft +// LimiterWaitCount is a counter that tracks the amount of times WaitN was called. This happens when limiterTicksLeft // hits 0, and we throttle the function execution. func (self *Runtime) LimiterWaitCount() uint64 { return self.limiterWaitCount From 5edfab1cfc897df873392a9abf1986aa2effce22 Mon Sep 17 00:00:00 2001 From: Calvin Nix Date: Fri, 16 Feb 2024 11:55:01 -0500 Subject: [PATCH 04/13] Improve wait tracking logic --- runtime.go | 14 ++++++++++---- vm.go | 11 ++++++++++- 2 files changed, 20 insertions(+), 5 deletions(-) diff --git a/runtime.go b/runtime.go index 29b6e788..0798ef55 100644 --- a/runtime.go +++ b/runtime.go @@ -203,9 +203,11 @@ type Runtime struct { limiter *rate.Limiter limiterTicksLeft int - limiterWaitCount uint64 ticks uint64 + limiterWaitCount int64 + limiterWaitTotalTime int64 + tickMetricTrackingEnabled bool tickMetrics map[string]uint64 } @@ -214,12 +216,16 @@ func (self *Runtime) Ticks() uint64 { return self.ticks } -// LimiterWaitCount is a counter that tracks the amount of times WaitN was called. This happens when limiterTicksLeft -// hits 0, and we throttle the function execution. -func (self *Runtime) LimiterWaitCount() uint64 { +// LimiterWaitCount tracks the amount of times the rate limiter throttles the execution. +func (self *Runtime) LimiterWaitCount() int64 { return self.limiterWaitCount } +// LimiterWaitTotalTime tracks the total amount of time, in nanoseconds, that the execution was throttled. +func (self *Runtime) LimiterWaitTotalTime() int64 { + return self.limiterWaitTotalTime +} + // 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. diff --git a/vm.go b/vm.go index 49871cab..ab077871 100644 --- a/vm.go +++ b/vm.go @@ -9,6 +9,7 @@ import ( "strings" "sync" "sync/atomic" + "time" "github.com/dop251/goja/unistring" ) @@ -617,7 +618,7 @@ func (vm *vm) run() { ctx = context.Background() } - vm.r.limiterWaitCount++ + start := time.Now() if waitErr := vm.r.limiter.WaitN(ctx, vm.r.limiterTicksLeft); waitErr != nil { if vm.r.vm.ctx == nil { panic(waitErr) @@ -630,6 +631,14 @@ func (vm *vm) run() { } panic(waitErr) } + timeWaited := time.Since(start).Nanoseconds() + // We are only tracking that a "wait" occurred when the time waited is above 10k nanoseconds. This is to + // account for the overhead it takes to actually call the WaitN function. + // I've observed that WaitN takes ~1000 nanoseconds, but I've included a buffer. + if timeWaited > 10_000 { + vm.r.limiterWaitCount++ + vm.r.limiterWaitTotalTime += timeWaited + } } if interrupted = atomic.LoadUint32(&vm.interrupted) != 0; interrupted { From c0dc87aa5ad7e28be712bfec5160ab1eed417553 Mon Sep 17 00:00:00 2001 From: Calvin Nix Date: Tue, 20 Feb 2024 15:39:41 -0500 Subject: [PATCH 05/13] adjust how we wait to be more efficient --- vm.go | 44 ++++++++++++++++++++++++++------------------ 1 file changed, 26 insertions(+), 18 deletions(-) diff --git a/vm.go b/vm.go index ab077871..708d1929 100644 --- a/vm.go +++ b/vm.go @@ -618,26 +618,22 @@ func (vm *vm) run() { ctx = context.Background() } - start := time.Now() - if waitErr := vm.r.limiter.WaitN(ctx, vm.r.limiterTicksLeft); waitErr != nil { - if vm.r.vm.ctx == nil { - panic(waitErr) - } - if ctxErr := vm.r.vm.ctx.Err(); ctxErr != nil { - panic(ctxErr) - } - if strings.Contains(waitErr.Error(), "would exceed") { - panic(context.DeadlineExceeded) - } - panic(waitErr) + now := time.Now() + r := vm.r.limiter.ReserveN(now, vm.r.limiterTicksLeft) + if !r.OK() { + panic("failed to make reservation") } - timeWaited := time.Since(start).Nanoseconds() - // We are only tracking that a "wait" occurred when the time waited is above 10k nanoseconds. This is to - // account for the overhead it takes to actually call the WaitN function. - // I've observed that WaitN takes ~1000 nanoseconds, but I've included a buffer. - if timeWaited > 10_000 { + + delay := r.DelayFrom(now) + if delay > 0 { vm.r.limiterWaitCount++ - vm.r.limiterWaitTotalTime += timeWaited + vm.r.limiterWaitTotalTime += delay.Nanoseconds() + + err := sleep(ctx, delay) + if err != nil { + r.Cancel() + panic(err) + } } } @@ -5616,3 +5612,15 @@ func (s valueStack) MemUsage(ctx *MemUsageContext) (memUsage uint64, newMemUsage return memUsage, newMemUsage, nil } + +// sleep is equivalent to time.Sleep, but is interruptible via context cancelation. +func sleep(ctx context.Context, duration time.Duration) error { + timer := time.NewTimer(duration) + defer timer.Stop() + select { + case <-ctx.Done(): + return ctx.Err() + case <-timer.C: + return nil + } +} From 9796a867c35ba2918067c1e71557a4dbbea5224c Mon Sep 17 00:00:00 2001 From: Calvin Nix Date: Wed, 21 Feb 2024 08:56:52 -0500 Subject: [PATCH 06/13] change limiterWaitTotalTime type to time.Duration --- runtime.go | 6 +++--- vm.go | 2 +- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/runtime.go b/runtime.go index 0798ef55..726866f3 100644 --- a/runtime.go +++ b/runtime.go @@ -206,7 +206,7 @@ type Runtime struct { ticks uint64 limiterWaitCount int64 - limiterWaitTotalTime int64 + limiterWaitTotalTime time.Duration tickMetricTrackingEnabled bool tickMetrics map[string]uint64 @@ -221,8 +221,8 @@ func (self *Runtime) LimiterWaitCount() int64 { return self.limiterWaitCount } -// LimiterWaitTotalTime tracks the total amount of time, in nanoseconds, that the execution was throttled. -func (self *Runtime) LimiterWaitTotalTime() int64 { +// LimiterWaitTotalTime tracks the total amount of time that the execution was throttled. +func (self *Runtime) LimiterWaitTotalTime() time.Duration { return self.limiterWaitTotalTime } diff --git a/vm.go b/vm.go index 708d1929..356137b5 100644 --- a/vm.go +++ b/vm.go @@ -627,7 +627,7 @@ func (vm *vm) run() { delay := r.DelayFrom(now) if delay > 0 { vm.r.limiterWaitCount++ - vm.r.limiterWaitTotalTime += delay.Nanoseconds() + vm.r.limiterWaitTotalTime += delay err := sleep(ctx, delay) if err != nil { From d861907109658815a167df373d94721a576e09dc Mon Sep 17 00:00:00 2001 From: Calvin Nix Date: Wed, 21 Feb 2024 09:03:23 -0500 Subject: [PATCH 07/13] clean up if condition --- vm.go | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/vm.go b/vm.go index 356137b5..d417280f 100644 --- a/vm.go +++ b/vm.go @@ -629,8 +629,7 @@ func (vm *vm) run() { vm.r.limiterWaitCount++ vm.r.limiterWaitTotalTime += delay - err := sleep(ctx, delay) - if err != nil { + if err := sleep(ctx, delay); err != nil { r.Cancel() panic(err) } From e07d00782a281f6b87dd0fb59a45f27663a6969b Mon Sep 17 00:00:00 2001 From: Calvin Nix Date: Wed, 21 Feb 2024 09:13:34 -0500 Subject: [PATCH 08/13] another area to clean up if condition --- vm.go | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/vm.go b/vm.go index d417280f..344f2eaa 100644 --- a/vm.go +++ b/vm.go @@ -624,8 +624,7 @@ func (vm *vm) run() { panic("failed to make reservation") } - delay := r.DelayFrom(now) - if delay > 0 { + if delay := r.DelayFrom(now); delay > 0 { vm.r.limiterWaitCount++ vm.r.limiterWaitTotalTime += delay From c4ada0f986fd99164bb8661cbfb70e3e3e3b48ac Mon Sep 17 00:00:00 2001 From: Calvin Nix Date: Thu, 22 Feb 2024 10:01:56 -0500 Subject: [PATCH 09/13] need to check if context is Done, this check doesn't happen if delay is 0 --- vm.go | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/vm.go b/vm.go index 344f2eaa..eba693a5 100644 --- a/vm.go +++ b/vm.go @@ -633,6 +633,10 @@ func (vm *vm) run() { panic(err) } } + select { + case <-ctx.Done(): + panic(ctx.Err()) + } } if interrupted = atomic.LoadUint32(&vm.interrupted) != 0; interrupted { From 8b8c99f7b15acc310a3807d3fb9c50efcf897ed1 Mon Sep 17 00:00:00 2001 From: Calvin Nix Date: Wed, 28 Feb 2024 12:20:40 -0500 Subject: [PATCH 10/13] remove ctx cancel check, may re-add and include default case since that might be why it was failing --- vm.go | 4 ---- 1 file changed, 4 deletions(-) diff --git a/vm.go b/vm.go index eba693a5..344f2eaa 100644 --- a/vm.go +++ b/vm.go @@ -633,10 +633,6 @@ func (vm *vm) run() { panic(err) } } - select { - case <-ctx.Done(): - panic(ctx.Err()) - } } if interrupted = atomic.LoadUint32(&vm.interrupted) != 0; interrupted { From 5f81ce0b1a784b2109b234e49e06cef05b1638cc Mon Sep 17 00:00:00 2001 From: Calvin Nix Date: Wed, 28 Feb 2024 13:22:43 -0500 Subject: [PATCH 11/13] implement the ctx deadline check correctly --- vm.go | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/vm.go b/vm.go index 344f2eaa..77acb7c7 100644 --- a/vm.go +++ b/vm.go @@ -633,6 +633,11 @@ func (vm *vm) run() { panic(err) } } + select { + case <-ctx.Done(): + panic(ctx.Err()) + default: + } } if interrupted = atomic.LoadUint32(&vm.interrupted) != 0; interrupted { From 760c1e6b4a46a99216540add935d3caf83b93ef4 Mon Sep 17 00:00:00 2001 From: Calvin Nix Date: Wed, 28 Feb 2024 15:48:58 -0500 Subject: [PATCH 12/13] update panic error message --- vm.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/vm.go b/vm.go index 77acb7c7..3987ebec 100644 --- a/vm.go +++ b/vm.go @@ -621,7 +621,7 @@ func (vm *vm) run() { now := time.Now() r := vm.r.limiter.ReserveN(now, vm.r.limiterTicksLeft) if !r.OK() { - panic("failed to make reservation") + panic(context.DeadlineExceeded) } if delay := r.DelayFrom(now); delay > 0 { From 43a5dab4e25f3bf8c9096cc2ee4fa556af10ae71 Mon Sep 17 00:00:00 2001 From: Calvin Nix Date: Wed, 28 Feb 2024 16:35:07 -0500 Subject: [PATCH 13/13] move select statement for consistency --- vm.go | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/vm.go b/vm.go index 3987ebec..e1661fbb 100644 --- a/vm.go +++ b/vm.go @@ -618,6 +618,12 @@ func (vm *vm) run() { ctx = context.Background() } + select { + case <-ctx.Done(): + panic(ctx.Err()) + default: + } + now := time.Now() r := vm.r.limiter.ReserveN(now, vm.r.limiterTicksLeft) if !r.OK() { @@ -633,11 +639,6 @@ func (vm *vm) run() { panic(err) } } - select { - case <-ctx.Done(): - panic(ctx.Err()) - default: - } } if interrupted = atomic.LoadUint32(&vm.interrupted) != 0; interrupted {