Merge pull request #4172 from NativeScript/profiling

Profiling module

tests/app/profiling/profiling-tests.ts

@@ -0,0 +1,66 @@
+import * as TKUnit from "../TKUnit";
+import * as prof from "tns-core-modules/profiling";
+
+export function setUp() {
+    prof.enable();
+}
+
+export function tearDown() {
+    prof.disable();
+}
+
+export function test_time_throws_if_not_enabled() {
+    prof.disable();
+    TKUnit.assertThrows(prof.time);
+};
+
+export function test_time_returns_number_if_enabled() {
+    TKUnit.assertEqual(typeof prof.time(), "number");
+};
+
+export function test_start_stop() {
+    prof.start("__test1__");
+    const res = prof.stop("__test1__");
+
+    TKUnit.assertEqual(res.count, 1);
+    TKUnit.assert(res.totalTime <= 1);
+};
+
+export function test_start_pause() {
+    for (var i = 0; i < 10; i++) {
+        prof.start("__test2__");
+        prof.pause("__test2__");
+    }
+
+    const res = prof.stop("__test2__");
+    TKUnit.assertEqual(res.count, 10);
+    TKUnit.assert(res.totalTime <= 1);
+};
+
+export function test_timer_performance() {
+    for (var i = 0; i < 10000; i++) {
+        prof.start("__test3__");
+        prof.pause("__test3__");
+    }
+
+    const res = prof.stop("__test3__");
+    TKUnit.assertEqual(res.count, 10000);
+    TKUnit.assert(res.totalTime <= 30, "Total time for 1000 timer operations is too much: " + res.totalTime);
+};
+
+export function test_profile_decorator_count_counts() {
+    class TestClass {
+        @prof.profile("__func_decorator__")
+        f() {
+            //noop
+        }
+    }
+
+    const test = new TestClass();
+
+    for (var i = 0; i < 10; i++) {
+        test.f();
+    }
+    const res = prof.stop("__func_decorator__");
+    TKUnit.assertEqual(res.count, 10);
+}

tests/app/testRunner.ts

@@ -31,6 +31,9 @@ export function isRunningOnEmulator(): boolean {
 
 export var allTests = {};
 
+import * as profilingTests from "./profiling/profiling-tests";
+allTests["PROFILING"] = profilingTests;
+
 import * as platformTests from "./platform/platform-tests";
 allTests["PLATFORM"] = platformTests;
 

tns-core-modules/profiling/package.json

@@ -0,0 +1,6 @@
+{
+  "name" : "profiling",
+  "main" : "profiling",
+  "types" : "profiling.d.ts",
+  "nativescript": {}
+}

tns-core-modules/profiling/profiling.d.ts

@@ -0,0 +1,73 @@
+/**
+ * Contains contains utility methods for profiling.
+ * All methods in this module are experimental and may be changed in a non-major version.
+ * @module "profiling"
+ */ /** */
+
+interface TimerInfo {
+    totalTime: number;
+    count: number;
+}
+
+/**
+ * Enables profiling.
+ */
+export declare function enable(): void;
+
+/**
+ * Disables profiling.
+ */
+export declare function disable(): void;
+
+/**
+ * Gets accurate system timestamp in ms. 
+ * Works only if profiling is enabled.
+ */
+export declare function time(): number;
+
+/**
+ * Starts a timer with a specific name.
+ * Works only if profiling is enabled.
+ * @param name Name of the timer.
+ */
+export declare function start(name: string): void;
+
+/**
+ * Pauses a timer with a specific name. This will increase call count and accumulate time.
+ * Works only if profiling is enabled.
+ * @param name Name of the timer.
+ * @returns TimerInfo for the paused timer.
+ */
+export declare function pause(name: string): TimerInfo;
+
+/**
+ * Stops a timer with a specific name. This will print the count and the total time and will also reset the timer.
+ * Works only if profiling is enabled.
+ * @param name Name of the timer.
+ * @returns TimerInfo for the stopped timer.
+ */
+export declare function stop(name: string): TimerInfo;
+
+/**
+ * Method decorator factory. It will intercept the method call and start and pause a timer before and after the method call.
+ * Works only if profiling is enabled.
+ * @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;
+
+/**
+ * Prints the timer for all methods instrumented with profile decorator.
+ */
+export declare function dumpProfiles(): void;
+
+/**
+ * Starts android cpu profiling.
+ * @param name Name of the cpu profiling session.
+ */
+export declare function startCPUProfile(name: string): void;
+
+/**
+ * Stops android cpu profiling.
+ * @param name Name of the cpu profiling session.
+ */
+export declare function stopCPUProfile(name: string): void;

tns-core-modules/profiling/profiling.ts

@@ -0,0 +1,174 @@
+declare var __startCPUProfiler: any;
+declare var __stopCPUProfiler: any;
+
+import { TimerInfo as TimerInfoDefinition } from ".";
+
+interface TimerInfo extends TimerInfoDefinition {
+    totalTime: number;
+    lastTime?: number;
+    count: number;
+    currentStart: number;
+    isRunning: boolean;
+}
+
+let anyGlobal = <any>global;
+let ENABLED = true;
+let nativeTimeFunc: () => number;
+let profileNames: string[] = [];
+let timers = new Map<string, TimerInfo>();
+
+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; };
+        }
+    }
+}
+
+export function disable() {
+    ENABLED = false;
+}
+
+export function time(): number {
+    if (!ENABLED) {
+        throw new Error("Profiling is not enabled");
+    }
+
+    return nativeTimeFunc();
+}
+
+export function start(name: string): void {
+    if (!ENABLED) {
+        return;
+    }
+
+    let info = timers.get(name);
+    if (info) {
+        if (info.isRunning) {
+            throw new Error(`Timer already running: ${name}`);
+        }
+        info.currentStart = time();
+        info.isRunning = true;
+    } else {
+        info = {
+            totalTime: 0,
+            count: 0,
+            currentStart: time(),
+            isRunning: true
+        };
+        timers.set(name, info);
+    }
+}
+
+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}`);
+
+    timers.delete(name);
+    return info;
+}
+
+function pauseInternal(name: string): TimerInfo {
+    let info = timers.get(name);
+    if (!info) {
+        throw new Error(`No timer started: ${name}`);
+    }
+
+    if (info.isRunning) {
+        info.lastTime = Math.round(time() - info.currentStart);
+        info.totalTime += info.lastTime;
+        info.count++;
+        info.currentStart = 0;
+        info.isRunning = false;
+    }
+
+    return info;
+}
+
+export function profile(name?: string): MethodDecorator {
+    return (target, key, descriptor) => {
+        if (!ENABLED) {
+            return;
+        }
+
+        // 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;
+
+        if (!name) {
+            name = key;
+        }
+
+        profileNames.push(name);
+
+        //editing the descriptor/value parameter
+        descriptor.value = function () {
+            start(name);
+
+            var result = originalMethod.apply(this, arguments);
+
+            pause(name)
+
+            return result;
+        };
+
+        // return edited descriptor as opposed to overwriting the descriptor
+        return descriptor;
+    }
+}
+
+export function dumpProfiles(): void {
+    profileNames.forEach(function (name) {
+        let info = timers.get(name);
+        if (info) {
+            console.log("---- [" + name + "] STOP total: " + info.totalTime + " count:" + info.count);
+        }
+        else {
+            console.log("---- [" + name + "] Never called");
+        }
+    });
+}
+
+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);
+    }
+}