add logging for data workspace extension (#20601)

* add logging for data workspace extension

* Addressing comments

* adding back getProjectsInWorkspace() in constructor

* Add more logging in activate()

extensions/data-workspace/src/common/constants.ts

@@ -33,6 +33,7 @@ export const Select = localize('dataworkspace.select', "Select");
 export const WorkspaceFileExtension = '.code-workspace';
 export const DefaultInputWidth = '400px';
 export const DefaultButtonWidth = '80px';
+export const DataWorkspaceOutputChannel = 'Data Workspace';
 
 // New Project Dialog
 export const NewProjectDialogTitle = localize('dataworkspace.NewProjectDialogTitle', "Create new database project");

extensions/data-workspace/src/common/logger.ts

@@ -2,10 +2,37 @@
  *  Copyright (c) Microsoft Corporation. All rights reserved.
  *  Licensed under the Source EULA. See License.txt in the project root for license information.
  *--------------------------------------------------------------------------------------------*/
+import * as vscode from 'vscode';
+import { DataWorkspaceOutputChannel } from './constants';
 
 export class Log {
-	error(msg: string): void {
+	private output: vscode.OutputChannel;
-		console.error(msg);
+
+	constructor() {
+		this.output = vscode.window.createOutputChannel(DataWorkspaceOutputChannel);
+	}
+
+	error(message: string): void {
+		this.output.appendLine(`[Error - ${this.now()}] ${message}`);
+		console.error(message);
+	}
+
+	log(message: string): void {
+		this.output.appendLine(`[Info - ${this.now()}] ${message}`);
+	}
+
+	private now(): string {
+		const now = new Date();
+		return this.padLeft(now.getUTCFullYear() + '', 2, '0')
+			+ '-' + this.padLeft(now.getUTCMonth() + '', 2, '0')
+			+ '-' + this.padLeft(now.getUTCDate() + '', 2, '0')
+			+ ' ' + this.padLeft(now.getUTCHours() + '', 2, '0')
+			+ ':' + this.padLeft(now.getMinutes() + '', 2, '0')
+			+ ':' + this.padLeft(now.getUTCSeconds() + '', 2, '0') + '.' + now.getMilliseconds();
+	}
+
+	private padLeft(s: string, n: number, pad = ' ') {
+		return pad.repeat(Math.max(0, n - s.length)) + s;
 	}
 }
 const Logger = new Log();

extensions/data-workspace/src/common/workspaceTreeDataProvider.ts

@@ -9,6 +9,7 @@ import { IWorkspaceService } from './interfaces';
 import { ProjectsFailedToLoad, UnknownProjectsError } from './constants';
 import { WorkspaceTreeItem } from 'dataworkspace';
 import { TelemetryReporter } from './telemetry';
+import Logger from './logger';
 
 /**
  * Tree data provider for the workspace main view
@@ -24,6 +25,7 @@ export class WorkspaceTreeDataProvider implements vscode.TreeDataProvider<Worksp
 	readonly onDidChangeTreeData?: vscode.Event<void | WorkspaceTreeItem | null | undefined> | undefined = this._onDidChangeTreeData?.event;
 
 	async refresh(): Promise<void> {
+		Logger.log(`Refreshing projects tree`);
 		await this._workspaceService.getProjectsInWorkspace(undefined, true);
 		this._onDidChangeTreeData?.fire();
 	}
@@ -39,6 +41,7 @@ export class WorkspaceTreeDataProvider implements vscode.TreeDataProvider<Worksp
 		}
 		else {
 			// if the element is undefined return the project tree items
+			Logger.log(`Calling getProjectsInWorkspace() from getChildren()`);
 			const projects = await this._workspaceService.getProjectsInWorkspace(undefined, false);
 			await vscode.commands.executeCommand('setContext', 'isProjectsViewEmpty', projects.length === 0);
 			const unknownProjects: string[] = [];

extensions/data-workspace/src/main.ts

@@ -15,23 +15,44 @@ import { IconPathHelper } from './common/iconHelper';
 import { ProjectDashboard } from './dialogs/projectDashboard';
 import { getAzdataApi } from './common/utils';
 import { createNewProjectWithQuickpick } from './dialogs/newProjectQuickpick';
+import Logger from './common/logger';
 
 export async function activate(context: vscode.ExtensionContext): Promise<IExtension> {
+	const startTime = new Date().getTime();
+	Logger.log(`Starting Data Workspace activate()`);
+
+	const azDataApiStartTime = new Date().getTime();
 	const azdataApi = getAzdataApi();
 	void vscode.commands.executeCommand('setContext', 'azdataAvailable', !!azdataApi);
-	const workspaceService = new WorkspaceService();
+	Logger.log(`Setting azdataAvailable took ${new Date().getTime() - azDataApiStartTime}ms`);
 
+	const workspaceServiceConstructorStartTime = new Date().getTime();
+	const workspaceService = new WorkspaceService();
+	Logger.log(`WorkspaceService constructor took ${new Date().getTime() - workspaceServiceConstructorStartTime}ms`);
+
+	const workspaceTreeDataProviderStartTime = new Date().getTime();
 	const workspaceTreeDataProvider = new WorkspaceTreeDataProvider(workspaceService);
 	context.subscriptions.push(vscode.workspace.onDidChangeWorkspaceFolders(async () => {
 		await workspaceTreeDataProvider.refresh();
 	}));
+	Logger.log(`WorkspaceTreeDataProvider constructor took ${new Date().getTime() - workspaceTreeDataProviderStartTime}ms`);
+
+	const dataWorkspaceExtensionStartTime = new Date().getTime();
 	const dataWorkspaceExtension = new DataWorkspaceExtension(workspaceService);
+	Logger.log(`DataWorkspaceExtension constructor took ${new Date().getTime() - dataWorkspaceExtensionStartTime}ms`);
+
+	const registerTreeDataProvidertartTime = new Date().getTime();
 	context.subscriptions.push(vscode.window.registerTreeDataProvider('dataworkspace.views.main', workspaceTreeDataProvider));
+	Logger.log(`registerTreeDataProvider took ${new Date().getTime() - registerTreeDataProvidertartTime}ms`);
+
+	const settingProjectProviderContextStartTime = new Date().getTime();
 	context.subscriptions.push(vscode.extensions.onDidChange(() => {
 		setProjectProviderContextValue(workspaceService);
 	}));
 	setProjectProviderContextValue(workspaceService);
+	Logger.log(`setProjectProviderContextValue took ${new Date().getTime() - settingProjectProviderContextStartTime}ms`);
 
+	const registerCommandStartTime = new Date().getTime();
 	context.subscriptions.push(vscode.commands.registerCommand('projects.new', async () => {
 		if (azdataApi) {
 			const dialog = new NewProjectDialog(workspaceService);
@@ -70,9 +91,13 @@ export async function activate(context: vscode.ExtensionContext): Promise<IExten
 		const dashboard = new ProjectDashboard(workspaceService, treeItem);
 		await dashboard.showDashboard();
 	}));
+	Logger.log(`Registering commands took ${new Date().getTime() - registerCommandStartTime}ms`);
 
+	const iconPathHelperTime = new Date().getTime();
 	IconPathHelper.setExtensionContext(context);
+	Logger.log(`IconPathHelper took ${new Date().getTime() - iconPathHelperTime}ms`);
 
+	Logger.log(`Finished activating Data Workspace extension. Total time = ${new Date().getTime() - startTime}ms`);
 	return Promise.resolve(dataWorkspaceExtension);
 }
 

extensions/data-workspace/src/services/workspaceService.ts

@@ -27,22 +27,22 @@ export class WorkspaceService implements IWorkspaceService {
 	private excludedProjects: string[] | undefined;
 
 	constructor() {
-		this.getProjectsInWorkspace(undefined, true).catch(err => console.error('Error initializing projects in workspace ', err));
+		Logger.log(`Calling getProjectsInWorkspace() from WorkspaceService constructor`);
-
+		this.getProjectsInWorkspace(undefined, true).catch(err => Logger.error(`Error initializing projects in workspace ${err}`));
-		TelemetryReporter.createActionEvent(TelemetryViews.WorkspaceTreePane, TelemetryActions.ProjectsLoaded)
-			.withAdditionalProperties({
-				openProjectCount: this.openedProjects?.length.toString() ?? '0',
-				exludedProjectCount: this.excludedProjects?.length.toString() ?? '0'
-			}).send();
 	}
 
 	get isProjectProviderAvailable(): boolean {
+		Logger.log(`Checking ${vscode.extensions.all.length} extensions to see if there is a project provider is available`);
+		const startTime = new Date().getTime();
 		for (const extension of vscode.extensions.all) {
 			const projectTypes = extension.packageJSON.contributes && extension.packageJSON.contributes.projects as string[];
 			if (projectTypes && projectTypes.length > 0) {
+				Logger.log(`Project provider found. Total time = ${new Date().getTime() - startTime}ms`);
 				return true;
 			}
 		}
+
+		Logger.log(`No project providers found. Total time = ${new Date().getTime() - startTime}ms`);
 		return false;
 	}
 
@@ -134,6 +134,8 @@ export class WorkspaceService implements IWorkspaceService {
 	 * @returns array of file URIs for projects
 	 */
 	public async getProjectsInWorkspace(ext?: string, refreshFromDisk: boolean = false): Promise<vscode.Uri[]> {
+		Logger.log(`Getting projects in workspace`);
+		const startTime = new Date().getTime();
 
 		if (refreshFromDisk || this.openedProjects === undefined) { // always check if nothing cached
 			await this.refreshProjectsFromDisk();
@@ -147,6 +149,8 @@ export class WorkspaceService implements IWorkspaceService {
 		this.excludedProjects = this.getWorkspaceConfigurationValue<string[]>(ExcludedProjectsConfigurationName);
 		this.openedProjects = this.openedProjects.filter(project => !this.excludedProjects?.find(excludedProject => excludedProject === vscode.workspace.asRelativePath(project)));
 
+		Logger.log(`Finished looking for projects in workspace. Opened: ${this.openedProjects.length}. Excluded: ${this.excludedProjects.length}. Total time = ${new Date().getTime() - startTime}ms`);
+
 		// filter by specified extension
 		if (ext) {
 			return this.openedProjects.filter(p => p.fsPath.toLowerCase().endsWith(ext.toLowerCase()));