feat: track hooks execution time

Author: KristianDD

lib/common/decorators.ts

@@ -1,4 +1,4 @@
-const { performance } = require('perf_hooks');
+import { AnalyticsEventLabelDelimiter } from "../constants";
 
 /**
  * Caches the result of the first execution of the method and returns it whenever it is called instead of executing it again.
@@ -91,28 +91,28 @@ export function performanceLog(injector?: IInjector): any {
 	return function (target: any, propertyKey: string, descriptor: PropertyDescriptor): any {
 		const originalMethod = descriptor.value;
 		const className = target.constructor.name;
-		const trackName = `${className}.${propertyKey}`;
+		const trackName = `${className}${AnalyticsEventLabelDelimiter}${propertyKey}`;
 		const performanceService: IPerformanceService = injector.resolve("performanceService");
 
 		//needed for the returned function to have the same name as the original - used in hooks decorator
 		const tempObject = {
 			[originalMethod.name]: function (...args: Array<any>) {
-				const start = performance.now();
+				const start = performanceService.now();
 				const result = originalMethod.apply(this, args);
 				const resolvedPromise = Promise.resolve(result);
 				let end;
 
 				if (resolvedPromise !== result) {
-					end = performance.now();
+					end = performanceService.now();
 					performanceService.processExecutionData(trackName, start, end, args);
 				} else {
 					resolvedPromise
 					.then(() => {
-						end = performance.now();
+						end = performanceService.now();
 						performanceService.processExecutionData(trackName, start, end, args);
 					})
 					.catch((err) => {
-						end = performance.now();
+						end = performanceService.now();
 						performanceService.processExecutionData(trackName, start, end, args);
 					});
 

lib/common/services/hooks-service.ts

@@ -1,6 +1,7 @@
 import * as path from "path";
 import * as util from "util";
 import { annotate, getValueFromNestedObject } from "../helpers";
+import { AnalyticsEventLabelDelimiter } from "../../constants";
 
 class Hook implements IHook {
 	constructor(public name: string,
@@ -22,7 +23,8 @@ export class HooksService implements IHooksService {
 		private $staticConfig: Config.IStaticConfig,
 		private $injector: IInjector,
 		private $projectHelper: IProjectHelper,
-		private $options: IOptions) { }
+		private $options: IOptions,
+		private $performanceService: IPerformanceService) { }
 
 	public get hookArgsName(): string {
 		return "hookArgs";
@@ -93,9 +95,11 @@ export class HooksService implements IHooksService {
 		hookArguments = hookArguments || {};
 		const results: any[] = [];
 		const hooks = this.getHooksByName(directoryPath, hookName);
+
 		for (let i = 0; i < hooks.length; ++i) {
 			const hook = hooks[i];
-			this.$logger.info("Executing %s hook from %s", hookName, hook.fullPath);
+			const relativePath = path.relative(directoryPath, hook.fullPath);
+			const trackId = relativePath.replace(new RegExp('\\' + path.sep, 'g'), AnalyticsEventLabelDelimiter);
 			let command = this.getSheBangInterpreter(hook);
 			let inProc = false;
 			if (!command) {
@@ -106,6 +110,7 @@ export class HooksService implements IHooksService {
 				}
 			}
 
+			const startTime = this.$performanceService.now();
 			if (inProc) {
 				this.$logger.trace("Executing %s hook at location %s in-process", hookName, hook.fullPath);
 				const hookEntryPoint = require(hook.fullPath);
@@ -155,7 +160,11 @@ export class HooksService implements IHooksService {
 				if (output.exitCode !== 0) {
 					throw new Error(output.stdout + output.stderr);
 				}
+
+				this.$logger.trace("Finished executing %s hook at location %s with environment ", hookName, hook.fullPath, environment);
 			}
+			const endTime = this.$performanceService.now();
+			this.$performanceService.processExecutionData(trackId, startTime, endTime, [hookArguments]);
 		}
 
 		return results;

lib/declarations.d.ts

@@ -77,6 +77,7 @@ interface INodePackageManager {
 
 interface IPerformanceService {
 	processExecutionData(methodInfo: string, startTime: number, endTime: number, args: any[]): void;
+	now(): number;
 }
 
 interface IPackageInstallationManager {

lib/services/performance-service.ts

@@ -1,6 +1,7 @@
-import { TrackActionNames } from "../constants";
+import { TrackActionNames, AnalyticsEventLabelDelimiter } from "../constants";
 const EOL = require("os").EOL;
 import { getFormattedDate } from "../common/helpers";
+const { performance } = require('perf_hooks');
 
 export class PerformanceService implements IPerformanceService {
 	public static LOG_MESSAGE_TEMPLATE = `Execution of method "%s" took %s ms.`;
@@ -25,6 +26,10 @@ export class PerformanceService implements IPerformanceService {
 		}
 	}
 
+	public now(): number {
+		return performance.now();
+	}
+
 	private trackAnalyticsData(methodInfo: string, executionTime: number): void {
 		this.$analyticsService.trackEventActionInGoogleAnalytics({
 			action: TrackActionNames.Performance,