add profile for functions, profile CSS-es on startup, use __time

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}`);
-}
+        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`);
+    });
+}

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();
 

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<F extends Function>(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<F extends Function>(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<T>(target: Object, propertyKey: string | symbol, descriptor: TypedPropertyDescriptor<T>): TypedPropertyDescriptor<T> | 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;

tns-core-modules/profiling/profiling.ts

@@ -3,6 +3,8 @@ declare var __stopCPUProfiler: any;
 
 import { TimerInfo as TimerInfoDefinition } from ".";
 
+export const uptime = global.android ? (<any>org).nativescript.Process.getUpTime : (<any>global).__tns_uptime;
+
 interface TimerInfo extends TimerInfoDefinition {
     totalTime: number;
     lastTime?: number;
@@ -16,41 +18,19 @@ const timers: { [index: string]: TimerInfo } = {};
 const anyGlobal = <any>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 = (<any>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<F extends Function>(fn: F, customName?: string): F {
+    const name = customName || fn.name;
+    profileNames.push(name);
+    return <any>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);
     }

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 {