Merge pull request #4242 from NativeScript/kddimitrov/track-perf-decorator

Kddimitrov/track perf decorator

Author: KristianDD

lib/bootstrap.ts

@@ -8,6 +8,7 @@ $injector.require("nativescript-cli", "./nativescript-cli");
 $injector.requirePublicClass("constants", "./constants-provider");
 $injector.require("projectData", "./project-data");
 $injector.requirePublic("projectDataService", "./services/project-data-service");
+$injector.require("performanceService", "./services/performance-service");
 $injector.requirePublic("projectService", "./services/project-service");
 $injector.require("androidProjectService", "./services/android-project-service");
 $injector.require("androidPluginBuildService", "./services/android-plugin-build-service");

lib/commands/debug.ts

@@ -4,6 +4,7 @@ import { cache } from "../common/decorators";
 import { DebugCommandErrors } from "../constants";
 import { ValidatePlatformCommandBase } from "./command-base";
 import { LiveSyncCommandHelper } from "../helpers/livesync-command-helper";
+import { performanceLog } from "../common/decorators";
 
 export class DebugPlatformCommand extends ValidatePlatformCommandBase implements ICommand {
 	public allowedParameters: ICommandParameter[] = [];
@@ -55,6 +56,7 @@ export class DebugPlatformCommand extends ValidatePlatformCommandBase implements
 		});
 	}
 
