feat: show execution time

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 './finishTimeLogger'

packages/core-loggers/src/finishTimeLogger.ts

@@ -0,0 +1,12 @@
+import baseLogger, {
+  LogBase,
+} from '@pnpm/logger'
+
+export const finishTimeLogger = baseLogger('finish-time')
+
+export interface FinishTimeMessage {
+  startedAt: number
+  finishedAt: number
+}
+
+export type FinishTimeLog = { name: 'pnpm:finish-time' } & LogBase & FinishTimeMessage

packages/core-loggers/src/index.ts

@@ -2,6 +2,7 @@ import {
   ContextLog,
   DeprecationLog,
   FetchingProgressLog,
+  FinishTimeLog,
   HookLog,
   InstallCheckLog,
   LifecycleLog,
@@ -27,6 +28,7 @@ export type Log =
   | ContextLog
   | DeprecationLog
   | FetchingProgressLog
+  | FinishTimeLog
   | 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 finishTimePushStream = new Rx.Subject<logs.FinishTimeLog>()
   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:finish-time':
+        finishTimePushStream.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),
+    finishTime: Rx.from(finishTimePushStream),
     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 reportFinishTime from './reportFinishTime'
 import reportDeprecations from './reportDeprecations'
 import reportHooks from './reportHooks'
 import reportInstallChecks from './reportInstallChecks'
@@ -23,6 +24,7 @@ export default function (
   log$: {
     context: Rx.Observable<logs.ContextLog>
     fetchingProgress: Rx.Observable<logs.FetchingProgressLog>
+    finishTime: Rx.Observable<logs.FinishTimeLog>
     progress: Rx.Observable<logs.ProgressLog>
     stage: Rx.Observable<logs.StageLog>
     deprecation: Rx.Observable<logs.DeprecationLog>
@@ -88,6 +90,10 @@ export default function (
     reportUpdateCheck(log$.updateCheck, opts),
   ]
 
+  if (['install', 'update', 'add', 'remove'].includes(opts.cmd)) {
+    outputs.push(reportFinishTime(log$.finishTime))
+  }
+
   // logLevelNumber: 0123 = error warn info debug
   const logLevelNumber = LOG_LEVEL_NUMBER[opts.logLevel ?? 'info'] ?? LOG_LEVEL_NUMBER['info']
 

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

@@ -0,0 +1,17 @@
+import prettyMs from 'pretty-ms'
+import { FinishTimeLog } from '@pnpm/core-loggers'
+import * as Rx from 'rxjs'
+import { map, take } from 'rxjs/operators'
+
+export default (
+  finishTime$: Rx.Observable<FinishTimeLog>
+) => {
+  return finishTime$.pipe(
+    take(1),
+    map((log) => {
+      return Rx.of({
+        msg: `Done in ${prettyMs(log.finishedAt - log.startedAt)}`,
+      })
+    })
+  )
+}

packages/default-reporter/test/reportingFinishTime.ts

@@ -0,0 +1,55 @@
+import { finishTimeLogger } from '@pnpm/core-loggers'
+import { toOutput$ } from '@pnpm/default-reporter'
+import { createStreamParser } from '@pnpm/logger'
+import { take } from 'rxjs/operators'
+
+test('does not print finish time for help command', (done) => {
+  const output$ = toOutput$({
+    context: {
+      argv: ['help'],
+    },
+    streamParser: createStreamParser(),
+  })
+
+  finishTimeLogger.debug({
+    startedAt: 1665279402859,
+    finishedAt: 1665279413671,
+  })
+
+  const subscription = output$.subscribe({
+    complete: () => done(),
+    error: done,
+    next: () => {
+      done('should not log anything')
+    },
+  })
+
+  setTimeout(() => {
+    done()
+    subscription.unsubscribe()
+  }, 10)
+})
+
+test('prints finish time for install command', (done) => {
+  const output$ = toOutput$({
+    context: {
+      argv: ['install'],
+    },
+    streamParser: createStreamParser(),
+  })
+
+  finishTimeLogger.debug({
+    startedAt: 1665279402859,
+    finishedAt: 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['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['startedAt']) {
+  global['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 { finishTimeLogger, 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
     }
+    finishTimeLogger.debug({
+      startedAt: global['startedAt'],
+      finishedAt: Date.now(),
+    })
     if (!result) {
       return { output: null, exitCode: 0 }
     }