From 67144bb125d76547c27a6abba1609d1d3e7c8188 Mon Sep 17 00:00:00 2001 From: Johannes Date: Fri, 2 Sep 2022 17:12:00 +0200 Subject: [PATCH 1/4] Add a command to print DI cycles --- .../common/instantiationService.ts | 25 +++++-- .../test/common/instantiationService.test.ts | 66 +++++++++++++++++++ .../browser/performance.contribution.ts | 26 ++++++++ 3 files changed, 113 insertions(+), 4 deletions(-) diff --git a/src/vs/platform/instantiation/common/instantiationService.ts b/src/vs/platform/instantiation/common/instantiationService.ts index 1f6bba77e24ce..8efe96fc0b6d7 100644 --- a/src/vs/platform/instantiation/common/instantiationService.ts +++ b/src/vs/platform/instantiation/common/instantiationService.ts @@ -28,12 +28,16 @@ export class InstantiationService implements IInstantiationService { private readonly _strict: boolean; private readonly _parent?: InstantiationService; + readonly _globalGraph: Graph; + private _globalGraphImplicitDependency?: string; + constructor(services: ServiceCollection = new ServiceCollection(), strict: boolean = false, parent?: InstantiationService) { this._services = services; this._strict = strict; this._parent = parent; this._services.set(IInstantiationService, this); + this._globalGraph = parent?._globalGraph ?? new Graph(e => e); } createChild(services: ServiceCollection): IInstantiationService { @@ -130,6 +134,9 @@ export class InstantiationService implements IInstantiationService { } protected _getOrCreateServiceInstance(id: ServiceIdentifier, _trace: Trace): T { + if (this._globalGraphImplicitDependency) { + this._globalGraph.insertEdge(this._globalGraphImplicitDependency, String(id)); + } const thing = this._getServiceInstanceOrDescriptor(id); if (thing instanceof SyncDescriptor) { return this._safeCreateAndCacheServiceInstance(id, thing, _trace.branch(id, true)); @@ -178,6 +185,9 @@ export class InstantiationService implements IInstantiationService { this._throwIfStrict(`[createInstance] ${id} depends on ${dependency.id} which is NOT registered.`, true); } + // take note of all service dependencies + this._globalGraph.insertEdge(String(item.id), String(dependency.id)); + if (instanceOrDesc instanceof SyncDescriptor) { const d = { id: dependency.id, desc: instanceOrDesc, _trace: item._trace.branch(dependency.id, true) }; graph.insertEdge(item, d); @@ -216,7 +226,7 @@ export class InstantiationService implements IInstantiationService { private _createServiceInstanceWithOwner(id: ServiceIdentifier, ctor: any, args: any[] = [], supportsDelayedInstantiation: boolean, _trace: Trace): T { if (this._services.get(id) instanceof SyncDescriptor) { - return this._createServiceInstance(ctor, args, supportsDelayedInstantiation, _trace); + return this._createServiceInstance(id, ctor, args, supportsDelayedInstantiation, _trace); } else if (this._parent) { return this._parent._createServiceInstanceWithOwner(id, ctor, args, supportsDelayedInstantiation, _trace); } else { @@ -224,16 +234,23 @@ export class InstantiationService implements IInstantiationService { } } - private _createServiceInstance(ctor: any, args: any[] = [], _supportsDelayedInstantiation: boolean, _trace: Trace): T { - if (!_supportsDelayedInstantiation) { + private _createServiceInstance(id: ServiceIdentifier, ctor: any, args: any[] = [], supportsDelayedInstantiation: boolean, _trace: Trace): T { + if (!supportsDelayedInstantiation) { // eager instantiation return this._createInstance(ctor, args, _trace); } else { + const child = new InstantiationService(undefined, this._strict, this); + child._globalGraphImplicitDependency = String(id); + // Return a proxy object that's backed by an idle value. That // strategy is to instantiate services in our idle time or when actually // needed but not when injected into a consumer - const idle = new IdleValue(() => this._createInstance(ctor, args, _trace)); + const idle = new IdleValue(() => { + const result = child._createInstance(ctor, args, _trace); + // child._globalGraphImplicitDependency = undefined; + return result; + }); return new Proxy(Object.create(null), { get(target: any, key: PropertyKey): any { if (key in target) { diff --git a/src/vs/platform/instantiation/test/common/instantiationService.test.ts b/src/vs/platform/instantiation/test/common/instantiationService.test.ts index 90bd049d0caa0..fb32a992f309e 100644 --- a/src/vs/platform/instantiation/test/common/instantiationService.test.ts +++ b/src/vs/platform/instantiation/test/common/instantiationService.test.ts @@ -393,4 +393,70 @@ suite('Instantiation Service', () => { assert.ok(obj); }); + test('Sync/Async dependency loop', async function () { + + const A = createDecorator('A'); + const B = createDecorator('B'); + interface A { _serviceBrand: undefined; doIt(): void } + interface B { _serviceBrand: undefined; b(): boolean } + + class BConsumer { + constructor(@B readonly b: B) { + + } + doIt() { + return this.b.b(); + } + } + + class AService implements A { + _serviceBrand: undefined; + prop: BConsumer; + constructor(@IInstantiationService insta: IInstantiationService) { + this.prop = insta.createInstance(BConsumer); + } + doIt() { + return this.prop.doIt(); + } + } + + class BService implements B { + _serviceBrand: undefined; + constructor(@A a: A) { + assert.ok(a); + } + b() { return true; } + } + + // SYNC -> explodes AImpl -> [insta:BConsumer] -> BImpl -> AImpl + { + const insta1 = new InstantiationService(new ServiceCollection( + [A, new SyncDescriptor(AService)], + [B, new SyncDescriptor(BService)], + )); + + try { + insta1.invokeFunction(accessor => accessor.get(A)); + assert.ok(false); + + } catch (error) { + assert.ok(error instanceof Error); + assert.ok(error.message.includes('RECURSIVELY')); + } + } + + // ASYNC -> doesn't explode but cycle is tracked + { + const insta2 = new InstantiationService(new ServiceCollection( + [A, new SyncDescriptor(AService, undefined, true)], + [B, new SyncDescriptor(BService, undefined)], + )); + + const a = insta2.invokeFunction(accessor => accessor.get(A)); + a.doIt(); + + const cycle = insta2._globalGraph.findCycleSlow(); + assert.strictEqual(cycle, 'A -> B -> A'); + } + }); }); diff --git a/src/vs/workbench/contrib/performance/browser/performance.contribution.ts b/src/vs/workbench/contrib/performance/browser/performance.contribution.ts index d001722562ca5..38a99f1767766 100644 --- a/src/vs/workbench/contrib/performance/browser/performance.contribution.ts +++ b/src/vs/workbench/contrib/performance/browser/performance.contribution.ts @@ -13,6 +13,7 @@ import { Extensions, IWorkbenchContributionsRegistry } from 'vs/workbench/common import { EditorExtensions, IEditorSerializer, IEditorFactoryRegistry } from 'vs/workbench/common/editor'; import { PerfviewContrib, PerfviewInput } from 'vs/workbench/contrib/performance/browser/perfviewEditor'; import { IEditorService } from 'vs/workbench/services/editor/common/editorService'; +import { InstantiationService } from 'vs/platform/instantiation/common/instantiationService'; // -- startup performance view @@ -55,3 +56,28 @@ registerAction2(class extends Action2 { return editorService.openEditor(instaService.createInstance(PerfviewInput), { pinned: true }); } }); + + +registerAction2(class extends Action2 { + + constructor() { + super({ + id: 'instantiation.printAsyncCycles', + title: { value: localize('cycles', "Print Service Cycles"), original: 'Print Service Cycles' }, + category: CATEGORIES.Developer, + f1: true + }); + } + + run(accessor: ServicesAccessor) { + const instaService = accessor.get(IInstantiationService); + if (instaService instanceof InstantiationService) { + const cycle = instaService._globalGraph.findCycleSlow(); + if (cycle) { + console.warn(`CYCLE`, cycle); + } else { + console.warn(`YEAH, no more cycles`); + } + } + } +}); From 8da3d82320c7fa0eddbac9c22109f152ebd653cc Mon Sep 17 00:00:00 2001 From: Johannes Date: Mon, 5 Sep 2022 14:21:57 +0200 Subject: [PATCH 2/4] make global graph tracking optional --- .../common/instantiationService.ts | 39 +++++++++---------- .../test/common/instantiationService.test.ts | 6 +-- .../test/common/instantiationServiceMock.ts | 2 +- .../browser/performance.contribution.ts | 2 +- 4 files changed, 23 insertions(+), 26 deletions(-) diff --git a/src/vs/platform/instantiation/common/instantiationService.ts b/src/vs/platform/instantiation/common/instantiationService.ts index 8efe96fc0b6d7..afec7feb84c7e 100644 --- a/src/vs/platform/instantiation/common/instantiationService.ts +++ b/src/vs/platform/instantiation/common/instantiationService.ts @@ -11,7 +11,7 @@ import { IInstantiationService, ServiceIdentifier, ServicesAccessor, _util } fro import { ServiceCollection } from 'vs/platform/instantiation/common/serviceCollection'; // TRACING -const _enableTracing = false; +const _enableAllTracing = false; class CyclicDependencyError extends Error { constructor(graph: Graph) { @@ -24,28 +24,26 @@ export class InstantiationService implements IInstantiationService { declare readonly _serviceBrand: undefined; - private readonly _services: ServiceCollection; - private readonly _strict: boolean; - private readonly _parent?: InstantiationService; - - readonly _globalGraph: Graph; + readonly _globalGraph?: Graph; private _globalGraphImplicitDependency?: string; - constructor(services: ServiceCollection = new ServiceCollection(), strict: boolean = false, parent?: InstantiationService) { - this._services = services; - this._strict = strict; - this._parent = parent; + constructor( + private readonly _services: ServiceCollection = new ServiceCollection(), + private readonly _strict: boolean = false, + private readonly _parent?: InstantiationService, + private readonly _enableTracing: boolean = _enableAllTracing + ) { this._services.set(IInstantiationService, this); - this._globalGraph = parent?._globalGraph ?? new Graph(e => e); + this._globalGraph = _enableTracing ? _parent?._globalGraph ?? new Graph(e => e) : undefined; } createChild(services: ServiceCollection): IInstantiationService { - return new InstantiationService(services, this._strict, this); + return new InstantiationService(services, this._strict, this, this._enableTracing); } invokeFunction(fn: (accessor: ServicesAccessor, ...args: TS) => R, ...args: TS): R { - const _trace = Trace.traceInvocation(fn); + const _trace = Trace.traceInvocation(this._enableTracing, fn); let _done = false; try { const accessor: ServicesAccessor = { @@ -73,10 +71,10 @@ export class InstantiationService implements IInstantiationService { let _trace: Trace; let result: any; if (ctorOrDescriptor instanceof SyncDescriptor) { - _trace = Trace.traceCreation(ctorOrDescriptor.ctor); + _trace = Trace.traceCreation(this._enableTracing, ctorOrDescriptor.ctor); result = this._createInstance(ctorOrDescriptor.ctor, ctorOrDescriptor.staticArguments.concat(rest), _trace); } else { - _trace = Trace.traceCreation(ctorOrDescriptor); + _trace = Trace.traceCreation(this._enableTracing, ctorOrDescriptor); result = this._createInstance(ctorOrDescriptor, rest, _trace); } _trace.stop(); @@ -135,7 +133,7 @@ export class InstantiationService implements IInstantiationService { protected _getOrCreateServiceInstance(id: ServiceIdentifier, _trace: Trace): T { if (this._globalGraphImplicitDependency) { - this._globalGraph.insertEdge(this._globalGraphImplicitDependency, String(id)); + this._globalGraph?.insertEdge(this._globalGraphImplicitDependency, String(id)); } const thing = this._getServiceInstanceOrDescriptor(id); if (thing instanceof SyncDescriptor) { @@ -186,7 +184,7 @@ export class InstantiationService implements IInstantiationService { } // take note of all service dependencies - this._globalGraph.insertEdge(String(item.id), String(dependency.id)); + this._globalGraph?.insertEdge(String(item.id), String(dependency.id)); if (instanceOrDesc instanceof SyncDescriptor) { const d = { id: dependency.id, desc: instanceOrDesc, _trace: item._trace.branch(dependency.id, true) }; @@ -240,7 +238,7 @@ export class InstantiationService implements IInstantiationService { return this._createInstance(ctor, args, _trace); } else { - const child = new InstantiationService(undefined, this._strict, this); + const child = new InstantiationService(undefined, this._strict, this, this._enableTracing); child._globalGraphImplicitDependency = String(id); // Return a proxy object that's backed by an idle value. That @@ -248,7 +246,6 @@ export class InstantiationService implements IInstantiationService { // needed but not when injected into a consumer const idle = new IdleValue(() => { const result = child._createInstance(ctor, args, _trace); - // child._globalGraphImplicitDependency = undefined; return result; }); return new Proxy(Object.create(null), { @@ -297,11 +294,11 @@ export class Trace { override branch() { return this; } }; - static traceInvocation(ctor: any): Trace { + static traceInvocation(_enableTracing: boolean, ctor: any): Trace { return !_enableTracing ? Trace._None : new Trace(TraceType.Invocation, ctor.name || (ctor.toString() as string).substring(0, 42).replace(/\n/g, '')); } - static traceCreation(ctor: any): Trace { + static traceCreation(_enableTracing: boolean, ctor: any): Trace { return !_enableTracing ? Trace._None : new Trace(TraceType.Creation, ctor.name); } diff --git a/src/vs/platform/instantiation/test/common/instantiationService.test.ts b/src/vs/platform/instantiation/test/common/instantiationService.test.ts index fb32a992f309e..a737b46533cd4 100644 --- a/src/vs/platform/instantiation/test/common/instantiationService.test.ts +++ b/src/vs/platform/instantiation/test/common/instantiationService.test.ts @@ -433,7 +433,7 @@ suite('Instantiation Service', () => { const insta1 = new InstantiationService(new ServiceCollection( [A, new SyncDescriptor(AService)], [B, new SyncDescriptor(BService)], - )); + ), true, undefined, true); try { insta1.invokeFunction(accessor => accessor.get(A)); @@ -450,12 +450,12 @@ suite('Instantiation Service', () => { const insta2 = new InstantiationService(new ServiceCollection( [A, new SyncDescriptor(AService, undefined, true)], [B, new SyncDescriptor(BService, undefined)], - )); + ), true, undefined, true); const a = insta2.invokeFunction(accessor => accessor.get(A)); a.doIt(); - const cycle = insta2._globalGraph.findCycleSlow(); + const cycle = insta2._globalGraph?.findCycleSlow(); assert.strictEqual(cycle, 'A -> B -> A'); } }); diff --git a/src/vs/platform/instantiation/test/common/instantiationServiceMock.ts b/src/vs/platform/instantiation/test/common/instantiationServiceMock.ts index 993fbfe9643e4..504f2600de87e 100644 --- a/src/vs/platform/instantiation/test/common/instantiationServiceMock.ts +++ b/src/vs/platform/instantiation/test/common/instantiationServiceMock.ts @@ -28,7 +28,7 @@ export class TestInstantiationService extends InstantiationService { } public get(service: ServiceIdentifier): T { - return super._getOrCreateServiceInstance(service, Trace.traceCreation(TestInstantiationService)); + return super._getOrCreateServiceInstance(service, Trace.traceCreation(false, TestInstantiationService)); } public set(service: ServiceIdentifier, instance: T): T { diff --git a/src/vs/workbench/contrib/performance/browser/performance.contribution.ts b/src/vs/workbench/contrib/performance/browser/performance.contribution.ts index 38a99f1767766..06869c4b2ddd4 100644 --- a/src/vs/workbench/contrib/performance/browser/performance.contribution.ts +++ b/src/vs/workbench/contrib/performance/browser/performance.contribution.ts @@ -72,7 +72,7 @@ registerAction2(class extends Action2 { run(accessor: ServicesAccessor) { const instaService = accessor.get(IInstantiationService); if (instaService instanceof InstantiationService) { - const cycle = instaService._globalGraph.findCycleSlow(); + const cycle = instaService._globalGraph?.findCycleSlow(); if (cycle) { console.warn(`CYCLE`, cycle); } else { From 7917990b20aa7c8d102d6fa2fb0bfb82306359fa Mon Sep 17 00:00:00 2001 From: Johannes Date: Tue, 13 Sep 2022 16:22:04 +0200 Subject: [PATCH 3/4] :lipstick: --- src/vs/platform/instantiation/common/instantiationService.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/vs/platform/instantiation/common/instantiationService.ts b/src/vs/platform/instantiation/common/instantiationService.ts index afec7feb84c7e..a6ac0e6cee7e3 100644 --- a/src/vs/platform/instantiation/common/instantiationService.ts +++ b/src/vs/platform/instantiation/common/instantiationService.ts @@ -132,8 +132,8 @@ export class InstantiationService implements IInstantiationService { } protected _getOrCreateServiceInstance(id: ServiceIdentifier, _trace: Trace): T { - if (this._globalGraphImplicitDependency) { - this._globalGraph?.insertEdge(this._globalGraphImplicitDependency, String(id)); + if (this._globalGraph && this._globalGraphImplicitDependency) { + this._globalGraph.insertEdge(this._globalGraphImplicitDependency, String(id)); } const thing = this._getServiceInstanceOrDescriptor(id); if (thing instanceof SyncDescriptor) { From e0b32e20299c9d01d68c8cd9bda4188f3e715490 Mon Sep 17 00:00:00 2001 From: Johannes Date: Tue, 13 Sep 2022 16:53:01 +0200 Subject: [PATCH 4/4] add command to print DI traces add command to print Emitter profiling --- src/vs/base/common/event.ts | 26 +++++---- .../common/instantiationService.ts | 10 ++-- .../browser/performance.contribution.ts | 53 +++++++++++++++++-- 3 files changed, 72 insertions(+), 17 deletions(-) diff --git a/src/vs/base/common/event.ts b/src/vs/base/common/event.ts index 054cf4de2d448..e8d7a30dfc42e 100644 --- a/src/vs/base/common/event.ts +++ b/src/vs/base/common/event.ts @@ -493,32 +493,36 @@ export interface EmitterOptions { } -class EventProfiling { +export class EventProfiling { + + static readonly all = new Set(); private static _idPool = 0; - private _name: string; + readonly name: string; + public listenerCount: number = 0; + public invocationCount = 0; + public elapsedOverall = 0; + public durations: number[] = []; + private _stopWatch?: StopWatch; - private _listenerCount: number = 0; - private _invocationCount = 0; - private _elapsedOverall = 0; constructor(name: string) { - this._name = `${name}_${EventProfiling._idPool++}`; + this.name = `${name}_${EventProfiling._idPool++}`; + EventProfiling.all.add(this); } start(listenerCount: number): void { this._stopWatch = new StopWatch(true); - this._listenerCount = listenerCount; + this.listenerCount = listenerCount; } stop(): void { if (this._stopWatch) { const elapsed = this._stopWatch.elapsed(); - this._elapsedOverall += elapsed; - this._invocationCount += 1; - - console.info(`did FIRE ${this._name}: elapsed_ms: ${elapsed.toFixed(5)}, listener: ${this._listenerCount} (elapsed_overall: ${this._elapsedOverall.toFixed(2)}, invocations: ${this._invocationCount})`); + this.durations.push(elapsed); + this.elapsedOverall += elapsed; + this.invocationCount += 1; this._stopWatch = undefined; } } diff --git a/src/vs/platform/instantiation/common/instantiationService.ts b/src/vs/platform/instantiation/common/instantiationService.ts index a6ac0e6cee7e3..21908bbcff087 100644 --- a/src/vs/platform/instantiation/common/instantiationService.ts +++ b/src/vs/platform/instantiation/common/instantiationService.ts @@ -11,7 +11,9 @@ import { IInstantiationService, ServiceIdentifier, ServicesAccessor, _util } fro import { ServiceCollection } from 'vs/platform/instantiation/common/serviceCollection'; // TRACING -const _enableAllTracing = false; +const _enableAllTracing = false + // || "TRUE" // DO NOT CHECK IN! + ; class CyclicDependencyError extends Error { constructor(graph: Graph) { @@ -288,6 +290,8 @@ const enum TraceType { export class Trace { + static all = new Set(); + private static readonly _None = new class extends Trace { constructor() { super(-1, null); } override stop() { } @@ -295,7 +299,7 @@ export class Trace { }; static traceInvocation(_enableTracing: boolean, ctor: any): Trace { - return !_enableTracing ? Trace._None : new Trace(TraceType.Invocation, ctor.name || (ctor.toString() as string).substring(0, 42).replace(/\n/g, '')); + return !_enableTracing ? Trace._None : new Trace(TraceType.Invocation, ctor.name || new Error().stack!.split('\n').slice(3, 4).join('\n')); } static traceCreation(_enableTracing: boolean, ctor: any): Trace { @@ -348,7 +352,7 @@ export class Trace { ]; if (dur > 2 || causedCreation) { - console.log(lines.join('\n')); + Trace.all.add(lines.join('\n')); } } } diff --git a/src/vs/workbench/contrib/performance/browser/performance.contribution.ts b/src/vs/workbench/contrib/performance/browser/performance.contribution.ts index 06869c4b2ddd4..ac2fe4488886c 100644 --- a/src/vs/workbench/contrib/performance/browser/performance.contribution.ts +++ b/src/vs/workbench/contrib/performance/browser/performance.contribution.ts @@ -13,7 +13,8 @@ import { Extensions, IWorkbenchContributionsRegistry } from 'vs/workbench/common import { EditorExtensions, IEditorSerializer, IEditorFactoryRegistry } from 'vs/workbench/common/editor'; import { PerfviewContrib, PerfviewInput } from 'vs/workbench/contrib/performance/browser/perfviewEditor'; import { IEditorService } from 'vs/workbench/services/editor/common/editorService'; -import { InstantiationService } from 'vs/platform/instantiation/common/instantiationService'; +import { InstantiationService, Trace } from 'vs/platform/instantiation/common/instantiationService'; +import { EventProfiling } from 'vs/base/common/event'; // -- startup performance view @@ -58,11 +59,11 @@ registerAction2(class extends Action2 { }); -registerAction2(class extends Action2 { +registerAction2(class PrintServiceCycles extends Action2 { constructor() { super({ - id: 'instantiation.printAsyncCycles', + id: 'perf.insta.printAsyncCycles', title: { value: localize('cycles', "Print Service Cycles"), original: 'Print Service Cycles' }, category: CATEGORIES.Developer, f1: true @@ -81,3 +82,49 @@ registerAction2(class extends Action2 { } } }); + +registerAction2(class PrintServiceTraces extends Action2 { + + constructor() { + super({ + id: 'perf.insta.printTraces', + title: { value: localize('insta.trace', "Print Service Traces"), original: 'Print Service Traces' }, + category: CATEGORIES.Developer, + f1: true + }); + } + + run() { + if (Trace.all.size === 0) { + console.log('Enable via `instantiationService.ts#_enableAllTracing`'); + return; + } + + for (const item of Trace.all) { + console.log(item); + } + } +}); + + +registerAction2(class PrintEventProfiling extends Action2 { + + constructor() { + super({ + id: 'perf.event.profiling', + title: { value: localize('emitter', "Print Emitter Profiles"), original: 'Print Emitter Profiles' }, + category: CATEGORIES.Developer, + f1: true + }); + } + + run(): void { + if (EventProfiling.all.size === 0) { + console.log('USE `EmitterOptions._profName` to enable profiling'); + return; + } + for (const item of EventProfiling.all) { + console.log(`${item.name}: ${item.invocationCount}invocations COST ${item.elapsedOverall}ms, ${item.listenerCount} listeners, avg cost is ${item.durations.reduce((a, b) => a + b, 0) / item.durations.length}ms`); + } + } +});