Skip to content

Commit 5763d66

Browse files
krausestkrausest
committed
raf fix
1 parent bc2a611 commit 5763d66

File tree

6 files changed

+447
-306
lines changed

6 files changed

+447
-306
lines changed

‎webdriver-ts-results/src/results.ts

Lines changed: 263 additions & 263 deletions
Large diffs are not rendered by default.

‎webdriver-ts-results/table.html

Lines changed: 1 addition & 1 deletion
Large diffs are not rendered by default.

‎webdriver-ts/package-lock.json

Lines changed: 50 additions & 0 deletions
Some generated files are not rendered by default. Learn more about customizing how changed files appear on GitHub.

‎webdriver-ts/results.json

Lines changed: 1 addition & 1 deletion
Large diffs are not rendered by default.

‎webdriver-ts/src/forkedBenchmarkRunnerPuppeteer.ts

Lines changed: 108 additions & 29 deletions
Original file line numberDiff line numberDiff line change
@@ -35,17 +35,20 @@ export function extractRelevantEvents(entries: any[]) {
3535
filteredEvents.push({type:'click', ts: +e.ts, dur: +e.dur, end: +e.ts+e.dur});
3636
}
3737
} else if (e.name==='CompositeLayers' && e.ph==="X") {
38-
if (config.LOG_DETAILS) console.log("CompositeLayers",+e.ts+e.dur, +e.ts+e.dur-click_start);
38+
if (config.LOG_DETAILS) console.log("CompositeLayers",+e.ts, +e.ts+e.dur-click_start);
3939
filteredEvents.push({type:'compositelayers', ts: +e.ts, dur: +e.dur, end: +e.ts+e.dur, evt: JSON.stringify(e)});
4040
} else if (e.name==='Layout' && e.ph==="X") {
41-
if (config.LOG_DETAILS) console.log("Layout",+e.ts+e.dur, +e.ts+e.dur-click_start);
41+
if (config.LOG_DETAILS) console.log("Layout",+e.ts, +e.ts+e.dur-click_start);
4242
filteredEvents.push({type:'layout', ts: +e.ts, dur: +e.dur, end: +e.ts+e.dur, evt: JSON.stringify(e)});
4343
} else if (e.name==='Paint' && e.ph==="X") {
44-
if (config.LOG_DETAILS) console.log("PAINT",+e.ts+e.dur, +e.ts+e.dur-click_start);
44+
if (config.LOG_DETAILS) console.log("PAINT",+e.ts, +e.ts+e.dur-click_start);
4545
filteredEvents.push({type:'paint', ts: +e.ts, dur: +e.dur, end: +e.ts+e.dur, evt: JSON.stringify(e)});
4646
} else if (e.name==='FireAnimationFrame' && e.ph==="X") {
47-
if (config.LOG_DETAILS) console.log("FireAnimationFrame",+e.ts+e.dur, +e.ts-click_start);
47+
if (config.LOG_DETAILS) console.log("FireAnimationFrame",+e.ts, +e.ts-click_start);
4848
filteredEvents.push({type:'fireAnimationFrame', ts: +e.ts, dur: +e.dur, end: +e.ts+e.dur, evt: JSON.stringify(e)});
49+
} else if (e.name==='UpdateLayoutTree' && e.ph==="X") {
50+
if (config.LOG_DETAILS) console.log("UpdateLayoutTree",+e.ts, +e.ts-click_start);
51+
filteredEvents.push({type:'updateLayoutTree', ts: +e.ts, dur: +e.dur, end: +e.ts+e.dur, evt: JSON.stringify(e)});
4952
} else if (e.name==='RequestAnimationFrame') {
5053
if (config.LOG_DETAILS) console.log("RequestAnimationFrame",+e.ts, +e.ts-click_start, +e.ts-click_end);
5154
filteredEvents.push({type:'requestAnimationFrame', ts: +e.ts, dur: 0, end: +e.ts, evt: JSON.stringify(e)});
@@ -71,6 +74,70 @@ function type_eq(requiredType: string) {
7174
return (e: Timingresult) => e.type=== requiredType;
7275
}
7376

77+
// export async function computeResultsCPUNew(fileName: string, durationMeasurementMode: DurationMeasurementMode): Promise<number> {
78+
// let contents = await readFile(fileName, {encoding: "utf8"});
79+
// let traceObj = JSON.parse(contents)
80+
// let entries = traceObj['traceEvents'];
81+
82+
// let clickEvents = entries.filter((e:any) => {
83+
// return (e.name==='EventDispatch') && (e.args.data.type==="click") ;
84+
// });
85+
// console.log("# clickEvents", clickEvents.length);
86+
// let click_ts = +clickEvents[0].ts;
87+
88+
// // let eventsBeforeClick = entries.filter((e:any) => {
89+
// // return (e.ts< click_ts &&
90+
// // !( (e.name=='CompositeLayers')
91+
// // || (e.name==='RunTask')
92+
// // || (e.name==='Layout')
93+
// // || (e.name==='Paint')
94+
// // || (e.name==='FireAnimationFrame')
95+
// // || (e.name==='UpdateLayoutTree')
96+
// // || (e.name==='RequestAnimationFrame')
97+
// // || (e.name==='HitTest')
98+
// // || (e.name==='ScheduleStyleRecalculation')
99+
// // || (e.name==='EventDispatch')
100+
// // || (e.name==='UpdateLayerTree')
101+
// // || (e.name==='UpdateLayer')
102+
// // || (e.name==='SetLayerTreeId')
103+
// // || (e.name==='IntersectionObserverController::computeIntersections')
104+
// // || (e.name==='FunctionCall')
105+
// // || (e.name==='RasterTask')
106+
// // || (e.name==='EventTiming')
107+
// // ))
108+
// // });
109+
// // console.log("before", click_ts);
110+
// // console.log(eventsBeforeClick);
111+
112+
// let eventsAfterClick = entries.filter((e:any) => {
113+
// return !(e.ts< click_ts &&
114+
// ( (e.name=='CompositeLayers')
115+
// || (e.name==='RunTask')
116+
// || (e.name==='Layout')
117+
// || (e.name==='Paint')
118+
// || (e.name==='FireAnimationFrame')
119+
// || (e.name==='UpdateLayoutTree')
120+
// || (e.name==='RequestAnimationFrame')
121+
// || (e.name==='HitTest')
122+
// || (e.name==='ScheduleStyleRecalculation')
123+
// || (e.name==='EventDispatch')
124+
// || (e.name==='UpdateLayerTree')
125+
// || (e.name==='UpdateLayer')
126+
// || (e.name==='SetLayerTreeId')
127+
// || (e.name==='IntersectionObserverController::computeIntersections')
128+
// || (e.name==='FunctionCall')
129+
// || (e.name==='RasterTask')
130+
// || (e.name==='EventTiming')
131+
// ))
132+
// });
133+
// console.log("#events total", entries.length, "#events after click", eventsAfterClick.length);
134+
135+
136+
// const tasks = new Tracelib(eventsAfterClick)
137+
// const summary = tasks.getSummary()
138+
// console.log("painting", summary.painting, "rendering", summary.rendering, "scripting", summary.scripting)
139+
// return summary.painting +summary.rendering + summary.scripting;
140+
// }
74141
export async function computeResultsCPU(fileName: string, durationMeasurementMode: DurationMeasurementMode): Promise<number> {
75142
const perfLogEvents = (await fetchEventsFromPerformanceLog(fileName));
76143
let eventsDuringBenchmark = R.sortBy((e: Timingresult) => e.end)(perfLogEvents);
@@ -105,44 +172,54 @@ export async function computeResultsCPU(fileName: string, durationMeasurementMod
105172

106173
let paints = R.filter((e: Timingresult) => e.ts > onlyUsePaintEventsAfter.end)(R.filter(type_eq('paint'))(eventsDuringBenchmark));
107174
if (paints.length == 0) {
108-
console.log("ERROR: No paint event found");
175+
console.log("ERROR: No paint event found ",fileName);
109176
throw "No paint event found";
110177
}
178+
let paint = paints[durationMeasurementMode==DurationMeasurementMode.FIRST_PAINT_AFTER_LAYOUT ? 0 : paints.length-1];
179+
let duration = (paint.end - clicks[0].ts)/1000.0;
111180
if (paints.length > 1) {
112-
console.log("more than one paint event found");
181+
console.log("more than one paint event found ",fileName);
113182
paints.forEach(l => {
114183
console.log("paints event",(l.end-click.ts)/1000.0);
115184
})
185+
if (durationMeasurementMode==DurationMeasurementMode.FIRST_PAINT_AFTER_LAYOUT) {
186+
console.log("IGNORING more than one paint due to FIRST_PAINT_AFTER_LAYOUT", fileName, duration);
187+
}
116188
}
117-
let paint = paints[durationMeasurementMode==DurationMeasurementMode.FIRST_PAINT_AFTER_LAYOUT ? 0 : paints.length-1];
118-
let duration = (paint.end - clicks[0].ts)/1000.0;
119189
console.log("duration", duration);
120190

191+
// let updateLayoutTree = R.filter((e: Timingresult) => e.ts > click.end)(R.filter(type_eq('updateLayoutTree'))(eventsDuringBenchmark));
192+
// console.log("updateLayoutTree", updateLayoutTree.length, updateLayoutTree[0].end);
193+
121194
let rafs_withinClick = R.filter((e: Timingresult) => e.ts >= click.ts && e.ts <= click.end)(R.filter(type_eq('requestAnimationFrame'))(eventsDuringBenchmark));
122-
if (rafs_withinClick.length =1) {
123-
let fafs = R.filter((e: Timingresult) => e.ts >= click.ts && e.ts < paint.ts)(R.filter(type_eq('fireAnimationFrame'))(eventsDuringBenchmark));
124-
if (layouts.length>0) {
125-
fafs = R.filter((e: Timingresult) => e.end < layouts[0].ts)(fafs);
126-
}
127-
if (paints.length>0) {
128-
fafs = R.filter((e: Timingresult) => e.end < paints[0].ts)(fafs);
129-
}
130-
if (fafs.length !=1) {
131-
console.log(`*#* there were ${fafs.length} fafs`);
132-
}
133-
if (fafs.length > 0 && rafs_withinClick.length > 0) {
134-
let waitDelay = (fafs[0].ts - click.end) / 1000.0;
135-
duration = duration - waitDelay;
136-
if (waitDelay > 16) {
137-
console.log(`*#* WARNING: duration of raf delay is longer than expected: ${waitDelay}`);
195+
let fafs = R.filter((e: Timingresult) => e.ts >= click.ts && e.ts < paint.ts)(R.filter(type_eq('fireAnimationFrame'))(eventsDuringBenchmark));
196+
197+
if (rafs_withinClick.length>0 && fafs.length>0) {
198+
let waitDelay = (fafs[0].ts - click.end) / 1000.0;
199+
if (rafs_withinClick.length==1 && fafs.length==1) {
200+
if (waitDelay > 16) {
201+
let ignored = false;
202+
for (let e of layouts) {
203+
if (e.ts<fafs[0].ts) {
204+
console.log("IGNORING 1 raf, 1 faf, but layout before raf", waitDelay, fileName);
205+
ignored = true;
206+
break;
207+
}
138208
}
139-
console.log(`*#* there was one faf and one raf with a idle duration of ${waitDelay}. New duration ${duration}`);
140-
} else if (fafs.length!=0 && rafs_withinClick.length == 1) {
141-
console.log(`*#* ERROR: unexpected raf faf pattern: ${fafs.length} fafs and ${rafs_withinClick.length} rafs`);
209+
if (!ignored) {
210+
duration = duration - waitDelay;
211+
console.log("FOUND delay for 1 raf, 1 faf, but layout before raf", waitDelay, fileName);
212+
}
213+
} else {
214+
console.log("IGNORING delay < 16 msecs 1 raf, 1 faf ", waitDelay, fileName);
142215
}
216+
} else if (fafs.length==1) {
217+
throw "Unexpected situation. Did not happen in the past. One fire animation frame, but non consistent request animation frames in "+fileName;
218+
} else {
219+
console.log(`IGNORING Bad case ${rafs_withinClick.length} raf, ${fafs.length} faf ${fileName}`);
220+
}
143221
}
144222

145-
146223
return duration;
147224
}
148225

@@ -241,11 +318,13 @@ async function runCPUBenchmark(framework: FrameworkData, benchmark: CPUBenchmark
241318
}
242319

243320
let categories = [
321+
"blink.user_timing",
244322
"devtools.timeline",
245323
'disabled-by-default-devtools.timeline',
246324
];
247325
// let categories = [
248-
// 'devtools.timeline',
326+
// "loading",
327+
// 'devtools.timeline',
249328
// 'disabled-by-default-devtools.timeline',
250329
// '-*',
251330
// 'v8.execute',

‎webdriver-ts/src/parseTrace.ts

Lines changed: 24 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -8,25 +8,37 @@ import { config, initializeFrameworks } from './common';
88
import { computeResultsCPU } from './forkedBenchmarkRunnerPuppeteer';
99
import {benchmarks} from "./benchmarkConfiguration";
1010
import { writeResults } from "./writeResults";
11-
12-
/*
13-
0 1 2 3 4 5 6 7 8 9 10 11
14-
CPU results before: 11.404, 22.339, 7.968, 6.486, 20.566, 12.011, 8.693, 22.172, 20.764, 8.445, 10.791, 7.754
15-
*/
16-
17-
// config.LOG_DETAILS = true;
11+
// let TimelineModelBrowser = require("./timeline-model-browser.js");
12+
let Tracelib = require('tracelib').default;
13+
// import Tracelib from 'tracelib';
14+
//var DevtoolsTimelineModel = require('devtools-timeline-model');
1815

1916
async function main() {
2017

2118

2219

23-
// console.log(await computeResultsCPU(`traces/vanillajs-keyed_04_select1k_0.json`, false))
2420
// for (let i = 1; i < 2; i++) {
2521
// let trace = `traces/angular-v13.0.0-keyed_01_run1k_${i}.json`;
26-
let trace = `traces/elm-v0.19.1-3-keyed_06_remove-one-1k_2.json`;
27-
console.log("trace", trace)
28-
console.log(await computeResultsCPU(trace, DurationMeasurementMode.LAST_PAINT));
22+
let trace = 'traces/react-tracked-v17.0.1 + 1.6.0-keyed_07_create10k_10.json';
23+
console.log(await computeResultsCPU(trace, DurationMeasurementMode.LAST_PAINT))
24+
// let contents = await readFile(trace, {encoding: "utf8"});
25+
// let traceObj = JSON.parse(contents)
26+
// let entries = traceObj['traceEvents'];
27+
28+
// const tasks = new Tracelib(entries)
29+
// const summary = tasks.getSummary()
30+
// console.log(summary.painting+summary.rendering+summary.scripting)
31+
32+
33+
// const model = new TimelineModelBrowser(traceStr);
34+
// console.log(model);
35+
36+
// let r = TraceProcessor.processTrace(traceObj);
37+
// console.log("r", r)
38+
// console.log(await computeResultsCPU(trace, DurationMeasurementMode.LAST_PAINT));
2939
// }
40+
41+
3042
}
3143

3244
async function readAll() {
@@ -43,7 +55,7 @@ async function readAll() {
4355
if (!fs.existsSync(trace)) {
4456
console.log("ignoring ", trace, "since it doesn't exist.");
4557
} else {
46-
console.log("checking ", trace);
58+
console.log("checking ", trace, benchmark.benchmarkInfo.durationMeasurementMode);
4759
let result = await computeResultsCPU(trace, benchmark.benchmarkInfo.durationMeasurementMode);
4860
results.push(result);
4961
console.log(result);

0 commit comments

Comments
 (0)