Skip to content

Commit d5ca5ae

Browse files
nbbeekennbbeeken
committed
perf(NODE-4726): bench many strings in large batch in parallel
1 parent 027ffb7 commit d5ca5ae

File tree

5 files changed

+2723
-1088
lines changed

5 files changed

+2723
-1088
lines changed

‎.gitignore‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -26,3 +26,5 @@ coverage/
2626
docs/public
2727

2828
*.0x
29+
*.cpuprofile
30+
*.heapprofile

‎etc/benchmarks/lib_runner.mjs‎

Lines changed: 62 additions & 35 deletions
Original file line numberDiff line numberDiff line change
@@ -1,10 +1,13 @@
11
/* eslint-disable @typescript-eslint/explicit-module-boundary-types */
22
/* eslint-disable @typescript-eslint/no-var-requires */
3-
import { performance } from 'perf_hooks';
3+
import { createHistogram } from 'perf_hooks';
44
import { readFile } from 'fs/promises';
55
import { cpus, totalmem } from 'os';
66
import { exec as execCb } from 'child_process';
7-
import { promisify } from 'util';
7+
import { promisify, types } from 'util';
8+
import { writeFile } from 'fs/promises';
9+
import v8Profiler from 'v8-profiler-next';
10+
import chalk from 'chalk';
811
const exec = promisify(execCb);
912

1013
const hw = cpus();
@@ -23,27 +26,26 @@ export const systemInfo = iterations =>
2326
export const readJSONFile = async path =>
2427
JSON.parse(await readFile(new URL(path, import.meta.url), { encoding: 'utf8' }));
2528

