joh/insta print cycles

src/vs/base/common/event.ts

@@ -493,32 +493,36 @@ export interface EmitterOptions {
 }
 
 
-class EventProfiling {
+export class EventProfiling {
+
+	static readonly all = new Set<EventProfiling>();
 
 	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;
 		}
 	}

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 _enableTracing = false;
+const _enableAllTracing = false
+	// || "TRUE" // DO NOT CHECK IN!
+	;
 
 class CyclicDependencyError extends Error {
 	constructor(graph: Graph<any>) {
@@ -24,24 +26,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<string>;
+	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 = _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<R, TS extends any[] = []>(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 = {
@@ -69,10 +73,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();
@@ -130,6 +134,9 @@ export class InstantiationService implements IInstantiationService {
 	}
 
 	protected _getOrCreateServiceInstance<T>(id: ServiceIdentifier<T>, _trace: Trace): T {
+		if (this._globalGraph && 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,24 +226,30 @@ export class InstantiationService implements IInstantiationService {
 
 	private _createServiceInstanceWithOwner<T>(id: ServiceIdentifier<T>, 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 {
 			throw new Error(`illegalState - creating UNKNOWN service instance ${ctor.name}`);
 		}
 	}
 
-	private _createServiceInstance<T>(ctor: any, args: any[] = [], _supportsDelayedInstantiation: boolean, _trace: Trace): T {
-		if (!_supportsDelayedInstantiation) {
+	private _createServiceInstance<T>(id: ServiceIdentifier<T>, 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, this._enableTracing);
+			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<any>(() => this._createInstance<T>(ctor, args, _trace));
+			const idle = new IdleValue<any>(() => {
+				const result = child._createInstance<T>(ctor, args, _trace);
+				return result;
+			});
 			return <T>new Proxy(Object.create(null), {
 				get(target: any, key: PropertyKey): any {
 					if (key in target) {
@@ -274,17 +290,19 @@ const enum TraceType {
 
 export class Trace {
 
+	static all = new Set<string>();
+
 	private static readonly _None = new class extends Trace {
 		constructor() { super(-1, null); }
 		override stop() { }
 		override branch() { return this; }
 	};
 
-	static traceInvocation(ctor: any): Trace {
-		return !_enableTracing ? Trace._None : new Trace(TraceType.Invocation, ctor.name || (ctor.toString() as string).substring(0, 42).replace(/\n/g, ''));
+	static traceInvocation(_enableTracing: boolean, ctor: any): Trace {
+		return !_enableTracing ? Trace._None : new Trace(TraceType.Invocation, ctor.name || new Error().stack!.split('\n').slice(3, 4).join('\n'));
 	}
 
-	static traceCreation(ctor: any): Trace {
+	static traceCreation(_enableTracing: boolean, ctor: any): Trace {
 		return !_enableTracing ? Trace._None : new Trace(TraceType.Creation, ctor.name);
 	}
 
@@ -334,7 +352,7 @@ export class Trace {
 		];
 
 		if (dur > 2 || causedCreation) {
-			console.log(lines.join('\n'));
+			Trace.all.add(lines.join('\n'));
 		}
 	}
 }

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>('A');
+		const B = createDecorator<B>('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)],
+			), true, undefined, true);
+
+			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)],
+			), true, undefined, true);
+
+			const a = insta2.invokeFunction(accessor => accessor.get(A));
+			a.doIt();
+
+			const cycle = insta2._globalGraph?.findCycleSlow();
+			assert.strictEqual(cycle, 'A -> B -> A');
+		}
+	});
 });

src/vs/platform/instantiation/test/common/instantiationServiceMock.ts

@@ -28,7 +28,7 @@ export class TestInstantiationService extends InstantiationService {
 	}
 
 	public get<T>(service: ServiceIdentifier<T>): T {
-		return super._getOrCreateServiceInstance(service, Trace.traceCreation(TestInstantiationService));
+		return super._getOrCreateServiceInstance(service, Trace.traceCreation(false, TestInstantiationService));
 	}
 
 	public set<T>(service: ServiceIdentifier<T>, instance: T): T {

src/vs/workbench/contrib/performance/browser/performance.contribution.ts

@@ -13,6 +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, Trace } from 'vs/platform/instantiation/common/instantiationService';
+import { EventProfiling } from 'vs/base/common/event';
 
 // -- startup performance view
 
@@ -55,3 +57,74 @@ registerAction2(class extends Action2 {
 		return editorService.openEditor(instaService.createInstance(PerfviewInput), { pinned: true });
 	}
 });
+
+
+registerAction2(class PrintServiceCycles extends Action2 {
+
+	constructor() {
+		super({
+			id: 'perf.insta.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`);
+			}
+		}
+	}
+});
+
+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`);
+		}
+	}
+});