From c07334ca039596e7cd0cfa7c12d81c67ea8717e9 Mon Sep 17 00:00:00 2001 From: Vitali Zaidman Date: Fri, 14 Mar 2025 09:16:30 -0700 Subject: [PATCH] logging- log socket connection uptime in dev middleware (#50016) Summary: Pull Request resolved: https://github.com/facebook/react-native/pull/50016 Changelog: [General][Internal] logging- log socket connection uptime in dev middleware Reviewed By: robhogan Differential Revision: D71126344 fbshipit-source-id: 026bac9620ffb933d90db255b59fbf79bfed902b --- .../CDPMessagesQueueLogging.js | 2 +- .../src/inspector-proxy/Device.js | 2 ++ .../inspector-proxy/DeviceEventReporter.js | 9 +++++++ .../inspector-proxy/EventLoopPerfTracker.js | 7 ++++- .../src/inspector-proxy/InspectorProxy.js | 26 +++++++++++++++---- .../dev-middleware/src/types/EventReporter.js | 11 ++++++++ 6 files changed, 50 insertions(+), 7 deletions(-) diff --git a/packages/dev-middleware/src/inspector-proxy/CDPMessagesQueueLogging.js b/packages/dev-middleware/src/inspector-proxy/CDPMessagesQueueLogging.js index a732f044e3c..d14b313d593 100644 --- a/packages/dev-middleware/src/inspector-proxy/CDPMessagesQueueLogging.js +++ b/packages/dev-middleware/src/inspector-proxy/CDPMessagesQueueLogging.js @@ -48,7 +48,7 @@ export default class CDPMessagesQueueLogging { if (this.#loggingTimeout) { this.#loggingTimeout.refresh(); } else { - this.#debounceStartMs = new Date().getTime(); + this.#debounceStartMs = Date.now(); this.#loggingTimeout = setTimeout(() => { this.#onHighMessageQueueSize( diff --git a/packages/dev-middleware/src/inspector-proxy/Device.js b/packages/dev-middleware/src/inspector-proxy/Device.js index fe4d7533e8d..74c6700edcb 100644 --- a/packages/dev-middleware/src/inspector-proxy/Device.js +++ b/packages/dev-middleware/src/inspector-proxy/Device.js @@ -158,6 +158,7 @@ export default class Device { this.#id = id; this.#name = name; this.#app = app; + const deviceConnectedTimestamp = Date.now(); this.#messageFromDeviceQueueLogging = new CDPMessagesQueueLogging( (maxCDPMessageQueueSize: number, maxCDPMessageQueueMemory: number) => { @@ -181,6 +182,7 @@ export default class Device { type: 'device_high_message_queue', maxCDPMessageQueueSize, maxCDPMessageQueueMemory, + connectionUptime: Date.now() - deviceConnectedTimestamp, ...debuggerSessionIDs, }); } diff --git a/packages/dev-middleware/src/inspector-proxy/DeviceEventReporter.js b/packages/dev-middleware/src/inspector-proxy/DeviceEventReporter.js index 1d467ce6a1d..a86877b07c9 100644 --- a/packages/dev-middleware/src/inspector-proxy/DeviceEventReporter.js +++ b/packages/dev-middleware/src/inspector-proxy/DeviceEventReporter.js @@ -59,9 +59,12 @@ class DeviceEventReporter { #metadata: DeviceMetadata; + #deviceConnectedTimestamp: number; + constructor(eventReporter: EventReporter, metadata: DeviceMetadata) { this.#eventReporter = eventReporter; this.#metadata = metadata; + this.#deviceConnectedTimestamp = Date.now(); } logRequest( @@ -99,6 +102,7 @@ class DeviceEventReporter { pageId: metadata.pageId, frontendUserAgent: metadata.frontendUserAgent, prefersFuseboxFrontend: metadata.prefersFuseboxFrontend, + connectionUptime: this.#deviceConnectedTimestamp - Date.now(), }); return; } @@ -125,6 +129,7 @@ class DeviceEventReporter { pageId: pendingCommand.metadata.pageId, frontendUserAgent: pendingCommand.metadata.frontendUserAgent, prefersFuseboxFrontend: metadata.prefersFuseboxFrontend, + connectionUptime: this.#deviceConnectedTimestamp - Date.now(), }); return; } @@ -142,6 +147,7 @@ class DeviceEventReporter { pageId: pendingCommand.metadata.pageId, frontendUserAgent: pendingCommand.metadata.frontendUserAgent, prefersFuseboxFrontend: metadata.prefersFuseboxFrontend, + connectionUptime: this.#deviceConnectedTimestamp - Date.now(), }); } @@ -199,6 +205,7 @@ class DeviceEventReporter { pageId: pendingCommand.metadata.pageId, frontendUserAgent: pendingCommand.metadata.frontendUserAgent, prefersFuseboxFrontend: pendingCommand.metadata.prefersFuseboxFrontend, + connectionUptime: this.#deviceConnectedTimestamp - Date.now(), }); } this.#pendingCommands.clear(); @@ -220,6 +227,7 @@ class DeviceEventReporter { deviceId: this.#metadata.deviceId, deviceName: this.#metadata.deviceName, pageId: null, + connectionUptime: this.#deviceConnectedTimestamp - Date.now(), }); } @@ -245,6 +253,7 @@ class DeviceEventReporter { pageId: pendingCommand.metadata.pageId, frontendUserAgent: pendingCommand.metadata.frontendUserAgent, prefersFuseboxFrontend: pendingCommand.metadata.prefersFuseboxFrontend, + connectionUptime: this.#deviceConnectedTimestamp - Date.now(), }); } } diff --git a/packages/dev-middleware/src/inspector-proxy/EventLoopPerfTracker.js b/packages/dev-middleware/src/inspector-proxy/EventLoopPerfTracker.js index c7a4230b842..3a649aa4610 100644 --- a/packages/dev-middleware/src/inspector-proxy/EventLoopPerfTracker.js +++ b/packages/dev-middleware/src/inspector-proxy/EventLoopPerfTracker.js @@ -28,6 +28,7 @@ export type OnHighDelayArgs = { maxEventLoopDelayPercent: number, duration: number, debuggerSessionIDs: DebuggerSessionIDs, + connectionUptime: number, }; export default class EventLoopPerfTracker { @@ -44,7 +45,10 @@ export default class EventLoopPerfTracker { this.#eventLoopPerfMeasurementOngoing = false; } - trackPerfThrottled(debuggerSessionIDs: DebuggerSessionIDs): void { + trackPerfThrottled( + debuggerSessionIDs: DebuggerSessionIDs, + connectionUptime: number, + ): void { if (this.#eventLoopPerfMeasurementOngoing) { return; } @@ -76,6 +80,7 @@ export default class EventLoopPerfTracker { maxEventLoopDelayPercent, duration: this.#perfMeasurementDuration, debuggerSessionIDs, + connectionUptime, }); } diff --git a/packages/dev-middleware/src/inspector-proxy/InspectorProxy.js b/packages/dev-middleware/src/inspector-proxy/InspectorProxy.js index 5022c2f60e9..f6680d69b2b 100644 --- a/packages/dev-middleware/src/inspector-proxy/InspectorProxy.js +++ b/packages/dev-middleware/src/inspector-proxy/InspectorProxy.js @@ -118,6 +118,7 @@ export default class InspectorProxy implements InspectorProxyQueries { maxEventLoopDelayPercent, duration, debuggerSessionIDs, + connectionUptime, }) => { debug( "[perf] high event loop delay in the last %ds- event loop utilization='%d%' max event loop delay percent='%d%'", @@ -131,6 +132,7 @@ export default class InspectorProxy implements InspectorProxyQueries { eventLoopUtilization, maxEventLoopDelayPercent, duration, + connectionUptime, ...debuggerSessionIDs, }); }, @@ -275,14 +277,13 @@ export default class InspectorProxy implements InspectorProxyQueries { /* returns true if proxy didn't receive any messages from * either the device or debugger for PROXY_IDLE_TIMEOUT_MS */ #isIdle(): boolean { - return ( - new Date().getTime() - this.#lastMessageTimestamp > PROXY_IDLE_TIMEOUT_MS - ); + return Date.now() - this.#lastMessageTimestamp > PROXY_IDLE_TIMEOUT_MS; } #onMessageFromDeviceOrDebugger( message: string, debuggerSessionIDs: DebuggerSessionIDs, + connectionUptime: number, ): void { // TODO: instead remove this and any other messages in idle state we find // Not using JSON.parse for performance reasons. Worst case, we'll get @@ -291,9 +292,12 @@ export default class InspectorProxy implements InspectorProxyQueries { return; } - this.#lastMessageTimestamp = new Date().getTime(); + this.#lastMessageTimestamp = Date.now(); - this.#eventLoopPerfTracker?.trackPerfThrottled(debuggerSessionIDs); + this.#eventLoopPerfTracker?.trackPerfThrottled( + debuggerSessionIDs, + connectionUptime, + ); } // Adds websocket handler for device connections. @@ -311,6 +315,8 @@ export default class InspectorProxy implements InspectorProxyQueries { }); // $FlowFixMe[value-as-type] wss.on('connection', async (socket: WS, req) => { + const wssTimestamp = Date.now(); + const fallbackDeviceId = String(this.#deviceCounter++); const query = url.parse(req.url || '', true).query || {}; @@ -389,6 +395,7 @@ export default class InspectorProxy implements InspectorProxyQueries { type: 'device_high_ping', duration: roundtripDuration, isIdle, + connectionUptime: Date.now() - wssTimestamp, ...debuggerSessionIDs, }); }, @@ -414,6 +421,7 @@ export default class InspectorProxy implements InspectorProxyQueries { type: 'device_timeout', duration: roundtripDuration, isIdle, + connectionUptime: Date.now() - wssTimestamp, ...debuggerSessionIDs, }); }, @@ -425,6 +433,7 @@ export default class InspectorProxy implements InspectorProxyQueries { this.#onMessageFromDeviceOrDebugger( message.toString(), debuggerSessionIDs, + Date.now() - wssTimestamp, ), ); @@ -442,6 +451,7 @@ export default class InspectorProxy implements InspectorProxyQueries { code, reason, isIdle: this.#isIdle(), + connectionUptime: Date.now() - wssTimestamp, ...debuggerSessionIDs, }); @@ -477,6 +487,8 @@ export default class InspectorProxy implements InspectorProxyQueries { }); // $FlowFixMe[value-as-type] wss.on('connection', async (socket: WS, req) => { + const wssTimestamp = Date.now(); + const query = url.parse(req.url || '', true).query || {}; const deviceId = query.device; const pageId = query.page; @@ -528,6 +540,7 @@ export default class InspectorProxy implements InspectorProxyQueries { type: 'debugger_high_ping', duration: roundtripDuration, isIdle, + connectionUptime: Date.now() - wssTimestamp, ...debuggerSessionIDs, }); }, @@ -553,6 +566,7 @@ export default class InspectorProxy implements InspectorProxyQueries { type: 'debugger_timeout', duration: roundtripDuration, isIdle, + connectionUptime: Date.now() - wssTimestamp, ...debuggerSessionIDs, }); }, @@ -564,6 +578,7 @@ export default class InspectorProxy implements InspectorProxyQueries { this.#onMessageFromDeviceOrDebugger( message.toString(), debuggerSessionIDs, + Date.now() - wssTimestamp, ), ); @@ -586,6 +601,7 @@ export default class InspectorProxy implements InspectorProxyQueries { code, reason, isIdle: this.#isIdle(), + connectionUptime: Date.now() - wssTimestamp, ...debuggerSessionIDs, }); }); diff --git a/packages/dev-middleware/src/types/EventReporter.js b/packages/dev-middleware/src/types/EventReporter.js index 047417461f3..021c4e25876 100644 --- a/packages/dev-middleware/src/types/EventReporter.js +++ b/packages/dev-middleware/src/types/EventReporter.js @@ -33,6 +33,10 @@ export type DebuggerSessionIDs = { pageId: string | null, }; +export type ConnectionUptime = { + connectionUptime: number, +}; + export type ReportableEvent = | { type: 'launch_debugger_frontend', @@ -64,6 +68,7 @@ export type ReportableEvent = responseOrigin: 'proxy' | 'device', timeSinceStart: number | null, ...DebuggerSessionIDs, + ...ConnectionUptime, frontendUserAgent: string | null, prefersFuseboxFrontend: boolean | null, ... @@ -91,18 +96,21 @@ export type ReportableEvent = message: string, error: string, errorStack: string, + ...ConnectionUptime, ...DebuggerSessionIDs, } | { type: 'debugger_high_ping' | 'device_high_ping', duration: number, isIdle: boolean, + ...ConnectionUptime, ...DebuggerSessionIDs, } | { type: 'debugger_timeout' | 'device_timeout', duration: number, isIdle: boolean, + ...ConnectionUptime, ...DebuggerSessionIDs, } | { @@ -110,6 +118,7 @@ export type ReportableEvent = code: number, reason: string, isIdle: boolean, + ...ConnectionUptime, ...DebuggerSessionIDs, } | { @@ -117,12 +126,14 @@ export type ReportableEvent = eventLoopUtilization: number, maxEventLoopDelayPercent: number, duration: number, + ...ConnectionUptime, ...DebuggerSessionIDs, } | { type: 'device_high_message_queue', maxCDPMessageQueueSize: number, maxCDPMessageQueueMemory: number, + ...ConnectionUptime, ...DebuggerSessionIDs, };