feat(ios): fire onDisplayed event when first frame is ready to be displayed (NativeScript#5344)

sis0k0 · Alexander Vakrilov · commit 1c78e4784cdf · 2018-01-29T13:47:35.000+02:00
* feat: add a 'profiling: lifecycle' to track startup times

* feat: log when displayed event fires

* feat(ios): fire onDisplayed event when first frame is ready to be
displayed
diff --git a/tns-core-modules/application/application-common.ts b/tns-core-modules/application/application-common.ts
@@ -2,6 +2,12 @@
 require("globals");
 
 import { Observable, EventData } from "../data/observable";
+import {
+    trace as profilingTrace,
+    time,
+    uptime,
+    level as profilingLevel,
+} from "../profiling";
 
 const events = new Observable();
 let launched = false;
@@ -11,6 +17,15 @@ function setLaunched() {
 }
 events.on("launch", setLaunched);
 
+if (profilingLevel() > 0) {
+    events.on("displayed", () => {
+        const duration = uptime();
+        const end = time();
+        const start = end - duration;
+        profilingTrace(`Displayed in ${duration.toFixed(2)}ms`, start, end);
+    });
+}
+
 export function hasLaunched(): boolean {
     return launched;
 }
diff --git a/tns-core-modules/application/application.ios.ts b/tns-core-modules/application/application.ios.ts
@@ -20,14 +20,12 @@ import { ios as iosView, View } from "../ui/core/view";
 import { Frame, NavigationEntry } from "../ui/frame";
 import { ios } from "../ui/utils";
 import * as utils from "../utils/utils";
-import { profile } from "../profiling";
+import { profile, level as profilingLevel, Level } from "../profiling";
 
 class Responder extends UIResponder {
     //
 }
 
-let displayedOnce = false;
-
 class NotificationObserver extends NSObject {
     private _onReceiveCallback: (notification: NSNotification) => void;
 
@@ -46,6 +44,24 @@ class NotificationObserver extends NSObject {
     };
 }
 
+let displayedOnce = false;
+let displayedLinkTarget;
+let displayedLink;
+class CADisplayLinkTarget extends NSObject {
+    onDisplayed(link: CADisplayLink) {
+        link.invalidate();
+        const ios = utils.ios.getter(UIApplication, UIApplication.sharedApplication);
+        const object = iosApp;
+        displayedOnce = true;
+        notify(<ApplicationEventData>{ eventName: displayedEvent, object, ios });
+        displayedLinkTarget = null;
+        displayedLink = null;
+    }
+    public static ObjCExposedMethods = {
+        "onDisplayed": { returns: interop.types.void, params: [CADisplayLink] }
+    }
+}
+
 class IOSApplication implements IOSApplicationDefinition {
     private _delegate: typeof UIApplicationDelegate;
     private _currentOrientation = utils.ios.getter(UIDevice, UIDevice.currentDevice).orientation;
@@ -101,6 +117,13 @@ class IOSApplication implements IOSApplicationDefinition {
 
     @profile
     private didFinishLaunchingWithOptions(notification: NSNotification) {
+        if (!displayedOnce && profilingLevel() >= Level.lifecycle) {
+            displayedLinkTarget = CADisplayLinkTarget.new();
+            displayedLink = CADisplayLink.displayLinkWithTargetSelector(displayedLinkTarget, "onDisplayed");
+            displayedLink.addToRunLoopForMode(NSRunLoop.mainRunLoop, NSDefaultRunLoopMode);
+            displayedLink.addToRunLoopForMode(NSRunLoop.mainRunLoop, UITrackingRunLoopMode);
+        }
+
         this._window = UIWindow.alloc().initWithFrame(utils.ios.getter(UIScreen, UIScreen.mainScreen).bounds);
         // TODO: Expose Window module so that it can we styled from XML & CSS
         this._window.backgroundColor = utils.ios.getter(UIColor, UIColor.whiteColor);
@@ -126,11 +149,6 @@ class IOSApplication implements IOSApplicationDefinition {
         if (rootView && !rootView.isLoaded) {
             rootView.callLoaded();
         }
-
-        if (!displayedOnce) {
-            notify(<ApplicationEventData>{ eventName: displayedEvent, object, ios });
-            displayedOnce = true;
-        }
     }
 
     private didEnterBackground(notification: NSNotification) {
diff --git a/tns-core-modules/profiling/profiling.d.ts b/tns-core-modules/profiling/profiling.d.ts
@@ -11,10 +11,25 @@ interface TimerInfo {
 
 /**
  * Profiling mode to use.
- *  - `counters` Accumulates method call counts and times until dumpProfiles is called and then prints agregated statistic in the console. This is the default.
+ *  - `counters` Accumulates method call counts and times until dumpProfiles is called and then prints aggregated statistic in the console. This is the default.
  *  - `timeline` Outputs method names along start/end timestamps in the console on the go.
+ *  - `lifecycle` Outputs basic non-verbose times for startup, navigation, etc.
  */
-type InstrumentationMode = "counters" | "timeline";
+type InstrumentationMode = "counters" | "timeline" | "lifecycle";
+
+/**
+ * Logging levels in order of verbosity.
+ */
+export enum Level {
+    none,
+    lifecycle,
+    timeline,
+}
+
+/**
+ * Get the current logging level.
+ */
+export function level(): Level;
 
 /**
  * Enables profiling.
@@ -32,8 +47,9 @@ type InstrumentationMode = "counters" | "timeline";
  * ```
  * 
  * @param type Profiling mode to use.
- *  - "counters" - Accumulates method call counts and times until dumpProfiles is called and then prints agregated statistic in the console. This is the default.
+ *  - "counters" - Accumulates method call counts and times until dumpProfiles is called and then prints aggregated statistic in the console. This is the default.
  *  - "timeline" - Outputs method names along start/end timestamps in the console on the go.
+ *  - "lifecycle" - Outputs basic non-verbose times for startup, navigation, etc.
  */
 export declare function enable(type?: InstrumentationMode): void;
 
@@ -132,4 +148,14 @@ export function uptime(): number;
 /**
  * Logs important messages. Contrary to console.log's behavior, the profiling log should output even for release builds.
  */
-export function log(message: string): void;
+export function log(message: string): void;
+
+/**
+ * Manually output profiling messages. The `@profile` decorator is useful when measuring times that function calls take on the stack
+ * but when measuring times between longer periods (startup times, times between the navigatingTo - navigatedTo events etc.)
+ * you can call this method and provide manually the times to be logged.
+ * @param message A string message
+ * @param start The start time (see `time()`)
+ * @param end The end time (see `time()`)
+ */
+export function trace(message: string, start: number, end: number): void;
diff --git a/tns-core-modules/profiling/profiling.ts b/tns-core-modules/profiling/profiling.ts
@@ -10,9 +10,8 @@ export function uptime() {
 export function log(message: string): void {
     if ((<any>global).__nslog) {
         (<any>global).__nslog("CONSOLE LOG: " + message);
-    } else {
-        console.log(message);
     }
+    console.log(message);
 }
 
 interface TimerInfo extends TimerInfoDefinition {
@@ -130,12 +129,24 @@ const enum MemberType {
     Instance
 }
 
+export enum Level {
+    none,
+    lifecycle,
+    timeline,
+}
+let tracingLevel: Level = Level.none;
+
 let profileFunctionFactory: <F extends Function>(fn: F, name: string, type?: MemberType) => F;
 export function enable(mode: InstrumentationMode = "counters") {
     profileFunctionFactory = mode && {
         counters: countersProfileFunctionFactory,
         timeline: timelineProfileFunctionFactory
     }[mode];
+
+    tracingLevel = {
+        lifecycle: Level.lifecycle,
+        timeline: Level.timeline,
+    }[mode] || Level.none;
 }
 
 try {
@@ -294,3 +305,11 @@ export function stopCPUProfile(name: string) {
         __stopCPUProfiler(name);
     }
 }
+
+export function level(): Level {
+    return tracingLevel;
+}
+
+export function trace(message: string, start: number, end: number): void {
+    log(`Timeline: Modules: ${message}  (${start}ms. - ${end}ms.)`);
+}
