feat: show execution time (#5468)

close #1021

.changeset/silly-peas-think.md

@@ -0,0 +1,7 @@
+---
+"@pnpm/core-loggers": minor
+"@pnpm/default-reporter": minor
+"pnpm": patch
+---
+
+Show execution time on `install`, `update`, `add`, and `remove` [#1021](https://github.com/pnpm/pnpm/issues/1021).

packages/core-loggers/src/all.ts

@@ -19,3 +19,4 @@ export * from './stageLogger'
 export * from './statsLogger'
 export * from './summaryLogger'
 export * from './updateCheckLogger'
+export * from './executionTimeLogger'

packages/core-loggers/src/executionTimeLogger.ts

@@ -0,0 +1,12 @@
+import baseLogger, {
+  LogBase,
+} from '@pnpm/logger'
+
+export const executionTimeLogger = baseLogger('execution-time')
+
+export interface ExecutionTimeMessage {
+  startedAt: number
+  endedAt: number
+}
+
+export type ExecutionTimeLog = { name: 'pnpm:execution-time' } & LogBase & ExecutionTimeMessage

packages/core-loggers/src/index.ts

@@ -2,6 +2,7 @@ import {
   ContextLog,
   DeprecationLog,
   FetchingProgressLog,
+  ExecutionTimeLog,
   HookLog,
   InstallCheckLog,
   LifecycleLog,
@@ -27,6 +28,7 @@ export type Log =
   | ContextLog
   | DeprecationLog
   | FetchingProgressLog
+  | ExecutionTimeLog
   | HookLog
   | InstallCheckLog
   | LifecycleLog

packages/default-reporter/src/index.ts

@@ -101,6 +101,7 @@ export function toOutput$ (
   opts = opts || {}
   const contextPushStream = new Rx.Subject<logs.ContextLog>()
   const fetchingProgressPushStream = new Rx.Subject<logs.FetchingProgressLog>()
+  const executionTimePushStream = new Rx.Subject<logs.ExecutionTimeLog>()
   const progressPushStream = new Rx.Subject<logs.ProgressLog>()
   const stagePushStream = new Rx.Subject<logs.StageLog>()
   const deprecationPushStream = new Rx.Subject<logs.DeprecationLog>()
@@ -126,6 +127,9 @@ export function toOutput$ (
       case 'pnpm:context':
         contextPushStream.next(log)
         break
+      case 'pnpm:execution-time':
+        executionTimePushStream.next(log)
+        break
       case 'pnpm:fetching-progress':
         fetchingProgressPushStream.next(log)
         break
@@ -204,6 +208,7 @@ export function toOutput$ (
     context: Rx.from(contextPushStream),
     deprecation: Rx.from(deprecationPushStream),
     fetchingProgress: Rx.from(fetchingProgressPushStream),
+    executionTime: Rx.from(executionTimePushStream),
     hook: Rx.from(hookPushStream),
     installCheck: Rx.from(installCheckPushStream),
     lifecycle: Rx.from(lifecyclePushStream),

packages/default-reporter/src/reporterForClient/index.ts

@@ -5,6 +5,7 @@ import * as Rx from 'rxjs'
 import { throttleTime } from 'rxjs/operators'
 import reportBigTarballsProgress from './reportBigTarballsProgress'
 import reportContext from './reportContext'
+import { reportExecutionTime } from './reportExecutionTime'
 import reportDeprecations from './reportDeprecations'
 import reportHooks from './reportHooks'
 import reportInstallChecks from './reportInstallChecks'
@@ -19,10 +20,18 @@ import reportStats from './reportStats'
 import reportSummary from './reportSummary'
 import reportUpdateCheck from './reportUpdateCheck'
 
+const PRINT_EXECUTION_TIME_IN_COMMANDS = {
+  install: true,
+  update: true,
+  add: true,
+  remove: true,
+}
+
 export default function (
   log$: {
     context: Rx.Observable<logs.ContextLog>
     fetchingProgress: Rx.Observable<logs.FetchingProgressLog>
+    executionTime: Rx.Observable<logs.ExecutionTimeLog>
     progress: Rx.Observable<logs.ProgressLog>
     stage: Rx.Observable<logs.StageLog>
     deprecation: Rx.Observable<logs.DeprecationLog>
@@ -88,6 +97,10 @@ export default function (
     reportUpdateCheck(log$.updateCheck, opts),
   ]
 
+  if (PRINT_EXECUTION_TIME_IN_COMMANDS[opts.cmd]) {
+    outputs.push(reportExecutionTime(log$.executionTime))
+  }
+
   // logLevelNumber: 0123 = error warn info debug
   const logLevelNumber = LOG_LEVEL_NUMBER[opts.logLevel ?? 'info'] ?? LOG_LEVEL_NUMBER['info']
 

packages/default-reporter/src/reporterForClient/reportExecutionTime.ts

@@ -0,0 +1,18 @@
+import prettyMs from 'pretty-ms'
+import { ExecutionTimeLog } from '@pnpm/core-loggers'
+import * as Rx from 'rxjs'
+import { map, take } from 'rxjs/operators'
+
+export function reportExecutionTime (
+  executionTime$: Rx.Observable<ExecutionTimeLog>
+) {
+  return executionTime$.pipe(
+    take(1),
+    map((log) => {
+      return Rx.of({
+        fixed: true, // Without this, for some reason sometimes the progress bar is printed after the execution time
+        msg: `Done in ${prettyMs(log.endedAt - log.startedAt)}`,
+      })
+    })
+  )
+}

packages/default-reporter/test/reportingExecutionTime.ts

@@ -0,0 +1,55 @@
+import { executionTimeLogger } from '@pnpm/core-loggers'
+import { toOutput$ } from '@pnpm/default-reporter'
+import { createStreamParser } from '@pnpm/logger'
+import { take } from 'rxjs/operators'
+
+test('does not print execution time for help command', (done) => {
+  const output$ = toOutput$({
+    context: {
+      argv: ['help'],
+    },
+    streamParser: createStreamParser(),
+  })
+
+  executionTimeLogger.debug({
+    startedAt: 1665279402859,
+    endedAt: 1665279413671,
+  })
+
+  const subscription = output$.subscribe({
+    complete: () => done(),
+    error: done,
+    next: () => {
+      done('should not log anything')
+    },
+  })
+
+  setTimeout(() => {
+    done()
+    subscription.unsubscribe()
+  }, 10)
+})
+
+test('prints execution time for install command', (done) => {
+  const output$ = toOutput$({
+    context: {
+      argv: ['install'],
+    },
+    streamParser: createStreamParser(),
+  })
+
+  executionTimeLogger.debug({
+    startedAt: 1665279402859,
+    endedAt: 1665279413671,
+  })
+
+  expect.assertions(1)
+
+  output$.pipe(take(1)).subscribe({
+    complete: () => done(),
+    error: done,
+    next: output => {
+      expect(output).toBe('Done in 10.8s')
+    },
+  })
+})

packages/pnpm/bin/pnpm.cjs

@@ -12,6 +12,7 @@ ${COMPATIBILITY_PAGE}`)
   process.exit(1)
 }
 
+global['pnpm__startedAt'] = Date.now()
 require('../dist/pnpm.cjs')
 
 // if you want to debug at your local env, you can use this

packages/pnpm/src/main.ts

@@ -1,10 +1,14 @@
+/* eslint-disable import/first */
+if (!global['pnpm__startedAt']) {
+  global['pnpm__startedAt'] = Date.now()
+}
 import loudRejection from 'loud-rejection'
 import packageManager from '@pnpm/cli-meta'
 import { getConfig } from '@pnpm/cli-utils'
 import {
   Config,
 } from '@pnpm/config'
-import { scopeLogger } from '@pnpm/core-loggers'
+import { executionTimeLogger, scopeLogger } from '@pnpm/core-loggers'
 import { filterPackagesFromDir } from '@pnpm/filter-workspace-packages'
 import logger from '@pnpm/logger'
 import { ParsedCliArgs } from '@pnpm/parse-cli-args'
@@ -263,6 +267,10 @@ export default async function run (inputArgv: string[]) {
     if (result instanceof Promise) {
       result = await result
     }
+    executionTimeLogger.debug({
+      startedAt: global['pnpm__startedAt'],
+      endedAt: Date.now(),
+    })
     if (!result) {
       return { output: null, exitCode: 0 }
     }