add telemetry and log for build and provisioning step times

packages/core/src/commands/build.ts

@@ -7,6 +7,8 @@ import { Logger } from '../log'
 import { BuildSpec, generateBuild } from '../build'
 import { gitContext } from '../git'
 import { childProcessPromise } from '../child-process'
+import { telemetryEmitter } from '../telemetry'
+import { measureTime } from '../timing'
 
 const buildCommand = async ({
   log,
@@ -43,7 +45,12 @@ const buildCommand = async ({
   ]
 
   log.info(`Running: docker ${dockerArgs.join(' ')}`)
-  await childProcessPromise(spawn('docker', dockerArgs, { stdio: 'inherit', cwd, env }))
+  const { elapsedTimeSec } = await measureTime(() => childProcessPromise(spawn('docker', dockerArgs, { stdio: 'inherit', cwd, env })))
+  telemetryEmitter().capture('build success', {
+    elapsed_sec: elapsedTimeSec,
+    has_registry: Boolean(buildSpec.registry),
+  })
+  log.info(`Elapsed time for build step: ${elapsedTimeSec.toLocaleString(undefined, { maximumFractionDigits: 2 })} sec`)
 
   return { buildModel, deployModel }
 }

packages/core/src/commands/up.ts

@@ -12,6 +12,8 @@ import { BuildSpec } from '../build'
 import modelCommand from './model'
 import buildCommand from './build'
 import { CommandExecuter } from '../command-executer'
+import { telemetryEmitter } from '../telemetry'
+import { measureTime } from '../timing'
 
 const uploadFiles = async ({
   log,
@@ -143,7 +145,14 @@ const up = async ({
   log.info(`Running: docker compose up ${composeArgs.join(' ')}`)
 
   await using dockerContext = await dockerEnvContext({ connection, log })
-  await compose.spawnPromise(composeArgs, { stdio: 'inherit', env: dockerContext.env })
+
+  const { elapsedTimeSec } = await measureTime(() => compose.spawnPromise(composeArgs, { stdio: 'inherit', env: dockerContext.env }))
+  telemetryEmitter().capture('provisioning success', {
+    elapsed_sec: elapsedTimeSec,
+    with_build: Boolean(buildSpec),
+    has_registry: Boolean(buildSpec?.registry),
+  })
+  log.info(`Elapsed time for provisioning step: ${elapsedTimeSec.toLocaleString(undefined, { maximumFractionDigits: 2 })} sec`)
 
   return { composeModel, projectLocalDataDir }
 }

packages/core/src/timing.ts

@@ -0,0 +1,6 @@
+export const measureTime = async <T>(f: () => Promise<T>) => {
+  const startTime = Date.now()
+  const result = await f()
+  const elapsedTimeSec = (new Date().getTime() - startTime) / 1000
+  return { result, elapsedTimeSec }
+}