allow other events than click to be the starting point for the duration measurement (e.g. pointerup)

Author: krausest

webdriver-ts/src/common.ts

@@ -90,6 +90,7 @@ export interface FrameworkData {
   useRowShadowRoot: boolean;
   shadowRootName: string | undefined;
   buttonsInShadowRoot: boolean;
+  startLogicEventName: string;
   issues: number[];
   frameworkHomeURL: string;
 }
@@ -108,6 +109,7 @@ export interface FrameworkInformation {
   versions?: { [key: string]: string };
   frameworkVersionString: string;
   frameworkHomeURL: string;
+  startLogicEventName: string;
 }
 
 export interface MatchPredicate {
@@ -163,6 +165,7 @@ export async function initializeFrameworks(
         buttonsInShadowRoot: !!frameworkVersionInformation.buttonsInShadowRoot,
         issues: (frameworkVersionInformation.issues ?? []).map(Number),
         frameworkHomeURL: frameworkVersionInformation.frameworkHomeURL ?? "",
+        startLogicEventName: frameworkVersionInformation.startLogicEventName
       });
     }
   }

webdriver-ts/src/forkedBenchmarkRunnerPlaywright.ts

@@ -113,7 +113,7 @@ async function runCPUBenchmark(
       if (throttleCPU) {
         await client.send("Emulation.setCPUThrottlingRate", { rate: 1 });
       }
-      let result = await computeResultsCPU(fileNameTrace(framework, benchmark.benchmarkInfo, i, benchmarkOptions));
+      let result = await computeResultsCPU(fileNameTrace(framework, benchmark.benchmarkInfo, i, benchmarkOptions), framework.startLogicEventName);
       let resultScript = await computeResultsJS(
         result,
         config,

webdriver-ts/src/forkedBenchmarkRunnerPuppeteer.ts

@@ -151,7 +151,7 @@ async function runCPUBenchmark(
       // console.log("afterBenchmark", m1, m2);
       // let result = (m2.TaskDuration - m1.TaskDuration)*1000.0; //await computeResultsCPU(fileNameTrace(framework, benchmark, i), benchmarkOptions, framework, benchmark, warnings, benchmarkOptions.batchSize);
       try {
-        let result = await computeResultsCPU(fileNameTrace(framework, benchmark.benchmarkInfo, i, benchmarkOptions));
+        let result = await computeResultsCPU(fileNameTrace(framework, benchmark.benchmarkInfo, i, benchmarkOptions), framework.startLogicEventName);
         let resultScript = await computeResultsJS(
           result,
           config,

webdriver-ts/src/forkedBenchmarkRunnerWebdriverCDP.ts

@@ -162,7 +162,7 @@ async function runCPUBenchmark(
       await cdpConnection.execute("Tracing.end", {});
       await p;
 
-      let result = await computeResultsCPU(fileNameTrace(framework, benchmark.benchmarkInfo, i, benchmarkOptions));
+      let result = await computeResultsCPU(fileNameTrace(framework, benchmark.benchmarkInfo, i, benchmarkOptions), framework.startLogicEventName);
       let resultScript = await computeResultsJS(
         result,
         config,

webdriver-ts/src/parseTrace.ts

@@ -12,10 +12,10 @@ async function debugSingle() {
   // const trace = `traces/alpine-v3.12.0-keyed_07_create10k_0.json`;
   // const trace = `traces/arrowjs-v1.0.0-alpha.9-keyed_07_create10k_0.json`;
   // const trace = `traces/better-react-v1.1.3-keyed_04_select1k_1.json`;
-    const trace = `traces/openui5-v1.120.0-keyed_02_replace1k_0.json`;
+    const trace = `traces/targetjs-v1.0.137-keyed_09_clear1k_x8_3.json`;
     // const trace = `traces/vanillajs-keyed_01_run1k_0.json`;
     console.log("analyzing trace", trace);
-    const cpuTrace = await computeResultsCPU(trace);
+    const cpuTrace = await computeResultsCPU(trace, "click");
     console.log(trace, cpuTrace);
     values.push(cpuTrace.duration);
     let resultJS = await computeResultsJS(cpuTrace, config, trace);
@@ -54,12 +54,12 @@ async function debugAll() {
   let plausibilityCheck = new PlausibilityCheck();
   for (let framework of frameworks) {
     for (let benchmarkInfo of cpuCPUBenchmarks) {
-      await parseCPUTrace(benchmarkOptions, framework, benchmarkInfo, plausibilityCheck);
+      await parseCPUTrace(benchmarkOptions, framework, benchmarkInfo, plausibilityCheck, framework.startLogicEventName);
     }
   }
   plausibilityCheck.print();
 }
 
-debugSingle()
+debugAll()
   .then(() => console.log("done"))
   .catch((error) => console.log(error));

webdriver-ts/src/timeline.ts

@@ -15,61 +15,73 @@ interface TimingResult {
   evt?: any;
 }
 
-export function extractRelevantEvents(entries: any[]) {
+/**
+ * 
+ * @param entries 
+ * @param startLogicEvent usually "click", but might be "pointerup" if needed
+ * @returns 
+ */
+export function extractRelevantEvents(entries: any[], startLogicEvent: string) {
   let filteredEvents: TimingResult[] = [];
-  let click_start = 0;
-  let click_end = 0;
+  let startLogicEvent_startTS = 0;
+  let startLogicEvent_endTS = 0;
 
   entries.forEach((x) => {
     let e = x;
     if (config.LOG_DEBUG) console.log(JSON.stringify(e));
     if (e.name === "EventDispatch") {
+      if (e.args.data.type === startLogicEvent) {
+        if (config.LOG_DETAILS) console.log("startLogicEvent", e.args.data.type, +e.ts);
+        startLogicEvent_startTS = +e.ts;
+        startLogicEvent_endTS = +e.ts + e.dur;
+        filteredEvents.push({ type: "startLogicEvent", ts: +e.ts, dur: +e.dur, end: +e.ts + e.dur, pid: e.pid, evt: JSON.stringify(e) });
+      }
       if (e.args.data.type === "click") {
-        if (config.LOG_DETAILS) console.log("CLICK", +e.ts);
-          click_start = +e.ts;
-          click_end = +e.ts + e.dur;
           filteredEvents.push({ type: "click", ts: +e.ts, dur: +e.dur, end: +e.ts + e.dur, pid: e.pid, evt: JSON.stringify(e) });
-      } else if (e.args.data.type === "mousedown") {
+        } else if (e.args.data.type === "mousedown") {
         if (config.LOG_DETAILS) console.log("MOUSEDOWN", +e.ts);
         filteredEvents.push({ type: "mousedown", ts: +e.ts, dur: +e.dur, end: +e.ts + e.dur, pid: e.pid, evt: JSON.stringify(e) });
+      } else if (e.args.data.type === "pointerup") {
+        if (config.LOG_DETAILS) console.log("POINTERUP", +e.ts);
+        filteredEvents.push({ type: "pointerup", ts: +e.ts, dur: +e.dur, end: +e.ts + e.dur, pid: e.pid, evt: JSON.stringify(e) });
       }
     } else if (e.name === "Layout" && e.ph === "X") {
-      if (config.LOG_DETAILS) console.log("Layout", +e.ts, +e.ts + e.dur - click_start);
+      if (config.LOG_DETAILS) console.log("Layout", +e.ts, +e.ts + e.dur - startLogicEvent_startTS);
       filteredEvents.push({ type: "layout", ts: +e.ts, dur: +e.dur, end: +e.ts + e.dur, pid: e.pid, evt: JSON.stringify(e) });
     } else if (e.name === "FunctionCall" && e.ph === "X") {
-      if (config.LOG_DETAILS) console.log("FunctionCall", +e.ts, +e.ts + e.dur - click_start);
+      if (config.LOG_DETAILS) console.log("FunctionCall", +e.ts, +e.ts + e.dur - startLogicEvent_startTS);
       filteredEvents.push({ type: "functioncall", ts: +e.ts, dur: +e.dur, end: +e.ts + e.dur, pid: e.pid, evt: JSON.stringify(e) });
     } else if (e.name === "HitTest" && e.ph === "X") {
-      if (config.LOG_DETAILS) console.log("HitTest", +e.ts, +e.ts + e.dur - click_start);
+      if (config.LOG_DETAILS) console.log("HitTest", +e.ts, +e.ts + e.dur - startLogicEvent_startTS);
       filteredEvents.push({ type: "hittest", ts: +e.ts, dur: +e.dur, end: +e.ts + e.dur, pid: e.pid, evt: JSON.stringify(e) });
     } else if (e.name === "Commit" && e.ph === "X") {
-      if (config.LOG_DETAILS) console.log("COMMIT PAINT", +e.ts, +e.ts + e.dur - click_start);
+      if (config.LOG_DETAILS) console.log("COMMIT PAINT", +e.ts, +e.ts + e.dur - startLogicEvent_startTS);
       filteredEvents.push({ type: "commit", ts: +e.ts, dur: +e.dur, end: +e.ts + e.dur, pid: e.pid, evt: JSON.stringify(e) });
     } else if (e.name === "Paint" && e.ph === "X") {
-      if (config.LOG_DETAILS) console.log("PAINT", +e.ts, +e.ts + e.dur - click_start);
+      if (config.LOG_DETAILS) console.log("PAINT", +e.ts, +e.ts + e.dur - startLogicEvent_startTS);
       filteredEvents.push({ type: "paint", ts: +e.ts, dur: +e.dur, end: +e.ts + e.dur, pid: e.pid, evt: JSON.stringify(e) });
     } else if (e.name === "FireAnimationFrame" && e.ph === "X") {
-      if (config.LOG_DETAILS) console.log("FireAnimationFrame", +e.ts, +e.ts - click_start);
+      if (config.LOG_DETAILS) console.log("FireAnimationFrame", +e.ts, +e.ts - startLogicEvent_startTS);
       filteredEvents.push({ type: "fireAnimationFrame", ts: +e.ts, dur: +e.dur, end: +e.ts + e.dur, pid: e.pid, evt: JSON.stringify(e) });
     } else if (e.name === "TimerFire" && e.ph === "X") {
-      if (config.LOG_DETAILS) console.log("TimerFire", +e.ts, +e.ts - click_start, +e.ts - click_end);
+      if (config.LOG_DETAILS) console.log("TimerFire", +e.ts, +e.ts - startLogicEvent_startTS, +e.ts - startLogicEvent_endTS);
       filteredEvents.push({ type: "timerFire", ts: +e.ts, dur: 0, end: +e.ts, pid: e.pid, evt: JSON.stringify(e) });
     } else if (e.name === "RequestAnimationFrame") {
-      if (config.LOG_DETAILS) console.log("RequestAnimationFrame", +e.ts, +e.ts - click_start, +e.ts - click_end);
+      if (config.LOG_DETAILS) console.log("RequestAnimationFrame", +e.ts, +e.ts - startLogicEvent_startTS, +e.ts - startLogicEvent_endTS);
       filteredEvents.push({ type: "requestAnimationFrame", ts: +e.ts, dur: 0, end: +e.ts, pid: e.pid, evt: JSON.stringify(e) });
     }
     });
     return filteredEvents;
   }
 
-async function fetchEventsFromPerformanceLog(fileName: string): Promise<TimingResult[]> {
+async function fetchEventsFromPerformanceLog(fileName: string, startLogicEventName: string): Promise<TimingResult[]> {
   let timingResults: TimingResult[] = [];
     let entries = [];
     do {
       let contents = await readFile(fileName, { encoding: "utf8" });
       let json = JSON.parse(contents);
       let entries = json["traceEvents"];
-      const filteredEvents = extractRelevantEvents(entries);
+      const filteredEvents = extractRelevantEvents(entries, startLogicEventName);
       timingResults = timingResults.concat(filteredEvents);
     } while (entries.length > 0);
     return timingResults;
@@ -158,8 +170,9 @@ function logEvents(events: TimingResult[], click: TimingResult) {
 
 export async function computeResultsCPU(
   fileName: string,
+  startLogicEventName: string,
 ): Promise<CPUDurationResult> {
-  const perfLogEvents = await fetchEventsFromPerformanceLog(fileName);
+  const perfLogEvents = await fetchEventsFromPerformanceLog(fileName, startLogicEventName);
   let events = R.sortBy((e: TimingResult) => e.end)(perfLogEvents);
 
     // Find mousedown event. This is the start of the benchmark
@@ -173,9 +186,9 @@ export async function computeResultsCPU(
       console.log("more than one mousedown event", fileName, events);
       throw "at most one mousedown event is expected";
     }
-  
-  // Find click event. This is the start of the benchmark
-  let clicks = R.filter(type_eq("click"))(events);
+
+  // Find click event. This is the start of the benchmark. We're using the synthetic "startLogicEvent" event we've created above
+  let clicks = R.filter(type_eq("startLogicEvent"))(events);
   // Invariant: There must be exactly one click event
   if (clicks.length !== 1) {
     console.log("exactly one click event is expected", fileName, events);
@@ -189,7 +202,7 @@ export async function computeResultsCPU(
     if (mousedownToClick>0) {
       console.log("mousedownToClick", mousedownToClick, fileName);
     }
-    if (mousedownToClick > 10000) {
+    if (mousedownToClick > 5000) {
       console.log("difference between mousedown and click is unusually long", mousedownToClick, fileName);
       // throw "difference between mousedown and click is unusually long";
     }
@@ -445,15 +458,16 @@ export async function parseCPUTrace(
   benchmarkOptions: BenchmarkOptions,
   framework: FrameworkData,
   benchmarkInfo: CPUBenchmarkInfo,
-  plausibilityCheck: PlausibilityCheck
+  plausibilityCheck: PlausibilityCheck,
+  startLogicEventName: string
 ) {
   let results: CPUBenchmarkResult[] = [];
   for (let i = 0; i < benchmarkOptions.numIterationsForCPUBenchmarks + benchmarkInfo.additionalNumberOfRuns; i++) {
     let trace = `${fileNameTrace(framework, benchmarkInfo, i, benchmarkOptions)}`;
     if (fs.existsSync(trace)) {
       console.log("analyzing trace", trace);
       try {
-        let result = await computeResultsCPU(trace);
+        let result = await computeResultsCPU(trace, startLogicEventName);
         plausibilityCheck.check(result, trace, framework, benchmarkInfo);
         let resultJS = await computeResultsJS(result, config, trace);
         let resultPaint = await computeResultsPaint(result, config, trace);