+	@performanceLog()
 	public async getDeviceForDebug(): Promise<Mobile.IDevice> {
 		if (this.$options.forDevice && this.$options.emulator) {
 			this.$errors.fail(DebugCommandErrors.UNABLE_TO_USE_FOR_DEVICE_AND_EMULATOR);

lib/common/decorators.ts

@@ -1,3 +1,5 @@
+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.
  * Works with methods and getters.
@@ -83,3 +85,48 @@ export function exported(moduleName: string): any {
 		return descriptor;
 	};
 }
+
+export function performanceLog(injector?: IInjector): any {
+	injector = injector || $injector;
+	return function (target: any, propertyKey: string, descriptor: PropertyDescriptor): any {
+		const originalMethod = descriptor.value;
+		const className = target.constructor.name;
+		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 functionWrapper = {
+			[originalMethod.name]: function (...args: Array<any>) {
+				const start = performanceService.now();
+				const result = originalMethod.apply(this, args);
+				const resolvedPromise = Promise.resolve(result);
+				let end;
+
+				if (resolvedPromise !== result) {
+					end = performanceService.now();
+					performanceService.processExecutionData(trackName, start, end, args);
+				} else {
+					resolvedPromise
+					.then(() => {
+						end = performanceService.now();
+						performanceService.processExecutionData(trackName, start, end, args);
+					})
+					.catch((err) => {
+						end = performanceService.now();
+						performanceService.processExecutionData(trackName, start, end, args);
+					});
+				}
+
+				return result;
+			}
+		};
+		descriptor.value = functionWrapper[originalMethod.name];
+
+		// used to get parameter names in hooks decorator
+		descriptor.value.toString = () => {
+			return originalMethod.toString();
+		};
+
+		return descriptor;
+	};
+}

lib/common/definitions/google-analytics.d.ts

@@ -48,6 +48,11 @@ interface IEventActionData {
 	 * Project directory, in case the action is executed inside project.
 	 */
 	projectDir?: string;
+
+	/**
+	 * Value that should be tracked
+	 */
+	value?: number;
 }
 
 /**

lib/common/helpers.ts

@@ -568,6 +568,34 @@ export function stringify(value: any, replacer?: (key: string, value: any) => an
 	return JSON.stringify(value, replacer, space || 2);
 }
 
+//2019-01-07 18:29:50.745
+export function getFixedLengthDateString(): string {
+	const currentDate = new Date();
+	const year = currentDate.getFullYear();
+	const month = getFormattedDateComponent((currentDate.getMonth() + 1));
+	const day = getFormattedDateComponent(currentDate.getDate());
+	const hour = getFormattedDateComponent(currentDate.getHours());
+	const minutes = getFormattedDateComponent(currentDate.getMinutes());
+	const seconds = getFormattedDateComponent(currentDate.getSeconds());
+	const milliseconds = getFormattedMilliseconds(currentDate);
+
+	return `${[year, month, day].join('-')} ${[hour, minutes, seconds].join(":")}.${milliseconds}`;
+}
+
+export function getFormattedDateComponent(component: number): string {
+	const stringComponent = component.toString();
+	return stringComponent.length === 1 ? `0${stringComponent}` : stringComponent;
+}
+
+export function getFormattedMilliseconds(date: Date): string {
+	let milliseconds = date.getMilliseconds().toString();
+	while (milliseconds.length < 3) {
+		milliseconds = `0${milliseconds}`;
+	}
+
+	return milliseconds;
+}
+
 //--- begin part copied from AngularJS
 
 //The MIT License

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/common/test/unit-tests/decorators.ts

@@ -4,13 +4,26 @@ import { assert } from "chai";
 import { CacheDecoratorsTest } from "./mocks/decorators-cache";
 import { InvokeBeforeDecoratorsTest } from "./mocks/decorators-invoke-before";
 import { isPromise } from "../../helpers";
+import * as stubs from "../../../../test/stubs";
+import * as sinon from "sinon";
+import { PerformanceService } from "../../../services/performance-service";
 
 describe("decorators", () => {
-	const moduleName = "moduleName", // This is the name of the injected dependency that will be resolved, for example fs, devicesService, etc.
-		propertyName = "propertyName"; // This is the name of the method/property from the resolved module
+	const moduleName = "moduleName"; // This is the name of the injected dependency that will be resolved, for example fs, devicesService, etc.
+	const propertyName = "propertyName"; // This is the name of the method/property from the resolved module
+	const expectedResults: any[] = [
+		"string result",
+		1,
+		{ a: 1, b: "2" },
+		["string 1", "string2"],
+		true,
+		undefined,
+		null
+	];
 
 	beforeEach(() => {
 		$injector = new Yok();
+		$injector.register("performanceService", stubs.PerformanceService);
 	});
 
 	after(() => {
@@ -19,15 +32,6 @@ describe("decorators", () => {
 	});
 
 	describe("exported", () => {
-		const expectedResults: any[] = [
-			"string result",
-			1,
-			{ a: 1, b: "2" },
-			["string 1", "string2"],
-			true,
-			undefined,
-			null
-		];
 
 		const generatePublicApiFromExportedDecorator = () => {
 			assert.deepEqual($injector.publicApi.__modules__[moduleName], undefined);
@@ -358,4 +362,128 @@ describe("decorators", () => {
 			});
 		});
 	});
+
+	describe("performanceLog", () => {
+		const testErrorMessage = "testError";
+		let testInjector: IInjector;
+		let sandbox: sinon.SinonSandbox;
+		interface ITestInterface {
+			testMethod(arg: any): any;
+			throwMethod?(): void;
+			testAsyncMehtod(arg: any): Promise<any>;
+			rejectMethod?(): Promise<any>;
+		}
+		let testInstance: ITestInterface;
+		let undecoratedTestInstance: ITestInterface;
+
+		function createTestInjector(): IInjector {
+			testInjector = new Yok();
+			testInjector.register("performanceService", PerformanceService);
+			testInjector.register("options", {});
+			testInjector.register("fs", stubs.FileSystemStub);
+			testInjector.register("logger", stubs.LoggerStub);
+			testInjector.register("analyticsService", {
+				trackEventActionInGoogleAnalytics: () => { return Promise.resolve(); }
+			});
+
+			return testInjector;
+		}
+
+		beforeEach(() => {
+			sandbox = sinon.sandbox.create();
+			testInjector = createTestInjector();
+
+			class TestClass implements ITestInterface {
+				@decoratorsLib.performanceLog(testInjector)
+				testMethod(arg: any) {
+					return arg;
+				}
+
+				@decoratorsLib.performanceLog(testInjector)
+				throwMethod() {
+					throw new Error("testErrorMessage");
+				}
+
+				@decoratorsLib.performanceLog(testInjector)
+				async testAsyncMehtod(arg: any) {
+					return Promise.resolve(arg);
+				}
+
+				rejectMethod() {
+					return Promise.reject(testErrorMessage);
+				}
+			}
+
+			class UndecoratedTestClass implements ITestInterface {
+				testMethod(arg: any) {
+					return arg;
+				}
+
+				async testAsyncMehtod(arg: any) {
+					return Promise.resolve(arg);
+				}
+			}
+
+			undecoratedTestInstance = new UndecoratedTestClass();
+			testInstance = new TestClass();
+		});
+
+		afterEach(() => {
+			sandbox.restore();
+		});
+
+		_.each(expectedResults, (expectedResult: any) => {
+			it("returns proper result",  () => {
+				const actualResult = testInstance.testMethod(expectedResult);
+				assert.deepEqual(actualResult, expectedResult);
+			});
+
+			it("returns proper result when async",  () => {
+				const promise = testInstance.testAsyncMehtod(expectedResult);
+
+				assert.notDeepEqual(promise.then, undefined);
+
+				return promise.then((actualResult: any) => {
+					assert.deepEqual(actualResult, expectedResult);
+				});
+			});
+		});
+
+		it("method has same toString",  () => {
+			assert.equal(testInstance.testMethod.toString(), undecoratedTestInstance.testMethod.toString());
+		});
+
+		it("method has same name",  () => {
+			assert.equal(testInstance.testMethod.name, undecoratedTestInstance.testMethod.name);
+		});
+
+		it("does not eat errors",  () => {
+			assert.throws(testInstance.throwMethod, testErrorMessage);
+			assert.isRejected(testInstance.rejectMethod(), testErrorMessage);
+		});
+
+		it("calls performance service on method call",  async () => {
+			const performanceService = testInjector.resolve("performanceService");
+			const processExecutionDataStub: sinon.SinonStub = sinon.stub(performanceService, "processExecutionData");
+
+			const checkSubCall = (call: sinon.SinonSpyCall, methodData: string) => {
+				const callArgs = call.args;
+				const methodInfo = callArgs[0];
+				const startTime = callArgs[1];
+				const endTime = callArgs[2];
+
+				assert(methodInfo === methodData);
+				assert.isNumber(startTime);
+				assert.isNumber(endTime);
+				assert.isTrue(endTime > startTime);
+				assert.isDefined(callArgs[3][0] === "test");
+			};
+
+			testInstance.testMethod("test");
+			await testInstance.testAsyncMehtod("test");
+
+			checkSubCall(processExecutionDataStub.firstCall, "TestClass__testMethod");
+			checkSubCall(processExecutionDataStub.secondCall, "TestClass__testAsyncMehtod");
+		});
+	});
 });

lib/constants.ts

@@ -152,7 +152,8 @@ export const enum TrackActionNames {
 	CheckLocalBuildSetup = "Check Local Build Setup",
 	CheckEnvironmentRequirements = "Check Environment Requirements",
 	Options = "Options",
-	AcceptTracking = "Accept Tracking"
+	AcceptTracking = "Accept Tracking",
+	Performance = "Performance"
 }
 
 export const AnalyticsEventLabelDelimiter = "__";

lib/declarations.d.ts

@@ -75,6 +75,14 @@ interface INodePackageManager {
 	getCachePath(): Promise<string>;
 }
 
+interface IPerformanceService {
+	// Will process the data based on the command opitons (--performance flag and user-reporting setting)
+	processExecutionData(methodInfo: string, startTime: number, endTime: number, args: any[]): void;
+
+	// Will return a reference time in milliseconds
+	now(): number;
+}
+
 interface IPackageInstallationManager {
 	install(packageName: string, packageDir: string, options?: INpmInstallOptions): Promise<any>;
 	getLatestVersion(packageName: string): Promise<string>;
@@ -563,6 +571,7 @@ interface IOptions extends IRelease, IDeviceIdentifier, IJustLaunch, IAvd, IAvai
 	hmr: boolean;
 	link: boolean;
 	analyticsLogFile: string;
+	performance: Object;
 }
 
 interface IEnvOptions {

lib/options.ts

@@ -119,7 +119,8 @@ export class Options {
 			analyticsLogFile: { type: OptionType.String, hasSensitiveValue: true },
 			hooks: { type: OptionType.Boolean, default: true, hasSensitiveValue: false },
 			link: { type: OptionType.Boolean, default: false, hasSensitiveValue: false },
-			aab: { type: OptionType.Boolean, hasSensitiveValue: false }
+			aab: { type: OptionType.Boolean, hasSensitiveValue: false },
+			performance: { type: OptionType.Object, hasSensitiveValue: true }
 		};
 	}