From b22a5fe4fe542326d968f8e3384372eb29fc5dc3 Mon Sep 17 00:00:00 2001 From: "Joshua A. Horton" Date: Wed, 12 Jun 2024 12:49:57 +0700 Subject: [PATCH 1/2] refactor(web): overhaul ExecutionTimer to better detect paused time There are three main operations during correction-search: - replay of old results, if applicable - generation of new corrections - generation of predictions rooted on found corrections Each type naturally has a different 'expected' runtime... so we now make buckets for each. We can then use stats principles to detect outliers on each level. (Mixing them all together = higher variance, thus worse detection.) Also adds a full set of unit tests at 100% coverage for the new implementation. Fun detail - in practice, when running all of the unit tests on my personal machine, it's able to pick up a fair few 1-5 ms outliers during the prediction-oriented tests! We previously lacked the resolution to detect those smaller-end cases. This is work toward #3580, but not the final resolution of it. --- .../src/main/correction/distance-modeler.ts | 103 ++-- .../src/main/correction/execution-timer.ts | 445 ++++++++++++++---- .../lm-worker/src/main/correction/index.ts | 3 +- .../cases/edit-distance/execution-timer.js | 332 +++++++++++++ 4 files changed, 737 insertions(+), 146 deletions(-) create mode 100644 common/web/lm-worker/src/test/mocha/cases/edit-distance/execution-timer.js diff --git a/common/web/lm-worker/src/main/correction/distance-modeler.ts b/common/web/lm-worker/src/main/correction/distance-modeler.ts index 30cf822cd9..57b94650be 100644 --- a/common/web/lm-worker/src/main/correction/distance-modeler.ts +++ b/common/web/lm-worker/src/main/correction/distance-modeler.ts @@ -14,6 +14,12 @@ export const QUEUE_NODE_COMPARATOR: Comparator = function(arg1, arg2 return arg1.currentCost - arg2.currentCost; } +enum TimedTaskTypes { + CACHED_RESULT = 0, + PREDICTING = 1, + CORRECTING = 2 +} + // Represents a processed node for the correction-search's search-space's tree-like graph. May represent // internal and 'leaf' nodes on said graph, as well as the overall root of the search. Also used to represent // edges on the graph TO said nodes - there's a bit of overloading here. Either way, it stores the cost of the @@ -606,69 +612,78 @@ export class SearchSpace { if(returnedValues.length > 0) { let preprocessedQueue = new PriorityQueue(QUEUE_NODE_COMPARATOR, returnedValues); - timer.startLoop(); while(preprocessedQueue.count > 0) { - let entry = preprocessedQueue.dequeue(); + const entryFromCache = timer.time(() => { + let entry = preprocessedQueue.dequeue(); - // Is the entry a reasonable result? - if(entry.isFullReplacement) { - // If the entry's 'match' fully replaces the input string, we consider it - // unreasonable and ignore it. - continue; - } + // Is the entry a reasonable result? + if(entry.isFullReplacement) { + // If the entry's 'match' fully replaces the input string, we consider it + // unreasonable and ignore it. + return null; + } - timer.markIteration(); - - if(!currentReturns[entry.resultKey]) { currentReturns[entry.resultKey] = entry; // Do not track yielded time. - yield new SearchResult(entry); + return new SearchResult(entry); + }, TimedTaskTypes.CACHED_RESULT); + + if(entryFromCache) { + // Time yielded here is generally spent on turning corrections into predictions. + // It's timing a different sort of task, so... different task set ID. + const timeSpan = timer.start(TimedTaskTypes.PREDICTING); + yield entryFromCache; + timeSpan.end(); } } } // Stage 2: the fun part; actually searching! - timer.resetOutlierCheck(); - timer.startLoop(); let timedOut = false; do { - let newResult: PathResult; + const entry = timer.time(() => { + let newResult: PathResult = this.handleNextNode(); - // Search for a 'complete' path, skipping all partial paths as long as time remains. - do { - newResult = this.handleNextNode(); - timer.markIteration(); - - if(timer.shouldTimeout()) { + if(timer.elapsed) { timedOut = true; } - } while(!timedOut && newResult.type == 'intermediate') - if(newResult.type == 'none') { - break; - } else if(newResult.type == 'complete') { - // Is the entry a reasonable result? - if(newResult.finalNode.isFullReplacement) { - // If the entry's 'match' fully replaces the input string, we consider it - // unreasonable and ignore it. Also, if we've reached this point... - // we can(?) assume that everything thereafter is as well. - break; + if(newResult.type == 'none') { + return null; + } else if(newResult.type == 'complete') { + const node = newResult.finalNode; + + // Is the entry a reasonable result? + if(node.isFullReplacement) { + // If the entry's 'match' fully replaces the input string, we consider it + // unreasonable and ignore it. Also, if we've reached this point... + // we can(?) assume that everything thereafter is as well. + return null; + } + + const entry = newResult.finalNode; + + // As we can't guarantee a monotonically-increasing cost during the search - + // due to effects from keystrokes with deleteLeft > 0 - it's technically + // possible to find a lower-cost path later in such cases. + // + // If it occurs, we should re-emit it - it'll show up earlier in the + // suggestions that way, as it should. + if((currentReturns[entry.resultKey]?.currentCost ?? Number.MAX_VALUE) > entry.currentCost) { + currentReturns[entry.resultKey] = entry; + searchSpace.returnedValues[entry.resultKey] = entry; + // Do not track yielded time. + return new SearchResult(entry); + } } - const entry = newResult.finalNode; + return null; + }, TimedTaskTypes.CORRECTING); - // As we can't guarantee a monotonically-increasing cost during the search - - // due to effects from keystrokes with deleteLeft > 0 - it's technically - // possible to find a lower-cost path later in such cases. - // - // If it occurs, we should re-emit it - it'll show up earlier in the - // suggestions that way, as it should. - if((currentReturns[entry.resultKey]?.currentCost ?? Number.MAX_VALUE) > entry.currentCost) { - currentReturns[entry.resultKey] = entry; - searchSpace.returnedValues[entry.resultKey] = entry; - // Do not track yielded time. - yield new SearchResult(entry); - } + if(entry) { + const timeSpan = timer.start(TimedTaskTypes.PREDICTING); + yield entry; + timeSpan.end(); } } while(!timedOut && this.hasNextMatchEntry()); diff --git a/common/web/lm-worker/src/main/correction/execution-timer.ts b/common/web/lm-worker/src/main/correction/execution-timer.ts index 29e3e01051..ac698eb3d5 100644 --- a/common/web/lm-worker/src/main/correction/execution-timer.ts +++ b/common/web/lm-worker/src/main/correction/execution-timer.ts @@ -1,26 +1,16 @@ -/** - * This inner class is designed to help the algorithm detect its active execution time. - * While there's no official JS way to do this, we can approximate it by polling the - * current system time (in ms) after each iteration of a short-duration loop. Unusual - * spikes in system time for a single iteration is likely to indicate that an OS - * context switch occurred at some point during the iteration's execution. - */ -export class ExecutionTimer { - /** - * The system time when this instance was created. - */ - private start: number; +import { timedPromise } from "@keymanapp/web-utils"; - /** - * Marks the system time at the start of the currently-running loop, as noted - * by a call to the `startLoop` function. - */ - private loopStart: number; +const MIN_OUTLIER = 1; // 1ms. +const MAX_CANDIDATES = 5; - private maxExecutionTime: number; - private maxTrueTime: number; +export class ExecutionBucket { + // Could make these readonly outside via getter... + // but the class isn't exposed outside of the timer. + // No need to worry. + timeSpent: number = 0; + eventCount: number = 0; - private executionTime: number; + private timeSquared: number = 0; /** * Used to track intervals in which potential context swaps by the OS may @@ -29,102 +19,355 @@ export class ExecutionTimer { * within just 1 ms. So, any possible context switch should have the * longest observed change in system time. * - * See `updateOutliers` for more details. + * They are sorted in descending order so that the smallest potential outlier + * is always accessible. */ - private largestIntervals: number[] = [0]; + private nearOutliers: number[] = []; + + private outliers: number[] = []; + + private preventOutliers: boolean = false; + + constructor(preventOutliers?: boolean) { + this.preventOutliers = !!preventOutliers; + } + + add(time: number) { + if(time < 0) { + throw new Error("time may not be negative"); + } + + this.eventCount++; + this.timeSpent += time; + this.timeSquared += time * time; + + // As a safety, to prevent the outlier detection from getting too + // aggressive, we set a flat minimum time threshold for something to be + // considered an outlier. + if(time >= MIN_OUTLIER && (this.nearOutliers.length < MAX_CANDIDATES || (this.nearOutliers[MAX_CANDIDATES-1] < time))) { + this.nearOutliers.push(time); + // sort in descending order + this.nearOutliers.sort((a, b) => b-a); + } + + this.checkForOutlier(); + } + + /** + * Performs outlier detection based upon the Student's t-test distribution. + * Only one candidate will be evaluated per call. + * @returns + */ + private checkForOutlier() { + // We won't allow cases that result in less than 3 observations left after excluding + // outliers; the stats-requirement for outlier detection at that point is too extreme. + // We can always check candidate observations again when we have enough other samples. + if(this.preventOutliers || this.eventCount < 4 || this.nearOutliers.length == 0) { + return; + } + + // For consideration: the largest outlier candidate. + // It wasn't ruled out in any previous pass, so neither were any smaller ones. + // + // Checking only one candidate per time observation helps keep this simpler + // than it'd otherwise be. + const possOutlier = this.nearOutliers[0]; + + // For outlier comparison, temporarily remove them from the accumulated + // stats. They'd heavily skew the stats otherwise. + this.timeSpent -= possOutlier; + this.timeSquared -= possOutlier * possOutlier; + this.eventCount--; + + // And now we do stats. How far from the average IS the candidate, + // relative to the variance without it present? + const avg = this.average; + const delta = possOutlier - avg; + const variance = this.variance; + + // Calculated this way to avoid the expense of a Math.sqrt. + const squaredDeviations = (delta * delta) / variance; + + // We could go more granular with this check, but that'd add complexity. + // This should be "good enough". Gives us 99% confidence in our decision. + // + // There is potential to accidentally exclude ~ 1 per 100 non-outliers; + // that's the meaning of "99% confidence". It's not ideal, but it's also a + // comparatively small fraction of the total. There's always the issue of + // 'false positives' vs 'false negatives', and requiring more confidence + // will increase 'false negatives'. The MIN_OUTLIER threshold used in + // `add()` aims to mitigate 'false positives' based on the tendency for + // OS-triggered context switches to be on the order of milliseconds. + // + // Reference for values used: https://www.tdistributiontable.com/ (Or almost + // any textbook for statistics majors/minors.) + // + // See the "t .99" column. "df" = 1 less than non-outlier count. + /* precise: 6.965 */ /* precise: 2.998 */ + /* 3-7: > 7 times std dev */ /* 8+ non-outliers: > 3 times std dev */ + if(squaredDeviations >= 49 || (this.eventCount >= 8 && squaredDeviations >= 9)) { + // we now consider the largest 'potential outlier' an actual outlier. + // + // At 7 "degrees of freedom" (8 non-outlier observations) a sample has + // only a 0.5% chance of lying at or past 3 * the standard deviation - or + // 9 times the variance. 2.998 would be more precise ("one tail", + // p-factor 0.01, df = 7), but 3's "close enough". + // + // With just 3 non-outlier observations, we need a factor of 7 instead of + // 3. We'll allow it because actual 'predicting' should have a low total + // count; 'correcting' will have significantly more observations. 6.965 + // would be more precise ("one tail", p-factor 0.01, df = 2), but 3's + // "close enough". + this.nearOutliers.shift(); + this.outliers.push(possOutlier); + // // Useful for seeing how the settings look with real timings when running full + // // unit test suite. + // console.log(`detected outlier: ${possOutlier}`); + // console.log(`avg: ${avg}, variance: ${variance}, eventCount: ${this.eventCount}`); + } else { + // Restore it; we decided it's not an outlier. + // + // We might lose least-significant-digit numerical precision due to manipulating + // these values in this manner, but we don't need perfection here. + this.timeSpent += possOutlier; + this.timeSquared += possOutlier * possOutlier; + this.eventCount++; + } + } + + get average(): number { + return this.timeSpent / this.eventCount; + } + + get variance(): number { + const N = this.eventCount; + if(N <= 1) { + return NaN; + } + + // easy, efficient variance computation. + return this.timeSquared / N - (this.timeSpent * this.timeSpent) / (N*N); + } + + get outlierTime(): number { + let sum = 0; + for(let i=0; i < this.outliers.length; i++) { + sum += this.outliers[i]; + } + return sum; + } +} + +export class ExecutionSpan { + private start: number; + private finish?: number; + private bucket: ExecutionBucket; + private finalizer: () => void; + + constructor(bucket: ExecutionBucket, finalizer: () => void) { + this.bucket = bucket; + this.finalizer = finalizer; + this.start = performance.now(); + } + + end() { + this.finish = performance.now(); + this.bucket.add(this.duration); + this.finalizer(); + } + + // Useful for tracking 'time since yield', etc. + get duration() { + return (this.finish ?? performance.now()) - this.start; + } +} + +/** + * This is designed to help the correction-search algorithm detect its active + * execution time. While there's no official JS way to do this, we can + * approximate it by polling the current system time (in ms) after each + * iteration of a short-duration loop. Unusual spikes in system time for a + * single iteration is likely to indicate that an OS context switch occurred at + * some point during the iteration's execution. + * + * Note: `.elapsedTime` + `.deferTime` may not sum up to the true total time spent; + * the time spent between `.time()`, `.defer()`, and `start`-`end` timings is not + * itself tracked and included, though that time should generally be minimal. + */ +export class ExecutionTimer { + /** + * The system time when this instance was created. + */ + private trueStart: number; + + private buckets: Record = {}; + private deferBucket: ExecutionBucket = new ExecutionBucket(true /* prevent outliers */); + + private activeSpan: ExecutionSpan = null; + + private maxExecutionTime: number; + private maxTrueTime: number; + + // TODO: (next PR) track "time since last yield"? + // That'd make a decent condition for yielding control briefly to the message-loop. constructor(maxExecutionTime: number, maxTrueTime: number) { - // JS measures time by the number of milliseconds since Jan 1, 1970. - this.loopStart = this.start = Date.now(); + this.trueStart = performance.now(); // is in ms. this.maxExecutionTime = maxExecutionTime; this.maxTrueTime = maxTrueTime; } - startLoop() { - this.loopStart = Date.now(); - } - - markIteration() { - const now = Date.now(); - const delta = now - this.loopStart; - this.executionTime += delta; - - /** - * Update the list of the three longest system-time intervals observed - * for execution of a single loop iteration. - * - * Ignore any zero-ms length intervals; they'd make the logic much - * messier than necessary otherwise. - */ - if(delta && delta > this.largestIntervals[0]) { - // If the currently-observed interval is longer than the shortest of the 3 - // previously-observed longest intervals, replace it. - if(this.largestIntervals.length > 2) { - this.largestIntervals[0] = delta; - } else { - this.largestIntervals.push(delta); - } - - // Puts the list in ascending order. Shortest of the list becomes the head, - // longest one the tail. - this.largestIntervals.sort(); - - // Then, determine if we need to update our outlier-based tweaks. - this.updateOutliers(); + /** + * Used to enforce the specification set by `start()` - if a + * previously-`start`ed span is not completed, it will throw an error. + */ + private validateStart() { + if(this.activeSpan) { + throw new Error("illegal state - span-based timer still pending"); } } - updateOutliers() { - /* Base assumption: since each loop of the search should evaluate within ~1ms, - * notably longer execution times are probably context switches. - * - * Base assumption: OS context switches generally last at least 16ms. (Based on - * a window.setTimeout() usually not evaluating for at least - * that long, even if set to 1ms.) - * - * To mitigate these assumptions: we'll track the execution time of every loop - * iteration. If the longest observation somehow matches or exceeds the length of - * the next two almost-longest observations twice over... we have a very strong - * 'context switch' candidate. - * - * Or, in near-formal math/stats: we expect a very low variance in execution - * time among the iterations of the search's loops. With a very low variance, - * ANY significant proportional spikes in execution time are outliers - outliers - * likely caused by an OS context switch. - * - * Rather than do intensive math, we use a somewhat lazy approach below that - * achieves the same net results given our assumptions, even when relaxed somewhat. - * - * The logic below relaxes the base assumptions a bit to be safe: - * - [2ms, 2ms, 8ms] will cause 8ms to be seen as an outlier. - * - [2ms, 3ms, 10ms] will cause 10ms to be seen as an outlier. - * - * Ideally: - * - [1ms, 1ms, 4ms] will view 4ms as an outlier. - * - * So we can safely handle slightly longer average intervals and slightly shorter - * OS context-switch time intervals. - */ - if(this.largestIntervals.length > 2) { - // Precondition: the `largestIntervals` array is sorted in ascending order. - // Shortest entry is at the head, longest at the tail. - if(this.largestIntervals[2] >= 2 * (this.largestIntervals[0] + this.largestIntervals[1])) { - this.executionTime -= this.largestIntervals[2]; - this.largestIntervals.pop(); - } + /** + * Gets the 'timing bucket' requested by the "timing set ID", creating it if + * necessary. + * @param timingSetId + * @returns + */ + private getBucket(timingSetId?: number): ExecutionBucket { + timingSetId ??= -1; + + let bucket = this.buckets[timingSetId]; + if(!bucket) { + bucket = this.buckets[timingSetId] = new ExecutionBucket(/* allow outliers */); } + + return bucket; } - shouldTimeout(): boolean { - const now = Date.now(); - if(now - this.start > this.maxTrueTime) { + /** + * The total amount of time spent executing. Cases where extraordinarily + * high amounts of time were spent are excluded as outliers. + * + * Does not include time spent since the last `.start()` call if the + * corresponding `.end()` call has not yet occurred. + */ + get executionTime(): number { + const buckets = Object.values(this.buckets); + let total = 0; + for(let bucket of buckets) { + total += bucket.timeSpent; + } + + return total; + } + + /** + * The total amount of time waited during `defer`. Cases where extraordinarily + * high amounts of time were spent during execution are included here, as + * outliers are considered to have been the result of context-switching + * that would background their corresponding task. + */ + get deferredTime(): number { + const buckets = Object.values(this.buckets); + let total = 0; + + for(let bucket of buckets) { + total += bucket.outlierTime; + } + + total += this.deferBucket.timeSpent; + + return total; + } + + /** + * This may be used to time a method's execution. The original return value + * will be preserved and passed through. + * + * Use set identifiers to ensure that outlier logic only applies among + * observations of the same task type, as different tasks naturally take + * different amounts of time. + * @param closure The method to time + * @param timingSetId A numerical identifier for the 'class' of things being + * timed. If not set, defaults to -1. + * @returns + */ + time(closure: () => Type, timingSetId?: number): Type { + this.validateStart(); + + const start = performance.now(); + const result = closure(); + const time = performance.now() - start; + + const bucket = this.getBucket(timingSetId); + bucket.add(time); + + return result; + } + + /** + * This may be called to defer control to the base JS message loop / + * task queue, resuming after all current entries are processed. + * + * The call will track the amount of time spent 'paused' due to this + * deferment and will not count it against 'elapsed' time unless in + * overly-high quantities. + * + * @param minWait Minimum time to wait before resuming. + */ + async defer(minWait?: number) { + this.validateStart(); + minWait ??= 0; + + const start = performance.now(); + // WebWorker messages appear to come in via the macrotask queue. + await timedPromise(minWait); + const time = performance.now() - start; + + this.deferBucket.add(time); + } + + /** + * Creates a split 'span' timer for cases where a closure is not viable. + * Call the returned object's `end` method to finalize the timing span. + * + * All timing methods will throw errors when called if a 'span' from this + * method is left unfinalized. + * + * Use set identifiers to ensure that outlier logic only applies among + * observations of the same task type, as different tasks naturally take + * different amounts of time. + * @param timingSetId A numerical identifier for the 'class' of things being + * timed. If not set, defaults to -1. + * @returns An object used to complete the "timing span" started by this function call. + */ + start(timingSetId?: number): ExecutionSpan { + this.validateStart(); + + const bucket = this.getBucket(timingSetId); + + this.activeSpan = new ExecutionSpan(bucket, () => { + this.activeSpan = null; + }); + + return this.activeSpan; + } + + // TODO: In follow-up PR: add `terminate()` to force early termination + // Also, rework correction-search to take an ExecutionTimer, not just the raw max length. + // From there, can have new predict calls call `.terminate()` on the prior call's timer. + + /** + * Returns `true` if the time interval represented by this timer should be considered + * as fully elapsed. + * @returns + */ + get elapsed(): boolean { + const now = performance.now(); + if(now - this.trueStart >= this.maxTrueTime) { return true; } - return this.executionTime > this.maxExecutionTime; - } - - resetOutlierCheck() { - this.largestIntervals = []; + return this.executionTime >= this.maxExecutionTime; } } \ No newline at end of file diff --git a/common/web/lm-worker/src/main/correction/index.ts b/common/web/lm-worker/src/main/correction/index.ts index 890c49ae33..33d9f70f54 100644 --- a/common/web/lm-worker/src/main/correction/index.ts +++ b/common/web/lm-worker/src/main/correction/index.ts @@ -1,3 +1,4 @@ export * from './classical-calculation.js'; export * from './context-tracker.js'; -export * from './distance-modeler.js'; \ No newline at end of file +export * from './distance-modeler.js'; +export * from './execution-timer.js'; \ No newline at end of file diff --git a/common/web/lm-worker/src/test/mocha/cases/edit-distance/execution-timer.js b/common/web/lm-worker/src/test/mocha/cases/edit-distance/execution-timer.js new file mode 100644 index 0000000000..221f966f9b --- /dev/null +++ b/common/web/lm-worker/src/test/mocha/cases/edit-distance/execution-timer.js @@ -0,0 +1,332 @@ +import { assert } from 'chai'; +import { useFakeTimers } from 'sinon'; + +import { ExecutionBucket, ExecutionTimer } from '#./correction/index.js'; + +describe('ExecutionTimer', () => { + /** @type {import('sinon').SinonFakeTimers} */ + let timeControl; + + beforeEach(() => { + timeControl = useFakeTimers(); + }); + + afterEach(() => { + timeControl.restore(); + }); + + it('has expected state on construction', () => { + const timer = new ExecutionTimer(40, 100); + assert.equal(timer.executionTime, 0); + assert.equal(timer.deferredTime, 0); + assert.isFalse(timer.elapsed); + }); + + it('time()', () => { + const timer = new ExecutionTimer(40, 100); + // Mocked timers give us 100% full control. + timer.time(() => timeControl.tick(12.34), 1); + assert.equal(timer.executionTime, 12.34); + + timer.time(() => timeControl.tick(40), 2); + assert.equal(timer.executionTime, 52.34); + + assert.equal(timer.deferredTime, 0); + }); + + it('start()', () => { + const timer = new ExecutionTimer(40, 100); + const timeSpan1 = timer.start(1); + timeControl.tick(12.34); + + // The ExecutionTimer class does not include uncompleted timings. + // Checking total execution-time during an active timing isn't + // something we aim to support for the class. + assert.equal(timer.executionTime, 0); + + // That said, the `.duration` property can be useful for tracking + // time since the last `.defer()` call, even when not completed... + // so it should be updated without calling `.end()`. + assert.equal(timeSpan1.duration, 12.34); + timeSpan1.end(); + assert.equal(timer.executionTime, 12.34); + + const timeSpan2 = timer.start(2); + timeControl.tick(40); + assert.equal(timer.executionTime, 12.34); // does not include an uncompleted timing. + assert.equal(timeSpan2.duration, 40); + timeSpan2.end(); + assert.equal(timer.executionTime, 52.34); + + // Previously-elapsed 'spans', if kept around, should have their duration locked. + assert.equal(timeSpan1.duration, 12.34); + + // No simulated defers were triggered; time should equal 0. + assert.equal(timer.deferredTime, 0); + }); + + it('throws when start() not end()-ed', async () => { + const timer = new ExecutionTimer(40, 100); + timer.start(1); + + assert.throws(() => timer.start()); + assert.throws(() => timer.time(() => {})); + try { + await timer.defer(); + assert.fail('timer.defer() did not throw'); + } catch (err) {} + }); + + it('defer()', async () => { + const timer = new ExecutionTimer(50, 100); + + const promise = timer.defer(20); + const runAll = timeControl.runAllAsync(); + await Promise.all([promise, runAll]); + + assert.equal(timer.deferredTime, 20); + + assert.equal(timer.executionTime, 0); + }); + + it('defer() - alternate setup', async () => { + const timer = new ExecutionTimer(50, 100); + + const delaySetup = new Promise(async (resolve) => { + // The passed-in function does not delay by default; this will wait for + // one microtask delay before proceeding. + // + // (This allows defer's start to begin before this function takes + // control.) + await Promise.resolve(); + timeControl.tick(20); + + resolve(); + }); + + const promise = timer.defer(); + const runAll = timeControl.runAllAsync(); + await Promise.all([delaySetup, promise, runAll]); + + assert.equal(timer.deferredTime, 20); + + assert.equal(timer.executionTime, 0); + }); + + it('elapsed - from active time', () => { + const timer = new ExecutionTimer(50, 100); + timer.time(() => timeControl.tick(12.34)); + assert.isFalse(timer.elapsed); + timer.time(() => timeControl.tick(40)); + assert.isTrue(timer.elapsed); + }); + + it('elapsed - from total time waited', async () => { + const timer = new ExecutionTimer(50, 100); + + const promise1 = timer.defer(60); + timeControl.runAllAsync(); + await promise1; + + assert.isFalse(timer.elapsed); + + const promise2 = timer.defer(40); + timeControl.runAllAsync(); + await promise2; + + assert.isTrue(timer.elapsed); + }); +}); + +describe('ExecutionBucket', () => { + // No need for time-control here; this class does not internally reference + // performance.now or similar constructs. + describe('without outlier logic', () => { + it('has expected values after construction', () => { + const bucket = new ExecutionBucket(true); + + assert.equal(bucket.timeSpent, 0); + assert.equal(bucket.outlierTime, 0); + assert.equal(bucket.eventCount, 0); + assert.isNaN(bucket.average); // requires at least one sample + assert.isNaN(bucket.variance); // requires at least two samples + }); + + it('throws when expected', () => { + const bucket = new ExecutionBucket(true); + + assert.throws(() => bucket.add(-1)); + assert.throws(() => bucket.add(-0.0001)); + assert.doesNotThrow(() => bucket.add(0)); + assert.doesNotThrow(() => bucket.add(2)); + }); + + it('has expected values after adding one observation', () => { + const bucket = new ExecutionBucket(true); + bucket.add(3); + + assert.equal(bucket.timeSpent, 3); + assert.equal(bucket.outlierTime, 0); + assert.equal(bucket.eventCount, 1); + assert.equal(bucket.average, 3); + assert.isNaN(bucket.variance); + }); + + it('has expected values after adding two observations', () => { + const bucket = new ExecutionBucket(true); + bucket.add(3); + bucket.add(5); + + assert.equal(bucket.timeSpent, 8); + assert.equal(bucket.outlierTime, 0); + assert.equal(bucket.eventCount, 2); + assert.equal(bucket.average, 4); + assert.equal(bucket.variance, 1); // both are evenly spaced on either side of the average. + }); + + it('has expected values after adding numerous observations', () => { + const bucket = new ExecutionBucket(true); + + for(let i=1; i <= 9; i++) { + bucket.add(i); + } + + assert.equal(bucket.timeSpent, 45); // 1+9, 2+8... but 5 is unpaired. + assert.equal(bucket.outlierTime, 0); + assert.equal(bucket.eventCount, 9); + assert.equal(bucket.average, 5); + + // 20/3 = 6.666..., which means a std. deviation of about 2.58. + // We're using an approximately uniform distribution, not a bell-curve, + // so it makes reasonable sense. + assert.approximately(bucket.variance, 20/3, 0.001); + }); + }); + + describe('with outlier logic', () => { + it('does not find outlier among 4 nearby samples', () => { + const bucket = new ExecutionBucket(); + + const samples = [0, 1, 2, 1]; + samples.forEach((entry) => bucket.add(entry)); + + assert.equal(bucket.timeSpent, 4); + assert.equal(bucket.outlierTime, 0); + assert.equal(bucket.eventCount, 4); + assert.equal(bucket.average, 1); + + assert.approximately(bucket.variance, 0.5, 0.001); + }); + + it('does not find outlier among 3 nearby samples + 1 somewhat far sample', () => { + const bucket = new ExecutionBucket(); + + // 4 looks like it could be an outlier, but we have too low a sample count + // to definitely exclude it at this point, statistically-speaking. + const samples = [0, 1, 3.9, 1]; // 4.0 actually IS far enough: 50 vs 49 in squared-variance. + samples.forEach((entry) => bucket.add(entry)); + + assert.equal(bucket.timeSpent, 5.9); + assert.equal(bucket.outlierTime, 0); + assert.equal(bucket.eventCount, 4); + assert.equal(bucket.average, 1.475); + + assert.isAbove(bucket.variance, 2); + }); + + it('does find outlier among 3 nearby samples + 1 far sample', () => { + const bucket = new ExecutionBucket(); + + // 6 is definitely a much larger value when the other three observed entries thus far. + const samples = [0, 1, 6, 0]; + samples.forEach((entry) => bucket.add(entry)); + + assert.equal(bucket.timeSpent, 1); + assert.equal(bucket.outlierTime, 6); + assert.equal(bucket.eventCount, 3); + assert.approximately(bucket.average, 1/3, 1e-6); + + assert.isBelow(bucket.variance, .5); + }); + + it('finds 1 outlier among 5 nearby samples + 2 slightly far samples', () => { + const bucket = new ExecutionBucket(); + + // The 2 is a notable jump above the others. 1 is kinda close, though. + const samples = [.5, 1, 2, .5, .6, .8, .6]; + + // Outlier logic rules out the 2 on the final 'add'. + samples.forEach((entry) => bucket.add(entry)); + + assert.approximately(bucket.timeSpent, 4, 1e-6); + assert.equal(bucket.outlierTime, 2); + assert.equal(bucket.eventCount, 6); + assert.approximately(bucket.average, 4/6, 1e-6); + + // Only the 1 is over 0.2 away, and it's not that far outside. + assert.isBelow(bucket.variance, 0.2); + }); + + it('finds 1 outlier among 7 nearby samples + 2 slightly far samples', () => { + const bucket = new ExecutionBucket(); + + // The 2 is a notable jump above the others. 1 is kind of too far from the others + // too, but without the 2, we're one sample shy of excluding the 1. + const samples = [.5, 1, 2, .5, .6, .8, .6, .7, .7]; + + // Outlier logic rules out the 2 on the final 0.6 'add'. + samples.forEach((entry) => bucket.add(entry)); + + assert.approximately(bucket.timeSpent, 5.4, 1e-6); + assert.equal(bucket.outlierTime, 2); + assert.equal(bucket.eventCount, 8); + assert.approximately(bucket.average, .675, 1e-6); + + assert.isBelow(bucket.variance, 0.1); + }); + + it('finds 2 outliers among 8 nearby samples + 2 slightly far samples', () => { + const bucket = new ExecutionBucket(); + + // The 2 is a notable jump above the others. 1 is too far from the others + // as well; we only gain confidence in this when reaching the 8-sample threshold. + // + // Note: 1 is the minimum value we currently allow for anything to be considered + // an 'outlier'. + const samples = [.5, 1, 2, .5, .6, .8, .6, .7, .7, .6]; + + // Outlier logic rules out the 2 on the final 'add'. + samples.forEach((entry) => bucket.add(entry)); + + assert.approximately(bucket.timeSpent, 5, 1e-6); + assert.equal(bucket.outlierTime, 3); + assert.equal(bucket.eventCount, 8); + assert.approximately(bucket.average, .625, 1e-6); + + assert.isBelow(bucket.variance, 0.05); + }); + + it('finds no outliers among 10 large but nearby samples', () => { + const bucket = new ExecutionBucket(); + + // The 4 is a bit of a jump above the other values, and 2 a bit below. + // The spread is wide enough that we can't consider them outliers in good + // faith. (Also, we don't consider low-end outliers given our domain + // knowledge.) + // + // 4 is over 2 std-deviations out when excluded, but not the required 3. + const samples = [2, 3, 4, 3.5, 2.5, 3.1, 3.3, 2.7, 2.9, 3.2]; + + // Outlier logic rules out the 2 on the final 'add'. + samples.forEach((entry) => bucket.add(entry)); + + assert.approximately(bucket.timeSpent, 30.2, 1e-6); + assert.equal(bucket.outlierTime, 0); + assert.equal(bucket.eventCount, 10); + assert.approximately(bucket.average, 3.02, 1e-6); + + // actual: 0.2736, putting std.dev ~= .523 (with `4` included). + assert.isBelow(bucket.variance, 0.5); + }); + }); +}); \ No newline at end of file From fe600b3b700609a37726749c9a07469f3a8ecb33 Mon Sep 17 00:00:00 2001 From: "Joshua A. Horton" Date: Fri, 14 Jun 2024 12:21:06 +0700 Subject: [PATCH 2/2] chore(web): pull up some changes, comments from child PR --- .../src/main/correction/execution-timer.ts | 46 +++++++++++++++---- 1 file changed, 38 insertions(+), 8 deletions(-) diff --git a/common/web/lm-worker/src/main/correction/execution-timer.ts b/common/web/lm-worker/src/main/correction/execution-timer.ts index ac698eb3d5..2f565e231f 100644 --- a/common/web/lm-worker/src/main/correction/execution-timer.ts +++ b/common/web/lm-worker/src/main/correction/execution-timer.ts @@ -3,6 +3,11 @@ import { timedPromise } from "@keymanapp/web-utils"; const MIN_OUTLIER = 1; // 1ms. const MAX_CANDIDATES = 5; +/** + * Handles statistical tracking + data management for one type of task + * component comprising the high-level task managed by its owning + * `ExecutionTimer`. + */ export class ExecutionBucket { // Could make these readonly outside via getter... // but the class isn't exposed outside of the timer. @@ -158,6 +163,9 @@ export class ExecutionBucket { } } +/** + * Represents the timing of an individual task component. + */ export class ExecutionSpan { private start: number; private finish?: number; @@ -170,13 +178,22 @@ export class ExecutionSpan { this.start = performance.now(); } + /** + * Ends the timer for the represented timed task and records the + * results. + */ end() { this.finish = performance.now(); this.bucket.add(this.duration); this.finalizer(); } - // Useful for tracking 'time since yield', etc. + /** + * Indicates the amount of time taken for the task if `end()` has been called. + * + * If `end()` has not been called, indicates the amount of time since this + * `ExecutionSpan` was created by `start()`. + */ get duration() { return (this.finish ?? performance.now()) - this.start; } @@ -200,17 +217,29 @@ export class ExecutionTimer { */ private trueStart: number; + private maxExecutionTime: number; + private maxTrueTime: number; + private buckets: Record = {}; private deferBucket: ExecutionBucket = new ExecutionBucket(true /* prevent outliers */); + /** + * Holds the active `ExecutionSpan` if one exists, representing a task of some + * sort being timed. + * + * While an instance is tracked here, this class will throw an error if an attempt is made to time + * something else. (Aside from 'time since last defer', which isn't considered a task component.) + */ private activeSpan: ExecutionSpan = null; - private maxExecutionTime: number; - private maxTrueTime: number; - // TODO: (next PR) track "time since last yield"? // That'd make a decent condition for yielding control briefly to the message-loop. + /** + * @param maxExecutionTime The maximum amount of time alloted to task execution + * @param maxTrueTime Time until the task's absolute deadline, even if + * prevented from using all execution time. + */ constructor(maxExecutionTime: number, maxTrueTime: number) { this.trueStart = performance.now(); // is in ms. this.maxExecutionTime = maxExecutionTime; @@ -307,13 +336,15 @@ export class ExecutionTimer { /** * This may be called to defer control to the base JS message loop / - * task queue, resuming after all current entries are processed. + * task queue, resuming after all current pending executable tasks + * are processed. * * The call will track the amount of time spent 'paused' due to this * deferment and will not count it against 'elapsed' time unless in * overly-high quantities. * - * @param minWait Minimum time to wait before resuming. + * @param minWait Minimum time to wait before resuming. (Designed for + * use in unit tests) */ async defer(minWait?: number) { this.validateStart(); @@ -358,8 +389,7 @@ export class ExecutionTimer { // From there, can have new predict calls call `.terminate()` on the prior call's timer. /** - * Returns `true` if the time interval represented by this timer should be considered - * as fully elapsed. + * Returns `true` if the represented high-level task has no more time alloted to it. * @returns */ get elapsed(): boolean {