Skip to content

Commit 169eea1

Browse files
andrewigginsandrewiggins
committed
Add script to analyze chromium trace logs
1 parent 5c54453 commit 169eea1

File tree

6 files changed

+577
-1
lines changed

6 files changed

+577
-1
lines changed

‎benches/jsconfig.json‎

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,8 @@
1+
{
2+
"compilerOptions": {
3+
"target": "es2020",
4+
"checkJs": true,
5+
"moduleResolution": "node"
6+
},
7+
"exclude": ["node_modules", "dist"]
8+
}

‎benches/package.json‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@
66
"description": "Benchmarks for Preact",
77
"scripts": {
88
"start": "node ./scripts config many_updates.html && tach --force-clean-npm-install --config dist/many_updates.config.json --manual",
9+
"analyze": "node ./scripts analyze",
910
"bench": "node ./scripts bench",
1011
"deopts": "node ./scripts deopts",
1112
"help": "node ./scripts --help"

‎benches/scripts/analyze.js‎

Lines changed: 334 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,334 @@
1+
import { readFile, readdir } from 'fs/promises';
2+
import { frameworks } from './config.js';
3+
import { benchesRoot } from './utils.js';
4+
5+
// @ts-ignore
6+
import tachometerStats from 'tachometer/lib/stats.js';
7+
// @ts-ignore
8+
import tachometerFormat from 'tachometer/lib/format.js';
9+
10+
/**
11+
* @typedef {import('./tracing').TraceEvent} TraceEvent
12+
* @typedef {import('tachometer/lib/stats').SummaryStats} SummaryStats
13+
* @typedef {import('tachometer/lib/stats').ResultStats} ResultStats
14+
* @typedef {import('tachometer/lib/stats').ResultStatsWithDifferences} ResultStatsWithDifferences
15+
* @type {import('tachometer/lib/stats')}
16+
*/
17+
const statsLib = tachometerStats;
18+
const { summaryStats, computeDifferences } = statsLib;
19+
/** @type {import('tachometer/lib/format')} */
20+
const formatLib = tachometerFormat;
21+
const { automaticResultTable, verticalTermResultTable } = formatLib;
22+
23+
const toTrack = new Set([
24+
// 'V8.CompileCode', // Might be tachometer code?? But maybe not?
25+
'V8.MarkCandidatesForOptimization',
26+
'V8.OptimizeCode',
27+
'V8.OptimizeConcurrentPrepare',
28+
'V8.OptimizeNonConcurrent',
29+
// 'V8.OptimizeBackground', // Runs on background thread
30+
'V8.InstallOptimizedFunctions',
31+
'V8.DeoptimizeCode',
32+
'MinorGC',
33+
'V8.GCDeoptMarkedAllocationSites'
34+
]);
35+
36+
/**
37+
* @template T
38+
* @param {Map<string, T[]>} grouping
39+
* @param {Map<string, T | T[]>} results
40+
*/
41+
function addToGrouping(grouping, results) {
42+
for (let [group, data] of results.entries()) {
43+
if (grouping.has(group)) {
44+
if (Array.isArray(data)) {
45+
grouping.get(group).push(...data);
46+
} else {
47+
grouping.get(group).push(data);
48+
}
49+
} else {
50+
if (Array.isArray(data)) {
51+
grouping.set(group, data);
52+
} else {
53+
grouping.set(group, [data]);
54+
}
55+
}
56+
}
57+
}
58+
59+
/**
60+
* @template K
61+
* @template V
62+
* @param {Map<K, V[]>} map
63+
* @param {K} key
64+
* @param {...V} values
65+
*/
66+
function addToMapArray(map, key, ...values) {
67+
if (map.has(key)) {
68+
map.get(key).push(...values);
69+
} else {
70+
map.set(key, values);
71+
}
72+
}
73+
74+
/**
75+
* @template K
76+
* @template V
77+
* @param {Map<K, V[]>} map
78+
* @param {K} key
79+
* @param {number} index
80+
* @param {V} value
81+
*/
82+
function setInMapArray(map, key, index, value) {
83+
if (map.has(key)) {
84+
map.get(key)[index] = value;
85+
} else {
86+
map.set(key, [value]);
87+
}
88+
}
89+
90+
/**
91+
* @param {ResultStats[]} results
92+
*/
93+
function logDifferences(key, results) {
94+
let withDifferences = computeDifferences(results);
95+
console.log();
96+
let { fixed, unfixed } = automaticResultTable(withDifferences);
97+
// console.log(horizontalTermResultTable(fixed));
98+
console.log(key);
99+
console.log(verticalTermResultTable(unfixed));
100+
}
101+
102+
/**
103+
* @param {string} version
104+
* @param {string[]} logPaths
105+
* @param {(logs: TraceEvent[], logFilePath: string) => number} [getThreadId]
106+
* @param {(log: TraceEvent) => boolean} [trackEventsIn]
107+
* @returns {Promise<Map<string, ResultStats>>}
108+
*/
109+
async function getStatsFromLogs(version, logPaths, getThreadId, trackEventsIn) {
110+
/** @type {Map<string, number[]>} Sums for each function for each file */
111+
const data = new Map();
112+
for (let logPath of logPaths) {
113+
/** @type {TraceEvent[]} */
114+
const logs = JSON.parse(await readFile(logPath, 'utf8'));
115+
116+
let tid = getThreadId ? getThreadId(logs, logPath) : null;
117+
118+
/** @type {Array<{ id: string; start: number; end: number; }>} Determine what durations to track events under */
119+
const parentLogs = [];
120+
for (let log of logs) {
121+
if (trackEventsIn && trackEventsIn(log)) {
122+
if (log.ph == 'X') {
123+
parentLogs.push({
124+
id: log.name,
125+
start: log.ts,
126+
end: log.ts + log.dur
127+
});
128+
} else if (log.ph == 'b') {
129+
parentLogs.push({
130+
id: log.name,
131+
start: log.ts,
132+
end: log.ts
133+
});
134+
} else if (log.ph == 'e') {
135+
parentLogs.find(l => l.id == log.name).end = log.ts;
136+
} else {
137+
throw new Error(`Unsupported parent log type: ${log.ph}`);
138+
}
139+
}
140+
}
141+
142+
/** @type {Map<string, import('./tracing').AsyncEvent>} */
143+
const durationBeginEvents = new Map();
144+
145+
/** @type {Map<string, number[]>} Sum of time spent in each function for this log file */
146+
const sumsForFile = new Map();
147+
for (let log of logs) {
148+
if (tid != null && log.tid !== tid) {
149+
// if (toTrack.has(log.name)) {
150+
// console.log(
151+
// `Skipping ${log.name} on tid ${log.tid} (expected ${tid}) in ${logPath}`
152+
// );
153+
// }
154+
155+
continue;
156+
}
157+
158+
if (log.ph == 'X') {
159+
// Track duration event
160+
if (toTrack.has(log.name)) {
161+
let key = `Sum of ${log.name} time`;
162+
let sum = sumsForFile.get(key)?.[0] ?? 0;
163+
// sumsForFile.set(log.name, sum + log.dur / 1000);
164+
setInMapArray(sumsForFile, key, 0, sum + log.dur / 1000);
165+
166+
key = `Count of ${log.name}`;
167+
sum = sumsForFile.get(key)?.[0] ?? 0;
168+
// sumsForFile.set(key, sum + 1);
169+
setInMapArray(sumsForFile, key, 0, sum + 1);
170+
171+
key = `Sum of V8 runtime`;
172+
sum = sumsForFile.get(key)?.[0] ?? 0;
173+
// sumsForFile.set(key, sum + log.dur / 1000);
174+
setInMapArray(sumsForFile, key, 0, sum + log.dur / 1000);
175+
176+
for (let parentLog of parentLogs) {
177+
if (
178+
parentLog.start <= log.ts &&
179+
log.ts + log.dur <= parentLog.end
180+
) {
181+
key = `In ${parentLog.id}, Sum of V8 runtime`;
182+
sum = sumsForFile.get(key)?.[0] ?? 0;
183+
setInMapArray(sumsForFile, key, 0, sum + log.dur / 1000);
184+
}
185+
}
186+
}
187+
188+
if (log.name == 'MinorGC' || log.name == 'MajorGC') {
189+
let key = `${log.name} usedHeapSizeBefore`;
190+
addToMapArray(sumsForFile, key, log.args.usedHeapSizeBefore / 1e6);
191+
192+
key = `${log.name} usedHeapSizeAfter`;
193+
addToMapArray(sumsForFile, key, log.args.usedHeapSizeAfter / 1e6);
194+
}
195+
} else if (
196+
(log.ph == 'b' || log.ph == 'e') &&
197+
log.cat == 'blink.user_timing' &&
198+
log.scope == 'blink.user_timing'
199+
) {
200+
// TODO: Doesn't handle nested events of same name. Oh well.
201+
if (log.ph == 'b') {
202+
durationBeginEvents.set(log.name, log);
203+
} else {
204+
const beginEvent = durationBeginEvents.get(log.name);
205+
const endEvent = log;
206+
durationBeginEvents.delete(log.name);
207+
208+
let key = beginEvent.name;
209+
let duration = (endEvent.ts - beginEvent.ts) / 1000;
210+
addToMapArray(sumsForFile, key, duration);
211+
212+
if (key.startsWith('run-') && key !== 'run-warmup-0') {
213+
// Skip run-warmup-0 since it doesn't do unmounting
214+
addToMapArray(sumsForFile, 'average run duration', duration);
215+
}
216+
}
217+
}
218+
}
219+
220+
addToGrouping(data, sumsForFile);
221+
}
222+
223+
const stats = new Map();
224+
for (let [key, sums] of data) {
225+
stats.set(key, {
226+
result: {
227+
name: '02_replace1k',
228+
version: version,
229+
measurement: {
230+
name: key,
231+
mode: 'expression',
232+
expression: key,
233+
unit: key.startsWith('Count')
234+
? ''
235+
: key.includes('usedHeapSize')
236+
? 'MB'
237+
: null
238+
},
239+
browser: {
240+
name: 'chrome'
241+
},
242+
millis: sums
243+
},
244+
stats: summaryStats(sums)
245+
});
246+
}
247+
248+
return stats;
249+
}
250+
251+
/**
252+
* @param {import('./tracing').TraceEvent[]} logs
253+
* @param {string} logFilePath
254+
* @returns {number}
255+
*/
256+
function getDurationThread(logs, logFilePath) {
257+
let log = logs.find(isDurationLog);
258+
259+
if (log == null) {
260+
throw new Error(
261+
`Could not find blink.user_timing log for "run-final" or "duration" in ${logFilePath}.`
262+
);
263+
} else {
264+
return log.tid;
265+
}
266+
}
267+
268+
/**
269+
* @param {TraceEvent} log
270+
*/
271+
function isDurationLog(log) {
272+
return (
273+
(log.ph == 'b' || log.ph == 'e') &&
274+
log.cat == 'blink.user_timing' &&
275+
log.scope == 'blink.user_timing' &&
276+
// Tachometer may kill the tab after seeing the duration measure before
277+
// the tab can log it to the trace file
278+
(log.name == 'run-final' || log.name == 'duration')
279+
);
280+
}
281+
282+
export async function analyze() {
283+
// const frameworkNames = await readdir(p('logs'));
284+
const frameworkNames = frameworks.map(f => f.label);
285+
const listAtEnd = [
286+
'average run duration',
287+
'Sum of V8 runtime',
288+
'In run-final, Sum of V8 runtime',
289+
'In duration, Sum of V8 runtime',
290+
'duration'
291+
];
292+
293+
/** @type {Map<string, ResultStats[]>} */
294+
const resultStatsMap = new Map();
295+
for (let framework of frameworkNames) {
296+
const logDir = benchesRoot('logs', framework);
297+
298+
let logFilePaths;
299+
try {
300+
logFilePaths = (await readdir(logDir)).map(fn =>
301+
benchesRoot('logs', framework, fn)
302+
);
303+
} catch (e) {
304+
// If directory doesn't exist or we fail to read it, just skip
305+
continue;
306+
}
307+
308+
const resultStats = await getStatsFromLogs(
309+
framework,
310+
logFilePaths,
311+
getDurationThread,
312+
isDurationLog
313+
);
314+
addToGrouping(resultStatsMap, resultStats);
315+
316+
// console.log(`${framework}:`);
317+
// console.log(resultStats);
318+
}
319+
320+
// Compute differences and print table
321+
for (let [key, results] of resultStatsMap.entries()) {
322+
if (listAtEnd.includes(key)) {
323+
continue;
324+
}
325+
326+
logDifferences(key, results);
327+
}
328+
329+
for (let key of listAtEnd) {
330+
if (resultStatsMap.has(key)) {
331+
logDifferences(key, resultStatsMap.get(key));
332+
}
333+
}
334+
}

‎benches/scripts/config.js‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -35,7 +35,7 @@ async function validateFileDep(framework) {
3535
* @typedef {ConfigFilePackageVersion & { isValid(): Promise<boolean>; }} BenchConfig
3636
* @type {BenchConfig[]}
3737
*/
38-
const frameworks = [
38+
export const frameworks = [
3939
{
4040
label: 'preact-v8',
4141
dependencies: {

‎benches/scripts/index.js‎

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@ import sade from 'sade';
22
import { generateSingleConfig } from './config.js';
33
import { defaultDeoptsOptions, runDeopts } from './deopts.js';
44
import { defaultBenchOptions, runBenches } from './bench.js';
5+
import { analyze } from './analyze.js';
56

67
const prog = sade('./scripts');
78

@@ -98,4 +99,12 @@ prog
9899
)
99100
.action(runDeopts);
100101

102+
prog
103+
.command('analyze')
104+
.describe(
105+
'Analyze the trace logs created by running benchmarks with the --trace flag'
106+
)
107+
.example('analyze')
108+
.action(analyze);
109+
101110
prog.parse(process.argv);

0 commit comments

Comments
 (0)