diff --git a/src/ipc-handlers.ts b/src/ipc-handlers.ts index eea06e0bf..9e8947fa7 100644 --- a/src/ipc-handlers.ts +++ b/src/ipc-handlers.ts @@ -197,6 +197,9 @@ export async function createSite( blueprint?: Blueprint; } = {} ): Promise< SiteDetails > { + const perfStart = performance.now(); + console.log( '[PERF] createSite: Starting site creation' ); + const { siteName, wpVersion, customDomain, enableHttps, siteId, blueprint } = config; const forceSetupSqlite = false; @@ -206,6 +209,7 @@ export async function createSite( // We only recursively create the directory if the user has not selected a // path from the dialog (and thus they use the "default" or suggested path). + const validationStart = performance.now(); if ( ! ( await pathExists( path ) ) && path.startsWith( DEFAULT_SITE_PATH ) ) { fs.mkdirSync( path, { recursive: true } ); } @@ -222,6 +226,7 @@ export async function createSite( } const port = await portFinder.getOpenPort(); + console.log( `[PERF] createSite: Validation and port allocation took ${ ( performance.now() - validationStart ).toFixed( 2 ) }ms` ); const details = { id: siteId || crypto.randomUUID(), @@ -240,7 +245,9 @@ export async function createSite( if ( ( await pathExists( path ) ) && ( await isEmptyDir( path ) ) ) { try { + const setupStart = performance.now(); await createSiteWorkingDirectory( server, wpVersion ); + console.log( `[PERF] createSite: WordPress setup took ${ ( performance.now() - setupStart ).toFixed( 2 ) }ms` ); } catch ( error ) { // If site creation failed, remove the generated files and re-throw the // error so it can be handled by the caller. @@ -250,6 +257,7 @@ export async function createSite( } if ( isWordPressDirectory( path ) ) { + const existingWpStart = performance.now(); // If the directory contains a WordPress installation, and user wants to force SQLite // integration, let's rename the wp-config.php file to allow WP Now to create a new one // and initialize things properly. @@ -269,11 +277,13 @@ export async function createSite( } else { await updateSiteUrl( server, getSiteUrl( details ) ); } + console.log( `[PERF] createSite: Existing WordPress setup took ${ ( performance.now() - existingWpStart ).toFixed( 2 ) }ms` ); } const parentWindow = BrowserWindow.fromWebContents( event.sender ); sendIpcEventToRendererWithWindow( parentWindow, 'theme-details-updating', { id: details.id } ); try { + const saveStart = performance.now(); await lockAppdata(); userData = await loadUserData(); @@ -281,6 +291,8 @@ export async function createSite( sortSites( userData.sites ); await saveUserData( userData ); + console.log( `[PERF] createSite: Save user data took ${ ( performance.now() - saveStart ).toFixed( 2 ) }ms` ); + console.log( `[PERF] createSite: Total time ${ ( performance.now() - perfStart ).toFixed( 2 ) }ms` ); return server.details; } finally { await unlockAppdata(); diff --git a/src/lib/wordpress-provider/playground-cli/playground-cli-provider.ts b/src/lib/wordpress-provider/playground-cli/playground-cli-provider.ts index 25daafe2c..d51bdb904 100644 --- a/src/lib/wordpress-provider/playground-cli/playground-cli-provider.ts +++ b/src/lib/wordpress-provider/playground-cli/playground-cli-provider.ts @@ -141,11 +141,23 @@ export class PlaygroundCliProvider implements WordPressProvider { } async setupWordPressSite( server: SiteServer, wpVersion = 'latest' ): Promise< boolean > { + const setupStartTime = Date.now(); + console.log( '[PERF] setupWordPressSite: Starting setup' ); + const { path, name } = server.details; try { + const onlineCheckStart = Date.now(); const isOnlineStatus = await isOnline(); + console.log( + `[PERF] setupWordPressSite: Online check took ${ Date.now() - onlineCheckStart }ms` + ); + + const languageStart = Date.now(); const siteLanguage = await getPreferredSiteLanguage( wpVersion ); + console.log( + `[PERF] setupWordPressSite: getPreferredSiteLanguage took ${ Date.now() - languageStart }ms` + ); const setupSteps: StepDefinition[] = []; @@ -174,6 +186,9 @@ export class PlaygroundCliProvider implements WordPressProvider { } if ( ! isOnlineStatus ) { + console.log( + `[PERF] setupWordPressSite: Using bundled WordPress files (offline: ${ ! isOnlineStatus }, version: ${ wpVersion })` + ); if ( wpVersion !== 'latest' ) { throw new Error( `Cannot set up WordPress version '${ wpVersion }' while offline. ` + @@ -197,7 +212,11 @@ export class PlaygroundCliProvider implements WordPressProvider { } try { + const copyStartTime = Date.now(); await recursiveCopyDirectory( bundledWPPath, path ); + console.log( + `[PERF] setupWordPressSite: Copy WordPress files took ${ Date.now() - copyStartTime }ms` + ); } catch ( error ) { throw new Error( `Failed to copy WordPress files for offline setup: ${ ( error as Error ).message }` @@ -211,8 +230,17 @@ export class PlaygroundCliProvider implements WordPressProvider { const existingSteps = server.meta.blueprint.steps || []; server.meta.blueprint.steps = [ ...setupSteps, ...existingSteps ]; + const sqliteStartTime = Date.now(); await keepSqliteIntegrationUpdated( path ); + console.log( + `[PERF] setupWordPressSite: SQLite integration update took ${ + Date.now() - sqliteStartTime + }ms` + ); + console.log( + `[PERF] setupWordPressSite: Total setup time ${ Date.now() - setupStartTime }ms` + ); return true; } catch ( error ) { console.error( 'Failed to setup WordPress site:', error ); diff --git a/src/lib/wordpress-provider/playground-cli/playground-server-process-child.ts b/src/lib/wordpress-provider/playground-cli/playground-server-process-child.ts index f69035974..e2292cf0b 100644 --- a/src/lib/wordpress-provider/playground-cli/playground-server-process-child.ts +++ b/src/lib/wordpress-provider/playground-cli/playground-server-process-child.ts @@ -48,6 +48,10 @@ const originalConsoleLog = console.log; const originalConsoleError = console.error; const originalConsoleWarn = console.warn; +// Track timing for playground-cli operations +let playgroundCliStartTime: number | null = null; +let lastLogTime: number | null = null; + function formatMessageForUI( message: string ): string { if ( message.includes( 'WordPress is running on' ) ) { return 'WordPress is running'; @@ -59,7 +63,21 @@ function formatMessageForUI( message: string ): string { } console.log = ( ...args: any[] ) => { - originalConsoleLog( '[playground-cli]', ...args ); + const now = Date.now(); + + // Initialize timing on first log + if ( playgroundCliStartTime === null ) { + playgroundCliStartTime = now; + lastLogTime = now; + } + + const elapsed = now - playgroundCliStartTime; + const delta = lastLogTime !== null ? now - lastLogTime : 0; + lastLogTime = now; + + // Add timing info to the log + originalConsoleLog( `[playground-cli | total: ${ elapsed }ms | since last: ${ delta }ms]`, ...args ); + const message = args.join( ' ' ); process.parentPort.postMessage( { type: 'activity' } ); const formattedMessage = formatMessageForUI( message ); @@ -69,12 +87,30 @@ console.log = ( ...args: any[] ) => { }; console.error = ( ...args: any[] ) => { - originalConsoleError( '[playground-cli]', ...args ); + const now = Date.now(); + if ( playgroundCliStartTime === null ) { + playgroundCliStartTime = now; + lastLogTime = now; + } + const elapsed = now - playgroundCliStartTime; + const delta = lastLogTime !== null ? now - lastLogTime : 0; + lastLogTime = now; + + originalConsoleError( `[playground-cli | total: ${ elapsed }ms | since last: ${ delta }ms]`, ...args ); process.parentPort.postMessage( { type: 'activity' } ); }; console.warn = ( ...args: any[] ) => { - originalConsoleWarn( '[playground-cli]', ...args ); + const now = Date.now(); + if ( playgroundCliStartTime === null ) { + playgroundCliStartTime = now; + lastLogTime = now; + } + const elapsed = now - playgroundCliStartTime; + const delta = lastLogTime !== null ? now - lastLogTime : 0; + lastLogTime = now; + + originalConsoleWarn( `[playground-cli | total: ${ elapsed }ms | since last: ${ delta }ms]`, ...args ); process.parentPort.postMessage( { type: 'activity' } ); }; @@ -144,12 +180,17 @@ async function startServer( options: PlaygroundCliOptions, serverOptions: WordPressServerOptions ): Promise< void > { + const startServerTime = Date.now(); + console.log( '[PERF] startServer (child): Starting server' ); + if ( server ) { return; } try { + const muPluginsStart = Date.now(); const [ studioMuPluginsHostPath, loaderMuPluginHostPath ] = await getMuPlugins( serverOptions ); + console.log( `[PERF] startServer (child): getMuPlugins took ${ Date.now() - muPluginsStart }ms` ); const defaultConstants = { WP_SQLITE_AST_DRIVER: true, @@ -196,11 +237,23 @@ async function startServer( args.blueprint.constants = { ...args.blueprint.constants, ...defaultConstants }; + console.log( '[PERF] startServer (child): Calling runCLI' ); + console.log( `[PERF] startServer (child): Blueprint has ${ args.blueprint.steps?.length || 0 } steps` ); + const runCLIStart = Date.now(); server = await runCLI( args ); + console.log( `[PERF] startServer (child): runCLI took ${ Date.now() - runCLIStart }ms` ); if ( serverOptions.adminPassword ) { - await setAdminPassword( server, serverOptions.adminPassword ); + try { + const setPasswordStart = Date.now(); + await setAdminPassword( server, serverOptions.adminPassword ); + console.log( `[PERF] startServer (child): setAdminPassword took ${ Date.now() - setPasswordStart }ms` ); + } catch { + console.warn( 'Failed to set admin password, but the server started successfully. Please check your site error log in wp-content/debug.log for more details' ); + } } + + console.log( `[PERF] startServer (child): Total server start time ${ Date.now() - startServerTime }ms` ); } catch ( error ) { server = null; throw new Error( `Could not start server: ${ error }` ); diff --git a/src/lib/wordpress-provider/playground-cli/playground-server-process.ts b/src/lib/wordpress-provider/playground-cli/playground-server-process.ts index ec598d350..304d628c6 100644 --- a/src/lib/wordpress-provider/playground-cli/playground-server-process.ts +++ b/src/lib/wordpress-provider/playground-cli/playground-server-process.ts @@ -35,7 +35,11 @@ export class PlaygroundServerProcess implements WordPressServerProcess { } async start( siteId?: string ): Promise< void > { + const startTime = Date.now(); + console.log( '[PERF] PlaygroundServerProcess.start: Starting process' ); + if ( this.process ) { + console.log( '[PERF] PlaygroundServerProcess.start: Process already running, skipping' ); return; } @@ -44,12 +48,15 @@ export class PlaygroundServerProcess implements WordPressServerProcess { this.exitResolve = resolve; } ); + const forkStartTime = Date.now(); this.process = utilityProcess.fork( path.join( __dirname, 'playgroundServerProcess.js' ) ); + console.log( `[PERF] PlaygroundServerProcess.start: Fork process took ${ Date.now() - forkStartTime }ms` ); if ( siteId ) { this.siteId = siteId; } + const setupListenersStart = Date.now(); this.process.on( 'message', async ( message: { @@ -117,8 +124,10 @@ export class PlaygroundServerProcess implements WordPressServerProcess { this.exitResolve = null; } } ); + console.log( `[PERF] PlaygroundServerProcess.start: Setup listeners took ${ Date.now() - setupListenersStart }ms` ); // Wait for child process to be ready + const readyWaitStart = Date.now(); await new Promise< void >( ( resolve ) => { const readyHandler = ( message: { type?: string } ) => { if ( message.type === 'ready' ) { @@ -128,11 +137,15 @@ export class PlaygroundServerProcess implements WordPressServerProcess { }; this.process!.on( 'message', readyHandler ); } ); + console.log( `[PERF] PlaygroundServerProcess.start: Wait for ready took ${ Date.now() - readyWaitStart }ms` ); + const sendMessageStart = Date.now(); await this.sendMessage( 'start-server', { options: this.options, serverOptions: this.serverOptions, } ); + console.log( `[PERF] PlaygroundServerProcess.start: Send start-server message took ${ Date.now() - sendMessageStart }ms` ); + console.log( `[PERF] PlaygroundServerProcess.start: Total start time ${ Date.now() - startTime }ms` ); } async stop(): Promise< void > { diff --git a/src/site-server.ts b/src/site-server.ts index 8db7152a6..ab3d5257f 100644 --- a/src/site-server.ts +++ b/src/site-server.ts @@ -109,12 +109,17 @@ export class SiteServer { } async start() { + const siteStartTime = Date.now(); + console.log( `[PERF] SiteServer.start: Starting site '${ this.details.name }'` ); + if ( this.details.running || this.server ) { + console.log( '[PERF] SiteServer.start: Site already running, skipping' ); return; } // Handle custom domain if necessary if ( this.details.customDomain ) { + const domainSetupStart = Date.now(); await addDomainToHosts( this.details.customDomain, this.details.port ); // Generate certificates for HTTPS sites *before* the server starts // This ensures the certs are ready when the proxy server needs them @@ -123,7 +128,9 @@ export class SiteServer { `Generating certificates for ${ this.details.customDomain } during server start` ); + const certStart = Date.now(); const { cert, key } = await generateSiteCertificate( this.details.customDomain ); + console.log( `[PERF] SiteServer.start: Certificate generation took ${ Date.now() - certStart }ms` ); this.details = { ...this.details, tlsKey: key, @@ -131,9 +138,14 @@ export class SiteServer { }; } await startProxyServer(); + console.log( `[PERF] SiteServer.start: Domain setup took ${ Date.now() - domainSetupStart }ms` ); } + const blueprintFilterStart = Date.now(); const filteredBlueprint = filterUnsupportedBlueprintFeatures( this.meta.blueprint ); + console.log( `[PERF] SiteServer.start: Blueprint filtering took ${ Date.now() - blueprintFilterStart }ms` ); + + const startServerCallTime = Date.now(); const serverInstance = await startServer( { path: this.details.path, port: this.details.port, @@ -145,23 +157,33 @@ export class SiteServer { absoluteUrl: getAbsoluteUrl( this.details ), blueprint: filteredBlueprint, } ); + console.log( `[PERF] SiteServer.start: startServer call took ${ Date.now() - startServerCallTime }ms` ); + const portCheckStart = Date.now(); const isPortAvailable = await portFinder.isPortAvailable( this.details.port ); if ( ! isPortAvailable ) { throw new Error( `Port ${ this.details.port } is not available. error code: ERROR_PORT_IN_USE` ); } + console.log( `[PERF] SiteServer.start: Port check took ${ Date.now() - portCheckStart }ms` ); console.log( `Starting server for '${ this.details.name }'` ); + const createProcessStart = Date.now(); this.server = createServerProcess( serverInstance ); + console.log( `[PERF] SiteServer.start: createServerProcess took ${ Date.now() - createProcessStart }ms` ); + + const serverProcessStart = Date.now(); await this.server.start( this.details.id ); + console.log( `[PERF] SiteServer.start: server.start took ${ Date.now() - serverProcessStart }ms` ); if ( serverInstance.options.port === undefined ) { throw new Error( 'Server started with no port' ); } + const themeDetailsStart = Date.now(); const themeDetails = await phpGetThemeDetails( this.server ); + console.log( `[PERF] SiteServer.start: phpGetThemeDetails took ${ Date.now() - themeDetailsStart }ms` ); this.details = { ...this.details, @@ -174,6 +196,8 @@ export class SiteServer { themeDetails, }; + console.log( `[PERF] SiteServer.start: Total site start time ${ Date.now() - siteStartTime }ms` ); + if ( this.meta.blueprint ) { this.meta.blueprint = undefined; }