diff --git a/lib/bootstrap.ts b/lib/bootstrap.ts index e3b440ddd3..80ab81e867 100644 --- 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/commands/debug.ts b/lib/commands/debug.ts index e2cba61edc..323cbb605b 100644 --- a/lib/commands/debug.ts +++ b/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 { if (this.$options.forDevice && this.$options.emulator) { this.$errors.fail(DebugCommandErrors.UNABLE_TO_USE_FOR_DEVICE_AND_EMULATOR); diff --git a/lib/common/decorators.ts b/lib/common/decorators.ts index 1266c524a8..d44d174ebc 100644 --- a/lib/common/decorators.ts +++ b/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) { + 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; + }; +} diff --git a/lib/common/definitions/google-analytics.d.ts b/lib/common/definitions/google-analytics.d.ts index 5524cff204..4a99d9a7ae 100644 --- 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 index 886754d424..85117c7ea4 100644 --- a/lib/common/helpers.ts +++ b/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 diff --git a/lib/common/services/hooks-service.ts b/lib/common/services/hooks-service.ts index 05692c89e1..e1bd095e64 100644 --- a/lib/common/services/hooks-service.ts +++ b/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; diff --git a/lib/common/test/unit-tests/decorators.ts b/lib/common/test/unit-tests/decorators.ts index b21f7e16a5..46e5a117a7 100644 --- a/lib/common/test/unit-tests/decorators.ts +++ b/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; + rejectMethod?(): Promise; + } + 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"); + }); + }); }); diff --git a/lib/constants.ts b/lib/constants.ts index 5837094b12..e5fd7df784 100644 --- 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 index 9bf8b575f1..631462421e 100644 --- a/lib/declarations.d.ts +++ b/lib/declarations.d.ts @@ -75,6 +75,14 @@ interface INodePackageManager { getCachePath(): Promise; } +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; getLatestVersion(packageName: string): Promise; @@ -563,6 +571,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 index e984e9ef09..9c1000f297 100644 --- 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/package-manager.ts b/lib/package-manager.ts index 61ea037b82..61d5adbe36 100644 --- a/lib/package-manager.ts +++ b/lib/package-manager.ts @@ -1,5 +1,6 @@ import { cache, exported, invokeInit } from './common/decorators'; +import { performanceLog } from "./common/decorators"; export class PackageManager implements INodePackageManager { private packageManager: INodePackageManager; @@ -17,6 +18,7 @@ export class PackageManager implements INodePackageManager { } @exported("packageManager") + @performanceLog() @invokeInit() public install(packageName: string, pathToSave: string, config: INodePackageManagerInstallOptions): Promise { return this.packageManager.install(packageName, pathToSave, config); diff --git a/lib/services/analytics/analytics-logging-service.ts b/lib/services/analytics/analytics-logging-service.ts index feb1423d61..008382f0f8 100644 --- 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 { getFixedLengthDateString } 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 = getFixedLengthDateString(); 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 index ea3e992d75..58206abb17 100644 --- 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-device-debug-service.ts b/lib/services/android-device-debug-service.ts index 8b6cf0106a..febdceebac 100644 --- a/lib/services/android-device-debug-service.ts +++ b/lib/services/android-device-debug-service.ts @@ -1,6 +1,7 @@ import { sleep } from "../common/helpers"; import { DebugServiceBase } from "./debug-service-base"; import { LiveSyncPaths } from "../common/constants"; +import { performanceLog } from "../common/decorators"; export class AndroidDeviceDebugService extends DebugServiceBase implements IDeviceDebugService { private _packageName: string; @@ -24,6 +25,7 @@ export class AndroidDeviceDebugService extends DebugServiceBase implements IDevi this.deviceIdentifier = device.deviceInfo.identifier; } + @performanceLog() public async debug(debugData: IDebugData, debugOptions: IDebugOptions): Promise { this._packageName = debugData.applicationIdentifier; const result = this.device.isEmulator @@ -97,6 +99,7 @@ export class AndroidDeviceDebugService extends DebugServiceBase implements IDevi return this.device.adb.executeCommand(["forward", `tcp:${local}`, `localabstract:${remote}`]); } + @performanceLog() private async debugOnDevice(debugData: IDebugData, debugOptions: IDebugOptions): Promise { let packageFile = ""; @@ -119,9 +122,9 @@ export class AndroidDeviceDebugService extends DebugServiceBase implements IDevi return deviceActionResult[0].result; } + @performanceLog() private async debugCore(device: Mobile.IAndroidDevice, packageFile: string, appData: Mobile.IApplicationData, debugOptions: IDebugOptions): Promise { const result: IDebugResultInfo = { hasReconnected: false, debugUrl: null }; - if (debugOptions.stop) { await this.removePortForwarding(); return result; diff --git a/lib/services/android-project-service.ts b/lib/services/android-project-service.ts index c8cfd0062a..f53f16765e 100644 --- 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 { let task; const gradleArgs = this.getGradleBuildOptions(buildConfig, projectData); diff --git a/lib/services/debug-service.ts b/lib/services/debug-service.ts index 0b5186ca72..0d2ca0afa1 100644 --- a/lib/services/debug-service.ts +++ b/lib/services/debug-service.ts @@ -4,6 +4,7 @@ import { EventEmitter } from "events"; import { CONNECTION_ERROR_EVENT_NAME, DebugCommandErrors } from "../constants"; import { CONNECTED_STATUS } from "../common/constants"; import { DebugTools, TrackActionNames } from "../constants"; +import { performanceLog } from "../common/decorators"; export class DebugService extends EventEmitter implements IDebugService { private _platformDebugServices: IDictionary; @@ -17,6 +18,7 @@ export class DebugService extends EventEmitter implements IDebugService { this._platformDebugServices = {}; } + @performanceLog() public async debug(debugData: IDebugData, options: IDebugOptions): Promise { const device = this.$devicesService.getDeviceByIdentifier(debugData.deviceIdentifier); diff --git a/lib/services/ios-device-debug-service.ts b/lib/services/ios-device-debug-service.ts index ed711ff184..641657f0ec 100644 --- a/lib/services/ios-device-debug-service.ts +++ b/lib/services/ios-device-debug-service.ts @@ -8,6 +8,7 @@ import { getPidFromiOSSimulatorLogs } from "../common/helpers"; const inspectorAppName = "NativeScript Inspector.app"; const inspectorNpmPackageName = "tns-ios-inspector"; const inspectorUiDir = "WebInspectorUI/"; +import { performanceLog } from "../common/decorators"; export class IOSDeviceDebugService extends DebugServiceBase implements IDeviceDebugService { private _lldbProcess: ChildProcess; @@ -38,6 +39,7 @@ export class IOSDeviceDebugService extends DebugServiceBase implements IDeviceDe return "ios"; } + @performanceLog() public async debug(debugData: IDebugData, debugOptions: IDebugOptions): Promise { const result: IDebugResultInfo = { hasReconnected: false, debugUrl: null }; this.validateOptions(debugOptions); @@ -79,6 +81,7 @@ export class IOSDeviceDebugService extends DebugServiceBase implements IDeviceDe } } + @performanceLog() private async startDeviceLogProcess(debugData: IDebugData, debugOptions: IDebugOptions): Promise { if (debugOptions.justlaunch) { // No logs should be printed on console when `--justlaunch` option is passed. @@ -99,6 +102,7 @@ export class IOSDeviceDebugService extends DebugServiceBase implements IDeviceDe await this.device.openDeviceLogStream({ predicate: IOS_LOG_PREDICATE }); } + @performanceLog() private async startAppOnSimulator(debugData: IDebugData, debugOptions: IDebugOptions): Promise { const args = debugOptions.debugBrk ? "--nativescript-debug-brk" : "--nativescript-debug-start"; const launchResult = await this.$iOSEmulatorServices.runApplicationOnEmulator(debugData.pathToAppPackage, { @@ -116,6 +120,7 @@ export class IOSDeviceDebugService extends DebugServiceBase implements IDeviceDe this.startAppDebuggerOnSimulator(pid); } + @performanceLog() private async startAppOnDevice(debugData: IDebugData, debugOptions: IDebugOptions): Promise { const runOptions: IRunPlatformOptions = { device: this.deviceIdentifier, @@ -152,6 +157,7 @@ export class IOSDeviceDebugService extends DebugServiceBase implements IDeviceDe } } + @performanceLog() private async wireDebuggerClient(debugData: IDebugData, debugOptions: IDebugOptions): Promise { if ((debugOptions.inspector || !debugOptions.client) && this.$hostInfo.isDarwin) { return await this.setupTcpAppDebugProxy(debugData, debugOptions); @@ -184,6 +190,7 @@ export class IOSDeviceDebugService extends DebugServiceBase implements IDeviceDe return null; } + @performanceLog() private async openAppInspector(fileDescriptor: string, debugData: IDebugData, debugOptions: IDebugOptions): Promise { if (debugOptions.client) { const inspectorPath = await this.$packageInstallationManager.getInspectorFromCache(inspectorNpmPackageName, debugData.projectDir); diff --git a/lib/services/livesync/android-device-livesync-service.ts b/lib/services/livesync/android-device-livesync-service.ts index 07345a146b..7452030e18 100644 --- 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 { 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 { 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 index ddcdc75c7c..5a94d73cce 100644 --- 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(AndroidDeviceLiveSyncService, { device, data }); } + @performanceLog() public async liveSyncWatchAction(device: Mobile.IDevice, liveSyncInfo: ILiveSyncWatchInfo): Promise { 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 { 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 index e9e848d8bd..62f9a8aad5 100644 --- 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 { let transferredFiles: Mobile.ILocalToDevicePathData[] = []; diff --git a/lib/services/livesync/ios-device-livesync-service.ts b/lib/services/livesync/ios-device-livesync-service.ts index 03f693f0a9..45641da0ac 100644 --- 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 { 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 index 2cbd5f749d..b783c6208a 100644 --- 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 { const device = syncInfo.device; @@ -57,6 +59,7 @@ export class IOSLiveSyncService extends PlatformLiveSyncServiceBase implements I }; } + @performanceLog() public liveSyncWatchAction(device: Mobile.IDevice, liveSyncInfo: ILiveSyncWatchInfo): Promise { 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/livesync/livesync-service.ts b/lib/services/livesync/livesync-service.ts index f39e165ef2..849c64f7d6 100644 --- a/lib/services/livesync/livesync-service.ts +++ b/lib/services/livesync/livesync-service.ts @@ -8,6 +8,7 @@ import { DeviceTypes, DeviceDiscoveryEventNames, HmrConstants } from "../../comm import { cache } from "../../common/decorators"; import * as constants from "../../constants"; import { PreviewAppLiveSyncEvents } from "./playground/preview-app-constants"; +import { performanceLog } from "../../common/decorators"; const deviceDescriptorPrimaryKey = "identifier"; @@ -158,6 +159,7 @@ export class LiveSyncService extends EventEmitter implements IDebugLiveSyncServi } } + @performanceLog() private async refreshApplication(projectData: IProjectData, liveSyncResultInfo: ILiveSyncResultInfo, debugOpts?: IDebugOptions, outputPath?: string): Promise { const deviceDescriptor = this.getDeviceDescriptor(liveSyncResultInfo.deviceAppData.device.deviceInfo.identifier, projectData.projectDir); @@ -202,6 +204,7 @@ export class LiveSyncService extends EventEmitter implements IDebugLiveSyncServi return result; } + @performanceLog() private async refreshApplicationWithDebug(projectData: IProjectData, liveSyncResultInfo: ILiveSyncResultInfo, debugOptions: IDebugOptions, outputPath?: string): Promise { let didRestart = false; const deviceAppData = liveSyncResultInfo.deviceAppData; @@ -305,6 +308,7 @@ export class LiveSyncService extends EventEmitter implements IDebugLiveSyncServi return _.find(deviceDescriptors, d => d.identifier === deviceIdentifier); } + @performanceLog() private async enableDebuggingCoreWithoutWaitingCurrentAction(deviceOption: IEnableDebuggingDeviceOptions, debuggingAdditionalOptions: IDebuggingAdditionalOptions): Promise { const currentDeviceDescriptor = this.getDeviceDescriptor(deviceOption.deviceIdentifier, debuggingAdditionalOptions.projectDir); if (!currentDeviceDescriptor) { diff --git a/lib/services/livesync/playground/preview-app-livesync-service.ts b/lib/services/livesync/playground/preview-app-livesync-service.ts index 2883dd1ccf..286e2da588 100644 --- a/lib/services/livesync/playground/preview-app-livesync-service.ts +++ b/lib/services/livesync/playground/preview-app-livesync-service.ts @@ -5,6 +5,7 @@ import { PreviewAppLiveSyncEvents } from "./preview-app-constants"; import { HmrConstants } from "../../../common/constants"; import { stringify } from "../../../common/helpers"; import { EventEmitter } from "events"; +import { performanceLog } from "../../../common/decorators"; export class PreviewAppLiveSyncService extends EventEmitter implements IPreviewAppLiveSyncService { @@ -24,6 +25,7 @@ export class PreviewAppLiveSyncService extends EventEmitter implements IPreviewA super(); } + @performanceLog() public async initialize(data: IPreviewAppLiveSyncData): Promise { await this.$previewSdkService.initialize(async (device: Device) => { try { @@ -54,6 +56,7 @@ export class PreviewAppLiveSyncService extends EventEmitter implements IPreviewA }); } + @performanceLog() public async syncFiles(data: IPreviewAppLiveSyncData, filesToSync: string[], filesToRemove: string[]): Promise { this.showWarningsForNativeFiles(filesToSync); @@ -140,6 +143,7 @@ export class PreviewAppLiveSyncService extends EventEmitter implements IPreviewA } } + @performanceLog() private async onWebpackCompilationComplete(data: IPreviewAppLiveSyncData, hmrData: IDictionary, filesToSyncMap: IDictionary, promise: Promise, platform: string) { await promise .then(async () => { diff --git a/lib/services/performance-service.ts b/lib/services/performance-service.ts new file mode 100644 index 0000000000..612fc229a4 --- /dev/null +++ b/lib/services/performance-service.ts @@ -0,0 +1,98 @@ +import { TrackActionNames } from "../constants"; +const EOL = require("os").EOL; +import { getFixedLengthDateString } from "../common/helpers"; +import * as semver from "semver"; + +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 in file for method %s.`; + private static MIN_NODE_PERFORMANCE_MODULE_VERSION = "8.5.0"; + private performance: {now(): number} = null; + + constructor( + private $options: IOptions, + private $fs: IFileSystem, + private $logger: ILogger, + private $analyticsService: IAnalyticsService + ) { + if (this.isPerformanceModuleSupported()) { + this.performance = require("perf_hooks").performance; + } + } + + 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); + } + } + + public now(): number { + if (this.isPerformanceModuleSupported()) { + return this.performance.now(); + } else { + return new Date().getTime(); + } + } + + private isPerformanceModuleSupported(): boolean { + return semver.gte(process.version, PerformanceService.MIN_NODE_PERFORMANCE_MODULE_VERSION); + } + + 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; + + try { + methodArgs = JSON.stringify(args, this.getJsonSanitizer()); + } catch (e) { + methodArgs = "cyclic args"; + } + + const info = { + methodInfo, + executionTime, + timestamp: getFixedLengthDateString(), + methodArgs: JSON.parse(methodArgs) + }; + + try { + this.$fs.appendFile(filePath, `${JSON.stringify(info)}${EOL}`); + } catch (e) { + this.$logger.trace(PerformanceService.FAIL_LOG_MESSAGE_TEMPLATE, methodInfo); + this.$logger.info(PerformanceService.LOG_MESSAGE_TEMPLATE, methodInfo, executionTime); + } + } + + //removes any injected members of the arguments and excludes the options object even if it was renamed + private getJsonSanitizer() { + 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; + }; + } +} + +$injector.register('performanceService', PerformanceService); diff --git a/lib/services/platform-service.ts b/lib/services/platform-service.ts index 2a433e55c0..06fbe1f24c 100644 --- a/lib/services/platform-service.ts +++ b/lib/services/platform-service.ts @@ -9,6 +9,7 @@ import { EventEmitter } from "events"; import { AppFilesUpdater } from "./app-files-updater"; import { attachAwaitDetach } from "../common/helpers"; import * as temp from "temp"; +import { performanceLog } from ".././common/decorators"; temp.track(); const buildInfoFileName = ".nsbuildinfo"; @@ -190,6 +191,7 @@ export class PlatformService extends EventEmitter implements IPlatformService { return _.filter(this.$platformsData.platformsNames, p => { return this.isPlatformPrepared(p, projectData); }); } + @performanceLog() @helpers.hook('shouldPrepare') public async shouldPrepare(shouldPrepareInfo: IShouldPrepareInfo): Promise { shouldPrepareInfo.changesInfo = shouldPrepareInfo.changesInfo || await this.getChangesInfo(shouldPrepareInfo.platformInfo); @@ -222,6 +224,7 @@ export class PlatformService extends EventEmitter implements IPlatformService { return changesInfo; } + @performanceLog() public async preparePlatform(platformInfo: IPreparePlatformInfo): Promise { const changesInfo = await this.getChangesInfo(platformInfo); const shouldPrepare = await this.shouldPrepare({ platformInfo, changesInfo }); @@ -304,6 +307,7 @@ export class PlatformService extends EventEmitter implements IPlatformService { } /* Hooks are expected to use "filesToSync" parameter, as to give plugin authors additional information about the sync process.*/ + @performanceLog() @helpers.hook('prepare') private async preparePlatformCore(platform: string, appFilesUpdaterOptions: IAppFilesUpdaterOptions, @@ -401,6 +405,7 @@ export class PlatformService extends EventEmitter implements IPlatformService { return prepareInfo.changesRequireBuildTime !== buildInfo.prepareTime; } + @performanceLog() public async buildPlatform(platform: string, buildConfig: IBuildConfig, projectData: IProjectData): Promise { this.$logger.out("Building project..."); diff --git a/lib/services/prepare-platform-js-service.ts b/lib/services/prepare-platform-js-service.ts index 9c95d259ab..e555175d4e 100644 --- a/lib/services/prepare-platform-js-service.ts +++ b/lib/services/prepare-platform-js-service.ts @@ -4,6 +4,7 @@ import * as shell from "shelljs"; import * as temp from "temp"; import { hook } from "../common/helpers"; import { PreparePlatformService } from "./prepare-platform-service"; +import { performanceLog } from "./../common/decorators"; temp.track(); @@ -32,6 +33,7 @@ export class PreparePlatformJSService extends PreparePlatformService implements this.$projectDataService.setNSValue(info.projectData.projectDir, info.platformData.frameworkPackageName, frameworkPackageNameData); } + @performanceLog() @hook('prepareJSApp') public async preparePlatform(config: IPreparePlatformJSInfo): Promise { if (!config.changesInfo || config.changesInfo.appFilesChanged || config.changesInfo.changesRequirePrepare) { diff --git a/lib/services/prepare-platform-native-service.ts b/lib/services/prepare-platform-native-service.ts index e1f01e57b7..e41fc711d7 100644 --- a/lib/services/prepare-platform-native-service.ts +++ b/lib/services/prepare-platform-native-service.ts @@ -1,6 +1,7 @@ import * as constants from "../constants"; import * as path from "path"; import { PreparePlatformService } from "./prepare-platform-service"; +import { performanceLog } from "../common/decorators"; export class PreparePlatformNativeService extends PreparePlatformService implements IPreparePlatformService { @@ -14,6 +15,7 @@ export class PreparePlatformNativeService extends PreparePlatformService impleme super($fs, $hooksService, $xmlValidator); } + @performanceLog() public async addPlatform(info: IAddPlatformInfo): Promise { await info.platformData.platformProjectService.createProject(path.resolve(info.frameworkDir), info.installedVersion, info.projectData, info.config); info.platformData.platformProjectService.ensureConfigurationFileInAppResources(info.projectData); @@ -23,6 +25,7 @@ export class PreparePlatformNativeService extends PreparePlatformService impleme { nativePlatformStatus: constants.NativePlatformStatus.requiresPrepare }); } + @performanceLog() public async preparePlatform(config: IPreparePlatformJSInfo): Promise { if (config.changesInfo.hasChanges) { await this.cleanProject(config.platform, config.appFilesUpdaterOptions, config.platformData, config.projectData); diff --git a/lib/services/project-service.ts b/lib/services/project-service.ts index c77c192a83..3fc3cfd6cd 100644 --- a/lib/services/project-service.ts +++ b/lib/services/project-service.ts @@ -5,6 +5,7 @@ import { format } from "util"; import { exported } from "../common/decorators"; import { Hooks, TemplatesV2PackageJsonKeysToRemove } from "../constants"; import * as temp from "temp"; +import { performanceLog } from "../common/decorators"; export class ProjectService implements IProjectService { @@ -37,6 +38,7 @@ export class ProjectService implements IProjectService { } @exported("projectService") + @performanceLog() public async createProject(projectOptions: IProjectSettings): Promise { const projectName = await this.validateProjectName({ projectName: projectOptions.projectName, force: projectOptions.force, pathToProject: projectOptions.pathToProject }); const projectDir = this.getValidProjectDir(projectOptions.pathToProject, projectName); @@ -120,6 +122,7 @@ export class ProjectService implements IProjectService { return { projectName, projectDir }; } + @performanceLog() private async extractTemplate(projectDir: string, templateData: ITemplateData): Promise { this.$fs.ensureDirectoryExists(projectDir); @@ -142,6 +145,7 @@ export class ProjectService implements IProjectService { } } + @performanceLog() private async ensureAppResourcesExist(projectDir: string): Promise { const projectData = this.$projectDataService.getProjectData(projectDir); const appResourcesDestinationPath = projectData.getAppResourcesDirectoryPath(projectDir); @@ -221,6 +225,7 @@ export class ProjectService implements IProjectService { }; } + @performanceLog() private alterPackageJsonData(projectDir: string, projectId: string): void { const projectFilePath = path.join(projectDir, this.$staticConfig.PROJECT_FILE_NAME); @@ -242,6 +247,7 @@ export class ProjectService implements IProjectService { this.$projectDataService.setNSValue(projectDir, "id", projectId); } + @performanceLog() private async addTnsCoreModules(projectDir: string): Promise { const projectFilePath = path.join(projectDir, this.$staticConfig.PROJECT_FILE_NAME); const packageJsonData = this.$fs.readJson(projectFilePath); diff --git a/lib/services/project-templates-service.ts b/lib/services/project-templates-service.ts index d710ee8beb..665cf5acea 100644 --- a/lib/services/project-templates-service.ts +++ b/lib/services/project-templates-service.ts @@ -2,6 +2,7 @@ import * as path from "path"; import * as temp from "temp"; import * as constants from "../constants"; import { format } from "util"; +import { performanceLog } from "../common/decorators"; temp.track(); export class ProjectTemplatesService implements IProjectTemplatesService { @@ -15,6 +16,7 @@ export class ProjectTemplatesService implements IProjectTemplatesService { private $errors: IErrors, private $packageManager: INodePackageManager) { } + @performanceLog() public async prepareTemplate(templateValue: string, projectDir: string): Promise { if (!templateValue) { templateValue = constants.RESERVED_TEMPLATE_NAMES["default"]; diff --git a/test/stubs.ts b/test/stubs.ts index c573f2304f..a6d04b60b0 100644 --- a/test/stubs.ts +++ b/test/stubs.ts @@ -914,6 +914,11 @@ export class AndroidBundleValidatorHelper implements IAndroidBundleValidatorHelp } } +export class PerformanceService implements IPerformanceService { + now(): number { return 10; } + processExecutionData() {} +} + export class InjectorStub extends Yok implements IInjector { constructor() { super(); @@ -939,5 +944,6 @@ export class InjectorStub extends Yok implements IInjector { this.register("androidPluginBuildService", AndroidPluginBuildServiceStub); this.register('projectData', ProjectDataStub); this.register('packageInstallationManager', PackageInstallationManagerStub); + this.register('packageInstallationManager', PackageInstallationManagerStub); } } diff --git a/test/test-bootstrap.ts b/test/test-bootstrap.ts index f9cb09e9ac..5468c17745 100644 --- a/test/test-bootstrap.ts +++ b/test/test-bootstrap.ts @@ -22,6 +22,9 @@ $injector.register("analyticsService", { } }); +import { PerformanceService } from "./stubs"; +$injector.register("performanceService", PerformanceService); + // Converts the js callstack to typescript import errors = require("../lib/common/errors"); errors.installUncaughtExceptionListener();