Skip to content

Commit

Permalink
fix: write performance logs
Browse files Browse the repository at this point in the history
  • Loading branch information
maxakuru committed Jun 12, 2024
1 parent 11c574a commit d9a314c
Show file tree
Hide file tree
Showing 11 changed files with 205 additions and 120 deletions.
3 changes: 2 additions & 1 deletion params.json
Original file line number Diff line number Diff line change
Expand Up @@ -2,5 +2,6 @@
"CONCURRENCY_LIMIT": 10,
"BATCH_LIMIT": 1000,
"BUNDLER_DURATION_LIMIT": 540000,
"CDN_ENDPOINT": "https://rum.fastly-aem.page"
"CDN_ENDPOINT": "https://rum.fastly-aem.page",
"WRITE_PERF_LOGS": true
}
6 changes: 4 additions & 2 deletions src/bundler/index.js
Original file line number Diff line number Diff line change
Expand Up @@ -16,8 +16,9 @@ import { HelixStorage } from '../support/storage.js';
import Manifest from './Manifest.js';
import BundleGroup from './BundleGroup.js';
import {
errorWithResponse, getEnvVar, timeout, yesterday,
errorWithResponse, getEnvVar, yesterday,
} from '../support/util.js';
import { loop } from '../support/loop.js';
import { isNewDomain, setDomainKey } from '../support/domains.js';
import VIRTUAL_DOMAIN_RULES from './virtual.js';

