From 1f5cd552722154043f05309a8b26050ef44fa1aa Mon Sep 17 00:00:00 2001 From: antelle Date: Sun, 29 Mar 2020 10:59:40 +0200 Subject: [PATCH] app startup time profiling --- app/scripts/comp/app/start-profiler.js | 18 +++++- .../comp/launcher/launcher-electron.js | 2 + desktop/app.js | 62 ++++++++++++++++++- desktop/main.js | 16 +++++ release-notes.md | 1 + 5 files changed, 96 insertions(+), 3 deletions(-) diff --git a/app/scripts/comp/app/start-profiler.js b/app/scripts/comp/app/start-profiler.js index 4b0a6d09..24403348 100644 --- a/app/scripts/comp/app/start-profiler.js +++ b/app/scripts/comp/app/start-profiler.js @@ -20,8 +20,22 @@ const StartProfiler = { report() { const time = Math.round(performance.now()); - const details = operations.map(op => `${op.name}: ${Math.round(op.elapsed)}ms`).join(', '); - logger.info(`Started in ${time}ms. Details: ${details}`); + const details = operations.map(op => `${op.name}=${Math.round(op.elapsed)}ms`).join(', '); + let message = `Started in ${time}ms: ${details}.`; + + if (this.appProfile) { + message += ` Electron app started in ${this.appProfile.totalTime}ms: `; + message += + this.appProfile.timings + .map(op => `${op.name}=${Math.round(op.elapsed)}ms`) + .join(', ') + '.'; + } + + logger.info(message); + }, + + reportAppProfile(data) { + this.appProfile = data; } }; diff --git a/app/scripts/comp/launcher/launcher-electron.js b/app/scripts/comp/launcher/launcher-electron.js index 6d00aa7d..b4b58950 100644 --- a/app/scripts/comp/launcher/launcher-electron.js +++ b/app/scripts/comp/launcher/launcher-electron.js @@ -1,4 +1,5 @@ import { Events } from 'framework/events'; +import { StartProfiler } from 'comp/app/start-profiler'; import { RuntimeInfo } from 'const/runtime-info'; import { Locale } from 'util/locale'; import { Logger } from 'util/logger'; @@ -295,6 +296,7 @@ Events.on('launcher-exit-request', () => { }); Events.on('launcher-minimize', () => setTimeout(() => Events.emit('app-minimized'), 0)); Events.on('launcher-started-minimized', () => setTimeout(() => Launcher.minimizeApp(), 0)); +Events.on('start-profile', data => StartProfiler.reportAppProfile(data)); window.launcherOpen = file => Launcher.openFile(file); if (window.launcherOpenedFile) { diff --git a/desktop/app.js b/desktop/app.js index 374450ac..fa00422f 100644 --- a/desktop/app.js +++ b/desktop/app.js @@ -2,6 +2,9 @@ const electron = require('electron'); const path = require('path'); const fs = require('fs'); +let perfTimestamps = global.perfTimestamps; +perfTimestamps.push({ name: 'loading app requires', ts: process.hrtime() }); + const app = electron.app; let mainWindow = null; @@ -17,6 +20,8 @@ if (!gotTheLock) { app.quit(); } +perfTimestamps && perfTimestamps.push({ name: 'single instance lock', ts: process.hrtime() }); + let openFile = process.argv.filter(arg => /\.kdbx$/i.test(arg))[0]; const userDataDir = process.env.KEEWEB_PORTABLE_EXECUTABLE_DIR || @@ -51,7 +56,7 @@ const themeBgColors = { }; const defaultBgColor = '#282C34'; -app.setPath('userData', path.join(tempUserDataPath, tempUserDataPathRand)); +perfTimestamps && perfTimestamps.push({ name: 'defining args', ts: process.hrtime() }); setEnv(); restorePreferences(); @@ -69,6 +74,7 @@ app.on('window-all-closed', () => { } }); app.on('ready', () => { + perfTimestamps && perfTimestamps.push({ name: 'app on ready', ts: process.hrtime() }); appReady = true; setAppOptions(); setSystemAppearance(); @@ -143,6 +149,7 @@ app.setGlobalShortcuts = setGlobalShortcuts; function setAppOptions() { app.commandLine.appendSwitch('disable-background-timer-throttling'); + perfTimestamps && perfTimestamps.push({ name: 'setting app options', ts: process.hrtime() }); } function readAppSettings() { @@ -150,6 +157,9 @@ function readAppSettings() { return JSON.parse(fs.readFileSync(appSettingsFileName, 'utf8')); } catch (e) { return null; + } finally { + perfTimestamps && + perfTimestamps.push({ name: 'reading app settings', ts: process.hrtime() }); } } @@ -159,6 +169,8 @@ function setSystemAppearance() { electron.systemPreferences.appLevelAppearance = 'dark'; } } + perfTimestamps && + perfTimestamps.push({ name: 'setting system appearance', ts: process.hrtime() }); } function createMainWindow() { @@ -180,12 +192,17 @@ function createMainWindow() { windowOptions.icon = path.join(__dirname, 'icon.png'); } mainWindow = new electron.BrowserWindow(windowOptions); + perfTimestamps && perfTimestamps.push({ name: 'creating main window', ts: process.hrtime() }); + setMenu(); + perfTimestamps && perfTimestamps.push({ name: 'setting menu', ts: process.hrtime() }); + mainWindow.loadURL(htmlPath); if (showDevToolsOnStart) { mainWindow.openDevTools({ mode: 'bottom' }); } mainWindow.once('ready-to-show', () => { + perfTimestamps && perfTimestamps.push({ name: 'main window ready', ts: process.hrtime() }); if (startMinimized) { emitRemoteEvent('launcher-started-minimized'); } else { @@ -193,6 +210,8 @@ function createMainWindow() { } ready = true; notifyOpenFile(); + perfTimestamps && perfTimestamps.push({ name: 'main window shown', ts: process.hrtime() }); + reportStartProfile(); }); mainWindow.webContents.on('context-menu', onContextMenu); mainWindow.on('resize', delaySaveMainWindowPosition); @@ -217,7 +236,12 @@ function createMainWindow() { mainWindow.on('session-end', () => { emitRemoteEvent('os-lock'); }); + perfTimestamps && + perfTimestamps.push({ name: 'configuring main window', ts: process.hrtime() }); + restoreMainWindowPosition(); + perfTimestamps && + perfTimestamps.push({ name: 'restoring main window position', ts: process.hrtime() }); } function restoreMainWindow() { @@ -434,6 +458,8 @@ function setGlobalShortcuts(appSettings) { } catch (e) {} } } + perfTimestamps && + perfTimestamps.push({ name: 'setting global shortcuts', ts: process.hrtime() }); } function subscribePowerEvents() { @@ -446,9 +472,12 @@ function subscribePowerEvents() { electron.powerMonitor.on('lock-screen', () => { emitRemoteEvent('os-lock'); }); + perfTimestamps && + perfTimestamps.push({ name: 'subscribing to power events', ts: process.hrtime() }); } function setEnv() { + app.setPath('userData', path.join(tempUserDataPath, tempUserDataPathRand)); if ( process.platform === 'linux' && ['Pantheon', 'Unity:Unity7'].indexOf(process.env.XDG_CURRENT_DESKTOP) !== -1 @@ -456,6 +485,7 @@ function setEnv() { // https://github.com/electron/electron/issues/9046 process.env.XDG_CURRENT_DESKTOP = 'Unity'; } + perfTimestamps && perfTimestamps.push({ name: 'setting env', ts: process.hrtime() }); } function restorePreferences() { @@ -487,6 +517,8 @@ function restorePreferences() { } } } + + perfTimestamps && perfTimestamps.push({ name: 'restoring preferences', ts: process.hrtime() }); } function deleteOldTempFiles() { @@ -503,6 +535,8 @@ function deleteOldTempFiles() { } app.oldTempFilesDeleted = true; // this is added to prevent file deletion on restart }, 1000); + perfTimestamps && + perfTimestamps.push({ name: 'deleting old temp files', ts: process.hrtime() }); } function deleteRecursive(dir) { @@ -528,6 +562,8 @@ function hookRequestHeaders() { } callback({ requestHeaders: details.requestHeaders }); }); + perfTimestamps && + perfTimestamps.push({ name: 'setting request handlers', ts: process.hrtime() }); } // If a display is disconnected while KeeWeb is minimized, Electron does not @@ -570,3 +606,27 @@ function coerceMainWindowPositionToConnectedDisplay() { }); updateMainWindowPosition(); } + +function reportStartProfile() { + const processCreationTime = process.getCreationTime(); + const totalTime = Math.round(Date.now() - processCreationTime); + let lastTs = 0; + const timings = perfTimestamps + .map(milestone => { + const ts = milestone.ts; + const elapsed = lastTs + ? Math.round((ts[0] - lastTs[0]) * 1e3 + (ts[1] - lastTs[1]) / 1e6) + : 0; + lastTs = ts; + return { + name: milestone.name, + elapsed + }; + }) + .slice(1); + + perfTimestamps = global.perfTimestamps = undefined; + + const startProfile = { totalTime, timings }; + emitRemoteEvent('start-profile', startProfile); +} diff --git a/desktop/main.js b/desktop/main.js index 0d81d4f6..fb95a031 100644 --- a/desktop/main.js +++ b/desktop/main.js @@ -6,31 +6,43 @@ // (C) Antelle 2019, MIT license https://github.com/keeweb/keeweb +global.perfTimestamps = [{ name: 'pre-init', ts: process.hrtime() }]; + const app = require('electron').app; const path = require('path'); const fs = require('original-fs'); +global.perfTimestamps.push({ name: 'loading main requires', ts: process.hrtime() }); + const userDataDir = app.getPath('userData'); const userDataAppArchivePath = path.join(userDataDir, 'app.asar'); let entryPointDir = __dirname; +global.perfTimestamps.push({ name: 'getting data dir', ts: process.hrtime() }); + try { const appFilePath = entryPointDir.endsWith('app.asar') ? entryPointDir : __filename; let userPackageStat; try { userPackageStat = fs.statSync(userDataAppArchivePath); } catch (e) {} + global.perfTimestamps.push({ name: 'checking for new version', ts: process.hrtime() }); + if (userPackageStat) { const packageStat = fs.statSync(appFilePath); const userPackageStatTime = Math.max( userPackageStat.mtime.getTime(), userPackageStat.ctime.getTime() ); + global.perfTimestamps.push({ name: 'getting asar file time', ts: process.hrtime() }); + const packageStatTime = Math.max(packageStat.mtime.getTime(), packageStat.ctime.getTime()); if (userPackageStatTime > packageStatTime) { let versionLocal = require('./package.json').version; let versionUserData = require(path.join(userDataAppArchivePath, 'package.json')) .version; + global.perfTimestamps.push({ name: 'getting package version', ts: process.hrtime() }); + versionLocal = versionLocal.split('.'); versionUserData = versionUserData.split('.'); for (let i = 0; i < versionLocal.length; i++) { @@ -38,6 +50,10 @@ try { entryPointDir = userDataAppArchivePath; try { validateSignature(userDataDir); + global.perfTimestamps.push({ + name: 'validating signature', + ts: process.hrtime() + }); } catch (e) { exitWithError('Error validating signatures: ' + e); } diff --git a/release-notes.md b/release-notes.md index 45c3af55..f79bc510 100644 --- a/release-notes.md +++ b/release-notes.md @@ -19,6 +19,7 @@ Release notes `+` #855: appdata file in deb packages `*` signature key rotated `*` new Windows code signing certificate +`+` startup time profiling `*` fix #890: deb will no longer install to /opt `-` fix #1396: fixed hyperlinks in notes `-` fix #1323: version in the About dialog