chore(profiling): install time

src/compile/index.js

@@ -6,6 +6,7 @@ const path = require('path')
 const transformDependencies = require('./transform-dependencies')
 const installDependencies = require('./install-dependencies')
 const detectDependencies = require('./detect-dependencies')
+const timeSpan = require('@kikobeats/time-span')()
 const { debug, duration } = require('../debug')
 const template = require('../template')
 const build = require('./build')
@@ -26,22 +27,27 @@ const enqueueInstall = (tmpdir, dependencies, allow) => {
 
 module.exports = async (snippet, { tmpdir = DEFAULT_TMPDIR, allow = {} } = {}) => {
   let content = template(snippet)
+  const phases = { install: 0 }
 
   const dependencies = detectDependencies(content)
   if (dependencies.length) {
     content = transformDependencies(content)
     mkdirSync(tmpdir, { recursive: true })
+    const elapsed = timeSpan()
     await duration('npm:install', () => enqueueInstall(tmpdir, dependencies, allow), {
       dependencies
     })
+    phases.install = elapsed()
   }
 
   const cwd = dependencies.length ? tmpdir : process.cwd()
+  const elapsed = timeSpan()
   const result = await duration('esbuild', () => build({ content, cwd }))
+  phases.build = elapsed()
   debug('esbuild:output', { content: result.outputFiles[0].text.length })
   content = result.outputFiles[0].text
 
-  return content
+  return { content, phases }
 }
 
 module.exports.DEFAULT_TMPDIR = DEFAULT_TMPDIR

src/index.js

@@ -47,9 +47,9 @@ module.exports = ({ tmpdir } = {}) => {
       let total
       try {
         total = timeSpan()
-        const content = await compilePromise
-        const compileMs = total()
+        const compiled = await compilePromise
 
+        const spawnElapsed = timeSpan()
         const subprocess = spawn({
           args: JSON.stringify(args),
           env: {
@@ -59,27 +59,21 @@ module.exports = ({ tmpdir } = {}) => {
           timeout
         })
         subprocess.stdin.on('error', () => {})
-        Readable.from(content).pipe(subprocess.stdin)
+        Readable.from(compiled.content).pipe(subprocess.stdin)
         const { stdout } = await subprocess
+        const spawnMs = spawnElapsed()
         const { isFulfilled, value, profiling, logging } = JSON.parse(stdout)
-        const totalMs = total()
         const { run, ...rest } = profiling
         const result = {
           ...rest,
           phases: {
-            compile: compileMs,
-            spawn: totalMs - compileMs - run,
+            ...compiled.phases,
+            spawn: spawnMs - run,
             run,
-            total: totalMs
+            total: total()
           }
         }
-        debug('node', {
-          cpu: `${Math.round(result.cpu)}ms`,
-          memory: `${Math.round(result.memory / (1024 * 1024))}MiB`,
-          phases: `compile=${Math.round(result.phases.compile)}ms spawn=${Math.round(
-            result.phases.spawn
-          )}ms run=${Math.round(result.phases.run)}ms total=${Math.round(result.phases.total)}ms`
-        })
+        debug('node', { cpu: result.cpu, memory: result.memory, ...result.phases })
 
         return isFulfilled
           ? { isFulfilled, value, profiling: result, logging }

test/index.js

@@ -122,7 +122,8 @@ test('memory profiling', async t => {
   t.is(value, undefined)
   t.is(typeof profiling.cpu, 'number')
   t.is(typeof profiling.memory, 'number')
-  t.is(typeof profiling.phases.compile, 'number')
+  t.is(typeof profiling.phases.install, 'number')
+  t.is(typeof profiling.phases.build, 'number')
   t.is(typeof profiling.phases.spawn, 'number')
   t.is(typeof profiling.phases.run, 'number')
   t.is(typeof profiling.phases.total, 'number')