From f8894319e2ad28315f1e40243abad2f060e2769e Mon Sep 17 00:00:00 2001
From: Roy Razon <roy@livecycle.io>
Date: Tue, 28 Nov 2023 13:15:39 +0200
Subject: [PATCH] add telemetry and log for build and provisioning step times

---
 packages/core/src/commands/build.ts |  9 ++++++++-
 packages/core/src/commands/up.ts    | 11 ++++++++++-
 packages/core/src/timing.ts         |  6 ++++++
 3 files changed, 24 insertions(+), 2 deletions(-)
 create mode 100644 packages/core/src/timing.ts

diff --git a/packages/core/src/commands/build.ts b/packages/core/src/commands/build.ts
index 7fd6f76c..719761ef 100644
--- a/packages/core/src/commands/build.ts
+++ b/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 }
 }
diff --git a/packages/core/src/commands/up.ts b/packages/core/src/commands/up.ts
index 7e519666..ebac12c7 100644
--- a/packages/core/src/commands/up.ts
+++ b/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 }
 }
diff --git a/packages/core/src/timing.ts b/packages/core/src/timing.ts
new file mode 100644
index 00000000..1c8a62a9
--- /dev/null
+++ b/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 }
+}