Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add instrumentation for measuring metrics related to visit #276

Open
wants to merge 1 commit into
base: master
Choose a base branch
from
Open

Add instrumentation for measuring metrics related to visit #276

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
24 changes: 19 additions & 5 deletions src/ember-app.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -188,8 +188,11 @@ class EmberApp {
*
* @returns {Object}
*/
getAppInstanceInfo(appInstance, isAppInstancePreBuilt = true) {
return { app: appInstance, isSandboxPreBuilt: isAppInstancePreBuilt };
getAppInstanceInfo(
appInstance,
appAnalytics = { isAppInstancePreBuilt: true, appInstanceRetrievalTime: 0 }
) {
return { app: appInstance, appAnalytics };
}

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

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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();

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

+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

const queueObject = this._sandboxApplicationInstanceQueue.dequeue();
const app = await queueObject.item;

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

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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,
  }
});

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 😝

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

FWIW PerformanceEntry defines startTime and duration

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

});
}

/**
Expand Down Expand Up @@ -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
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we call this analytics instead of appAnalytics?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

agreed! 👍

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

result.analytics.appInstanceRetrievalTime = appAnalytics.appInstanceRetrievalTime;
if (buildSandboxPerVisit) {
// entangle the specific application instance to the result, so it can be
// destroyed when result._destroy() is called (after the visit is
Expand All @@ -248,7 +256,7 @@ class EmberApp {

// we add analytics information about the current request to know
// whether it used sandbox from the pre-built queue or built on demand.
result.analytics.usedPrebuiltSandbox = isSandboxPreBuilt;
result.analytics.usedPrebuiltSandbox = appAnalytics.isAppInstancePreBuilt;
} else {
// save the created application instance so that we can clean it up when
// this instance of `src/ember-app.js` is destroyed (e.g. reload)
Expand All @@ -262,7 +270,11 @@ class EmberApp {
registerFastBootInfo(fastbootInfo, instance);

await instance.boot(bootOptions);

const instanceVisitStartTime = Date.now();
await instance.visit(path, bootOptions);
result.analytics.instanceVisitTime = Date.now() - instanceVisitStartTime;
Comment on lines +274 to +276
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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,
};


await fastbootInfo.deferredPromise;
}

Expand Down Expand Up @@ -290,6 +302,7 @@ class EmberApp {
* @returns {Promise<Result>} result
*/
async visit(path, options) {
let fastbootVisitStartTime = Date.now();
let req = options.request;
let res = options.response;
let html = options.html || this.html;
Expand Down Expand Up @@ -323,6 +336,7 @@ class EmberApp {

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

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same as above

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?


if (!disableShoebox) {
// if shoebox is not disabled, then create the shoebox and send API data
Expand Down
57 changes: 31 additions & 26 deletions test/fastboot-test.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -441,27 +441,21 @@ describe('FastBoot', function() {
let html = await result.html();

expect(html).to.match(/Items: 1/);
expect(analytics).to.be.deep.equals({
usedPrebuiltSandbox: true,
});
expect(analytics.usedPrebuiltSandbox).to.equal(true);

result = await fastboot.visit('/', { buildSandboxPerVisit: true });
analytics = result.analytics;
html = await result.html();

expect(html).to.match(/Items: 1/);
expect(analytics).to.be.deep.equals({
usedPrebuiltSandbox: true,
});
expect(analytics.usedPrebuiltSandbox).to.equal(true);

result = await fastboot.visit('/', { buildSandboxPerVisit: true });
analytics = result.analytics;
html = await result.html();

expect(html).to.match(/Items: 1/);
expect(analytics).to.be.deep.equals({
usedPrebuiltSandbox: true,
});
expect(analytics.usedPrebuiltSandbox).to.equal(true);
});

it('errors can be properly attributed with buildSandboxPerVisit=true', async function() {
Expand Down Expand Up @@ -524,21 +518,15 @@ describe('FastBoot', function() {

let result = await first;
let analytics = result.analytics;
expect(analytics).to.be.deep.equals({
usedPrebuiltSandbox: true,
});
expect(analytics.usedPrebuiltSandbox).to.equal(true);

result = await second;
analytics = result.analytics;
expect(analytics).to.be.deep.equals({
usedPrebuiltSandbox: true,
});
expect(analytics.usedPrebuiltSandbox).to.equal(true);

result = await third;
analytics = result.analytics;
expect(analytics).to.be.deep.equals({
usedPrebuiltSandbox: false,
});
expect(analytics.usedPrebuiltSandbox).to.equal(false);
});

it('it leverages sandbox from queue when present', async function() {
Expand Down Expand Up @@ -566,21 +554,38 @@ describe('FastBoot', function() {

let result = await first;
let analytics = result.analytics;
expect(analytics).to.be.deep.equals({
usedPrebuiltSandbox: true,
});
expect(analytics.usedPrebuiltSandbox).to.equal(true);

result = await second;
analytics = result.analytics;
expect(analytics).to.be.deep.equals({
usedPrebuiltSandbox: true,
});
expect(analytics.usedPrebuiltSandbox).to.equal(true);

result = await third;
analytics = result.analytics;
expect(analytics).to.be.deep.equals({
usedPrebuiltSandbox: true,
expect(analytics.usedPrebuiltSandbox).to.equal(true);
});

it('should contain the analytics data for the visit', async function() {
this.timeout(3000);

var fastboot = new FastBoot({
distPath: fixture('app-with-prototype-mutations'),
});

let resultWithSandboxPerVisit = await fastboot.visit('/', { buildSandboxPerVisit: true });
expect(Object.keys(resultWithSandboxPerVisit.analytics)).to.deep.equals([
'appInstanceRetrievalTime',
'usedPrebuiltSandbox',
'instanceVisitTime',
'fastbootVisitTime',
]);

let resultWithoutSandboxPerVisit = await fastboot.visit('/');
expect(Object.keys(resultWithoutSandboxPerVisit.analytics)).to.deep.equals([
'appInstanceRetrievalTime',
'instanceVisitTime',
'fastbootVisitTime',
]);
});

it('htmlEntrypoint works', function() {
Expand Down