Merge pull request #4180 from NativeScript/profiling-try-catch

Profiling - handle exceptions inside deocrator

apps/app/ui-tests-app/font/all-fonts.ts

@@ -14,8 +14,8 @@ const genericFontFamilies = [
     "serif",
     "monospace",
 ];
-var fontFamilies = [];
+let fontFamilies = [];
-var fontNames = [];
+let fontNames = [];
 const embeddedFontNames = [
     "FontAwesome",
     "Pacifico",
@@ -37,21 +37,21 @@ const fontWeights = [
     FontWeight.black,
 ];
 
-var green = new Color("Green");
+let green = new Color("Green");
-var red = new Color("Red");
+let red = new Color("Red");
-var white = new Color("White");
+let white = new Color("White");
-var black = new Color("Black");
+let black = new Color("Black");
 
-var compareIgnoreCase = function (a, b) {
+let compareIgnoreCase = function (a, b) {
     return a.toLowerCase().localeCompare(b.toLowerCase());
 };
 
 if (font.ios) {
-    // for (var f = 0; f < embeddedFontNames.length; f++) {
+    // for (let f = 0; f < embeddedFontNames.length; f++) {
     //     font.ios.registerFont(`fonts/${embeddedFontNames[f]}.ttf`);
     // }
 
-    var font_internal = <any>font;
+    let font_internal = <any>font;
     font_internal.ensureSystemFontSets();
 
     (<Set<string>>font_internal.systemFontFamilies).forEach(f => fontFamilies.push(f));
@@ -62,9 +62,9 @@ if (font.ios) {
 }
 
 export function onPageLoaded(args: NavigatedData) {
-    var page = <Page>args.object;
+    let page = <Page>args.object;
-    var scrollView = new ScrollView();
+    let scrollView = new ScrollView();
-    var stackLayout = new StackLayout();
+    let stackLayout = new StackLayout();
     generateLabels(stackLayout);
     scrollView.content = stackLayout;
     page.content = scrollView;
@@ -72,11 +72,11 @@ export function onPageLoaded(args: NavigatedData) {
 
 function generateLabels(layout: StackLayout) {
     layout.addChild(prepareTitle("Generic Font Families", 24));
-    for (var f = 0; f < genericFontFamilies.length; f++) {
+    for (let f = 0; f < genericFontFamilies.length; f++) {
         layout.addChild(prepareTitle(genericFontFamilies[f], 20));
-        for (var s = 0; s < fontStyles.length; s++) {
+        for (let s = 0; s < fontStyles.length; s++) {
-            for (var w = 0; w < fontWeights.length; w++) {
+            for (let w = 0; w < fontWeights.length; w++) {
-                var view = prepareLabel(genericFontFamilies[f], fontStyles[s], fontWeights[w]);
+                let view = prepareLabel(genericFontFamilies[f], fontStyles[s], fontWeights[w]);
                 layout.addChild(view);
             }
         }
@@ -86,11 +86,11 @@ function generateLabels(layout: StackLayout) {
     {
         layout.addChild(prepareTitle("Font Families", 24));
     }
-    for (var f = 0; f < fontFamilies.length; f++) {
+    for (let f = 0; f < fontFamilies.length; f++) {
         layout.addChild(prepareTitle(fontFamilies[f], 20));
-        for (var s = 0; s < fontStyles.length; s++) {
+        for (let s = 0; s < fontStyles.length; s++) {
-            for (var w = 0; w < fontWeights.length; w++) {
+            for (let w = 0; w < fontWeights.length; w++) {
-                var view = prepareLabel(fontFamilies[f], fontStyles[s], fontWeights[w]);
+                let view = prepareLabel(fontFamilies[f], fontStyles[s], fontWeights[w]);
                 layout.addChild(view);
             }
         }
@@ -99,22 +99,22 @@ function generateLabels(layout: StackLayout) {
     if (fontNames.length > 0) {
         layout.addChild(prepareTitle("Phone Fonts", 24));
     }
-    for (var f = 0; f < fontNames.length; f++) {
+    for (let f = 0; f < fontNames.length; f++) {
-        var view = prepareLabel(fontNames[f], "normal", "normal");
+        let view = prepareLabel(fontNames[f], "normal", "normal");
         layout.addChild(view);
     }
 
     if (embeddedFontNames.length > 0) {
         layout.addChild(prepareTitle("Embedded Fonts", 24));
     }
-    for (var f = 0; f < embeddedFontNames.length; f++) {
+    for (let f = 0; f < embeddedFontNames.length; f++) {
-        var view = prepareLabel(embeddedFontNames[f], "normal", "normal");
+        let view = prepareLabel(embeddedFontNames[f], "normal", "normal");
         layout.addChild(view);
     }
 }
 
 function prepareTitle(text: string, fontSize: number) {
-    var title = new Label();
+    let title = new Label();
     title.text = text;
     title.height = 100;
     title.backgroundColor = black;
@@ -128,12 +128,12 @@ function prepareTitle(text: string, fontSize: number) {
 }
 
 function prepareLabel(fontFamily: string, fontStyle: string, fontWeight: string): View {
-    var label = new Label();
+    let label = new Label();
     label["font-family"] = fontFamily;
-    var fontFamilyCss = `font-family: ${fontFamily}; `;
+    let fontFamilyCss = `font-family: ${fontFamily}; `;
-    var fontStyleCss = fontStyle !== FontStyle.normal ? `font-style: ${fontStyle}; ` : "";
+    let fontStyleCss = fontStyle !== FontStyle.normal ? `font-style: ${fontStyle}; ` : "";
-    var fontWeightCss = fontWeight !== FontWeight.normal ? `font-weight: ${fontWeight}; ` : "";
+    let fontWeightCss = fontWeight !== FontWeight.normal ? `font-weight: ${fontWeight}; ` : "";
-    var css = `${fontFamilyCss}${fontStyleCss}${fontWeightCss}`;
+    let css = `${fontFamilyCss}${fontStyleCss}${fontWeightCss}`;
     label.text = `${typeUtils.getClass(label) } {${css}};`;
     label.textWrap = true;
     label.style.textAlignment = "left";
@@ -142,9 +142,9 @@ function prepareLabel(fontFamily: string, fontStyle: string, fontWeight: string)
     label.style.padding = "2"; 
     label.setInlineStyle(css);
     label.on("loaded", args => {
-        var sender = <Label>args.object;
+        let sender = <Label>args.object;
         if (sender.ios) {
-            var uiFont = _getUIFont(label);
+            let uiFont = _getUIFont(label);
             sender.text += `\niOS Font: ${uiFont.fontName};`;
             if (genericFontFamilies.indexOf(fontFamily) !== -1) {
                 return;

apps/app/ui-tests-app/pages/touch-event.ts

@@ -2,21 +2,21 @@
 import * as gestures from "tns-core-modules/ui/gestures";
 
 export function onTouch(args: gestures.TouchGestureEventData) {
-    var msg = " touch action: " + args.action +
+    let msg = " touch action: " + args.action +
         " x: " + Math.round(args.getX()) + " y: " + Math.round(args.getY()) +
         " count: " + args.getPointerCount();
 
-    var p;
+    let p;
     msg += " ACTIVE: ";
-    var pointers = args.getActivePointers();
+    let pointers = args.getActivePointers();
-    for (var index = 0; index < pointers.length; index++) {
+    for (let index = 0; index < pointers.length; index++) {
         p = pointers[index];
         msg += " p" + index + "[" + Math.round(p.getX()) + ", " + Math.round(p.getY()) + "]"
     }
 
     msg += " ALL: ";
     pointers = args.getAllPointers();
-    for (var index = 0; index < pointers.length; index++) {
+    for (let index = 0; index < pointers.length; index++) {
         p = pointers[index];
         msg += " p" + index + "[" + Math.round(p.getX()) + ", " + Math.round(p.getY()) + "]"
     }

tests/app/profiling/profiling-tests.ts

@@ -1,6 +1,20 @@
-import * as TKUnit from "../TKUnit";
+import { assert, assertEqual, assertFalse, assertTrue, assertThrows } from "../TKUnit";
 import * as prof from "tns-core-modules/profiling";
 
+prof.enable();
+class TestClass {
+    @prof.profile("__func_decorator__")
+    doNothing() {
+        //noop
+    }
+
+    @prof.profile("__func_decorator_error__")
+    throwError() {
+        throw new Error("This error is expected");
+    }
+}
+prof.disable();
+
 export function setUp() {
     prof.enable();
 }
@@ -11,56 +25,93 @@ export function tearDown() {
 
 export function test_time_throws_if_not_enabled() {
     prof.disable();
-    TKUnit.assertThrows(prof.time);
+    assertThrows(prof.time);
 };
 
 export function test_time_returns_number_if_enabled() {
-    TKUnit.assertEqual(typeof prof.time(), "number");
+    assertEqual(typeof prof.time(), "number");
 };
 
+export function test_isRunning() {
+    const name = "test_isRunning";
+    assertFalse(prof.isRunning(name), "isRunning should be false before start");
+ 
+    prof.start(name);
+    assertTrue(prof.isRunning(name), "isRunning should be true after start");
+
+    prof.pause(name);
+    assertFalse(prof.isRunning(name), "isRunning should be false after pause");
+
+    prof.start(name);
+    assertTrue(prof.isRunning(name), "isRunning should be true after second start");
+
+    prof.stop(name);
+    assertFalse(prof.isRunning(name), "isRunning should be false after stop");
+}
+
 export function test_start_stop() {
-    prof.start("__test1__");
+    const name = "test_start_stop";
-    const res = prof.stop("__test1__");
 
-    TKUnit.assertEqual(res.count, 1);
+    prof.start(name);
-    TKUnit.assert(res.totalTime <= 1);
+    const res = prof.stop(name);
+
+    assertEqual(res.count, 1);
+    assert(res.totalTime <= 1);
 };
 
-export function test_start_pause() {
+export function test_start_pause_count() {
+    const name = "test_start_pause_count";
+
     for (var i = 0; i < 10; i++) {
-        prof.start("__test2__");
+        prof.start(name);
-        prof.pause("__test2__");
+        prof.pause(name);
     }
 
-    const res = prof.stop("__test2__");
+    const res = prof.stop(name);
-    TKUnit.assertEqual(res.count, 10);
+    assertEqual(res.count, 10);
-    TKUnit.assert(res.totalTime <= 1);
 };
 
-export function test_timer_performance() {
+export function test_start_pause_performance() {
-    for (var i = 0; i < 10000; i++) {
+    const count = 1000;
-        prof.start("__test3__");
+    const name = "test_start_pause_performance";
-        prof.pause("__test3__");
+
+    for (var i = 0; i < count; i++) {
+        prof.start(name);
+        prof.pause(name);
     }
 
-    const res = prof.stop("__test3__");
+    const res = prof.stop(name);
-    TKUnit.assertEqual(res.count, 10000);
+    assertEqual(res.count, count);
-    TKUnit.assert(res.totalTime <= 30, "Total time for 1000 timer operations is too much: " + res.totalTime);
+    assert(res.totalTime <= 50, `Total time for ${count} timer operations is too much: ${res.totalTime}`);
 };
 
-export function test_profile_decorator_count_counts() {
+export function test_profile_decorator_count() {
-    class TestClass {
+    const test = new TestClass();
-        @prof.profile("__func_decorator__")
+    for (var i = 0; i < 10; i++) {
-        f() {
+        test.doNothing();
-            //noop
-        }
     }
 
+    const res = prof.stop("__func_decorator__");
+    assertEqual(res.count, 10);
+}
+
+export function test_profile_decorator_performance() {
+    const count = 1000;
+
     const test = new TestClass();
-
+    for (var i = 0; i < count; i++) {
-    for (var i = 0; i < 10; i++) {
+        test.doNothing();
-        test.f();
     }
+
     const res = prof.stop("__func_decorator__");
-    TKUnit.assertEqual(res.count, 10);
+    assertEqual(res.count, count);
+    assert(res.totalTime <= 50, `Total time for ${count} timer operations is too much: ${res.totalTime}`);
+}
+
+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");
 }

tests/app/ui/border/border-tests.ts

@@ -2,4 +2,6 @@
 import { Border } from "tns-core-modules/ui/border";
 // << border-require
 
-console.dir(Border);
+if (Border) {
+    // NOOP
+}

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

@@ -48,6 +48,13 @@ export declare function pause(name: string): TimerInfo;
  */
 export declare function stop(name: string): TimerInfo;
 
+/**
+ * Returns true if a timer is currently running.
+ * @param name Name of the timer.
+ * @returns true is the timer is currently running.
+ */
+export declare function isRunning(name: string): boolean;
+
 /**
  * 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.

tns-core-modules/profiling/profiling.ts

@@ -11,11 +11,13 @@ interface TimerInfo extends TimerInfoDefinition {
     isRunning: boolean;
 }
 
-let anyGlobal = <any>global;
+// Use object instead of map as it is a bit faster
+const timers: { [ index: string ]: TimerInfo } = {};
+const anyGlobal = <any>global;
+const profileNames: string[] = [];
+
 let ENABLED = true;
 let nativeTimeFunc: () => number;
-let profileNames: string[] = [];
-let timers = new Map<string, TimerInfo>();
 
 export function enable() {
     ENABLED = true;
@@ -49,7 +51,8 @@ export function start(name: string): void {
         return;
     }
 
-    let info = timers.get(name);
+    let info = timers[ name ];
+
     if (info) {
         if (info.isRunning) {
             throw new Error(`Timer already running: ${name}`);
@@ -63,7 +66,7 @@ export function start(name: string): void {
             currentStart: time(),
             isRunning: true
         };
-        timers.set(name, info);
+        timers[ name ] = info;
     }
 }
 
@@ -85,18 +88,24 @@ export function stop(name: string): TimerInfo {
     let info = pauseInternal(name);
     console.log(`---- [${name}] STOP total: ${info.totalTime} count:${info.count}`);
 
-    timers.delete(name);
+    timers[ name ] = undefined;
     return info;
 }
 
+export function isRunning(name: string): boolean {
+    const info = timers[ name ];
+    return !!(info && info.isRunning);
+}
+
 function pauseInternal(name: string): TimerInfo {
-    let info = timers.get(name);
+    const info = timers[ name ];
+
     if (!info) {
         throw new Error(`No timer started: ${name}`);
     }
 
     if (info.isRunning) {
-        info.lastTime = Math.round(time() - info.currentStart);
+        info.lastTime = time() - info.currentStart;
         info.totalTime += info.lastTime;
         info.count++;
         info.currentStart = 0;
@@ -120,7 +129,12 @@ export function profile(name?: string): MethodDecorator {
         var originalMethod = descriptor.value;
 
         if (!name) {
-            name = key;
+            let className = "";
+            if (target && target.constructor && target.constructor.name) {
+                className = target.constructor.name + ".";
+            }
+
+            name = className + key;
         }
 
         profileNames.push(name);
@@ -128,12 +142,11 @@ export function profile(name?: string): MethodDecorator {
         //editing the descriptor/value parameter
         descriptor.value = function () {
             start(name);
-
+            try {
-            var result = originalMethod.apply(this, arguments);
+                return originalMethod.apply(this, arguments);
-
+            } finally {
-            pause(name)
+                pause(name);
-
+            }
-            return result;
         };
 
         // return edited descriptor as opposed to overwriting the descriptor
@@ -143,7 +156,8 @@ export function profile(name?: string): MethodDecorator {
 
 export function dumpProfiles(): void {
     profileNames.forEach(function (name) {
-        let info = timers.get(name);
+        const info = timers[ name ];
+
         if (info) {
             console.log("---- [" + name + "] STOP total: " + info.totalTime + " count:" + info.count);
         }