feat: add initial preformance tracking

KristianDD · KristianDD · commit 83c63f5a85bc · 2019-01-14T16:39:39.000+02:00
diff --git a/lib/bootstrap.ts b/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");
diff --git a/lib/common/decorators.ts b/lib/common/decorators.ts
@@ -1,3 +1,5 @@
+const { performance } = require('perf_hooks');
+
 /**
  * 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,49 @@ 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}.${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 result = originalMethod.apply(this, args);
+				const resolvedPromise = Promise.resolve(result);
+				let end;
+	
+				if (resolvedPromise !== result) {
+					end = performance.now();
+					performanceService.processExecutionData(trackName, start, end, args);
+				} else {
+					resolvedPromise
+					.then(() => {
+						end = performance.now();
+						performanceService.processExecutionData(trackName, start, end, args);
+					})
+					.catch((err) => {
+						end = performance.now();
+						performanceService.processExecutionData(trackName, start, end, args);
+					});
+	
+				}
+	
+				return result;
+			}
+		}
+		descriptor.value = tempObject[originalMethod.name]
+
+		// used to get parameter names in hooks decorator
+		descriptor.value.toString = () => {
+			return originalMethod.toString();
+		};
+
+		return descriptor;
+	};
+}
diff --git a/lib/common/definitions/google-analytics.d.ts b/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;
 }
 
 /**
diff --git a/lib/common/helpers.ts b/lib/common/helpers.ts
@@ -568,6 +568,33 @@ export function stringify(value: any, replacer?: (key: string, value: any) => an
 	return JSON.stringify(value, replacer, space || 2);
 }
 
+export function getFormattedDate(): 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
diff --git a/lib/constants.ts b/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 = "__";
diff --git a/lib/declarations.d.ts b/lib/declarations.d.ts
@@ -75,6 +75,10 @@ interface INodePackageManager {
 	getCachePath(): Promise<string>;
 }
 
+interface IPerformanceService {
+	processExecutionData(methodInfo: string, startTime: number, endTime: number, args: any[]): void;
+}
+
 interface IPackageInstallationManager {
 	install(packageName: string, packageDir: string, options?: INpmInstallOptions): Promise<any>;
 	getLatestVersion(packageName: string): Promise<string>;
@@ -563,6 +567,7 @@ interface IOptions extends IRelease, IDeviceIdentifier, IJustLaunch, IAvd, IAvai
 	hmr: boolean;
 	link: boolean;
 	analyticsLogFile: string;
+	performance: Object;
 }
 
 interface IEnvOptions {
diff --git a/lib/options.ts b/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 }
 		};
 	}
 
diff --git a/lib/services/analytics/analytics-logging-service.ts b/lib/services/analytics/analytics-logging-service.ts
@@ -1,4 +1,5 @@
 import { EOL } from "os";
+import { getFormattedDate } from "../../common/helpers";
 
 export class AnalyticsLoggingService implements IAnalyticsLoggingService {
 	constructor(private $fs: IFileSystem,
@@ -7,35 +8,8 @@ export class AnalyticsLoggingService implements IAnalyticsLoggingService {
 	public logData(analyticsLoggingMessage: IAnalyticsLoggingMessage): void {
 		if (this.logFile && analyticsLoggingMessage && analyticsLoggingMessage.message) {
 			analyticsLoggingMessage.type = analyticsLoggingMessage.type || AnalyticsLoggingMessageType.Info;
-			const formattedDate = this.getFormattedDate();
+			const formattedDate = getFormattedDate();
 			this.$fs.appendFile(this.logFile, `[${formattedDate}] [${analyticsLoggingMessage.type}] ${analyticsLoggingMessage.message}${EOL}`);
 		}
 	}
-
-	private getFormattedDate(): string {
-		const currentDate = new Date();
-		const year = currentDate.getFullYear();
-		const month = this.getFormattedDateComponent((currentDate.getMonth() + 1));
-		const day = this.getFormattedDateComponent(currentDate.getDate());
-		const hour = this.getFormattedDateComponent(currentDate.getHours());
-		const minutes = this.getFormattedDateComponent(currentDate.getMinutes());
-		const seconds = this.getFormattedDateComponent(currentDate.getSeconds());
-		const milliseconds = this.getFormattedMilliseconds(currentDate);
-
-		return `${[year, month, day].join('-')} ${[hour, minutes, seconds].join(":")}.${milliseconds}`;
-	}
-
-	private getFormattedDateComponent(component: number): string {
-		const stringComponent = component.toString();
-		return stringComponent.length === 1 ? `0${stringComponent}` : stringComponent;
-	}
-
-	private getFormattedMilliseconds(date: Date): string {
-		let milliseconds = date.getMilliseconds().toString();
-		while (milliseconds.length < 3) {
-			milliseconds = `0${milliseconds}`;
-		}
-
-		return milliseconds;
-	}
 }
diff --git a/lib/services/analytics/analytics-service.ts b/lib/services/analytics/analytics-service.ts
@@ -122,7 +122,8 @@ export class AnalyticsService implements IAnalyticsService, IDisposable {
 			googleAnalyticsDataType: GoogleAnalyticsDataType.Event,
 			action: data.action,
 			label,
-			customDimensions
+			customDimensions,
+			value: data.value
 		};
 
 		await this.trackInGoogleAnalytics(googleAnalyticsEventData);
diff --git a/lib/services/android-project-service.ts b/lib/services/android-project-service.ts
@@ -7,6 +7,7 @@ import { DeviceAndroidDebugBridge } from "../common/mobile/android/device-androi
 import { attachAwaitDetach, isRecommendedAarFile } from "../common/helpers";
 import { Configurations, LiveSyncPaths } from "../common/constants";
 import { SpawnOptions } from "child_process";
+import { performanceLog } from ".././common/decorators";
 
 export class AndroidProjectService extends projectServiceBaseLib.PlatformProjectServiceBase implements IPlatformProjectService {
 	private static VALUES_DIRNAME = "values";
@@ -325,6 +326,7 @@ export class AndroidProjectService extends projectServiceBaseLib.PlatformProject
 		return true;
 	}
 
+	@performanceLog()
 	public async buildProject(projectRoot: string, projectData: IProjectData, buildConfig: IBuildConfig): Promise<void> {
 		let task;
 		const gradleArgs = this.getGradleBuildOptions(buildConfig, projectData);
diff --git a/lib/services/livesync/android-device-livesync-service.ts b/lib/services/livesync/android-device-livesync-service.ts
@@ -1,4 +1,5 @@
 import { AndroidDeviceLiveSyncServiceBase } from "./android-device-livesync-service-base";
+import { performanceLog } from "../../common/decorators";
 import * as helpers from "../../common/helpers";
 import { LiveSyncPaths } from "../../common/constants";
 import * as path from "path";
@@ -75,6 +76,7 @@ export class AndroidDeviceLiveSyncService extends AndroidDeviceLiveSyncServiceBa
 		await this.device.applicationManager.restartApplication({ appId: deviceAppData.appIdentifier, projectName });
 	}
 
+	@performanceLog()
 	public async beforeLiveSyncAction(deviceAppData: Mobile.IDeviceAppData): Promise<void> {
 		const deviceRootPath = await this.$devicePathProvider.getDeviceProjectRootPath(deviceAppData.device, {
 			appIdentifier: deviceAppData.appIdentifier,
@@ -111,6 +113,7 @@ export class AndroidDeviceLiveSyncService extends AndroidDeviceLiveSyncServiceBa
 		return true;
 	}
 
+	@performanceLog()
 	public async removeFiles(deviceAppData: Mobile.IDeviceAppData, localToDevicePaths: Mobile.ILocalToDevicePathData[]): Promise<void> {
 		const deviceRootPath = await this.$devicePathProvider.getDeviceProjectRootPath(deviceAppData.device, {
 			appIdentifier: deviceAppData.appIdentifier,
diff --git a/lib/services/livesync/android-livesync-service.ts b/lib/services/livesync/android-livesync-service.ts
@@ -1,6 +1,7 @@
 import { AndroidDeviceLiveSyncService } from "./android-device-livesync-service";
 import { AndroidDeviceSocketsLiveSyncService } from "./android-device-livesync-sockets-service";
 import { PlatformLiveSyncServiceBase } from "./platform-livesync-service-base";
+import { performanceLog } from "../../common/decorators";
 import * as semver from "semver";
 
 export class AndroidLiveSyncService extends PlatformLiveSyncServiceBase implements IPlatformLiveSyncService {
@@ -23,6 +24,7 @@ export class AndroidLiveSyncService extends PlatformLiveSyncServiceBase implemen
 		return this.$injector.resolve<INativeScriptDeviceLiveSyncService>(AndroidDeviceLiveSyncService, { device, data });
 	}
 
+	@performanceLog()
 	public async liveSyncWatchAction(device: Mobile.IDevice, liveSyncInfo: ILiveSyncWatchInfo): Promise<IAndroidLiveSyncResultInfo> {
 		let result = await this.liveSyncWatchActionCore(device, liveSyncInfo);
 
@@ -45,6 +47,7 @@ export class AndroidLiveSyncService extends PlatformLiveSyncServiceBase implemen
 		return result;
 	}
 
+	@performanceLog()
 	public async fullSync(syncInfo: IFullSyncInfo): Promise<IAndroidLiveSyncResultInfo> {
 		const liveSyncResult = await super.fullSync(syncInfo);
 		const result = await this.finalizeSync(syncInfo.device, syncInfo.projectData, liveSyncResult);
diff --git a/lib/services/livesync/device-livesync-service-base.ts b/lib/services/livesync/device-livesync-service-base.ts
@@ -1,5 +1,6 @@
 import { cache } from "../../common/decorators";
 import * as path from "path";
+import { performanceLog } from "../../common/decorators";
 
 export abstract class DeviceLiveSyncServiceBase {
 	private static FAST_SYNC_FILE_EXTENSIONS = [".css", ".xml", ".html"];
@@ -27,6 +28,7 @@ export abstract class DeviceLiveSyncServiceBase {
 		return fastSyncFileExtensions;
 	}
 
+	@performanceLog()
 	public async transferFiles(deviceAppData: Mobile.IDeviceAppData, localToDevicePaths: Mobile.ILocalToDevicePathData[], projectFilesPath: string, projectData: IProjectData, liveSyncDeviceInfo: ILiveSyncDeviceInfo, options: ITransferFilesOptions): Promise<Mobile.ILocalToDevicePathData[]> {
 		let transferredFiles: Mobile.ILocalToDevicePathData[] = [];
 
diff --git a/lib/services/livesync/ios-device-livesync-service.ts b/lib/services/livesync/ios-device-livesync-service.ts
@@ -2,6 +2,7 @@ import * as constants from "../../constants";
 import * as minimatch from "minimatch";
 import * as net from "net";
 import { DeviceLiveSyncServiceBase } from "./device-livesync-service-base";
+import { performanceLog } from "../../common/decorators";
 
 let currentPageReloadId = 0;
 
@@ -33,6 +34,7 @@ export class IOSDeviceLiveSyncService extends DeviceLiveSyncServiceBase implemen
 		return true;
 	}
 
+	@performanceLog()
 	public async removeFiles(deviceAppData: Mobile.IDeviceAppData, localToDevicePaths: Mobile.ILocalToDevicePathData[]): Promise<void> {
 		await Promise.all(_.map(localToDevicePaths, localToDevicePathData => this.device.fileSystem.deleteFile(localToDevicePathData.getDevicePath(), deviceAppData.appIdentifier)));
 	}
diff --git a/lib/services/livesync/ios-livesync-service.ts b/lib/services/livesync/ios-livesync-service.ts
@@ -4,6 +4,7 @@ import * as temp from "temp";
 import { IOSDeviceLiveSyncService } from "./ios-device-livesync-service";
 import { PlatformLiveSyncServiceBase } from "./platform-livesync-service-base";
 import { APP_FOLDER_NAME, TNS_MODULES_FOLDER_NAME } from "../../constants";
+import { performanceLog } from "../../common/decorators";
 
 export class IOSLiveSyncService extends PlatformLiveSyncServiceBase implements IPlatformLiveSyncService {
 	constructor(protected $fs: IFileSystem,
@@ -17,6 +18,7 @@ export class IOSLiveSyncService extends PlatformLiveSyncServiceBase implements I
 		super($fs, $logger, $platformsData, $projectFilesManager, $devicePathProvider, $projectFilesProvider);
 	}
 
+	@performanceLog()
 	public async fullSync(syncInfo: IFullSyncInfo): Promise<ILiveSyncResultInfo> {
 		const device = syncInfo.device;
 
@@ -57,6 +59,7 @@ export class IOSLiveSyncService extends PlatformLiveSyncServiceBase implements I
 		};
 	}
 
+	@performanceLog()
 	public liveSyncWatchAction(device: Mobile.IDevice, liveSyncInfo: ILiveSyncWatchInfo): Promise<ILiveSyncResultInfo> {
 		if (liveSyncInfo.isReinstalled) {
 			// In this case we should execute fullsync because iOS Runtime requires the full content of app dir to be extracted in the root of sync dir.
diff --git a/lib/services/performance-service.ts b/lib/services/performance-service.ts
@@ -0,0 +1,76 @@
+import { TrackActionNames } from "../constants";
+const EOL = require("os").EOL;
+import { getFormattedDate } from "../common/helpers";
+
+export class PerformanceService implements IPerformanceService {
+	public static LOG_MESSAGE_TEMPLATE = `Execution of method "%s" took %s ms.`;
+	public static FAIL_LOG_MESSAGE_TEMPLATE = `Failed to log pefromance data for method %s.`;
+
+	constructor(
+		private $options: IOptions,
+		private $fs: IFileSystem,
+		private $logger: ILogger,
+		private $analyticsService: IAnalyticsService
+	) { }
+
+	public processExecutionData(methodInfo: string, startTime: number, endTime: number, args: any[]): void {
+		const executionTime = Math.floor(endTime - startTime);
+
+		this.trackAnalyticsData(methodInfo, executionTime);
+
+		if (typeof this.$options.performance === "string") {
+			this.logDataToFile(this.$options.performance, methodInfo, executionTime, args);
+		} else if (this.$options.performance) {
+			this.$logger.info(PerformanceService.LOG_MESSAGE_TEMPLATE, methodInfo, executionTime);
+		}
+	}
+
+	private trackAnalyticsData(methodInfo: string, executionTime: number): void {
+		this.$analyticsService.trackEventActionInGoogleAnalytics({
+			action: TrackActionNames.Performance,
+			additionalData: methodInfo,
+			value: executionTime
+		})
+		.catch((err) => {
+			throw err;
+		});
+	}
+
+	private logDataToFile(filePath: string, methodInfo: string, executionTime: number, args: any[]) {
+		let methodArgs;
+		const getCircularReplacer = () => {
+			const seen = new WeakSet();
+			seen.add(this.$options);
+			return (key: any, value: any) => {
+				if (typeof value === "object" && value !== null) {
+					if (seen.has(value) || _.startsWith(key, "$")) {
+						return;
+					}
+					seen.add(value);
+				}
+				return value;
+			};
+		};
+
+		try {
+			methodArgs = JSON.stringify(args, getCircularReplacer());
+		} catch (e) {
+			methodArgs = "cyclic args";
+		}
+
+		const info = {
+			methodInfo,
+			executionTime,
+			timestamp: getFormattedDate(),
+			methodArgs: JSON.parse(methodArgs)
+		}
+
+		try {
+			this.$fs.appendFile(filePath, `${JSON.stringify(info)}${EOL}`);
+		} catch (e) {
+			this.$logger.trace(PerformanceService.FAIL_LOG_MESSAGE_TEMPLATE, methodInfo);
+		}
+	}
+}
+
+$injector.register('performanceService', PerformanceService);
diff --git a/lib/services/platform-service.ts b/lib/services/platform-service.ts
diff --git a/lib/services/prepare-platform-js-service.ts b/lib/services/prepare-platform-js-service.ts
diff --git a/lib/services/prepare-platform-native-service.ts b/lib/services/prepare-platform-native-service.ts

Original file line number	Diff line number	Diff line change
`@@ -152,7 +152,8 @@ export const enum TrackActionNames {`
`152`	`152`	`CheckLocalBuildSetup = "Check Local Build Setup",`
`153`	`153`	`CheckEnvironmentRequirements = "Check Environment Requirements",`
`154`	`154`	`Options = "Options",`
`155`		`- AcceptTracking = "Accept Tracking"`
	`155`	`+ AcceptTracking = "Accept Tracking",`
	`156`	`+ Performance = "Performance"`
`156`	`157`	`}`
`157`	`158`
`158`	`159`	`export const AnalyticsEventLabelDelimiter = "__";`
Original file line number	Diff line number	Diff line change
`@@ -119,7 +119,8 @@ export class Options {`
`119`	`119`	`analyticsLogFile: { type: OptionType.String, hasSensitiveValue: true },`
`120`	`120`	`hooks: { type: OptionType.Boolean, default: true, hasSensitiveValue: false },`
`121`	`121`	`link: { type: OptionType.Boolean, default: false, hasSensitiveValue: false },`
`122`		`- aab: { type: OptionType.Boolean, hasSensitiveValue: false }`
	`122`	`+ aab: { type: OptionType.Boolean, hasSensitiveValue: false },`
	`123`	`+ performance: { type: OptionType.Object, hasSensitiveValue: true }`
`123`	`124`	`};`
`124`	`125`	`}`
`125`	`126`