From 90bcdf4cbadefbb25c47bc08ea3897e1ec3b8fd5 Mon Sep 17 00:00:00 2001 From: Rafael Oleza Date: Tue, 7 May 2019 17:45:59 +0200 Subject: [PATCH] Add markers for more granular logging of startup time --- src/main-process/atom-application.js | 13 +++++++++++ src/main-process/atom-window.js | 19 ++++++++++++++++ src/main-process/main.js | 2 ++ src/main-process/start.js | 6 +++++ src/startup-time.js | 33 ++++++++++++++++++++++++++++ static/index.js | 23 ++++++++++++++++++- 6 files changed, 95 insertions(+), 1 deletion(-) create mode 100644 src/startup-time.js diff --git a/src/main-process/atom-application.js b/src/main-process/atom-application.js index d5b577775..9c23ab96c 100644 --- a/src/main-process/atom-application.js +++ b/src/main-process/atom-application.js @@ -6,6 +6,7 @@ const StorageFolder = require('../storage-folder') const Config = require('../config') const ConfigFile = require('../config-file') const FileRecoveryService = require('./file-recovery-service') +const StartupTime = require('../startup-time') const ipcHelpers = require('../ipc-helpers') const {BrowserWindow, Menu, app, clipboard, dialog, ipcMain, shell, screen} = require('electron') const {CompositeDisposable, Disposable} = require('event-kit') @@ -135,6 +136,8 @@ module.exports = class AtomApplication extends EventEmitter { // Public: The entry point into the Atom application. static open (options) { + StartupTime.addMarker('main-process:atom-application:open') + const socketSecret = getExistingSocketSecret(options.version) const socketPath = getSocketPath(socketSecret) const createApplication = options.createApplication || (async () => { @@ -172,6 +175,8 @@ class AtomApplication extends EventEmitter { } constructor (options) { + StartupTime.addMarker('main-process:atom-application:constructor:start') + super() this.quitting = false this.quittingForUpdate = false @@ -214,6 +219,8 @@ class AtomApplication extends EventEmitter { this.disposable = new CompositeDisposable() this.handleEvents() + + StartupTime.addMarker('main-process:atom-application:constructor:end') } // This stuff was previously done in the constructor, but we want to be able to construct this object @@ -221,6 +228,8 @@ class AtomApplication extends EventEmitter { // of these various sub-objects into the constructor, but you'll need to remove the side-effects they // perform during their construction, adding an initialize method that you call here. async initialize (options) { + StartupTime.addMarker('main-process:atom-application:initialize:start') + global.atomApplication = this // DEPRECATED: This can be removed at some point (added in 1.13) @@ -246,6 +255,8 @@ class AtomApplication extends EventEmitter { this.autoUpdateManager.initialize() await socketServerPromise + StartupTime.addMarker('main-process:atom-application:initialize:end') + return result } @@ -1084,6 +1095,7 @@ class AtomApplication extends EventEmitter { let openedWindow if (existingWindow) { openedWindow = existingWindow + StartupTime.addMarker('main-process:atom-application:open-in-existing') openedWindow.openLocations(locationsToOpen) if (openedWindow.isMinimized()) { openedWindow.restore() @@ -1108,6 +1120,7 @@ class AtomApplication extends EventEmitter { if (!resourcePath) resourcePath = this.resourcePath if (!windowDimensions) windowDimensions = this.getDimensionsForNewWindow() + StartupTime.addMarker('main-process:atom-application:create-window') openedWindow = this.createWindow({ locationsToOpen, windowInitializationScript, diff --git a/src/main-process/atom-window.js b/src/main-process/atom-window.js index 367fb77e4..b0ebeb5bb 100644 --- a/src/main-process/atom-window.js +++ b/src/main-process/atom-window.js @@ -2,6 +2,7 @@ const {BrowserWindow, app, dialog, ipcMain} = require('electron') const path = require('path') const url = require('url') const {EventEmitter} = require('events') +const StartupTime = require('../startup-time') const ICON_PATH = path.resolve(__dirname, '..', '..', 'resources', 'atom.png') @@ -11,6 +12,8 @@ let nextId = 0 module.exports = class AtomWindow extends EventEmitter { constructor (atomApplication, fileRecoveryService, settings = {}) { + StartupTime.addMarker('main-process:atom-window:start') + super() this.id = nextId++ @@ -78,6 +81,22 @@ class AtomWindow extends EventEmitter { .some(location => location.pathToOpen && !location.isDirectory) this.loadSettings.initialProjectRoots = this.projectRoots + StartupTime.addMarker('main-process:atom-window:end') + + // Expose the startup markers to the renderer process, so we can have unified + // measures about startup time between the main process and the renderer process. + Object.defineProperty(this.browserWindow, 'startupMarkers', { + get: () => { + // We only want to make the main process startup data available once, + // so if the window is refreshed or a new window is opened, the + // renderer process won't use it again. + const timingData = StartupTime.exportData() + StartupTime.deleteData() + + return timingData + } + }) + // Only send to the first non-spec window created if (includeShellLoadTime && !this.isSpec) { includeShellLoadTime = false diff --git a/src/main-process/main.js b/src/main-process/main.js index beb93f091..fac0c0617 100644 --- a/src/main-process/main.js +++ b/src/main-process/main.js @@ -3,6 +3,8 @@ if (typeof snapshotResult !== 'undefined') { } const startTime = Date.now() +const StartupTime = require('../startup-time') +StartupTime.setStartTime() const path = require('path') const fs = require('fs-plus') diff --git a/src/main-process/start.js b/src/main-process/start.js index 7fddf37ec..d5c1bfd0e 100644 --- a/src/main-process/start.js +++ b/src/main-process/start.js @@ -8,9 +8,13 @@ const atomPaths = require('../atom-paths') const fs = require('fs') const CSON = require('season') const Config = require('../config') +const StartupTime = require('../startup-time') + +StartupTime.setStartTime() module.exports = function start (resourcePath, devResourcePath, startTime) { global.shellStartTime = startTime + StartupTime.addMarker('main-process:start') process.on('uncaughtException', function (error = {}) { if (error.message != null) { @@ -85,7 +89,9 @@ module.exports = function start (resourcePath, devResourcePath, startTime) { app.setPath('userData', temp.mkdirSync('atom-test-data')) } + StartupTime.addMarker('main-process:electron-onready:start') app.on('ready', function () { + StartupTime.addMarker('main-process:electron-onready:end') app.removeListener('open-file', addPathToOpen) app.removeListener('open-url', addUrlToOpen) const AtomApplication = require(path.join(args.resourcePath, 'src', 'main-process', 'atom-application')) diff --git a/src/startup-time.js b/src/startup-time.js new file mode 100644 index 000000000..4e31c3cc0 --- /dev/null +++ b/src/startup-time.js @@ -0,0 +1,33 @@ +let startTime +let markers = [] + +module.exports = { + setStartTime () { + if (!startTime) { + startTime = Date.now() + } + }, + addMarker (label, dateTime) { + if (!startTime) { + return + } + + dateTime = dateTime || Date.now() + markers.push({label, time: dateTime - startTime}) + }, + importData (data) { + startTime = data.startTime + markers = data.markers + }, + exportData () { + if (!startTime) { + return undefined + } + + return { startTime, markers } + }, + deleteData () { + startTime = undefined + markers = [] + } +} diff --git a/static/index.js b/static/index.js index 7a7513683..118fcf3d8 100644 --- a/static/index.js +++ b/static/index.js @@ -3,16 +3,29 @@ // when using `NativeCompileCache` for the first time. require('cached-run-in-this-context') + // Define the window start time before the requires so we get a more accurate + // window:start marker. + const startWindowTime = Date.now() + const electron = require('electron') const path = require('path') const Module = require('module') const getWindowLoadSettings = require('../src/get-window-load-settings') + const StartupTime = require('../src/startup-time') const entryPointDirPath = __dirname let blobStore = null let useSnapshot = false + const startupMarkers = electron.remote.getCurrentWindow().startupMarkers + + if (startupMarkers) { + StartupTime.importData(startupMarkers) + } + StartupTime.addMarker('window:start', startWindowTime) + window.onload = function () { try { + StartupTime.addMarker('window:onload:start') const startTime = Date.now() process.on('unhandledRejection', function (error, promise) { @@ -64,12 +77,16 @@ if (getWindowLoadSettings().profileStartup) { profileStartup(Date.now() - startTime) } else { - setupWindow() + StartupTime.addMarker('window:setup-window:start') + setupWindow().then(() => { + StartupTime.addMarker('window:setup-window:end') + }) setLoadTime(Date.now() - startTime) } } catch (error) { handleSetupError(error) } + StartupTime.addMarker('window:onload:end') } function setLoadTime (loadTime) { @@ -103,7 +120,11 @@ const initScriptPath = path.relative(entryPointDirPath, getWindowLoadSettings().windowInitializationScript) const initialize = useSnapshot ? snapshotResult.customRequire(initScriptPath) : require(initScriptPath) + + StartupTime.addMarker('window:initialize:start') + return initialize({blobStore: blobStore}).then(function () { + StartupTime.addMarker('window:initialize:end') electron.ipcRenderer.send('window-command', 'window:loaded') }) }