From a8b9588db11498d40b3a2114c5d0e59372c1af9a Mon Sep 17 00:00:00 2001 From: Paul Irish Date: Wed, 25 Jan 2023 19:08:12 -0800 Subject: [PATCH 1/7] handle memgen-profile-xx.json - with ProcessReadyInBrowser --- core/lib/tracehouse/trace-processor.js | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/core/lib/tracehouse/trace-processor.js b/core/lib/tracehouse/trace-processor.js index eff4c6f0d22f..010dee187e35 100644 --- a/core/lib/tracehouse/trace-processor.js +++ b/core/lib/tracehouse/trace-processor.js @@ -489,20 +489,22 @@ class TraceProcessor { */ static findMainFramePidTids(mainFrameInfo, keyEvents) { const frameCommittedEvts = keyEvents.filter(evt => - evt.name === 'FrameCommittedInBrowser' && + // ProcessReadyInBrowser is used when a processID isn't available when the FrameCommittedInBrowser trace event is emitted. + // In that case. FrameCommittedInBrowser has no processId, but a processPseudoId. and the ReadyInBrowser event declares the proper processId. + (evt.name === 'FrameCommittedInBrowser' || evt.name === 'ProcessReadyInBrowser') && evt.args?.data?.frame === mainFrameInfo.frameId ); // "Modern" traces with a navigation have a FrameCommittedInBrowser event const mainFramePids = frameCommittedEvts.length - ? frameCommittedEvts.map(e => e?.args?.data?.processId) + ? frameCommittedEvts.map(e => e?.args?.data?.processId).filter(Boolean) // …But old traces and some timespan traces may not. In these situations, we'll assume the // primary process ID remains constant (as there were no navigations). : [mainFrameInfo.startingPid]; const pidToTid = new Map(); - mainFramePids.forEach(pid => { + Array.from(new Set(mainFramePids)).forEach(pid => { // While renderer tids are generally predictable, we'll doublecheck it const threadNameEvt = keyEvents.find(e => e.cat === '__metadata' && From 03a755fb958032d537ef065b8eaaf4c62bce93b6 Mon Sep 17 00:00:00 2001 From: Paul Irish Date: Mon, 6 Feb 2023 13:53:22 -0800 Subject: [PATCH 2/7] a comment --- core/lib/tracehouse/trace-processor.js | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/core/lib/tracehouse/trace-processor.js b/core/lib/tracehouse/trace-processor.js index 010dee187e35..7553501f29ce 100644 --- a/core/lib/tracehouse/trace-processor.js +++ b/core/lib/tracehouse/trace-processor.js @@ -714,7 +714,8 @@ class TraceProcessor { } const frameEvents = keyEvents.filter(e => associatedToMainFrame(e)); - // Filter to just events matching the main frame ID or any child frame IDs. + // Filter to just events matching the main frame ID or any child frame IDs. The subframes + // are either in-process (same origin) or, potentially, out-of-process. (OOPIFs) let frameTreeEvents = []; if (frameIdToRootFrameId.has(mainFrameInfo.frameId)) { frameTreeEvents = keyEvents.filter(e => associatedToAllFrames(e)); From 6c8b7817217baccb2f1e1bc27a9818d95bbb3288 Mon Sep 17 00:00:00 2001 From: Paul Irish Date: Wed, 15 Feb 2023 12:19:48 -0800 Subject: [PATCH 3/7] add test --- .../lib/tracehouse/trace-processor-test.js | 31 +++++++++++++++++-- 1 file changed, 29 insertions(+), 2 deletions(-) diff --git a/core/test/lib/tracehouse/trace-processor-test.js b/core/test/lib/tracehouse/trace-processor-test.js index f0cfc756bc5d..faf53e862656 100644 --- a/core/test/lib/tracehouse/trace-processor-test.js +++ b/core/test/lib/tracehouse/trace-processor-test.js @@ -23,6 +23,7 @@ const lcpTrace = readJson('../../fixtures/traces/lcp-m78.json', import.meta); const lcpAllFramesTrace = readJson('../../fixtures/traces/frame-metrics-m89.json', import.meta); const startedAfterNavstartTrace = readJson('../../fixtures/traces/tracingstarted-after-navstart.json', import.meta); const pidChangeTrace = readJson('../../fixtures/traces/pid-change.json', import.meta); +const decentlyModernTrace = readJson('../../fixtures/traces/frame-metrics-m90.json', import.meta); describe('TraceProcessor', () => { describe('_riskPercentiles', () => { @@ -943,10 +944,8 @@ Object { const mainFramePids = new Set(); mainFramePids.add(processed.mainFrameInfo.startingPid); [...processed._rendererPidToTid.keys()].forEach(pid => mainFramePids.add(pid)); - return {processEventsPct, frameEventsPct, mainFramePids}; } - // Single PID trace const lcpTraceSummarized = summarizeTrace(lcpTrace); expect(lcpTraceSummarized.mainFramePids.size).toEqual(1); @@ -964,5 +963,33 @@ Object { // The main frame's events should make up more than 40% of all key trace events // TODO: fix! // expect(pidChangeTraceSummarized.frameEventsPct).toBeGreaterThanOrEqual(0.4); + + + // FrameCommittedInBrowser w/o processId, but w/ processPsuedoId, and later a ProcessReadyInBrowser + // + // A 'normal' FrameCommittedInBrowser's data is: + // {"frame":"FRAME_ID","name":"","processId":72647,"url":"https://memegen.corp.google.com/"} + // But if the processId isn't ready at frame creation, we get this pair: + // {"args":{"data":{"frame":"FRAME_ID","name":"","processPseudoId":"0x7ff70022ca00","url":"https://memegen.com/"}},"cat":"disabled-by-default-devtools.timeline","name":"FrameCommittedInBrowser","ph":"I","pid":744,"s":"t","tid":775,"ts":123265406529,"tts":10824502153}, + // {"args":{"data":{"frame":"FRAME_ID","processId":72647,"processPseudoId":"0x7ff70022ca00"}},"cat":"disabled-by-default-devtools.timeline","name":"ProcessReadyInBrowser","ph":"I","pid":744,"s":"t","tid":775,"ts":123265450207,"tts":10824519750}, + + { + const psuedoProcTrace = JSON.parse(JSON.stringify(decentlyModernTrace)); + const fcibEvt = psuedoProcTrace.traceEvents.find(e => e.name === 'FrameCommittedInBrowser'); + const {url, processId, frame, name} = fcibEvt.args.data; + expect(processId).toBeTruthy(); + fcibEvt.args.data = {frame, name, url, process, processPseudoId: '0xbaabaa'}; + + const procReadyEvt = JSON.parse(JSON.stringify(fcibEvt)); + procReadyEvt.name = 'ProcessReadyInBrowser'; + procReadyEvt.args.data = {frame, processId, processPseudoId: '0xbaabaa'}; + procReadyEvt.ts = fcibEvt.ts + 10; + psuedoProcTrace.traceEvents.push(procReadyEvt); + + const psuedoProcSummarized = summarizeTrace(psuedoProcTrace); + expect(psuedoProcSummarized.mainFramePids.size).toEqual(1); + // The primary process events should make up more than 40% of all key trace events + expect(psuedoProcSummarized.processEventsPct).toBeGreaterThanOrEqual(0.4); + } }); }); From 4e2ac0cb248246f83dceefbe6886e79ebe4469b6 Mon Sep 17 00:00:00 2001 From: Paul Irish Date: Wed, 15 Feb 2023 12:22:32 -0800 Subject: [PATCH 4/7] oop --- core/test/lib/tracehouse/trace-processor-test.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/core/test/lib/tracehouse/trace-processor-test.js b/core/test/lib/tracehouse/trace-processor-test.js index faf53e862656..a794868c270a 100644 --- a/core/test/lib/tracehouse/trace-processor-test.js +++ b/core/test/lib/tracehouse/trace-processor-test.js @@ -978,7 +978,7 @@ Object { const fcibEvt = psuedoProcTrace.traceEvents.find(e => e.name === 'FrameCommittedInBrowser'); const {url, processId, frame, name} = fcibEvt.args.data; expect(processId).toBeTruthy(); - fcibEvt.args.data = {frame, name, url, process, processPseudoId: '0xbaabaa'}; + fcibEvt.args.data = {frame, name, url, processPseudoId: '0xbaabaa'}; const procReadyEvt = JSON.parse(JSON.stringify(fcibEvt)); procReadyEvt.name = 'ProcessReadyInBrowser'; From 2639c07902d2fda4beae69b05b27174bc458ec73 Mon Sep 17 00:00:00 2001 From: Paul Irish Date: Wed, 15 Feb 2023 12:32:18 -0800 Subject: [PATCH 5/7] break into sep it()s --- .../lib/tracehouse/trace-processor-test.js | 51 +++++++++---------- 1 file changed, 25 insertions(+), 26 deletions(-) diff --git a/core/test/lib/tracehouse/trace-processor-test.js b/core/test/lib/tracehouse/trace-processor-test.js index a794868c270a..abd884d2e99f 100644 --- a/core/test/lib/tracehouse/trace-processor-test.js +++ b/core/test/lib/tracehouse/trace-processor-test.js @@ -934,7 +934,7 @@ Object { }); }); - it('manages cross-process / cross-iframe traces', () => { + describe('manages cross-process / cross-iframe traces', () => { function summarizeTrace(trace) { const processed = TraceProcessor.processTrace(trace); const keyEventsLen = processed._keyEvents.length; @@ -946,34 +946,33 @@ Object { [...processed._rendererPidToTid.keys()].forEach(pid => mainFramePids.add(pid)); return {processEventsPct, frameEventsPct, mainFramePids}; } - // Single PID trace - const lcpTraceSummarized = summarizeTrace(lcpTrace); - expect(lcpTraceSummarized.mainFramePids.size).toEqual(1); - // The primary process events should make up more than 40% of all key trace events - expect(lcpTraceSummarized.processEventsPct).toBeGreaterThanOrEqual(0.4); - // The main frame's events should make up more than 40% of all key trace events - expect(lcpTraceSummarized.frameEventsPct).toBeGreaterThanOrEqual(0.4); - // Multi PID trace - const pidChangeTraceSummarized = summarizeTrace(pidChangeTrace); - expect(pidChangeTraceSummarized.mainFramePids.size).toEqual(2); - // The primary process events should make up more than 40% of all key trace events - expect(pidChangeTraceSummarized.processEventsPct).toBeGreaterThanOrEqual(0.4); - - // The main frame's events should make up more than 40% of all key trace events - // TODO: fix! - // expect(pidChangeTraceSummarized.frameEventsPct).toBeGreaterThanOrEqual(0.4); + it('with a basic single PID trace', () => { + const lcpTraceSummarized = summarizeTrace(lcpTrace); + expect(lcpTraceSummarized.mainFramePids.size).toEqual(1); + // The primary process events should make up more than 40% of all key trace events + expect(lcpTraceSummarized.processEventsPct).toBeGreaterThanOrEqual(0.4); + // The main frame's events should make up more than 40% of all key trace events + expect(lcpTraceSummarized.frameEventsPct).toBeGreaterThanOrEqual(0.4); + }); + it('with a multi PID trace', () => { + const pidChangeTraceSummarized = summarizeTrace(pidChangeTrace); + expect(pidChangeTraceSummarized.mainFramePids.size).toEqual(2); + // The primary process events should make up more than 40% of all key trace events + expect(pidChangeTraceSummarized.processEventsPct).toBeGreaterThanOrEqual(0.4); + // The main frame's events should make up more than 40% of all key trace events + // TODO: fix! + // expect(pidChangeTraceSummarized.frameEventsPct).toBeGreaterThanOrEqual(0.4); + }); // FrameCommittedInBrowser w/o processId, but w/ processPsuedoId, and later a ProcessReadyInBrowser - // - // A 'normal' FrameCommittedInBrowser's data is: - // {"frame":"FRAME_ID","name":"","processId":72647,"url":"https://memegen.corp.google.com/"} - // But if the processId isn't ready at frame creation, we get this pair: - // {"args":{"data":{"frame":"FRAME_ID","name":"","processPseudoId":"0x7ff70022ca00","url":"https://memegen.com/"}},"cat":"disabled-by-default-devtools.timeline","name":"FrameCommittedInBrowser","ph":"I","pid":744,"s":"t","tid":775,"ts":123265406529,"tts":10824502153}, - // {"args":{"data":{"frame":"FRAME_ID","processId":72647,"processPseudoId":"0x7ff70022ca00"}},"cat":"disabled-by-default-devtools.timeline","name":"ProcessReadyInBrowser","ph":"I","pid":744,"s":"t","tid":775,"ts":123265450207,"tts":10824519750}, - - { + it('with a processPsuedoId navigation', () => { + // A 'normal' FrameCommittedInBrowser's data is: + // {"frame":"FRAME_ID","name":"","processId":72647,"url":"https://memegen.corp.google.com/"} + // But if the processId isn't ready at frame creation, we get this pair: + // {"args":{"data":{"frame":"FRAME_ID","name":"","processPseudoId":"0x7ff70022ca00","url":"https://memegen.com/"}},"cat":"disabled-by-default-devtools.timeline","name":"FrameCommittedInBrowser","ph":"I","pid":744,"s":"t","tid":775,"ts":123265406529,"tts":10824502153}, + // {"args":{"data":{"frame":"FRAME_ID","processId":72647,"processPseudoId":"0x7ff70022ca00"}},"cat":"disabled-by-default-devtools.timeline","name":"ProcessReadyInBrowser","ph":"I","pid":744,"s":"t","tid":775,"ts":123265450207,"tts":10824519750}, const psuedoProcTrace = JSON.parse(JSON.stringify(decentlyModernTrace)); const fcibEvt = psuedoProcTrace.traceEvents.find(e => e.name === 'FrameCommittedInBrowser'); const {url, processId, frame, name} = fcibEvt.args.data; @@ -990,6 +989,6 @@ Object { expect(psuedoProcSummarized.mainFramePids.size).toEqual(1); // The primary process events should make up more than 40% of all key trace events expect(psuedoProcSummarized.processEventsPct).toBeGreaterThanOrEqual(0.4); - } + }); }); }); From ae5966eb933ed3af58e36c7361dd8c8dfc3f0b46 Mon Sep 17 00:00:00 2001 From: Paul Irish Date: Wed, 15 Feb 2023 12:38:25 -0800 Subject: [PATCH 6/7] rename --- core/lib/tracehouse/trace-processor.js | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/core/lib/tracehouse/trace-processor.js b/core/lib/tracehouse/trace-processor.js index 7553501f29ce..95d0c89c2040 100644 --- a/core/lib/tracehouse/trace-processor.js +++ b/core/lib/tracehouse/trace-processor.js @@ -488,7 +488,7 @@ class TraceProcessor { * @return {Map} Map where keys are process IDs and their values are thread IDs */ static findMainFramePidTids(mainFrameInfo, keyEvents) { - const frameCommittedEvts = keyEvents.filter(evt => + const frameProcessEvts = keyEvents.filter(evt => // ProcessReadyInBrowser is used when a processID isn't available when the FrameCommittedInBrowser trace event is emitted. // In that case. FrameCommittedInBrowser has no processId, but a processPseudoId. and the ReadyInBrowser event declares the proper processId. (evt.name === 'FrameCommittedInBrowser' || evt.name === 'ProcessReadyInBrowser') && @@ -496,8 +496,8 @@ class TraceProcessor { ); // "Modern" traces with a navigation have a FrameCommittedInBrowser event - const mainFramePids = frameCommittedEvts.length - ? frameCommittedEvts.map(e => e?.args?.data?.processId).filter(Boolean) + const mainFramePids = frameProcessEvts.length + ? frameProcessEvts.map(e => e?.args?.data?.processId).filter(Boolean) // …But old traces and some timespan traces may not. In these situations, we'll assume the // primary process ID remains constant (as there were no navigations). : [mainFrameInfo.startingPid]; From dbef354f02edd2e20f59dac9e26d5acbcb2a5dd1 Mon Sep 17 00:00:00 2001 From: Paul Irish Date: Tue, 28 Feb 2023 16:43:46 -0800 Subject: [PATCH 7/7] bckenny review feedback --- core/lib/tracehouse/trace-processor.js | 11 ++++++----- core/test/lib/tracehouse/trace-processor-test.js | 4 ++-- 2 files changed, 8 insertions(+), 7 deletions(-) diff --git a/core/lib/tracehouse/trace-processor.js b/core/lib/tracehouse/trace-processor.js index 95d0c89c2040..816df514177b 100644 --- a/core/lib/tracehouse/trace-processor.js +++ b/core/lib/tracehouse/trace-processor.js @@ -490,21 +490,22 @@ class TraceProcessor { static findMainFramePidTids(mainFrameInfo, keyEvents) { const frameProcessEvts = keyEvents.filter(evt => // ProcessReadyInBrowser is used when a processID isn't available when the FrameCommittedInBrowser trace event is emitted. - // In that case. FrameCommittedInBrowser has no processId, but a processPseudoId. and the ReadyInBrowser event declares the proper processId. + // In that case. FrameCommittedInBrowser has no processId, but a processPseudoId. and the ProcessReadyInBrowser event declares the proper processId. (evt.name === 'FrameCommittedInBrowser' || evt.name === 'ProcessReadyInBrowser') && - evt.args?.data?.frame === mainFrameInfo.frameId + evt.args?.data?.frame === mainFrameInfo.frameId && + evt?.args?.data?.processId ); // "Modern" traces with a navigation have a FrameCommittedInBrowser event const mainFramePids = frameProcessEvts.length - ? frameProcessEvts.map(e => e?.args?.data?.processId).filter(Boolean) + ? frameProcessEvts.map(e => e?.args?.data?.processId) // …But old traces and some timespan traces may not. In these situations, we'll assume the // primary process ID remains constant (as there were no navigations). : [mainFrameInfo.startingPid]; const pidToTid = new Map(); - Array.from(new Set(mainFramePids)).forEach(pid => { + for (const pid of new Set(mainFramePids)) { // While renderer tids are generally predictable, we'll doublecheck it const threadNameEvt = keyEvents.find(e => e.cat === '__metadata' && @@ -520,7 +521,7 @@ class TraceProcessor { } pidToTid.set(pid, tid); - }); + } return pidToTid; } diff --git a/core/test/lib/tracehouse/trace-processor-test.js b/core/test/lib/tracehouse/trace-processor-test.js index abd884d2e99f..35ebdeff6ace 100644 --- a/core/test/lib/tracehouse/trace-processor-test.js +++ b/core/test/lib/tracehouse/trace-processor-test.js @@ -975,9 +975,9 @@ Object { // {"args":{"data":{"frame":"FRAME_ID","processId":72647,"processPseudoId":"0x7ff70022ca00"}},"cat":"disabled-by-default-devtools.timeline","name":"ProcessReadyInBrowser","ph":"I","pid":744,"s":"t","tid":775,"ts":123265450207,"tts":10824519750}, const psuedoProcTrace = JSON.parse(JSON.stringify(decentlyModernTrace)); const fcibEvt = psuedoProcTrace.traceEvents.find(e => e.name === 'FrameCommittedInBrowser'); - const {url, processId, frame, name} = fcibEvt.args.data; + const {url, processId, frame} = fcibEvt.args.data; expect(processId).toBeTruthy(); - fcibEvt.args.data = {frame, name, url, processPseudoId: '0xbaabaa'}; + fcibEvt.args.data = {frame, name: '', url, processPseudoId: '0xbaabaa'}; const procReadyEvt = JSON.parse(JSON.stringify(fcibEvt)); procReadyEvt.name = 'ProcessReadyInBrowser';