feat: add elapsed time decorator to apex node class methods (#349)

* feat: add elapsedTime decorator

@W-14990874@

* chore: change signature and annotate methods

* chore: wip

* chore: fix unit tests

* chore: restore tests for async tests

* chore: apply review suggestions

package.json

@@ -6,7 +6,7 @@
   "bugs": "https://github.com/forcedotcom/salesforcedx-apex/issues",
   "main": "lib/src/index.js",
   "dependencies": {
-    "@salesforce/core": "^6.1.0",
+    "@salesforce/core": "^6.5.1",
     "@salesforce/kit": "^3.0.15",
     "@types/istanbul-reports": "^3.0.4",
     "faye": "1.4.0",
@@ -86,4 +86,4 @@
       "path": "./node_modules/cz-conventional-changelog"
     }
   }
-}
+}

src/execute/executeService.ts

@@ -20,6 +20,7 @@ import { refreshAuth } from '../utils';
 import { encodeBody } from './utils';
 import * as readline from 'readline';
 import { HttpRequest } from 'jsforce';
+import { elapsedTime } from '../utils/elapsedTime';
 
 export class ExecuteService {
   public readonly connection: Connection;
@@ -28,6 +29,7 @@ export class ExecuteService {
     this.connection = connection;
   }
 
+  @elapsedTime()
   public async executeAnonymous(
     options: ApexExecuteOptions
   ): Promise<ExecuteAnonymousResponse> {
@@ -56,6 +58,7 @@ export class ExecuteService {
     }
   }
 
+  @elapsedTime()
   public async getApexCode(options: ApexExecuteOptions): Promise<string> {
     if (options.apexCode) {
       return String(options.apexCode);
@@ -68,13 +71,15 @@ export class ExecuteService {
     }
   }
 
+  @elapsedTime()
   public readApexFile(filepath: string): string {
     if (!existsSync(filepath)) {
       throw new Error(nls.localize('fileNotFoundError', filepath));
     }
     return readFileSync(filepath, 'utf8');
   }
 
+  @elapsedTime()
   public async getUserInput(): Promise<string> {
     process.stdout.write(nls.localize('execAnonInputPrompt'));
     return new Promise<string>((resolve, reject) => {
@@ -125,6 +130,7 @@ export class ExecuteService {
     return request;
   }
 
+  @elapsedTime()
   public jsonFormat(soapResponse: SoapResponse): ExecuteAnonymousResponse {
     const execAnonResponse =
       soapResponse[soapEnv][soapBody].executeAnonymousResponse.result;
@@ -159,6 +165,7 @@ export class ExecuteService {
     return formattedResponse;
   }
 
+  @elapsedTime()
   public async connectionRequest(
     requestData: HttpRequest
   ): Promise<SoapResponse> {

src/logs/logService.ts

@@ -29,6 +29,7 @@ import * as path from 'path';
 import { nls } from '../i18n';
 import { createFile } from '../utils';
 import { TraceFlags } from '../utils/traceFlags';
+import { elapsedTime } from '../utils/elapsedTime';
 
 type StreamingLogMessage = {
   errorName?: string;
@@ -44,6 +45,7 @@ export class LogService {
     this.connection = connection;
   }
 
+  @elapsedTime()
   public async getLogIds(options: ApexLogGetOptions): Promise<string[]> {
     if (
       !(
@@ -62,6 +64,7 @@ export class LogService {
   }
 
   // TODO: readableStream cannot be used until updates are made in jsforce and sfdx-core
+  @elapsedTime()
   public async getLogs(options: ApexLogGetOptions): Promise<LogResult[]> {
     const logIdList = await this.getLogIds(options);
     const logPaths: string[] = [];
@@ -90,13 +93,15 @@ export class LogService {
     });
   }
 
+  @elapsedTime()
   public async getLogById(logId: string): Promise<LogResult> {
     const baseUrl = this.connection.tooling._baseUrl();
     const url = `${baseUrl}/sobjects/ApexLog/${logId}/Body`;
     const response = (await this.connection.tooling.request(url)) as AnyJson;
     return { log: response.toString() || '' };
   }
 
+  @elapsedTime()
   public async getLogRecords(numberOfLogs?: number): Promise<LogRecord[]> {
     let apexLogQuery = `
         SELECT Id, Application, DurationMilliseconds, Location, LogLength, LogUser.Name,
@@ -119,6 +124,7 @@ export class LogService {
     return response.records as LogRecord[];
   }
 
+  @elapsedTime()
   public async tail(org: Org, tailer?: (log: string) => void): Promise<void> {
     this.logger = await Logger.child('apexLogApi', { tag: 'tail' });
     this.logTailer = tailer;
@@ -132,6 +138,7 @@ export class LogService {
     });
   }
 
+  @elapsedTime()
   public async createStreamingClient(org: Org): Promise<StreamingClient> {
     const options = new StreamingClient.DefaultOptions(
       org,
@@ -143,6 +150,7 @@ export class LogService {
     return await StreamingClient.create(options);
   }
 
+  @elapsedTime()
   public async logCallback(message: StreamingLogMessage): Promise<void> {
     if (message.sobject && message.sobject.Id) {
       const log = await this.getLogById(message.sobject.Id);
@@ -152,6 +160,7 @@ export class LogService {
     }
   }
 
+  @elapsedTime()
   private streamingCallback(message: StreamingLogMessage): StatusResult {
     if (message.errorName === LISTENER_ABORTED_ERROR_NAME) {
       return { completed: true };
@@ -169,6 +178,7 @@ export class LogService {
     await flags.ensureTraceFlags(requestedDebugLevel);
   }
 
+  @elapsedTime()
   public async toolingRequest(url: string): Promise<AnyJson> {
     const log = (await this.connection.tooling.request(url)) as AnyJson;
     return log;

src/reporters/coverageReporter.ts

@@ -17,6 +17,7 @@ import * as path from 'path';
 import { glob } from 'glob';
 import * as fs from 'fs';
 import { nls } from '../i18n';
+import { elapsedTime } from '../utils/elapsedTime';
 
 const startOfSource = (source: string): number => {
   if (source) {
@@ -97,6 +98,7 @@ export class CoverageReporter {
     private readonly options?: CoverageReporterOptions
   ) {}
 
+  @elapsedTime()
   public generateReports(): void {
     try {
       this.coverageMap = this.buildCoverageMap();
@@ -120,6 +122,7 @@ export class CoverageReporter {
     }
   }
 
+  @elapsedTime()
   private buildCoverageMap(): libCoverage.CoverageMap {
     const pathsToFiles = this.findFullPathToClass(['cls', 'trigger']);
     const coverageMap = libCoverage.createCoverageMap();
@@ -183,6 +186,7 @@ export class CoverageReporter {
     return coverageMap;
   }
 
+  @elapsedTime()
   private findFullPathToClass(listOfExtensions: string[]): string[] {
     const searchPattern = `**/*.{${listOfExtensions.join(',')}}`;
     return glob.sync(searchPattern, { cwd: this.sourceDir });

src/reporters/humanReporter.ts

@@ -13,8 +13,11 @@ import {
   TestResult
 } from '../tests';
 import { nls } from '../i18n';
+import { elapsedTime } from '../utils/elapsedTime';
+import { LoggerLevel } from '@salesforce/core';
 
 export class HumanReporter {
+  @elapsedTime()
   public format(testResult: TestResult, detailedCoverage: boolean): string {
     let tbResult = this.formatSummary(testResult);
     if (!testResult.codecoverage || !detailedCoverage) {
@@ -30,6 +33,7 @@ export class HumanReporter {
     return tbResult;
   }
 
+  @elapsedTime()
   private formatSummary(testResult: TestResult): string {
     const tb = new Table();
 
@@ -95,6 +99,7 @@ export class HumanReporter {
     return summaryTable;
   }
 
+  @elapsedTime()
   private formatTestResults(tests: ApexTestResultData[]): string {
     const tb = new Table();
     const testRowArray: Row[] = [];
@@ -137,6 +142,7 @@ export class HumanReporter {
     return testResultTable;
   }
 
+  @elapsedTime()
   private formatDetailedCov(testResult: TestResult): string {
     const tb = new Table();
     const testRowArray: Row[] = [];
@@ -196,6 +202,7 @@ export class HumanReporter {
     return detailedCovTable;
   }
 
+  @elapsedTime()
   private formatCodeCov(codeCoverages: CodeCoverageResult[]): string {
     const tb = new Table();
     const codeCovRowArray: Row[] = [];
@@ -235,6 +242,7 @@ export class HumanReporter {
     return codeCovTable;
   }
 
+  @elapsedTime('elapsedTime', LoggerLevel.TRACE)
   private formatUncoveredLines(uncoveredLines: number[]): string {
     const arrayLimit = 5;
     if (uncoveredLines.length === 0) {

src/reporters/junitReporter.ts

@@ -10,6 +10,8 @@ import {
   TestResult
 } from '../tests/types';
 import { formatStartTime, msToSecond } from '../utils';
+import { elapsedTime } from '../utils/elapsedTime';
+import { LoggerLevel } from '@salesforce/core';
 
 // cli currently has spaces in multiples of four for junit format
 const tab = '    ';
@@ -23,6 +25,7 @@ const timeProperties = [
 // properties not in cli junit spec
 const skippedProperties = ['skipRate', 'totalLines', 'linesCovered'];
 export class JUnitReporter {
+  @elapsedTime()
   public format(testResult: TestResult): string {
     const { summary, tests } = testResult;
 
@@ -44,6 +47,7 @@ export class JUnitReporter {
     return output;
   }
 
+  @elapsedTime()
   private buildProperties(testResult: TestResult): string {
     let junitProperties = `${tab}${tab}<properties>\n`;
 
@@ -72,6 +76,7 @@ export class JUnitReporter {
     return junitProperties;
   }
 
+  @elapsedTime()
   private buildTestCases(tests: ApexTestResultData[]): string {
     let junitTests = '';
 
@@ -99,6 +104,7 @@ export class JUnitReporter {
     return junitTests;
   }
 
+  @elapsedTime('elapsedTime', LoggerLevel.TRACE)
   private xmlEscape(value: string): string {
     return value
       .replace(/&/g, '&amp;')

src/reporters/tapReporter.ts

@@ -9,6 +9,7 @@ import {
   ApexTestResultOutcome,
   TestResult
 } from '../tests/types';
+import { elapsedTime } from '../utils/elapsedTime';
 
 export interface TapResult {
   description: string;
@@ -18,6 +19,7 @@ export interface TapResult {
 }
 
 export class TapReporter {
+  @elapsedTime()
   public format(testResult: TestResult, epilog?: string[]): string {
     const results: TapResult[] = this.buildTapResults(testResult);
     const testPointCount = results.length;
@@ -39,6 +41,7 @@ export class TapReporter {
     return out;
   }
 
+  @elapsedTime()
   public buildTapResults(testResult: TestResult): TapResult[] {
     const tapResults: TapResult[] = [];
     testResult.tests.forEach((test: ApexTestResultData, index: number) => {
@@ -55,6 +58,7 @@ export class TapReporter {
     return tapResults;
   }
 
+  @elapsedTime()
   private buildTapDiagnostics(testResult: ApexTestResultData): string[] {
     const message = [];
     if (testResult.outcome !== 'Pass') {

src/streaming/streamingClient.ts

@@ -22,6 +22,7 @@ import {
   ApexTestQueueItemRecord,
   ApexTestQueueItemStatus
 } from '../tests/types';
+import { elapsedTime } from '../utils/elapsedTime';
 
 const TEST_RESULT_CHANNEL = '/systemTopic/TestResult';
 const DEFAULT_STREAMING_TIMEOUT_MS = 14400;
@@ -163,6 +164,7 @@ export class StreamingClient {
 
   public hasDisconnected = false;
 
+  @elapsedTime()
   public async subscribe(
     action?: () => Promise<string>,
     testRunId?: string
@@ -250,6 +252,7 @@ export class StreamingClient {
     return true;
   }
 
+  @elapsedTime()
   public async handler(
     message?: TestResultMessage,
     runId?: string

src/tests/asyncTests.ts

@@ -32,6 +32,7 @@ import * as util from 'util';
 import { QUERY_RECORD_LIMIT } from './constants';
 import { CodeCoverage } from './codeCoverage';
 import { HttpRequest } from 'jsforce';
+import { elapsedTime } from '../utils/elapsedTime';
 
 export class AsyncTests {
   public readonly connection: Connection;
@@ -50,6 +51,7 @@ export class AsyncTests {
    * @param progress progress reporter
    * @param token cancellation token
    */
+  @elapsedTime()
   public async runTests(
     options: AsyncTestConfiguration | AsyncTestArrayConfiguration,
     codeCoverage = false,
@@ -99,6 +101,7 @@ export class AsyncTests {
    * @param codeCoverage should report code coverages
    * @param token cancellation token
    */
+  @elapsedTime()
   public async reportAsyncResults(
     testRunId: string,
     codeCoverage = false,
@@ -138,6 +141,7 @@ export class AsyncTests {
     }
   }
 
+  @elapsedTime()
   public async checkRunStatus(
     testRunId: string,
     progress?: Progress<ApexTestProgressValue>
@@ -196,6 +200,7 @@ export class AsyncTests {
    * @param progress progress reporter
    * @returns
    */
+  @elapsedTime()
   public async formatAsyncResults(
     asyncRunResult: AsyncTestRun,
     commandStartTime: number,
@@ -280,6 +285,7 @@ export class AsyncTests {
     return result;
   }
 
+  @elapsedTime()
   public async getAsyncTestResults(
     testQueueResult: ApexTestQueueItem
   ): Promise<ApexTestResult[]> {
@@ -312,6 +318,7 @@ export class AsyncTests {
     return apexTestResults as ApexTestResult[];
   }
 
+  @elapsedTime()
   private async buildAsyncTestResults(
     apexTestResults: ApexTestResult[]
   ): Promise<{