From ec10be853fd7b7456ed9bd821e714e1f7cba3350 Mon Sep 17 00:00:00 2001 From: Bronley Plumb Date: Thu, 20 Jul 2023 13:30:58 -0400 Subject: [PATCH] Add busy status tracking --- src/BuildStatusTracker.spec.ts | 298 +++++++++++++++++++++++++++++++++ src/BuildStatusTracker.ts | 207 +++++++++++++++++++++++ src/LanguageServer.spec.ts | 2 + src/LanguageServer.ts | 160 ++++++++++-------- src/deferred.ts | 2 +- src/index.ts | 1 + 6 files changed, 602 insertions(+), 68 deletions(-) create mode 100644 src/BuildStatusTracker.spec.ts create mode 100644 src/BuildStatusTracker.ts diff --git a/src/BuildStatusTracker.spec.ts b/src/BuildStatusTracker.spec.ts new file mode 100644 index 000000000..d6fc9c6e6 --- /dev/null +++ b/src/BuildStatusTracker.spec.ts @@ -0,0 +1,298 @@ +import type { Connection } from 'vscode-languageserver'; +import type { BuildStatusEvent } from './BuildStatusTracker'; +import { BuildStatus, BuildStatusTracker } from './BuildStatusTracker'; +import { createSandbox } from 'sinon'; +import type { Project } from './LanguageServer'; +import { tempDir } from './testHelpers.spec'; +import { standardizePath as s } from './util'; +import { expect } from 'chai'; +import { Deferred } from './deferred'; +const sinon = createSandbox(); + +describe('BuildStatusTracker', () => { + let tracker: BuildStatusTracker; + let connection = { + sendNotification: () => { } + } as any as Connection; + + const project1 = { + projectNumber: 1, + projectPath: s`${tempDir}/project1` + } as Project; + + const project2 = { + projectNumber: 2, + projectPath: s`${tempDir}/project2` + } as Project; + + const timeoutDurations: number[] = []; + + beforeEach(() => { + tracker = new BuildStatusTracker(connection); + sinon.stub(tracker as any, 'getDuration').callsFake(() => { + return timeoutDurations.shift() ?? 30_000; + }); + }); + + it('supports tracking events without project info', () => { + tracker.run(undefined, () => { }); + expect(tracker['buildEvent']()).to.eql({ + projectInfo: [{ + projectNumber: undefined, + projectPath: undefined, + statistics: { + average: 30_000, + count: 1, + max: 30_000, + min: 30_000 + } + }], + status: BuildStatus.success + } as BuildStatusEvent); + }); + + it('tracks a single run', () => { + tracker.run(project1, () => { + //noop + }); + expect(tracker['buildEvent']()).to.eql({ + projectInfo: [{ + ...project1, + statistics: { + average: 30_000, + count: 1, + max: 30_000, + min: 30_000 + } + }], + status: BuildStatus.success + } as BuildStatusEvent); + }); + + it('tracks a single async flow', async () => { + const deferred = new Deferred(); + const finishedPromise = tracker.run(project1, () => { + return deferred.promise; + }); + //no data tracked yet + expect(tracker['buildEvent']()).to.eql({ + projectInfo: [{ + ...project1, + statistics: { + min: Number.MAX_SAFE_INTEGER, + max: 0, + average: 0, + count: 0 + } + }], + status: BuildStatus.building + } as BuildStatusEvent); + + deferred.resolve(); + await finishedPromise; + + expect(tracker['buildEvent']()).to.eql({ + projectInfo: [{ + ...project1, + statistics: { + min: 30_000, + max: 30_000, + average: 30_000, + count: 1 + } + }], + status: 'success' + } as BuildStatusEvent); + }); + + it('independently tracks multiple runs for same program', () => { + timeoutDurations.push(10_000, 20_000); + tracker.run(project1, () => { + //noop + }); + tracker.run(project1, () => { + //noop + }); + expect(tracker['buildEvent']()).to.eql({ + projectInfo: [{ + ...project1, + statistics: { + min: 10_000, + max: 20_000, + average: 15_000, + count: 2 + } + }], + status: 'success' + } as BuildStatusEvent); + }); + + it('returns "building" when one of the runs is still pending', async () => { + const deferred = new Deferred(); + tracker.run(project1, () => { + //noop + }); + const finishedPromise = tracker.run(project1, () => { + return deferred.promise; + }); + expect(tracker['buildEvent']()).to.eql({ + projectInfo: [{ + ...project1, + statistics: { + min: 30_000, + max: 30_000, + average: 30_000, + count: 1 + } + }], + status: BuildStatus.building + } as BuildStatusEvent); + + deferred.resolve(); + await finishedPromise; + + expect(tracker['buildEvent']()).to.eql({ + projectInfo: [{ + ...project1, + statistics: { + min: 30_000, + max: 30_000, + average: 30_000, + count: 2 + } + }], + status: BuildStatus.success + } as BuildStatusEvent); + }); + + it('handles error during synchronous flow', () => { + try { + tracker.run(project1, () => { + throw new Error('Crash'); + }); + } catch { } + + expect(tracker['buildEvent']()).to.eql({ + projectInfo: [{ + ...project1, + statistics: { + average: 30_000, + count: 1, + max: 30_000, + min: 30_000 + } + }], + status: BuildStatus.criticalError + } as BuildStatusEvent); + }); + + it('handles error during async flow', async () => { + try { + await tracker.run(project1, () => { + return Promise.reject(new Error('Crash')); + }); + } catch { } + + expect(tracker['buildEvent']()).to.eql({ + projectInfo: [{ + ...project1, + statistics: { + min: 30_000, + max: 30_000, + average: 30_000, + count: 1 + } + }], + status: BuildStatus.criticalError + } as BuildStatusEvent); + }); + + it('only finalizes on the first call to finalize', () => { + try { + tracker.run(project1, (finalize) => { + finalize(); + finalize(); + }); + } catch { } + + expect(tracker['buildEvent']()).to.eql({ + projectInfo: [{ + ...project1, + statistics: { + min: 30_000, + max: 30_000, + average: 30_000, + count: 1 + } + }], + status: BuildStatus.success + } as BuildStatusEvent); + }); + + it('supports multiple simultaneous projects', async () => { + //run the projects out of order + const deferred2 = new Deferred(); + const run1Promise = tracker.run(project2, () => { + return deferred2.promise; + }); + + const deferred1 = new Deferred(); + const run2Promise = tracker.run(project1, () => { + return deferred1.promise; + }); + + expect(tracker['buildEvent']()).to.eql({ + //the projects are sorted before being emitted + projectInfo: [{ + ...project1, + statistics: { + min: Number.MAX_SAFE_INTEGER, + max: 0, + average: 0, + count: 0 + } + }, { + ...project2, + statistics: { + min: Number.MAX_SAFE_INTEGER, + max: 0, + average: 0, + count: 0 + } + }], + status: BuildStatus.building + } as BuildStatusEvent); + + deferred1.resolve(); + deferred2.resolve(); + await Promise.all([run1Promise, run2Promise]); + + expect(tracker['buildEvent']()).to.eql({ + //the projects are sorted before being emitted + projectInfo: [{ + ...project1, + statistics: { + min: 30_000, + max: 30_000, + average: 30_000, + count: 1 + } + }, { + ...project2, + statistics: { + min: 30_000, + max: 30_000, + average: 30_000, + count: 1 + } + }], + status: BuildStatus.success + } as BuildStatusEvent); + }); + + it('getDuration returns a duration', () => { + expect( + new BuildStatusTracker(connection)['getDuration'](Date.now() - 500) + ).to.be.gte(500); + }); +}); diff --git a/src/BuildStatusTracker.ts b/src/BuildStatusTracker.ts new file mode 100644 index 000000000..d2be5588b --- /dev/null +++ b/src/BuildStatusTracker.ts @@ -0,0 +1,207 @@ +import type { Connection } from 'vscode-languageserver/node'; +import type { Project } from './LanguageServer'; + +/** + * Tracks the building/success/error status of various projects in the language server. + * Reports the overall status (is nothing building, is something building, did something fail) to the language client + */ +export class BuildStatusTracker { + constructor( + private connection: Connection + ) { } + + private projectContainers = new Map; + }>(); + + private globalProject = { + projectNumber: undefined, + projectPath: undefined + } as Project; + + public run>(project: Project, callback: (finalize?: FinalizeBuildStatusRun) => R): R { + const finalizeRun = this.createRun(project); + let result: R | PromiseLike; + //call the callback function + try { + result = callback(finalizeRun); + //if the result is a promise, don't finalize until it completes + if (typeof (result as any)?.then === 'function') { + return Promise.resolve(result).then(() => { + finalizeRun(); + }).catch((e) => { + finalizeRun(BuildStatus.criticalError); + }).then(() => result) as any; + } else { + finalizeRun(); + return result; + } + } catch (e) { + finalizeRun(BuildStatus.criticalError); + throw e; + } + } + + /** + * Create a new run, and return the "finished" callback function" + */ + private createRun(project: Project) { + project ??= this.globalProject; + + //create the project container if missing + if (!this.projectContainers.has(project)) { + this.projectContainers.set(project, { + min: Number.MAX_SAFE_INTEGER, + max: 0, + average: 0, + count: 0, + mostRecentStatus: BuildStatus.success, + activeRuns: new Set() + }); + } + const projectContainer = this.projectContainers.get(project); + + //create the current run + const currentRunData: BuildStatusRun = { + status: BuildStatus.building, + startTime: Date.now() + }; + projectContainer.activeRuns.add(currentRunData); + + //return a function that should be called when the job has completed + return (status = BuildStatus.success) => { + this.finalizeRun(project, currentRunData, status); + }; + } + + /** + * Roll up the new build time average and send the event + */ + private finalizeRun(project: Project, statusRun: BuildStatusRun, status: BuildStatus) { + const container = this.projectContainers.get(project); + //skip processing if we can't find that builder or we can't find this active run + if (!container || !container.activeRuns.has(statusRun)) { + return; + } + + const buildTime = this.getDuration(statusRun.startTime); + + //if this is the first completed status, just use the current build time + if (container.count === 0) { + container.min = buildTime; + container.max = buildTime; + container.average = buildTime; + } else { + container.min = Math.min(container.min, buildTime); + container.max = Math.max(container.max, buildTime); + //calculate a new average + container.average = ((container.average * container.count) + buildTime) / (container.count + 1); + } + container.count++; + container.mostRecentStatus = status; + + container.activeRuns.delete(statusRun); + + this.sendEvent( + this.buildEvent() + ); + } + + private getDuration(time: number) { + return Date.now() - time; + } + + /** + * Build the event object for this status event that will be sent to the client + */ + private buildEvent() { + const event: BuildStatusEvent = { + status: BuildStatus.success, + projectInfo: [] + }; + const projects = [...this.projectContainers].map(x => x[0]).sort((a, b) => a.projectNumber - b.projectNumber); + for (const project of projects) { + const container = this.projectContainers.get(project); + event.projectInfo.push({ + projectNumber: project.projectNumber, + projectPath: project.projectPath, + statistics: { + min: container.min, + max: container.max, + count: container.count, + average: container.average + } + }); + + //if there's a critical error, set the state to that + if (container.mostRecentStatus === BuildStatus.criticalError || event.status === BuildStatus.criticalError) { + event.status = BuildStatus.criticalError; + + //if there are in-flight runs, set the state to "building" + } else if (container.activeRuns.size > 0) { + event.status = BuildStatus.building; + } + } + return event; + } + + /** + * Rolls up all the current data into a single status event + */ + private sendEvent(event: BuildStatusEvent) { + this.connection.sendNotification('build-status', event); + } + +} + +interface BuildStatusRun { + status: BuildStatus; + startTime: number; +} + +export type FinalizeBuildStatusRun = (status?: BuildStatus) => void; + +export enum BuildStatus { + building = 'building', + success = 'success', + criticalError = 'criticalError' +} + +export interface BuildStatusEvent { + status: BuildStatus; + projectInfo: Array; +} +export interface ProjectInfo { + projectNumber?: number; + projectPath?: string; + status: BuildStatus; + statistics: { + min: number; + max: number; + average: number; + count: number; + }; +} diff --git a/src/LanguageServer.spec.ts b/src/LanguageServer.spec.ts index 1a07075a7..f15f19bd4 100644 --- a/src/LanguageServer.spec.ts +++ b/src/LanguageServer.spec.ts @@ -17,6 +17,7 @@ import { isBrsFile, isLiteralString } from './astUtils/reflection'; import { createVisitor, WalkMode } from './astUtils/visitors'; import { tempDir, rootDir } from './testHelpers.spec'; import { URI } from 'vscode-uri'; +import { BuildStatusTracker } from './BuildStatusTracker'; const sinon = createSandbox(); @@ -76,6 +77,7 @@ describe('LanguageServer', () => { beforeEach(() => { sinon.restore(); server = new LanguageServer(); + server['buildStatusTracker'] = new BuildStatusTracker(connection as any); workspaceFolders = [workspacePath]; vfs = {}; diff --git a/src/LanguageServer.ts b/src/LanguageServer.ts index 2947bc0c9..e5bcc01ca 100644 --- a/src/LanguageServer.ts +++ b/src/LanguageServer.ts @@ -46,6 +46,7 @@ import { KeyedThrottler } from './KeyedThrottler'; import { DiagnosticCollection } from './DiagnosticCollection'; import { isBrsFile } from './astUtils/reflection'; import { encodeSemanticTokens, semanticTokensLegend } from './SemanticTokenUtils'; +import { BuildStatusTracker } from './BuildStatusTracker'; export class LanguageServer { private connection = undefined as Connection; @@ -96,12 +97,16 @@ export class LanguageServer { return this.validateThrottler.run(this.boundValidateAll); } + private buildStatusTracker: BuildStatusTracker; + //run the server public run() { // Create a connection for the server. The connection uses Node's IPC as a transport. // Also include all preview / proposed LSP features. this.connection = this.createConnection(); + this.buildStatusTracker = new BuildStatusTracker(this.connection); + //listen to all of the output log events and pipe them into the debug channel in the extension this.loggerSubscription = Logger.subscribe((text) => { this.connection.tracer.log(text); @@ -310,44 +315,48 @@ export class LanguageServer { * Leave existing projects alone if they are not affected by these changes */ private async syncProjects() { - const workspacePaths = await this.getWorkspacePaths(); - let projectPaths = (await Promise.all( - workspacePaths.map(async workspacePath => { - const projectPaths = await this.getProjectPaths(workspacePath); - return projectPaths.map(projectPath => ({ - projectPath: projectPath, - workspacePath: workspacePath - })); - }) - )).flat(1); - - //delete projects not represented in the list - for (const project of this.getProjects()) { - if (!projectPaths.find(x => x.projectPath === project.projectPath)) { - this.removeProject(project); + await this.buildStatusTracker.run(this as any, async () => { + + const workspacePaths = await this.getWorkspacePaths(); + let projectPaths = (await Promise.all( + workspacePaths.map(async workspacePath => { + const projectPaths = await this.getProjectPaths(workspacePath); + return projectPaths.map(projectPath => ({ + projectPath: projectPath, + workspacePath: workspacePath + })); + }) + )).flat(1); + + //delete projects not represented in the list + for (const project of this.getProjects()) { + if (!projectPaths.find(x => x.projectPath === project.projectPath)) { + this.removeProject(project); + } } - } - //exclude paths to projects we already have - projectPaths = projectPaths.filter(x => { - //only keep this project path if there's not a project with that path - return !this.projects.find(project => project.projectPath === x.projectPath); - }); + //exclude paths to projects we already have + projectPaths = projectPaths.filter(x => { + //only keep this project path if there's not a project with that path + return !this.projects.find(project => project.projectPath === x.projectPath); + }); - //dedupe by project path - projectPaths = [ - ...projectPaths.reduce( - (acc, x) => acc.set(x.projectPath, x), - new Map() - ).values() - ]; + //dedupe by project path + projectPaths = [ + ...projectPaths.reduce( + (acc, x) => acc.set(x.projectPath, x), + new Map() + ).values() + ]; - //create missing projects - await Promise.all( - projectPaths.map(x => this.createProject(x.projectPath, x.workspacePath)) - ); - //flush diagnostics - await this.sendDiagnostics(); + //create missing projects + await Promise.all( + projectPaths.map(x => this.createProject(x.projectPath, x.workspacePath)) + ); + //flush diagnostics + await this.sendDiagnostics(); + + }); } /** @@ -412,7 +421,6 @@ export class LanguageServer { await this.initialProjectsCreated; } - let status: string; for (let project of this.getProjects()) { try { await project.firstRunPromise; @@ -424,7 +432,6 @@ export class LanguageServer { this.sendCriticalFailure(`BrighterScript language server failed to start: \n${e.message}`); } } - this.connection.sendNotification('build-status', status ? status : 'success'); } /** @@ -484,12 +491,18 @@ export class LanguageServer { return undefined; } + /** * A unique project counter to help distinguish log entries in lsp mode */ private projectCounter = 0; - private async createProject(projectPath: string, workspacePath = projectPath) { + /** + * @param projectPath path to the project + * @param workspacePath path to the workspace in which all project should reside or are referenced by + * @param projectNumber an optional project number to assign to the project. Used when reloading projects that should keep the same number + */ + private async createProject(projectPath: string, workspacePath = projectPath, projectNumber?: number) { workspacePath ??= projectPath; let project = this.projects.find((x) => x.projectPath === projectPath); //skip this project if we already have it @@ -498,7 +511,7 @@ export class LanguageServer { } let builder = new ProgramBuilder(); - const projectNumber = this.projectCounter++; + projectNumber ??= this.projectCounter++; builder.logger.prefix = `[prj${projectNumber}]`; builder.logger.log(`Created project #${projectNumber} for: "${projectPath}"`); @@ -528,22 +541,12 @@ export class LanguageServer { configFilePath = undefined; } - let firstRunPromise = builder.run({ - cwd: cwd, - project: configFilePath, - watch: false, - createPackage: false, - deploy: false, - copyToStaging: false, - showDiagnosticsInConsole: false - }); - firstRunPromise.catch((err) => { - console.error(err); - }); + const firstRunDeferred = new Deferred(); let newProject: Project = { + projectNumber: projectNumber, builder: builder, - firstRunPromise: firstRunPromise, + firstRunPromise: firstRunDeferred.promise, projectPath: projectPath, workspacePath: workspacePath, isFirstRunComplete: false, @@ -554,22 +557,35 @@ export class LanguageServer { this.projects.push(newProject); - await firstRunPromise.then(() => { + try { + await this.buildStatusTracker.run(project, async () => { + await builder.run({ + cwd: cwd, + project: configFilePath, + watch: false, + createPackage: false, + deploy: false, + copyToStaging: false, + showDiagnosticsInConsole: false + }); + }); newProject.isFirstRunComplete = true; newProject.isFirstRunSuccessful = true; - }).catch(() => { + firstRunDeferred.resolve(); + } catch (e) { + builder.logger.error(e); + firstRunDeferred.reject(e); newProject.isFirstRunComplete = true; newProject.isFirstRunSuccessful = false; - }).then(() => { - //if we found a deprecated brsconfig.json, add a diagnostic warning the user - if (configFilePath && path.basename(configFilePath) === 'brsconfig.json') { - builder.addDiagnostic(configFilePath, { - ...DiagnosticMessages.brsConfigJsonIsDeprecated(), - range: util.createRange(0, 0, 0, 0) - }); - return this.sendDiagnostics(); - } - }); + } + //if we found a deprecated brsconfig.json, add a diagnostic warning the user + if (configFilePath && path.basename(configFilePath) === 'brsconfig.json') { + builder.addDiagnostic(configFilePath, { + ...DiagnosticMessages.brsConfigJsonIsDeprecated(), + range: util.createRange(0, 0, 0, 0) + }); + return this.sendDiagnostics(); + } } private async createStandaloneFileProject(srcPath: string) { @@ -619,6 +635,7 @@ export class LanguageServer { }); let newProject: Project = { + projectNumber: this.projectCounter++, builder: builder, firstRunPromise: firstRunPromise, projectPath: srcPath, @@ -740,7 +757,7 @@ export class LanguageServer { this.removeProject(project); //create a new workspace/brs program - await this.createProject(project.projectPath, project.workspacePath); + await this.createProject(project.projectPath, project.workspacePath, project.projectNumber); //handle temp workspace } else { @@ -838,8 +855,6 @@ export class LanguageServer { //ensure programs are initialized await this.waitAllProjectFirstRuns(); - this.connection.sendNotification('build-status', 'building'); - let projects = this.getProjects(); //convert all file paths to absolute paths @@ -1101,7 +1116,14 @@ export class LanguageServer { //validate all programs await Promise.all( - projects.map((x) => x.builder.program.validate()) + projects.map((project) => { + return this.buildStatusTracker.run(project, () => { + + project.builder.program.validate(); + return project; + + }); + }) ); } catch (e: any) { this.connection.console.error(e); @@ -1287,6 +1309,10 @@ export class LanguageServer { } export interface Project { + /** + * A unique number for this project, generated during this current language server session. Mostly used so we can identify which project is doing logging + */ + projectNumber: number; firstRunPromise: Promise; builder: ProgramBuilder; /** diff --git a/src/deferred.ts b/src/deferred.ts index c746e4e35..2c9cb7ec1 100644 --- a/src/deferred.ts +++ b/src/deferred.ts @@ -37,7 +37,7 @@ export class Deferred { /** * Resolve the promise */ - public resolve(value: T) { + public resolve(value?: T) { if (this._isCompleted) { throw new Error('Already completed.'); } diff --git a/src/index.ts b/src/index.ts index 1a7218e90..adb95d67f 100644 --- a/src/index.ts +++ b/src/index.ts @@ -25,3 +25,4 @@ export * from './astUtils/reflection'; export * from './astUtils/creators'; export * from './astUtils/xml'; export * from './astUtils/AstEditor'; +export * from './BuildStatusTracker';