diff --git a/tests/app/profiling/profiling-tests.ts b/tests/app/profiling/profiling-tests.ts new file mode 100644 index 000000000..f79f0d83f --- /dev/null +++ b/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); +} \ No newline at end of file diff --git a/tests/app/testRunner.ts b/tests/app/testRunner.ts index dd4f21897..ecb5ffc5c 100644 --- a/tests/app/testRunner.ts +++ b/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; diff --git a/tns-core-modules/profiling/package.json b/tns-core-modules/profiling/package.json new file mode 100644 index 000000000..d7eccfcae --- /dev/null +++ b/tns-core-modules/profiling/package.json @@ -0,0 +1,6 @@ +{ + "name" : "profiling", + "main" : "profiling", + "types" : "profiling.d.ts", + "nativescript": {} +} diff --git a/tns-core-modules/profiling/profiling.d.ts b/tns-core-modules/profiling/profiling.d.ts new file mode 100644 index 000000000..9c0e7c0af --- /dev/null +++ b/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): (target, key, descriptor) => void; + +/** + * 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; diff --git a/tns-core-modules/profiling/profiling.ts b/tns-core-modules/profiling/profiling.ts new file mode 100644 index 000000000..9df4a6185 --- /dev/null +++ b/tns-core-modules/profiling/profiling.ts @@ -0,0 +1,176 @@ +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 = global; +let ENABLED = true; +let nativeTimeFunc: () => number; +let profileNames: string[] = []; +let timers = new Map(); + +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: TimerInfo; + if (timers.has(name)) { + info = timers.get(name); + 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): (target, key, descriptor) => void { + return (target, key, descriptor) => { + if (!ENABLED) { + // Return the original descriptor if not enabled + return 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; + + 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); + } +} \ No newline at end of file