Improve oclif metrics (#427)

* feat: improve oclif metrics

* chore: tests

* fix: possibly undefined

* chore: bump oclif/core

package.json

@@ -5,7 +5,7 @@
   "author": "Salesforce",
   "bugs": "https://github.com/forcedotcom/cli/issues",
   "dependencies": {
-    "@oclif/core": "^2.0.7",
+    "@oclif/core": "^2.5.0",
     "@salesforce/core": "^3.32.2",
     "@salesforce/telemetry": "^3.2.5",
     "debug": "^4.3.4",
@@ -67,7 +67,6 @@
     "commands": "./lib/commands",
     "bin": "sfdx",
     "hooks": {
-      "init": "./lib/hooks/telemetryInit.js",
       "prerun": "./lib/hooks/telemetryPrerun.js"
     },
     "devPlugins": [

src/commandExecution.ts

@@ -7,13 +7,12 @@
 
 import { join } from 'path';
 import * as fs from 'fs';
-import { Config, Command, Parser } from '@oclif/core';
+import { Config, Command, Parser, Performance } from '@oclif/core';
 import { FlagInput } from '@oclif/core/lib/interfaces/parser';
 import { SfProject } from '@salesforce/core';
 import { AsyncCreatable } from '@salesforce/kit';
 import { isNumber, JsonMap, Optional } from '@salesforce/ts-types';
-import { debug } from './debuger';
-import { InitData } from './hooks/telemetryInit';
+import { debug } from './debugger';
 
 export type CommandExecutionOptions = {
   command: Partial<Command.Class>;
@@ -28,8 +27,6 @@ interface PluginInfo {
 
 export class CommandExecution extends AsyncCreatable {
   public status?: number;
-  private start: number;
-  private upTimeAtCmdStart: number;
   private specifiedFlags: string[] = [];
   private specifiedFlagFullNames: string[] = [];
   private command: Partial<Command.Class>;
@@ -44,11 +41,9 @@ export class CommandExecution extends AsyncCreatable {
   public constructor(options: CommandExecutionOptions) {
     super(options);
 
-    this.start = Date.now();
     this.command = options.command;
     this.argv = options.argv;
     this.config = options.config;
-    this.upTimeAtCmdStart = process.uptime() * 1000;
   }
 
   /**
@@ -111,10 +106,32 @@ export class CommandExecution extends AsyncCreatable {
       // Don't log status or timestamp as a number, otherwise vscode will think it is a metric
       status: isNumber(this.status) ? this.status.toString() : undefined,
       timestamp: String(Date.now()),
-      runtime: Date.now() - this.start,
-      upTimeAtCmdStart: this.upTimeAtCmdStart,
-      oclifLoadTime: InitData.upTimeAtInit,
-      commandLoadTime: this.upTimeAtCmdStart - InitData.upTimeAtInit,
+
+      // The amount of time (ms) required for oclif to execute the main `run` function.
+      // This does not represent the entire execution time of the command. The `processUptime`
+      // metric is the most accurate measure of how long the command execution.
+      //
+      // Our CLIs instantiate the Config before running oclif's `run` method, meaning that
+      // this metric will be less than the actual time spent in oclif.
+      'oclif.runMs': Performance.highlights.runTime,
+      // The amount of time (ms) required for oclif to get to the point where it can start running the command.
+      'oclif.initMs': Performance.highlights.initTime,
+      // The amount of time (ms) required for oclif to load the Config.
+      'oclif.configLoadMs': Performance.highlights.configLoadTime,
+      // The amount of time (ms) required for oclif to load the command.
+      'oclif.commandLoadMs': Performance.highlights.commandLoadTime,
+      // The amount of time (ms) required for oclif to load core (i.e. bundled) plugins.
+      'oclif.corePluginsLoadMs': Performance.highlights.corePluginsLoadTime,
+      // The amount of time (ms) required for oclif to load user plugins.
+      'oclif.userPluginsLoadMs': Performance.highlights.userPluginsLoadTime,
+      // The amount of time (ms) required for oclif to load linked plugins.
+      'oclif.linkedPluginsLoadMs': Performance.highlights.linkedPluginsLoadTime,
+      // The amount of time (ms) required for oclif to run all the init hooks
+      'oclif.initHookMs': Performance.highlights.hookRunTimes.init?.total,
+      // The amount of time (ms) required for oclif to run all the prerun hooks
+      'oclif.prerunHookMs': Performance.highlights.hookRunTimes.prerun?.total,
+      // The amount of time (ms) required for oclif to run all the postrun hooks
+      'oclif.postrunHookMs': Performance.highlights.hookRunTimes.postrun?.total,
 
       // Salesforce Information
       // Set the usernames so the uploader can resolve it to orgIds.
@@ -138,19 +155,18 @@ export class CommandExecution extends AsyncCreatable {
 
   protected async init(): Promise<void> {
     const argv = this.argv;
-    const flagDefinitions = this.command.flags || {};
-
-    // We can't get varargs on type Class, so we need to cast to any to parse flags properly
-    // eslint-disable-next-line @typescript-eslint/no-explicit-any
-    const anyCmd: any = this.command;
-    // eslint-disable-next-line @typescript-eslint/no-unsafe-member-access
-    const commandDef = { flags: flagDefinitions, args: this.command.args, strict: !anyCmd.varargs };
+    const flagDefinitions = this.command.flags ?? {};
 
-    // eslint-disable-next-line @typescript-eslint/no-explicit-any
     let flags: FlagInput = {};
     try {
-      // eslint-disable-next-line @typescript-eslint/no-unsafe-assignment
-      flags = (await Parser.parse(argv, commandDef)).flags;
+      flags = (
+        await Parser.parse(argv, {
+          flags: flagDefinitions,
+          args: this.command.args,
+          // @ts-expect-error because varargs is not on SfCommand but is on SfdxCommand
+          strict: this.command.strict ?? !this.command.varargs,
+        })
+      ).flags;
     } catch (error) {
       debug('Error parsing flags');
     }
@@ -162,8 +178,7 @@ export class CommandExecution extends AsyncCreatable {
     this.vcs = await CommandExecution.resolveVCSInfo();
   }
 
-  // eslint-disable-next-line @typescript-eslint/no-explicit-any
-  private determineSpecifiedFlags(argv: string[], flags: any, flagDefinitions: FlagInput): void {
+  private determineSpecifiedFlags(argv: string[], flags: FlagInput, flagDefinitions: FlagInput): void {
     // Help won't be in the parsed flags
     const shortHelp = argv.find((arg) => /^-h$/.test(arg));
     const fullHelp = argv.find((arg) => /^--help$/.test(arg));
@@ -176,9 +191,7 @@ export class CommandExecution extends AsyncCreatable {
       this.specifiedFlagFullNames.push('help');
       // All other flags don't matter if help is specified, so end here.
     } else {
-      // eslint-disable-next-line @typescript-eslint/no-unsafe-argument
       Object.keys(flags).forEach((flagName) => {
-        // eslint-disable-next-line @typescript-eslint/no-unsafe-member-access
         const shortCode = flagDefinitions[flagName] && (flagDefinitions[flagName].char as string);
         // Oclif will include the flag if there is a default, but we only want to add it if the
         // user specified it, so confirm in the argv list.

src/hooks/telemetryPrerun.ts

@@ -12,7 +12,7 @@ import { TelemetryReporter } from '@salesforce/telemetry';
 import Telemetry from '../telemetry';
 import { TelemetryGlobal } from '../telemetryGlobal';
 import { CommandExecution } from '../commandExecution';
-import { debug } from '../debuger';
+import { debug } from '../debugger';
 
 declare const global: TelemetryGlobal;
 
@@ -56,13 +56,13 @@ const hook: Hook.Prerun = async function (options): Promise<void> {
 
     try {
       Lifecycle.getInstance().onTelemetry(async (data) => {
-        // lifecycle wants promises, telemetry is not a promise
-        // eslint-disable-next-line @typescript-eslint/await-thenable
-        await telemetry.record({
-          type: 'EVENT',
-          ...commonDataMemoized(),
-          ...data,
-        });
+        await Promise.resolve(
+          telemetry.record({
+            type: 'EVENT',
+            ...commonDataMemoized(),
+            ...data,
+          })
+        );
       });
     } catch (err) {
       // even if this throws, the rest of telemetry is not affected
@@ -98,7 +98,10 @@ const hook: Hook.Prerun = async function (options): Promise<void> {
       if (telemetry.firstRun) {
         telemetry.record({
           eventName: 'INSTALL',
-          installType: this.config.binPath?.includes(join('sfdx', 'client')) ? 'installer' : 'npm',
+          installType:
+            this.config.binPath?.includes(join('sfdx', 'client')) || this.config.binPath?.includes(join('sf', 'client'))
+              ? 'installer'
+              : 'npm',
           platform: this.config.platform,
         });
       }

src/telemetry.ts

@@ -14,7 +14,7 @@ import { Attributes } from '@salesforce/telemetry';
 import { AsyncCreatable, env } from '@salesforce/kit';
 import { SfError } from '@salesforce/core';
 import { isBoolean, isNumber, isString, JsonMap } from '@salesforce/ts-types';
-import { debug } from './debuger';
+import { debug } from './debugger';
 
 const CLI_ID_FILE_NAME = 'CLIID.txt';
 const USAGE_ACKNOWLEDGEMENT_FILE_NAME = 'acknowledgedUsageCollection.json';

src/uploader.ts

@@ -9,7 +9,7 @@ import { Org, SfError } from '@salesforce/core';
 import TelemetryReporter from '@salesforce/telemetry';
 import { asString, Dictionary } from '@salesforce/ts-types';
 import Telemetry from './telemetry';
-import { debug, version } from './debuger';
+import { debug, version } from './debugger';
 
 import { TelemetryGlobal } from './telemetryGlobal';
 

test/commandExecution.test.ts

@@ -5,7 +5,7 @@
  * For full license text, see LICENSE.txt file in the repo root or https://opensource.org/licenses/BSD-3-Clause
  */
 
-import { Interfaces } from '@oclif/core';
+import { Interfaces, Performance } from '@oclif/core';
 import { stubInterface, stubMethod } from '@salesforce/ts-sinon';
 import { expect } from 'chai';
 import { createSandbox } from 'sinon';
@@ -17,6 +17,20 @@ describe('toJson', () => {
 
   beforeEach(() => {
     stubMethod(sandbox, CommandExecution, 'resolveVCSInfo').returns('git');
+    stubMethod(sandbox, Performance, 'highlights').get(() => ({
+      runTime: 0,
+      initTime: 0,
+      configLoadTime: 0,
+      commandLoadTime: 0,
+      corePluginsLoadTime: 0,
+      userPluginsLoadTime: 0,
+      linkedPluginsLoadTime: 0,
+      hookRunTimes: {
+        init: { total: 0 },
+        prerun: { total: 0 },
+        postrun: { total: 0 },
+      },
+    }));
     process.env = {};
   });
 

yarn.lock

@@ -697,7 +697,7 @@
     widest-line "^3.1.0"
     wrap-ansi "^7.0.0"
 
-"@oclif/core@^2.0.3", "@oclif/core@^2.0.7", "@oclif/core@^2.0.8", "@oclif/core@^2.3.0":
+"@oclif/core@^2.0.3", "@oclif/core@^2.0.8", "@oclif/core@^2.3.0":
   version "2.3.1"
   resolved "https://registry.yarnpkg.com/@oclif/core/-/core-2.3.1.tgz#82d977338c68b3faeda84f780c2f97a3dd322cb2"
   integrity sha512-18CkjjF16hwhBd/42z+0CHAwvZlBfpyCmdZxpasN/od8c/hdm0oDEJvVB33/xD0LDYg8glKoQ5zVNVvPM/uJ/Q==
@@ -731,6 +731,40 @@
     wordwrap "^1.0.0"
     wrap-ansi "^7.0.0"
 
+"@oclif/core@^2.5.0":
+  version "2.5.0"
+  resolved "https://registry.yarnpkg.com/@oclif/core/-/core-2.5.0.tgz#ade1ff5cf0c2f46851eb101a036ba03e54146d9d"
+  integrity sha512-gHDqrJ3orSm9eV+EacNnw1hlbBie3BAUAenWLWKa7TfJHyfseVhLGV8skkb8uA9MTRAAESJNxWAADh0gIbtZKg==
+  dependencies:
+    "@types/cli-progress" "^3.11.0"
+    ansi-escapes "^4.3.2"
+    ansi-styles "^4.3.0"
+    cardinal "^2.1.1"
+    chalk "^4.1.2"
+    clean-stack "^3.0.1"
+    cli-progress "^3.12.0"
+    debug "^4.3.4"
+    ejs "^3.1.8"
+    fs-extra "^9.1.0"
+    get-package-type "^0.1.0"
+    globby "^11.1.0"
+    hyperlinker "^1.0.0"
+    indent-string "^4.0.0"
+    is-wsl "^2.2.0"
+    js-yaml "^3.14.1"
+    natural-orderby "^2.0.3"
+    object-treeify "^1.1.33"
+    password-prompt "^1.1.2"
+    semver "^7.3.7"
+    string-width "^4.2.3"
+    strip-ansi "^6.0.1"
+    supports-color "^8.1.1"
+    supports-hyperlinks "^2.2.0"
+    tslib "^2.5.0"
+    widest-line "^3.1.0"
+    wordwrap "^1.0.0"
+    wrap-ansi "^7.0.0"
+
 "@oclif/linewrap@^1.0.0":
   version "1.0.0"
   resolved "https://registry.yarnpkg.com/@oclif/linewrap/-/linewrap-1.0.0.tgz#aedcb64b479d4db7be24196384897b5000901d91"