diff --git a/tests/app/profiling/profiling-tests.ts b/tests/app/profiling/profiling-tests.ts index a44c31078..669962d2d 100644 --- a/tests/app/profiling/profiling-tests.ts +++ b/tests/app/profiling/profiling-tests.ts @@ -1,74 +1,100 @@ import { assert, assertEqual, assertFalse, assertTrue, assertThrows } from "../TKUnit"; -import * as prof from "tns-core-modules/profiling"; -import { isAndroid } from "tns-core-modules/platform"; +import { enable, disable, profile, time, start, stop, pause, isRunning } from "tns-core-modules/profiling"; -prof.enable(); +enable(); class TestClass { - @prof.profile("__func_decorator__") + @profile("__func_decorator__") doNothing() { //noop } - @prof.profile("__func_decorator_error__") + @profile("__func_decorator_error__") throwError() { throw new Error("This error is expected"); } + + @profile + unnamed1() { + // noop + } + + @profile() + unnamed2() { + // noop + } +} + +const testFunction1 = profile(function testFunction1() { + // noop +}); +const testFunction2 = profile("testFunction2", () => { + // noop +}); +disable(); + +function retry(count: number, action: () => void) { + for (var i = 1; i <= count; i++) { + try { + action(); + return; + } catch(e) { + if (i === count) { + throw e; + } + } + } } -prof.disable(); export function setUp() { - prof.enable(); + enable(); } export function tearDown() { - prof.disable(); + disable(); } -export function test_time_throws_if_not_enabled() { - prof.disable(); - assertThrows(prof.time); -}; - -export function test_time_returns_number_if_enabled() { - assertEqual(typeof prof.time(), "number"); +export function test_time_returns_number() { + assertEqual(typeof time(), "number"); }; export function test_isRunning() { const name = "test_isRunning"; - assertFalse(prof.isRunning(name), "isRunning should be false before start"); + assertFalse(isRunning(name), "isRunning should be false before start"); - prof.start(name); - assertTrue(prof.isRunning(name), "isRunning should be true after start"); + start(name); + assertTrue(isRunning(name), "isRunning should be true after start"); - prof.pause(name); - assertFalse(prof.isRunning(name), "isRunning should be false after pause"); + pause(name); + assertFalse(isRunning(name), "isRunning should be false after pause"); - prof.start(name); - assertTrue(prof.isRunning(name), "isRunning should be true after second start"); + start(name); + assertTrue(isRunning(name), "isRunning should be true after second start"); - prof.stop(name); - assertFalse(prof.isRunning(name), "isRunning should be false after stop"); + stop(name); + assertFalse(isRunning(name), "isRunning should be false after stop"); } export function test_start_stop() { - const name = "test_start_stop"; + retry(5, () => { + const name = "test_start_stop"; - prof.start(name); - const res = prof.stop(name); + start(name); + const res = stop(name); - assertEqual(res.count, 1); - assert(res.totalTime <= 1); + assertEqual(res.count, 1); + assert(res.totalTime <= 1); + }); }; export function test_start_pause_count() { const name = "test_start_pause_count"; for (var i = 0; i < 10; i++) { - prof.start(name); - prof.pause(name); + start(name); + pause(name); } - const res = prof.stop(name); + const res = stop(name); assertEqual(res.count, 10); }; @@ -76,52 +102,56 @@ export function test_profile_decorator_count() { const test = new TestClass(); for (var i = 0; i < 10; i++) { test.doNothing(); + test.unnamed1(); + test.unnamed2(); + testFunction1(); + testFunction2(); } - const res = prof.stop("__func_decorator__"); - assertEqual(res.count, 10); + ["__func_decorator__", "TestClass.unnamed1", "TestClass.unnamed2", "testFunction1", "testFunction2"].forEach(key => { + const res = stop(key); + assertEqual(res.count, 10, "Expected profile with name ${key} to have traced 10 calls."); + }); } export function test_profile_decorator_handles_exceptions() { const test = new TestClass(); assertThrows(() => test.throwError()); - assertFalse(prof.isRunning("__func_decorator_error__"), "Timer should be stopped on exception."); - assertEqual(prof.stop("__func_decorator_error__").count, 1, "Timer should be called once"); + assertFalse(isRunning("__func_decorator_error__"), "Timer should be stopped on exception."); + assertEqual(stop("__func_decorator_error__").count, 1, "Timer should be called once"); } export function test_start_pause_performance() { - if (isAndroid) { - // TODO: skip these test for android as they are unstable - return; - } + retry(5, () => { + const count = 10000; + const name = "test_start_pause_performance"; - const count = 10000; - const name = "test_start_pause_performance"; + for (var i = 0; i < count; i++) { + start(name); + pause(name); + } - for (var i = 0; i < count; i++) { - prof.start(name); - prof.pause(name); - } - - const res = prof.stop(name); - assertEqual(res.count, count); - assert(res.totalTime <= 50, `Total time for ${count} timer operations is too much: ${res.totalTime}`); + const res = stop(name); + assertEqual(res.count, count); + assert(res.totalTime <= 500, `Total time for ${count} timer operations is too much: ${res.totalTime}`); + }); }; export function test_profile_decorator_performance() { - if (isAndroid) { - // TODO: skip these test for android as they are unstable - return; - } + retry(5, () => { + var start = Date.now(); + const count = 10000; + const test = new TestClass(); + for (var i = 0; i < count; i++) { + test.doNothing(); + } - const count = 10000; - const test = new TestClass(); - for (var i = 0; i < count; i++) { - test.doNothing(); - } + const res = stop("__func_decorator__"); + assertEqual(res.count, count); - const res = prof.stop("__func_decorator__"); - assertEqual(res.count, count); - assert(res.totalTime <= 50, `Total time for ${count} timer operations is too much: ${res.totalTime}`); -} \ No newline at end of file + assert(res.totalTime <= 500, `Total time for ${count} timer operations is too much: ${res.totalTime}`); + var end = Date.now(); + assert(end - start <= 1000, `Total time for test execution is too much: ${end - start}ms`); + }); +} diff --git a/tns-core-modules/file-system/file-system.ts b/tns-core-modules/file-system/file-system.ts index 7c8761729..fe97ab75d 100644 --- a/tns-core-modules/file-system/file-system.ts +++ b/tns-core-modules/file-system/file-system.ts @@ -1,5 +1,6 @@ import * as file_access_module from "./file-system-access"; import * as platformModule from "../platform"; +import { profile } from "../profiling"; // The FileSystemAccess implementation, used through all the APIs. var fileAccess; @@ -257,6 +258,7 @@ export class File extends FileSystemEntity { }); } + @profile public readTextSync(onError?: (error: any) => any, encoding?: string): string { this.checkAccess(); diff --git a/tns-core-modules/profiling/profiling.d.ts b/tns-core-modules/profiling/profiling.d.ts index 047191096..a3b485585 100644 --- a/tns-core-modules/profiling/profiling.d.ts +++ b/tns-core-modules/profiling/profiling.d.ts @@ -20,8 +20,7 @@ export declare function enable(): void; export declare function disable(): void; /** - * Gets accurate system timestamp in ms. - * Works only if profiling is enabled. + * Gets accurate system timestamp in ms. */ export declare function time(): number; @@ -61,6 +60,23 @@ export declare function isRunning(name: string): boolean; * @param name Name of the timer which will be used for method calls. If not provided - the name of the method will be used. */ export declare function profile(name?: string): MethodDecorator; +/** + * Function factory. It will intercept the function call and start and pause a timer before and after the function call. Works only if profiling is enabled. + * Works only if profiling is enabled. + * @param fn The function to wrap. Uses the function name to track the times. + */ +export declare function profile(fn: F): F; +/** + * Function factory. It will intercept the function call and start and pause a timer before and after the function call. Works only if profiling is enabled. + * @param name The name used to track calls and times. + * @param fn The function to wrap. + */ +export declare function profile(name: string, fn: F): F; +/** + * Method decorator. It will intercept the method calls and start and pause a timer before and after the method call. Works only if profiling is enabled. + */ +export declare function profile(target: Object, propertyKey: string | symbol, descriptor: TypedPropertyDescriptor): TypedPropertyDescriptor | void; +export function profile(): any; /** * Prints the timer for all methods instrumented with profile decorator. @@ -83,3 +99,8 @@ export declare function startCPUProfile(name: string): void; * @param name Name of the cpu profiling session. */ export declare function stopCPUProfile(name: string): void; + +/** + * Gets the uptime of the current process in miliseconds. + */ +export function uptime(): number; \ No newline at end of file diff --git a/tns-core-modules/profiling/profiling.ts b/tns-core-modules/profiling/profiling.ts index c168d0c3d..bf6ac7597 100644 --- a/tns-core-modules/profiling/profiling.ts +++ b/tns-core-modules/profiling/profiling.ts @@ -3,6 +3,8 @@ declare var __stopCPUProfiler: any; import { TimerInfo as TimerInfoDefinition } from "."; +export const uptime = global.android ? (org).nativescript.Process.getUpTime : (global).__tns_uptime; + interface TimerInfo extends TimerInfoDefinition { totalTime: number; lastTime?: number; @@ -16,41 +18,19 @@ const timers: { [index: string]: TimerInfo } = {}; const anyGlobal = global; const profileNames: string[] = []; -let ENABLED = false; -let nativeTimeFunc: () => number; +let instrumentationEnabled = false; export function enable() { - ENABLED = true; - - if (!nativeTimeFunc) { - // init timeFunc - if (anyGlobal.android) { - const nanoTime = java.lang.System.nanoTime; - // 1 ms = 1000000 ns - nativeTimeFunc = () => { return nanoTime() / 1000000 }; - } else { - nativeTimeFunc = () => { return CACurrentMediaTime() * 1000; }; - } - } + instrumentationEnabled = true; } export function disable() { - ENABLED = false; + instrumentationEnabled = false; } -export function time(): number { - if (!ENABLED) { - throw new Error("Profiling is not enabled"); - } - - return nativeTimeFunc(); -} +export const time = (global).__time || Date.now; export function start(name: string): void { - if (!ENABLED) { - return; - } - let info = timers[name]; if (info) { @@ -71,20 +51,11 @@ export function start(name: string): void { } export function pause(name: string): TimerInfo { - if (!ENABLED) { - return; - } - let info = pauseInternal(name); - // console.log(`---- [${name}] PAUSE last: ${info.lastTime} total: ${info.totalTime} count: ${info.count}`); return info; } export function stop(name: string): TimerInfo { - if (!ENABLED) { - return; - } - let info = pauseInternal(name); console.log(`---- [${name}] STOP total: ${info.totalTime} count:${info.count}`); @@ -115,11 +86,52 @@ function pauseInternal(name: string): TimerInfo { return info; } -export function profile(name?: string): MethodDecorator { - return (target, key, descriptor) => { - if (!ENABLED) { - return; +function profileFunction(fn: F, customName?: string): F { + const name = customName || fn.name; + profileNames.push(name); + return function() { + start(name); + try { + return fn.apply(this, arguments); + } finally { + pause(name); } + } +} + +const profileMethodUnnamed = (target, key, descriptor) => { + // save a reference to the original method this way we keep the values currently in the + // descriptor and don't overwrite what another decorator might have done to the descriptor. + if (descriptor === undefined) { + descriptor = Object.getOwnPropertyDescriptor(target, key); + } + var originalMethod = descriptor.value; + + let className = ""; + if (target && target.constructor && target.constructor.name) { + className = target.constructor.name + "."; + } + + let name = className + key; + + profileNames.push(name); + + //editing the descriptor/value parameter + descriptor.value = function () { + start(name); + try { + return originalMethod.apply(this, arguments); + } finally { + pause(name); + } + }; + + // return edited descriptor as opposed to overwriting the descriptor + return descriptor; +} + +function profileMethodNamed(name: string): MethodDecorator { + return (target, key, descriptor) => { // save a reference to the original method this way we keep the values currently in the // descriptor and don't overwrite what another decorator might have done to the descriptor. @@ -128,15 +140,6 @@ export function profile(name?: string): MethodDecorator { } var originalMethod = descriptor.value; - if (!name) { - let className = ""; - if (target && target.constructor && target.constructor.name) { - className = target.constructor.name + "."; - } - - name = className + key; - } - profileNames.push(name); //editing the descriptor/value parameter @@ -154,6 +157,39 @@ export function profile(name?: string): MethodDecorator { } } +const voidMethodDecorator = () => { + // no op +}; + +export function profile(nameFnOrTarget?: string | Function | Object, fnOrKey?: Function | string | symbol, descriptor?: PropertyDescriptor): Function | MethodDecorator { + if (typeof nameFnOrTarget === "object" && (typeof fnOrKey === "string" || typeof fnOrKey === "symbol")) { + if (!instrumentationEnabled) { + return; + } + return profileMethodUnnamed(nameFnOrTarget, fnOrKey, descriptor); + } else if (typeof nameFnOrTarget === "string" && typeof fnOrKey === "function") { + if (!instrumentationEnabled) { + return fnOrKey; + } + return profileFunction(fnOrKey, nameFnOrTarget); + } else if (typeof nameFnOrTarget === "function") { + if (!instrumentationEnabled) { + return nameFnOrTarget; + } + return profileFunction(nameFnOrTarget); + } else if (typeof nameFnOrTarget === "string") { + if (!instrumentationEnabled) { + return voidMethodDecorator; + } + return profileMethodNamed(nameFnOrTarget); + } else { + if (!instrumentationEnabled) { + return voidMethodDecorator; + } + return profileMethodUnnamed; + } +} + export function dumpProfiles(): void { profileNames.forEach(function (name) { const info = timers[name]; @@ -182,20 +218,12 @@ export function resetProfiles(): void { } export function startCPUProfile(name: string) { - if (!ENABLED) { - return; - } - if (anyGlobal.android) { __startCPUProfiler(name); } } export function stopCPUProfile(name: string) { - if (!ENABLED) { - return; - } - if (anyGlobal.android) { __stopCPUProfiler(name); } diff --git a/tns-core-modules/ui/styling/style-scope.ts b/tns-core-modules/ui/styling/style-scope.ts index 3b07eaeaa..b4737e792 100644 --- a/tns-core-modules/ui/styling/style-scope.ts +++ b/tns-core-modules/ui/styling/style-scope.ts @@ -6,6 +6,7 @@ import { RuleSet, SelectorsMap, SelectorCore, SelectorsMatch, ChangeMap, fromAst import { write as traceWrite, categories as traceCategories, messageType as traceMessageType } from "../../trace"; import { File, knownFolders, path } from "../../file-system"; import * as application from "../../application"; +import { profile } from "../../profiling"; import * as kam from "../animation/keyframe-animation"; let keyframeAnimationModule: typeof kam; @@ -37,7 +38,7 @@ const applicationKeyframes: any = {}; const animationsSymbol: symbol = Symbol("animations"); const pattern: RegExp = /('|")(.*?)\1/; -function onCssChanged(args: application.CssChangedEventData): void { +const onCssChanged = profile('"style-scope".onCssChanged', (args: application.CssChangedEventData) => { if (args.cssText) { const parsed = createSelectorsFromCss(args.cssText, args.cssFile, applicationKeyframes); if (parsed) { @@ -47,13 +48,13 @@ function onCssChanged(args: application.CssChangedEventData): void { } else if (args.cssFile) { loadCss(args.cssFile); } -} +}); function onLiveSync(args: application.CssChangedEventData): void { loadCss(application.getCssFileName()); } -function loadCss(cssFile?: string): RuleSet[] { +const loadCss = profile(`"style-scope".loadCss`, (cssFile?: string) => { if (!cssFile) { return undefined; } @@ -70,15 +71,16 @@ function loadCss(cssFile?: string): RuleSet[] { mergeCssSelectors(); } } -} +}); application.on("cssChanged", onCssChanged); application.on("livesync", onLiveSync); -function loadCssOnLaunch() { +export const loadCssOnLaunch = profile('"style-scope".loadCssOnLaunch', () => { loadCss(application.getCssFileName()); application.off("launch", loadCssOnLaunch); -} +}); + if (application.hasLaunched()) { loadCssOnLaunch(); } else { @@ -180,6 +182,7 @@ export class StyleScope { this.appendCss(cssString, cssFileName) } + @profile private setCss(cssString: string, cssFileName?): void { this._css = cssString; this._reset(); @@ -188,6 +191,7 @@ export class StyleScope { this.ensureSelectors(); } + @profile private appendCss(cssString: string, cssFileName?): void { if (!cssString) { return; @@ -214,27 +218,32 @@ export class StyleScope { } public ensureSelectors(): number { - let toMerge: RuleSet[][]; if (this._applicationCssSelectorsAppliedVersion !== applicationCssSelectorVersion || this._localCssSelectorVersion !== this._localCssSelectorsAppliedVersion || !this._mergedCssSelectors) { - toMerge = []; - toMerge.push(applicationCssSelectors); - this._applicationCssSelectorsAppliedVersion = applicationCssSelectorVersion; - toMerge.push(this._localCssSelectors); - this._localCssSelectorsAppliedVersion = this._localCssSelectorVersion; - for (let keyframe in applicationKeyframes) { - this._keyframes[keyframe] = applicationKeyframes[keyframe]; - } + + this._createSelectors(); } - if (toMerge && toMerge.length > 0) { + return this._getSelectorsVersion(); + } + + @profile + private _createSelectors() { + let toMerge: RuleSet[][] = []; + toMerge.push(applicationCssSelectors); + this._applicationCssSelectorsAppliedVersion = applicationCssSelectorVersion; + toMerge.push(this._localCssSelectors); + this._localCssSelectorsAppliedVersion = this._localCssSelectorVersion; + for (let keyframe in applicationKeyframes) { + this._keyframes[keyframe] = applicationKeyframes[keyframe]; + } + + if (toMerge.length > 0) { this._mergedCssSelectors = toMerge.filter(m => !!m).reduce((merged, next) => merged.concat(next), []); this._applyKeyframesOnSelectors(); this._selectors = new SelectorsMap(this._mergedCssSelectors); } - - return this._getSelectorsVersion(); } public applySelectors(view: ViewBase): void {