Add instrumentation for measuring metrics related to visit #276

suchitadoshi1987 · 2020-10-07T18:22:01Z

Added instrumentation to measure

time taken to complete the fastboot visit
time taken to complete the instance visit
time taken to retrieve the app instance from the queue

rwjblue

Looking good! Left a few inline comments/ideas...

rwjblue · 2020-10-07T20:23:18Z

src/ember-app.js

@@ -205,10 +208,14 @@ class EmberApp {
   *                                       only
   */
  async getNewApplicationInstance() {
+    const appInstanceRetrievalStartTime = Date.now();


I'd generally prefer to use something with higher precision. Mind swapping to performance.now() (docs here):

const { performance } = require('perf_hooks'); // ...snip... const start = performance.now();

+1 to performance.now(), not only higher precision, more importantly it's using a monotonic clock therefore it is not subject to system clock skew or adjustments https://www.w3.org/TR/hr-time-2/#sec-monotonic-clock

rwjblue · 2020-10-07T20:26:11Z

src/ember-app.js

-    return this.getAppInstanceInfo(app, queueObject.isItemPreBuilt);
+    return this.getAppInstanceInfo(app, {
+      isAppInstancePreBuilt: queueObject.isItemPreBuilt,
+      appInstanceRetrievalTime: Date.now() - appInstanceRetrievalStartTime,


I'd like to store the start and stops too. Also can we rename this to buildAppInstanceTiming?

Something like:

const start = performance.now(); const queueObject = this._sandboxApplicationInstanceQueue.dequeue(); const app = await queueObject.item; const stop = performance.now(); return this.getAppInstanceInfo(app, { isAppInstancePreBuilt: queueObject.isItemPreBuilt, buildAppInstanceTiming: { start, stop, duration: stop - start, } });

Rob,

Do we need all 3 of 'start', 'stop', and 'duration'?

I'd prefer either (1) 'start' and 'stop' or (2) 'start' and 'duration'. I prefer the latter option more. The reason I like it is because: (1) it's smaller (which isn't a huge deal) and (2) whenever I see all 3 I do the subtraction to make sure 'duration' = 'stop' - 'start' because I always ask myself, why would they provide all 3?

That being said, this is not such a strong opinion and if you are strongly opinionated, I'll defer.

Thanks,
Mark

My reasoning here is basically that "clock time duration" isn't enough information in all cases, but in many cases it is. For example, if we just provided duration it is actually quite difficult to map the results to see how many were interleaved/overlapping/whateverTheWordIs. In general, I feel like this is in a "why not" kinda scenario (where it costs us roughly nothing to do all three, and in fact we basically have to know all three anyways in order to provide a duration). That being said, I definitely do not feel strongly about providing all 3. I think start and duration is probably enough info (and addresses my primary issue).

Let's call it "dealers choice", to the PR author go the spoils 😝

lol okk.... i will unveil the suspense in my next commit ;)

FWIW PerformanceEntry defines startTime and duration

rwjblue · 2020-10-07T20:26:30Z

src/ember-app.js

@@ -236,10 +243,11 @@ class EmberApp {
  async _visit(path, fastbootInfo, bootOptions, result, buildSandboxPerVisit) {
    let shouldBuildApp = buildSandboxPerVisit || this._applicationInstance === undefined;

-    let { app, isSandboxPreBuilt } = shouldBuildApp
+    let { app, appAnalytics } = shouldBuildApp


Can we call this analytics instead of appAnalytics?

Also, can we unify these? Can we funnel both cases through a single function (e.g. buildAppInstance or even getNewApplicationInstance) so the rest of the code doesn't need to care about the two pathways?

do you mean

? await this.getNewApplicationInstance() : this.getAppInstanceInfo(this._applicationInstance);

should instead be

let { app, appAnalytics } = await this.getNewApplicationInstance(shouldBuildApp)

and the function would return the appropriate response

Yes, IMHO we should have only a single function that is responsible for understanding:

if we should build a new instance (based on shouldBuildApp)

if we should build a new instance when the queue is empty and a new application instance is requested

how to build the proper set of analytics output

agreed! 👍

rwjblue · 2020-10-07T20:29:47Z

src/ember-app.js

+    const instanceVisitStartTime = Date.now();
    await instance.visit(path, bootOptions);
+    result.analytics.instanceVisitTime = Date.now() - instanceVisitStartTime;


Similar to above, lets use a POJO to group multiple values:

const start = performance.now(); await instance.visit(path, bootOptions); const stop = performance.now(); result.analytics.instanceVisitTimings = { start, stop, duration: stop - start, };

rwjblue · 2020-10-07T20:30:30Z

src/ember-app.js

@@ -323,6 +336,7 @@ class EmberApp {

    try {
      await this._visit(path, fastbootInfo, bootOptions, result, buildSandboxPerVisit);
+      result.analytics.fastbootVisitTime = Date.now() - fastbootVisitStartTime;


Same as above

SergeAstapov · 2020-10-08T00:44:27Z

@suchitadoshi1987 @rwjblue have you considered to instrument result._finalize() and createShoebox() as well?

rwjblue · 2020-10-08T20:48:56Z

@suchitadoshi1987 @rwjblue have you considered to instrument result._finalize() and createShoebox() as well?

Ya, we definitely can (and should!) add that. We should probably make an enumerated list over in #107.

kratiahuja

I believe this also needs README updates as the public API of result.analytics is being changed: https://github.com/ember-fastboot/fastboot#result

kratiahuja · 2020-10-09T00:19:18Z

src/ember-app.js

-    return this.getAppInstanceInfo(app, queueObject.isItemPreBuilt);
+    return this.getAppInstanceInfo(app, {
+      isAppInstancePreBuilt: queueObject.isItemPreBuilt,
+      appInstanceRetrievalTime: Date.now() - appInstanceRetrievalStartTime,


Instead of doing this here, shouldn't these metrics come from the queueObject like isItemPreBuilt? It seems a bit of an odd API where we return whether the item was pre built or built on the fly but not the metrics of the time spent for that task. In other words, we are already getting what task was dequeued but not it's timing info.

If it isn't prebuilt, it can capture the time to create the sandbox. This way the generator function takes care of creation of the object, determining the state of reterival and metrics. If the intent is to get the time taken to built the sanbox then it should come from as part of the dequeue API IMO.

kratiahuja · 2020-10-09T00:21:15Z

src/ember-app.js

@@ -323,6 +336,7 @@ class EmberApp {

    try {
      await this._visit(path, fastbootInfo, bootOptions, result, buildSandboxPerVisit);
+      result.analytics.fastbootVisitTime = Date.now() - fastbootVisitStartTime;


I think visit end time is when finally block is called in order capture the entire time. Is there specific reason why we are not capturing the remaining time to build the result and shoebox?

Add instrumentation for measuring metrics related to visit

c3a0379

suchitadoshi1987 requested a review from rwjblue October 7, 2020 18:22

rwjblue reviewed Oct 7, 2020

View reviewed changes

kratiahuja requested changes Oct 9, 2020

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add instrumentation for measuring metrics related to visit #276

Add instrumentation for measuring metrics related to visit #276

suchitadoshi1987 commented Oct 7, 2020

rwjblue left a comment

rwjblue Oct 7, 2020

xg-wang Oct 9, 2020

rwjblue Oct 7, 2020

melmerp Oct 8, 2020

rwjblue Oct 8, 2020

suchitadoshi1987 Oct 8, 2020

xg-wang Oct 9, 2020

rwjblue Oct 7, 2020

rwjblue Oct 7, 2020

suchitadoshi1987 Oct 7, 2020

rwjblue Oct 8, 2020

suchitadoshi1987 Oct 8, 2020

rwjblue Oct 7, 2020

rwjblue Oct 7, 2020

SergeAstapov commented Oct 8, 2020

rwjblue commented Oct 8, 2020

kratiahuja left a comment

kratiahuja Oct 9, 2020

kratiahuja Oct 9, 2020

Add instrumentation for measuring metrics related to visit #276

Are you sure you want to change the base?

Add instrumentation for measuring metrics related to visit #276

Conversation

suchitadoshi1987 commented Oct 7, 2020

rwjblue left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

SergeAstapov commented Oct 8, 2020

rwjblue commented Oct 8, 2020

kratiahuja left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment