Chore: Resolves #12088: Desktop: Add performance logging statements to the startup code (#12812)

packages/app-desktop/app.ts

@@ -60,6 +60,9 @@ import { PackageInfo } from '@joplin/lib/versionInfo';
 import { CustomProtocolHandler } from './utils/customProtocols/handleCustomProtocols';
 import { refreshFolders } from '@joplin/lib/folders-screen-utils';
 import initializeCommandService from './utils/initializeCommandService';
+import PerformanceLogger from '@joplin/lib/PerformanceLogger';
+
+const perfLogger = PerformanceLogger.create('app-desktop/app');
 
 const pluginClasses = [
 	require('./plugins/GotoAnything').default,
@@ -67,6 +70,8 @@ const pluginClasses = [
 
 const appDefaultState = createAppDefaultState(resourceEditWatcherDefaultState);
 
+type StartupTask = { label: string; task: ()=> void|Promise<void> };
+
 class Application extends BaseApplication {
 
 	// eslint-disable-next-line @typescript-eslint/no-explicit-any -- Old code before rule was applied
@@ -411,28 +416,14 @@ class Application extends BaseApplication {
 		});
 	}
 
-	// eslint-disable-next-line @typescript-eslint/no-explicit-any -- Old code before rule was applied
-	public async start(argv: string[], startOptions: StartOptions = null): Promise<any> {
-		// If running inside a package, the command line, instead of being "node.exe <path> <flags>" is "joplin.exe <flags>" so
-		// insert an extra argument so that they can be processed in a consistent way everywhere.
-		if (!bridge().electronIsDev()) argv.splice(1, 0, '.');
-
-		argv = await super.start(argv, startOptions);
-
-		await this.setupIntegrationTestUtils();
-
-		bridge().setLogFilePath(Logger.globalLogger.logFilePath());
-
-		await this.applySettingsSideEffects();
-
-		if (Setting.value('sync.upgradeState') === Setting.SYNC_UPGRADE_STATE_MUST_DO) {
-			reg.logger().info('app.start: doing upgradeSyncTarget action');
-			bridge().mainWindow().show();
-			return { action: 'upgradeSyncTarget' };
-		}
+	private buildStartupTasks_() {
+		const tasks: StartupTask[] = [];
+		const addTask = (label: string, task: StartupTask['task']) => {
+			tasks.push({ label, task });
+		};
 
+		addTask('set up extra debug logging', () => {
 			reg.logger().info('app.start: doing regular boot');
-
 			const dir: string = Setting.value('profileDir');
 
 			syncDebugLog.enabled = false;
@@ -444,23 +435,34 @@ class Application extends BaseApplication {
 				syncDebugLog.enabled = true;
 				syncDebugLog.info(`Profile dir: ${dir}`);
 			}
+		});
 
-		this.setupAutoUpdaterService();
-
-		AlarmService.setDriver(new AlarmServiceDriverNode({ appName: packageInfo.build.appId }));
-		AlarmService.setLogger(reg.logger());
-
+		addTask('set up registry', () => {
 			reg.setDispatch(this.dispatch.bind(this));
 			reg.setShowErrorMessageBoxHandler((message: string) => { bridge().showErrorMessageBox(message); });
+		});
+
+		addTask('set up auto updater', () => {
+			this.setupAutoUpdaterService();
+		});
+
+		addTask('set up AlarmService', () => {
+			AlarmService.setDriver(new AlarmServiceDriverNode({ appName: packageInfo.build.appId }));
+			AlarmService.setLogger(reg.logger());
+		});
 
 		if (Setting.value('flagOpenDevTools')) {
+			addTask('openDevTools', () => {
 				bridge().openDevTools();
+			});
 		}
 
+		addTask('set up custom protocol handler', async () => {
 			this.protocolHandler_ = bridge().electronApp().getCustomProtocolHandler();
 			this.protocolHandler_.allowReadAccessToDirectory(__dirname); // App bundle directory
 			this.protocolHandler_.allowReadAccessToDirectory(Setting.value('cacheDir'));
 			this.protocolHandler_.allowReadAccessToDirectory(Setting.value('resourceDir'));
+		});
 		// this.protocolHandler_.allowReadAccessTo(Setting.value('tempDir'));
 		// For now, this doesn't seem necessary:
 		//  this.protocolHandler_.allowReadAccessTo(Setting.value('profileDir'));
@@ -468,14 +470,13 @@ class Application extends BaseApplication {
 		// handler, and, as such, it may make sense to also limit permissions of
 		// allowed pages with a Content Security Policy.
 
+		addTask('initialize PluginManager, redux, CommandService, and KeymapService', async () => {
 			PluginManager.instance().dispatch_ = this.dispatch.bind(this);
 			PluginManager.instance().setLogger(reg.logger());
 			PluginManager.instance().register(pluginClasses);
 
 			this.initRedux();
 
-		PerFolderSortOrderService.initialize();
-
 			initializeCommandService(this.store(), Setting.value('env') === 'dev');
 
 			const keymapService = KeymapService.instance();
@@ -484,28 +485,37 @@ class Application extends BaseApplication {
 			keymapService.initialize(menuCommandNames());
 
 			try {
-			await keymapService.loadCustomKeymap(`${dir}/keymap-desktop.json`);
+				await keymapService.loadCustomKeymap(`${Setting.value('profileDir')}/keymap-desktop.json`);
 			} catch (error) {
 				reg.logger().error(error);
 			}
+		});
 
+		addTask('initialize PerFolderSortOrderService', () => {
+			PerFolderSortOrderService.initialize();
+		});
+
+		addTask('dispatch initial settings', () => {
 			// Since the settings need to be loaded before the store is
 			// created, it will never receive the SETTING_UPDATE_ALL even,
 			// which mean state.settings will not be initialised. So we
 			// manually call dispatchUpdateAll() to force an update.
 			Setting.dispatchUpdateAll();
+		});
 
-		// eslint-disable-next-line @typescript-eslint/no-explicit-any -- Old code before rule was applied
-		await refreshFolders((action: any) => this.dispatch(action), '');
+		addTask('update folders and tags', async () => {
+			await refreshFolders((action) => this.dispatch(action), '');
 
 			const tags = await Tag.allWithNotes();
-
 			this.dispatch({
 				type: 'TAG_UPDATE_ALL',
 				items: tags,
 			});
+		});
 
+		addTask('set up custom CSS', async () => {
 			await this.setupCustomCss();
+		});
 
 		// const masterKeys = await MasterKey.all();
 
@@ -514,6 +524,7 @@ class Application extends BaseApplication {
 		// 	items: masterKeys,
 		// });
 
+		addTask('send initial selection to redux', async () => {
 			const getNotesParent = async () => {
 				let notesParent = parseNotesParent(Setting.value('notesParent'), Setting.value('activeFolderId'));
 				if (notesParent.type === 'Tag' && !(await Tag.load(notesParent.selectedItemId))) {
@@ -526,7 +537,6 @@ class Application extends BaseApplication {
 			};
 
 			const notesParent = await getNotesParent();
-
 			if (notesParent.type === 'SmartFilter') {
 				this.store().dispatch({
 					type: 'SMART_FILTER_SELECT',
@@ -553,7 +563,24 @@ class Application extends BaseApplication {
 				type: 'NOTE_DEVTOOLS_SET',
 				value: Setting.value('flagOpenDevTools'),
 			});
+		});
 
+		addTask('initializeUserFetcher', async () => {
+			initializeUserFetcher();
+			shim.setInterval(() => { void userFetcher(); }, 1000 * 60 * 60);
+		});
+
+		addTask('updateTray', () => this.updateTray());
+
+		addTask('set main window state', () => {
+			if (Setting.value('startMinimized') && Setting.value('showTrayIcon')) {
+				bridge().mainWindow().hide();
+			} else {
+				bridge().mainWindow().show();
+			}
+		});
+
+		addTask('start maintenance tasks', () => {
 			// Always disable on Mac for now - and disable too for the few apps that may have the flag enabled.
 			// At present, it only seems to work on Windows.
 			if (shim.isMac()) {
@@ -578,21 +605,9 @@ class Application extends BaseApplication {
 				}
 			}
 
-		initializeUserFetcher();
-		shim.setInterval(() => { void userFetcher(); }, 1000 * 60 * 60);
-
-		this.updateTray();
-
 			shim.setTimeout(() => {
 				void AlarmService.garbageCollect();
 			}, 1000 * 60 * 60);
-
-		if (Setting.value('startMinimized') && Setting.value('showTrayIcon')) {
-			bridge().mainWindow().hide();
-		} else {
-			bridge().mainWindow().show();
-		}
-
 			void ShareService.instance().maintenance();
 
 			ResourceService.runInBackground();
@@ -610,6 +625,11 @@ class Application extends BaseApplication {
 				});
 			}
 
+			RevisionService.instance().runInBackground();
+			this.startRotatingLogMaintenance(Setting.value('profileDir'));
+		});
+
+		addTask('set up ClipperServer', () => {
 			const clipperLogger = new Logger();
 			clipperLogger.addTarget(TargetType.File, { path: `${Setting.value('profileDir')}/log-clipper.txt` });
 			clipperLogger.addTarget(TargetType.Console);
@@ -622,7 +642,9 @@ class Application extends BaseApplication {
 			if (ClipperServer.instance().enabled() && Setting.value('clipperServer.autoStart')) {
 				void ClipperServer.instance().start();
 			}
+		});
 
+		addTask('set up external edit watchers', () => {
 			ExternalEditWatcher.instance().setLogger(reg.logger());
 			ExternalEditWatcher.instance().initialize(bridge, this.store().dispatch);
 
@@ -640,11 +662,11 @@ class Application extends BaseApplication {
 			ResourceEditWatcher.instance().on('resourceChange', (event: any) => {
 				eventManager.emit(EventName.ResourceChange, event);
 			});
-
-		RevisionService.instance().runInBackground();
+		});
 
 		// Make it available to the console window - useful to call revisionService.collectRevisions()
 		if (Setting.value('env') === 'dev') {
+			addTask('add debug variables', () => {
 				// eslint-disable-next-line @typescript-eslint/no-explicit-any -- Old code before rule was applied
 				(window as any).joplin = {
 					revisionService: RevisionService.instance(),
@@ -658,8 +680,10 @@ class Application extends BaseApplication {
 					searchEngine: SearchEngine.instance(),
 					ocrService: () => this.ocrService_,
 				};
+			});
 		}
 
+		addTask('listen for main process events', () => {
 			bridge().addEventListener('nativeThemeUpdated', this.bridge_nativeThemeUpdated);
 			bridge().setOnAllowedExtensionsChangeListener((newExtensions) => {
 				Setting.setValue('linking.extraAllowedExtensions', newExtensions);
@@ -675,17 +699,19 @@ class Application extends BaseApplication {
 					});
 				}
 			});
+		});
 
-		await this.initPluginService();
+		addTask('initPluginService', () => this.initPluginService());
 
+		addTask('setupContextMenu', () => {
 			this.setupContextMenu();
+		});
 
+		addTask('set up SpellCheckerService', async () => {
 			await SpellCheckerService.instance().initialize(new SpellCheckerServiceDriverNative());
+		});
 
-		this.startRotatingLogMaintenance(Setting.value('profileDir'));
-
-		await this.setupOcrService();
-
+		addTask('listen for resource events', () => {
 			eventManager.on(EventName.OcrServiceResourcesProcessed, async () => {
 				await ResourceService.instance().indexNoteResources();
 			});
@@ -693,9 +719,42 @@ class Application extends BaseApplication {
 			eventManager.on(EventName.NoteResourceIndexed, async () => {
 				SearchEngine.instance().scheduleSyncTables();
 			});
+		});
+
+		addTask('setupOcrService', () => this.setupOcrService());
+
+		return tasks;
+	}
+
+	// eslint-disable-next-line @typescript-eslint/no-explicit-any -- Old code before rule was applied
+	public async start(argv: string[], startOptions: StartOptions = null): Promise<any> {
+		const startupTask = perfLogger.taskStart('start');
+
+		// If running inside a package, the command line, instead of being "node.exe <path> <flags>" is "joplin.exe <flags>" so
+		// insert an extra argument so that they can be processed in a consistent way everywhere.
+		if (!bridge().electronIsDev()) argv.splice(1, 0, '.');
+
+
+		argv = await super.start(argv, startOptions);
+
+		await this.setupIntegrationTestUtils();
+
+		bridge().setLogFilePath(Logger.globalLogger.logFilePath());
+		await this.applySettingsSideEffects();
+
+		if (Setting.value('sync.upgradeState') === Setting.SYNC_UPGRADE_STATE_MUST_DO) {
+			reg.logger().info('app.start: doing upgradeSyncTarget action');
+			bridge().mainWindow().show();
+			startupTask.onEnd();
+
+			return { action: 'upgradeSyncTarget' };
+		}
+
+		const startupTasks = this.buildStartupTasks_();
+		for (const task of startupTasks) {
+			await perfLogger.track(task.label, async () => task.task());
+		}
 
-		// Used by tests
-		ipcRenderer.send('startup-finished');
 
 		// setTimeout(() => {
 		// 	void populateDatabase(reg.db(), {
@@ -749,6 +808,10 @@ class Application extends BaseApplication {
 
 		// await runIntegrationTests();
 
+		// Used by tests
+		ipcRenderer.send('startup-finished');
+
+		startupTask.onEnd();
 		return null;
 	}
 

packages/app-desktop/main-html.ts

@@ -31,6 +31,7 @@ import FileApiDriverLocal from '@joplin/lib/file-api-driver-local';
 import * as React from 'react';
 import nodeSqlite = require('sqlite3');
 import initLib from '@joplin/lib/initLib';
+import PerformanceLogger from '@joplin/lib/PerformanceLogger';
 const pdfJs = require('pdfjs-dist');
 const { isAppleSilicon } = require('is-apple-silicon');
 require('@sentry/electron/renderer');
@@ -38,6 +39,8 @@ require('@sentry/electron/renderer');
 // Allows components to use React as a global
 window.React = React;
 
+const perfLogger = PerformanceLogger.create('main-html');
+
 
 const main = async () => {
 	// eslint-disable-next-line no-console
@@ -106,7 +109,7 @@ const main = async () => {
 	}
 };
 
-main().catch((error) => {
+perfLogger.track('main', main).catch((error) => {
 	const env = bridge().env();
 	console.error(error);
 

packages/lib/PerformanceLogger.ts

@@ -125,10 +125,12 @@ export default class PerformanceLogger {
 		}
 
 		const startTime = performance.now();
+		this.lastLogTime_ = startTime;
 		PerformanceLogger.logDebug_(`${name}: Start at ${formatAbsoluteTime(startTime)}`);
 
 		const onEnd = () => {
 			const now = performance.now();
+			this.lastLogTime_ = now;
 			if (hasPerformanceMarkApi) {
 				performance.mark(`${name}-end`);
 				performance.measure(name, `${name}-start`, `${name}-end`);

packages/lib/services/ResourceService.ts

@@ -11,8 +11,11 @@ import ItemChangeUtils from './ItemChangeUtils';
 import time from '../time';
 import eventManager, { EventName } from '../eventManager';
 import { ItemChangeEntity } from './database/types';
+import PerformanceLogger from '../PerformanceLogger';
 const { sprintf } = require('sprintf-js');
 
+const perfLogger = PerformanceLogger.create('ResourceService');
+
 export default class ResourceService extends BaseService {
 
 	public static isRunningInBackground_ = false;
@@ -34,6 +37,7 @@ export default class ResourceService extends BaseService {
 		}
 
 		this.isIndexing_ = true;
+		const task = perfLogger.taskStart('indexNoteResources');
 
 		try {
 			await ItemChange.waitForAllSaved();
@@ -110,6 +114,7 @@ export default class ResourceService extends BaseService {
 		}
 
 		this.isIndexing_ = false;
+		task.onEnd();
 
 		eventManager.emit(EventName.NoteResourceIndexed);
 
@@ -123,6 +128,8 @@ export default class ResourceService extends BaseService {
 
 	public async deleteOrphanResources(expiryDelay: number = null) {
 		if (expiryDelay === null) expiryDelay = Setting.value('revisionService.ttlDays') * 24 * 60 * 60 * 1000;
+		const task = perfLogger.taskStart('deleteOrphanResources');
+
 		const resourceIds = await NoteResource.orphanResources(expiryDelay);
 		this.logger().info('ResourceService::deleteOrphanResources:', resourceIds);
 		for (let i = 0; i < resourceIds.length; i++) {
@@ -138,6 +145,8 @@ export default class ResourceService extends BaseService {
 				await Resource.delete(resourceId, { sourceDescription: 'deleteOrphanResources' });
 			}
 		}
+
+		task.onEnd();
 	}
 
 	private static async autoSetFileSize(resourceId: string, filePath: string, waitTillExists = true) {

packages/lib/services/share/ShareService.ts

@@ -14,8 +14,10 @@ import { getMasterPassword } from '../e2ee/utils';
 import ResourceService from '../ResourceService';
 import { addMasterKey, getEncryptionEnabled, localSyncInfo } from '../synchronizer/syncInfoUtils';
 import { ShareInvitation, SharePermissions, State, stateRootKey, StateShare } from './reducer';
+import PerformanceLogger from '../../PerformanceLogger';
 
 const logger = Logger.create('ShareService');
+const perfLogger = PerformanceLogger.create('ShareService');
 
 export interface ApiShare {
 	id: string;
@@ -514,6 +516,7 @@ export default class ShareService {
 	}
 
 	public async maintenance() {
+		const task = perfLogger.taskStart('maintenance');
 		if (this.enabled) {
 			let hasError = false;
 
@@ -537,6 +540,7 @@ export default class ShareService {
 			// so we can run the clean up function.
 			if (!hasError) await this.updateNoLongerSharedItems();
 		}
+		task.onEnd();
 	}
 
 }