26-
function average(array) {
27-
let sum = 0;
28-
for (const value of array) sum += value;
29-
return sum / array.length;
30-
}
31-
32-
function testPerformance(lib, [fn, arg], iterations) {
33-
let measurements = [];
29+
async function testPerformance(lib, [fn, arg], iterations) {
3430
let thrownError = null;
31+
const histogram = createHistogram();
3532
for (let i = 0; i < iterations; i++) {
36-
const start = performance.now();
3733
try {
38-
fn(i, lib, arg);
34+
if (types.isAsyncFunction(fn)) {
35+
histogram.recordDelta();
36+
await fn(i, lib, arg);
37+
histogram.recordDelta();
38+
} else {
39+
histogram.recordDelta();
40+
fn(i, lib, arg);
41+
histogram.recordDelta();
42+
}
3943
} catch (error) {
4044
thrownError = error;
4145
break;
4246
}
43-
const end = performance.now();
44-
measurements.push(end - start);
4547
}
46-
return { result: average(measurements).toFixed(8), thrownError };
48+
return { histogram, thrownError };
4749
}
4850

4951
export function getCurrentLocalBSON(libs) {
@@ -52,15 +54,15 @@ export function getCurrentLocalBSON(libs) {
5254

5355
export async function getLibs() {
5456
return await Promise.all([
55-
(async () => {
56-
const { stdout } = await exec('git rev-parse --short HEAD');
57-
const hash = stdout.trim();
58-
return {
59-
name: 'local',
60-
lib: await import('../../lib/bson.js'),
61-
version: hash
62-
};
63-
})(),
57+
// (async () => {
58+
// const { stdout } = await exec('git rev-parse --short HEAD');
59+
// const hash = stdout.trim();
60+
// return {
61+
// name: 'local',
62+
// lib: await import('../../lib/bson.js'),
63+
// version: hash
64+
// };
65+
// })(),
6466
(async () => ({
6567
name: 'released',
6668
lib: await import('../../node_modules/bson_latest/lib/bson.js'),
@@ -73,12 +75,12 @@ export async function getLibs() {
7375
lib: { ...legacyBSON, ...legacyBSON.prototype },
7476
version: (await readJSONFile('../../node_modules/bson_legacy/package.json')).version
7577
};
76-
})(),
77-
(async () => ({
78-
name: 'bson-ext',
79-
lib: await import('../../node_modules/bson_ext/lib/index.js'),
80-
version: (await readJSONFile('../../node_modules/bson_ext/package.json')).version
81-
}))()
78+
})()
79+
// (async () => ({
80+
// name: 'bson-ext',
81+
// lib: await import('../../node_modules/bson_ext/lib/index.js'),
82+
// version: (await readJSONFile('../../node_modules/bson_ext/package.json')).version
83+
// }))()
8284
]).catch(error => {
8385
console.error(error);
8486
console.error(
@@ -91,6 +93,27 @@ export async function getLibs() {
9193
});
9294
}
9395

96+
const printHistogram = (name, h) => {
97+
const makeReadableTime = nanoseconds => (nanoseconds / 1e6).toFixed(3).padStart(7, ' ');
98+
console.log();
99+
console.log(chalk.green(name));
100+
console.log('-'.repeat(155));
101+
process.stdout.write(`| ${chalk.cyan('max')}: ${chalk.red(makeReadableTime(h.max))} ms |`);
102+
process.stdout.write(` ${chalk.cyan('min')}: ${chalk.red(makeReadableTime(h.min))} ms |`);
103+
process.stdout.write(` ${chalk.cyan('mean')}: ${chalk.red(makeReadableTime(h.mean))} ms |`);
104+
process.stdout.write(` ${chalk.cyan('stddev')}: ${chalk.red(makeReadableTime(h.stddev))} ms |`);
105+
process.stdout.write(
106+
` ${chalk.cyan('p90th')}: ${chalk.red(makeReadableTime(h.percentile(90)))} ms |`
107+
);
108+
process.stdout.write(
109+
` ${chalk.cyan('p95th')}: ${chalk.red(makeReadableTime(h.percentile(95)))} ms |`
110+
);
111+
process.stdout.write(
112+
` ${chalk.cyan('p99th')}: ${chalk.red(makeReadableTime(h.percentile(99)))} ms |`
113+
);
114+
console.log('\n' + '-'.repeat(155));
115+
};
116+
94117
/**
95118
* ```ts
96119
* interface {
@@ -109,19 +132,23 @@ export async function runner({ iterations, setup, name, run, skip }) {
109132
const BSONLibs = await getLibs();
110133
const setupResult = setup?.(BSONLibs) ?? null;
111134

112-
console.log(`\ntesting: ${name}`);
135+
console.log('-'.repeat(155));
113136

114137
for (const bson of BSONLibs) {
115-
const { result: perf, thrownError } = testPerformance(bson, [run, setupResult], iterations);
138+
const profileName = `${bson.name}_${name}`;
139+
v8Profiler.startProfiling(profileName, true);
140+
const { histogram, thrownError } = await testPerformance(bson, [run, setupResult], iterations);
116141
if (thrownError != null) {
117142
console.log(
118143
`${bson.name.padEnd(14, ' ')} - v ${bson.version.padEnd(8, ' ')} - error ${thrownError}`
119144
);
120145
} else {
121-
console.log(
122-
`${bson.name.padEnd(14, ' ')} - v ${bson.version.padEnd(8, ' ')} - avg ${perf}ms`
123-
);
146+
printHistogram(`${chalk.greenBright(bson.name)} - ${chalk.blue(name)}`, histogram);
124147
}
148+
const profile = v8Profiler.stopProfiling(profileName);
149+
const result = await promisify(profile.export.bind(profile))();
150+
await writeFile(`${profileName}.cpuprofile`, result);
151+
profile.delete();
125152
}
126153

127154
console.log();

‎etc/benchmarks/main.mjs‎

Lines changed: 37 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -2,15 +2,15 @@
22
import { performance } from 'perf_hooks';
33
import { runner, systemInfo, getCurrentLocalBSON } from './lib_runner.mjs';
44

5-
const iterations = 1_000_000;
5+
const iterations = 100;
66
const startedEntireRun = performance.now();
77
console.log(systemInfo(iterations));
88
console.log();
99

1010
////////////////////////////////////////////////////////////////////////////////////////////////////
1111
await runner({
1212
skip: true,
13-
name: 'deserialize({ oid, string }, { validation: { utf8: false } })',
13+
name: 'deserialize an objectId and a string without utf8 validation',
1414
iterations,
1515
setup(libs) {
1616
const bson = getCurrentLocalBSON(libs);
@@ -28,7 +28,7 @@ await runner({
2828
////////////////////////////////////////////////////////////////////////////////////////////////////
2929
await runner({
3030
skip: true,
31-
name: 'new Oid(buf)',
31+
name: 'objectId constructor',
3232
iterations,
3333
setup() {
3434
return Buffer.from('00'.repeat(12), 'hex');
@@ -40,7 +40,7 @@ await runner({
4040
////////////////////////////////////////////////////////////////////////////////////////////////////
4141
await runner({
4242
skip: true,
43-
name: 'BSON.deserialize(largeDocument)',
43+
name: 'deserialize a large document',
4444
iterations,
4545
setup(libs) {
4646
const bson = getCurrentLocalBSON(libs);
@@ -68,7 +68,7 @@ await runner({
6868
});
6969

7070
await runner({
71-
skip: false,
71+
skip: true,
7272
name: 'Double Deserialization',
7373
iterations,
7474
setup(libs) {
@@ -81,7 +81,7 @@ await runner({
8181
});
8282

8383
await runner({
84-
skip: false,
84+
skip: true,
8585
name: 'Many Doubles Deserialization',
8686
iterations,
8787
setup(libs) {
@@ -98,6 +98,37 @@ await runner({
9898
}
9999
});
100100

101+
/// Batch full of user doc with 20 char strings w/ 20 strings
102+
/// nextBatch simulate
103+
/// nextBatch: [ { string * 20 } * 1000 ] /// Garbage call
104+
await runner({
105+
skip: false,
106+
name: 'deserialize a large batch of documents each with an array of many strings',
107+
iterations,
108+
setup(libs) {
109+
const bson = libs[0].lib;
110+
return bson.serialize({
111+
nextBatch: Array.from({ length: 1000 }, () => ({
112+
_id: new bson.ObjectId(),
113+
arrayField: Array.from({ length: 20 }, (_, i) => '5e99f3f5d3ab06936d36000' + i)
114+
}))
115+
});
116+
},
117+
async run(i, bson, document) {
118+
await Promise.all(
119+
Array.from(
120+
{ length: 100 },
121+
(_, i) =>
122+
new Promise(resolve => {
123+
setTimeout(() => {
124+
resolve(bson.lib.deserialize(document, { validation: { utf8: false } }));
125+
}, 20);
126+
})
127+
)
128+
);
129+
}
130+
});
131+
101132
// End
102133
console.log(
103134
'Total time taken to benchmark:',

0 commit comments

Comments
 (0)