Add some basic perf logging for notebook renderers (microsoft#166649)

For microsoft#154873

Adds a new log file for the webview of a notebook. This is currently used to log the load, activation, and render times of notebook renderers

Author: mjbvz

src/vs/workbench/contrib/notebook/browser/view/renderers/backLayerWebView.ts

@@ -26,13 +26,13 @@ import { IContextKeyService } from 'vs/platform/contextkey/common/contextkey';
 import { IContextMenuService } from 'vs/platform/contextview/browser/contextView';
 import { IFileDialogService } from 'vs/platform/dialogs/common/dialogs';
 import { IFileService } from 'vs/platform/files/common/files';
+import { ILogger, ILoggerService, ILogService } from 'vs/platform/log/common/log';
 import { IOpenerService, matchesScheme, matchesSomeScheme } from 'vs/platform/opener/common/opener';
 import { IStorageService } from 'vs/platform/storage/common/storage';
 import { editorFindMatch, editorFindMatchHighlight } from 'vs/platform/theme/common/colorRegistry';
 import { IThemeService, Themable } from 'vs/platform/theme/common/themeService';
 import { IWorkspaceContextService } from 'vs/platform/workspace/common/workspace';
 import { IWorkspaceTrustManagementService } from 'vs/platform/workspace/common/workspaceTrust';
-import { asWebviewUri, webviewGenericCspSource } from 'vs/workbench/contrib/webview/common/webview';
 import { CellEditState, ICellOutputViewModel, ICellViewModel, ICommonCellInfo, IDisplayOutputLayoutUpdateRequest, IDisplayOutputViewModel, IFocusNotebookCellOptions, IGenericCellViewModel, IInsetRenderOutput, INotebookEditorCreationOptions, INotebookWebviewMessage, RenderOutputType } from 'vs/workbench/contrib/notebook/browser/notebookBrowser';
 import { NOTEBOOK_WEBVIEW_BOUNDARY } from 'vs/workbench/contrib/notebook/browser/view/notebookCellList';
 import { preloadsScriptStr } from 'vs/workbench/contrib/notebook/browser/view/renderers/webviewPreloads';
@@ -44,8 +44,10 @@ import { IScopedRendererMessaging } from 'vs/workbench/contrib/notebook/common/n
 import { INotebookService } from 'vs/workbench/contrib/notebook/common/notebookService';
 import { IWebviewElement, IWebviewService, WebviewContentPurpose, WebviewOriginStore } from 'vs/workbench/contrib/webview/browser/webview';
 import { WebviewWindowDragMonitor } from 'vs/workbench/contrib/webview/browser/webviewWindowDragMonitor';
+import { asWebviewUri, webviewGenericCspSource } from 'vs/workbench/contrib/webview/common/webview';
 import { IEditorGroupsService } from 'vs/workbench/services/editor/common/editorGroupsService';
 import { IWorkbenchEnvironmentService } from 'vs/workbench/services/environment/common/environmentService';
+import { registerLogChannel } from 'vs/workbench/services/output/common/output';
 import { FromWebviewMessage, IAckOutputHeight, IClickedDataUrlMessage, ICodeBlockHighlightRequest, IContentWidgetTopRequest, IControllerPreload, ICreationContent, ICreationRequestMessage, IFindMatch, IMarkupCellInitialization, RendererMetadata, StaticPreloadMetadata, ToWebviewMessage } from './webviewMessages';
 
 export interface ICachedInset<K extends ICommonCellInfo> {
@@ -99,6 +101,8 @@ interface BacklayerWebviewOptions {
 	readonly outputLineHeight: number;
 }
 
+const logChannelId = 'notebook.rendering';
+
 export class BackLayerWebView<T extends ICommonCellInfo> extends Themable {
 
 	private static _originStore?: WebviewOriginStore;
@@ -126,6 +130,8 @@ export class BackLayerWebView<T extends ICommonCellInfo> extends Themable {
 	private firstInit = true;
 	private initializeMarkupPromise?: { readonly requestId: string; readonly p: DeferredPromise<void>; readonly isFirstInit: boolean };
 
+	private readonly _renderLogger: ILogger;
+
 	private readonly nonce = UUID.generateUuid();
 
 	constructor(
@@ -150,10 +156,18 @@ export class BackLayerWebView<T extends ICommonCellInfo> extends Themable {
 		@IWorkspaceContextService private readonly workspaceContextService: IWorkspaceContextService,
 		@IEditorGroupsService private readonly editorGroupService: IEditorGroupsService,
 		@IStorageService private readonly storageService: IStorageService,
+		@ILoggerService loggerService: ILoggerService,
+		@ILogService logService: ILogService,
 		@IThemeService themeService: IThemeService,
 	) {
 		super(themeService);
 
+		const logsPath = joinPath(environmentService.windowLogsPath, 'notebook.rendering.log');
+		this._renderLogger = this._register(loggerService.createLogger(logsPath, { name: 'notebook.rendering' }));
+		registerLogChannel(logChannelId, nls.localize('renderChannelName', "Notebook rendering"), logsPath, fileService, logService);
+
+		this._logRendererDebugMessage('Creating backlayer webview for notebook');
+
 		this.element = document.createElement('div');
 
 		this.element.style.height = '1400px';
@@ -198,6 +212,10 @@ export class BackLayerWebView<T extends ICommonCellInfo> extends Themable {
 		this._updateOptions();
 	}
 
+	private _logRendererDebugMessage(msg: string) {
+		this._renderLogger.debug(`${this.id} - ${msg}`);
+	}
+
 	private _updateStyles() {
 		this._sendMessageToWebview({
 			type: 'notebookStyles',
@@ -861,6 +879,10 @@ var requirejs = (function() {
 					});
 					break;
 				}
+				case 'logRendererDebugMessage': {
+					this._logRendererDebugMessage(`${data.message}${data.data ? ' ' + JSON.stringify(data.data, null, 4) : ''}`);
+					break;
+				}
 			}
 		}));
 	}

src/vs/workbench/contrib/notebook/browser/view/renderers/webviewMessages.ts

@@ -446,6 +446,12 @@ export interface IReturnOutputItemMessage {
 	readonly output: OutputItemEntry | undefined;
 }
 
+export interface ILogRendererDebugMessage extends BaseToWebviewMessage {
+	readonly type: 'logRendererDebugMessage';
+	readonly message: string;
+	readonly data?: Record<string, string>;
+}
+
 
 export type FromWebviewMessage = WebviewInitialized |
 	IDimensionMessage |
@@ -476,7 +482,8 @@ export type FromWebviewMessage = WebviewInitialized |
 	IDidFindMessage |
 	IDidFindHighlightMessage |
 	IOutputResizedMessage |
-	IGetOutputItemMessage;
+	IGetOutputItemMessage |
+	ILogRendererDebugMessage;
 
 export type ToWebviewMessage = IClearMessage |
 	IFocusOutputMessage |

src/vs/workbench/contrib/notebook/browser/view/renderers/webviewPreloads.ts

@@ -1344,10 +1344,15 @@ async function webviewPreloads(ctx: PreloadContext) {
 			}
 
 			try {
+				const renderStart = performance.now();
 				await this._api.renderOutputItem(item, element, signal);
+				this.postDebugMessage('Rendered output item', { id: item.id, duration: `${performance.now() - renderStart}ms` });
+
 			} catch (e) {
 				if (!signal.aborted) {
 					showRenderError(`Error rendering output item using '${this.data.id}'`, element, e instanceof Error ? [e] : []);
+
+					this.postDebugMessage('Rendering output item failed', { id: item.id, error: e + '' });
 				}
 			}
 		}
@@ -1397,36 +1402,60 @@ async function webviewPreloads(ctx: PreloadContext) {
 
 		/** Inner function cached in the _loadPromise(). */
 		private async _load(): Promise<rendererApi.RendererApi | undefined> {
-			// Preloads need to be loaded before loading renderers.
-			await kernelPreloads.waitForAllCurrent();
+			this.postDebugMessage('Start loading renderer');
 
-			const module: RendererModule = await __import(this.data.entrypoint.path);
-			if (!module) {
-				return;
-			}
+			try {
+				// Preloads need to be loaded before loading renderers.
+				await kernelPreloads.waitForAllCurrent();
 
-			this._api = await module.activate(this.createRendererContext());
-			// Load all renderers that extend this renderer
-			await Promise.all(
-				ctx.rendererData
-					.filter(d => d.entrypoint.extends === this.data.id)
-					.map(async d => {
-						const renderer = renderers.getRenderer(d.id);
-						if (!renderer) {
-							throw new Error(`Could not find extending renderer: ${d.id}`);
-						}
+				const importStart = performance.now();
+				const module: RendererModule = await __import(this.data.entrypoint.path);
+				this.postDebugMessage('Imported renderer', { duration: `${performance.now() - importStart}ms` });
 
-						try {
-							return await renderer.load();
-						} catch (e) {
-							// Squash any errors extends errors. They won't prevent the renderer
-							// itself from working, so just log them.
-							console.error(e);
-							return undefined;
-						}
-					}));
+				if (!module) {
+					return;
+				}
+
+				this._api = await module.activate(this.createRendererContext());
+				this.postDebugMessage('Activated renderer', { duration: `${performance.now() - importStart}ms` });
+
+				const dependantRenderers = ctx.rendererData
+					.filter(d => d.entrypoint.extends === this.data.id);
+
+				if (dependantRenderers.length) {
+					this.postDebugMessage('Activating dependant renderers', { dependents: dependantRenderers.map(x => x.id).join(', ') });
+				}
 
-			return this._api;
+				// Load all renderers that extend this renderer
+				await Promise.all(dependantRenderers.map(async d => {
+					const renderer = renderers.getRenderer(d.id);
+					if (!renderer) {
+						throw new Error(`Could not find extending renderer: ${d.id}`);
+					}
+
+					try {
+						return await renderer.load();
+					} catch (e) {
+						// Squash any errors extends errors. They won't prevent the renderer
+						// itself from working, so just log them.
+						console.error(e);
+						this.postDebugMessage('Activating dependant renderer failed', { dependent: d.id, error: e + '' });
+						return undefined;
+					}
+				}));
+
+				return this._api;
+			} catch (e) {
+				this.postDebugMessage('Loading renderer failed');
+				throw e;
+			}
+		}
+
+		private postDebugMessage(msg: string, data?: Record<string, string>) {
+			postNotebookMessage<webviewMessages.ILogRendererDebugMessage>('logRendererDebugMessage', {
+				message: `[renderer ${this.data.id}] - ${msg}`,
+				data
+			});
 		}
 	}