Expand Down Expand Up @@ -403,10 +404,11 @@ async function doBundling(ctx) {
* @returns {Promise<RResponse>}
*/
export default async function bundleRUM(ctx) {
ctx.attributes.start = ctx.attributes.start || new Date();
const { env: { BUNDLER_DURATION_LIMIT } } = ctx;
const limit = parseInt(BUNDLER_DURATION_LIMIT || String(9 * 60 * 1000), 10);

const processor = timeout(doBundling, ctx, { limit });
const processor = loop(doBundling, ctx, { limit });

await lockOrThrow(ctx);
try {
Expand Down
1 change: 1 addition & 0 deletions src/index.js
Original file line number Diff line number Diff line change
Expand Up @@ -58,6 +58,7 @@ function shouldBundleRUM(req, ctx) {
async function run(request, context) {
const { log } = context;
context.attributes.stats = {};
context.attributes.start = new Date();

let resp;
try {
Expand Down
109 changes: 109 additions & 0 deletions src/support/loop.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,109 @@
/*
* Copyright 2024 Adobe. All rights reserved.
* This file is licensed to you under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License. You may obtain a copy
* of the License at http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software distributed under
* the License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR REPRESENTATIONS
* OF ANY KIND, either express or implied. See the License for the specific language
* governing permissions and limitations under the License.
*/

/* eslint-disable no-await-in-loop */

import { HelixStorage } from './storage.js';
import { errorWithResponse } from './util.js';

/**
* @param {UniversalContext} ctx
* @param {Object} data
*/
async function writeLogs(ctx, data) {
const now = ctx.attributes.start;
const day = now.getUTCDate();
const month = now.getUTCMonth() + 1;
const year = now.getUTCFullYear();
const { logBucket } = HelixStorage.fromContext(ctx);
// get existing
let existing = {};
const buf = await logBucket.get(`bundler/${year}/${month}/${day}.json`);
if (buf) {
existing = JSON.parse(buf.toString());
}

existing.performance = existing.performance || [];
existing.performance.push(data);

await logBucket.put(`bundler/${year}/${month}/${day}.json`, JSON.stringify(existing), 'application/json');
}

/**
* @typedef {{ limit: number; }} LoopOpts
* @type {<
* TFunc extends (...args: any[]) => boolean|Promise<boolean>
* >(
* fn: TFunc,
* ctx: UniversalContext,
* opts: LoopOpts
* ) => (...args: Parameters<TFunc>) => Promise<void>}
*/
export const loop = (fn, ctx, opts) => {
const { limit } = opts;

return async (...args) => {
let done = false;
let before = performance.now();

const state = {
timer: 0,
/** @type {number[]} */
times: [],
average() {
return this.timer / this.times.length;
},
/** @param {number} t */
push(t) {
this.times.push(t);
this.timer += t;
},
};

while (!done) {
done = await fn(...args);

const marks = performance.getEntriesByType('mark');
const starts = marks.filter((m) => m.name.startsWith('start'));
const measures = starts.reduce((acc, start) => {
const name = start.name.replace('start:', '');
const end = marks.find((m) => m.name === `end:${name}`);
if (end) {
acc[name] = end.startTime - start.startTime;
}
return acc;
}, {});
ctx.log.info(JSON.stringify({
message: 'performance',
measures,
stats: ctx.attributes.stats,
}));
if ([true, 'true'].includes(ctx.env.WRITE_PERF_LOGS)) {
await writeLogs(ctx, { measures, stats: ctx.attributes.stats });
}
performance.clearMarks();
ctx.attributes.stats = {};

const after = performance.now();
const dur = after - before;
before = after;
state.push(dur);

if (state.timer + state.average() >= limit) {
throw errorWithResponse(
504,
`timeout after ${state.times.length} runs (${Math.round(state.timer)} + ${Math.round(state.average())} >= ${limit})`,
);
}
}
};
};
68 changes: 0 additions & 68 deletions src/support/util.js
Original file line number Diff line number Diff line change
Expand Up @@ -108,74 +108,6 @@ export const pruneUndefined = (obj) => {
return result;
};

/**
* @typedef {{ limit: number; }} TimeoutOpts
* @type {<
* TFunc extends (...args: any[]) => Promise<boolean>
* >(
* fn: TFunc,
* ctx: UniversalContext,
* opts: TimeoutOpts
* ) => (...args: Parameters<TFunc>) => Promise<void>}
*/
export const timeout = (fn, ctx, opts) => {
const { limit } = opts;

return async (...args) => {
let done = false;
let before = performance.now();

const state = {
timer: 0,
/** @type {number[]} */
times: [],
average() {
return this.timer / this.times.length;
},
/** @param {number} t */
push(t) {
this.times.push(t);
this.timer += t;
},
};

while (!done) {
// eslint-disable-next-line no-await-in-loop
done = await fn(...args);

const marks = performance.getEntriesByType('mark');
const starts = marks.filter((m) => m.name.startsWith('start'));
const measures = starts.reduce((acc, start) => {
const name = start.name.replace('start:', '');
const end = marks.find((m) => m.name === `end:${name}`);
if (end) {
acc[name] = end.startTime - start.startTime;
}
return acc;
}, {});
ctx.log.info(JSON.stringify({
message: 'performance',
measures,
stats: ctx.attributes.stats,
}));
performance.clearMarks();
ctx.attributes.stats = {};

const after = performance.now();
const dur = after - before;
before = after;
state.push(dur);

if (state.timer + state.average() >= limit) {
throw errorWithResponse(
504,
`timeout after ${state.times.length} runs (${Math.round(state.timer)} + ${Math.round(state.average())} >= ${limit})`,
);
}
}
};
};

/**
* Conditionally compress response body
* @param {UniversalContext} ctx
Expand Down
1 change: 1 addition & 0 deletions src/types.d.ts
Original file line number Diff line number Diff line change
Expand Up @@ -55,6 +55,7 @@ declare module '@adobe/helix-universal' {
rumBundleGroups: LRUCache<BundleGroup | Promise<BundleGroup>>;
pathInfo: PathInfo;
stats: Record<string, unknown>;
start: Date;
[key: string]: unknown;
}

Expand Down
22 changes: 5 additions & 17 deletions test/api/bundles.test.js
Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,9 @@

import assert from 'assert';
import { assertAuthorized, getTTL } from '../../src/api/bundles.js';
import { DEFAULT_CONTEXT, Nock, assertRejectsWithResponse } from '../util.js';
import {
DEFAULT_CONTEXT, Nock, assertRejectsWithResponse, mockDate,
} from '../util.js';

describe('api/bundles Tests', () => {
describe('assertAuthorized()', () => {
Expand Down Expand Up @@ -45,25 +47,11 @@ describe('api/bundles Tests', () => {
});

describe('getTTL()', () => {
const ogDate = Date;
beforeEach(() => {
global.Date = class extends Date {
static _stubbed = [];

constructor(...args) {
// eslint-disable-next-line no-underscore-dangle
super(...(Date._stubbed.shift() || args));
}

static stub(...args) {
// eslint-disable-next-line no-underscore-dangle
Date._stubbed.push(args);
return Date;
}
};
mockDate();
});
afterEach(() => {
global.Date = ogDate;
global.Date.reset();
});

/**
Expand Down
26 changes: 19 additions & 7 deletions test/bundler/index.test.js
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,9 @@ import fs from 'fs/promises';
import zlib from 'zlib';
import { promisify } from 'util';
import bundleRUM, { sortRawEvents } from '../../src/bundler/index.js';
import { DEFAULT_CONTEXT, Nock, assertRejectsWithResponse } from '../util.js';
import {
DEFAULT_CONTEXT, Nock, assertRejectsWithResponse, mockDate,
} from '../util.js';

const gzip = promisify(zlib.gzip);

Expand Down Expand Up @@ -128,10 +130,12 @@ describe('bundler Tests', () => {
nock = new Nock().env();
ogUUID = crypto.randomUUID;
crypto.randomUUID = () => 'test-new-key';
mockDate();
});
afterEach(() => {
crypto.randomUUID = ogUUID;
nock.done();
global.Date.reset();
});

it('throws 409 if logs are locked', async () => {
Expand Down Expand Up @@ -162,6 +166,8 @@ describe('bundler Tests', () => {
bundle: [],
},
};
// used in perf logs
Date.stub(2024, 0, 1);

nock('https://helix-rum-logs.s3.us-east-1.amazonaws.com')
// logs not locked
Expand All @@ -183,6 +189,12 @@ describe('bundler Tests', () => {
.reply(200)
// unlock
.delete('/.lock?x-id=DeleteObject')
.reply(200)
// get bundler logs
.get('/bundler/2024/1/1.json?x-id=GetObject')
.reply(404)
// write bundler logs
.put('/bundler/2024/1/1.json?x-id=PutObject')
.reply(200);

// subdomain
Expand Down Expand Up @@ -267,7 +279,7 @@ describe('bundler Tests', () => {
return [200];
});

const ctx = DEFAULT_CONTEXT();
const ctx = DEFAULT_CONTEXT({ env: { WRITE_PERF_LOGS: 'true' } });
await bundleRUM(ctx);

const { subdomain, apex } = bodies;
Expand Down Expand Up @@ -470,10 +482,10 @@ describe('bundler Tests', () => {
});

// check that performance was measured and logged correctly
// .lock deleted message is last
const perfLog = JSON.parse(ctx.log.calls.info[ctx.log.calls.info.length - 2]);
const { measures } = perfLog;
perfLog.measures = undefined;
const [perfLog] = ctx.log.calls.info.find((args) => args && args[0] && args[0].startsWith('{"message":"performance"'));
const perfLogObj = JSON.parse(perfLog);
const { measures } = perfLogObj;
perfLogObj.measures = undefined;
Object.values(measures).forEach((m) => {
assert.strictEqual(typeof m, 'number');
});
Expand All @@ -487,7 +499,7 @@ describe('bundler Tests', () => {
'parse-logs',
'sort-events',
]);
assert.deepEqual(perfLog, {
assert.deepEqual(perfLogObj, {
message: 'performance',
measures: undefined,
stats: {
Expand Down
38 changes: 38 additions & 0 deletions test/support/loop.test.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,38 @@
/*
* Copyright 2024 Adobe. All rights reserved.
* This file is licensed to you under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License. You may obtain a copy
* of the License at http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software distributed under
* the License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR REPRESENTATIONS
* OF ANY KIND, either express or implied. See the License for the specific language
* governing permissions and limitations under the License.
*/

import assert from 'assert';
import { DEFAULT_CONTEXT, assertRejectsWithResponse, sleep } from '../util.js';
import { loop } from '../../src/support/loop.js';

describe('loop()', () => {
it('passes arguments to function', async () => {
const fn = (arg1, arg2) => {
assert.deepStrictEqual(arg1, 'foo');
assert.deepStrictEqual(arg2, 'bar');
return true;
};
const wrapped = loop(fn, DEFAULT_CONTEXT(), { limit: 100 });
await assert.doesNotReject(wrapped('foo', 'bar'));
});

it('throws timeout response if function loop will exceed timeout', async () => {
let count = 0;
const fn = async () => {
await sleep(10);
count += 1;
return count > 10;
};
const wrapped = loop(fn, DEFAULT_CONTEXT(), { limit: 50 });
await assertRejectsWithResponse(wrapped, 504, /^timeout after/);
});
});
Loading

0 comments on commit d9a314c

Please sign in to comment.