From d3396e81cda7290ba1616cc186778c66076b40ee Mon Sep 17 00:00:00 2001 From: Igor Randjelovic Date: Sat, 30 Jul 2022 22:26:35 +0200 Subject: [PATCH 1/4] feat(profiling): generate chrome compatible timeline data --- lib/bootstrap.ts | 4 + lib/common/mobile/device-log-provider.ts | 5 + lib/nativescript-cli.ts | 26 ++--- lib/services/timeline-profiler-service.ts | 114 ++++++++++++++++++++++ 4 files changed, 136 insertions(+), 13 deletions(-) create mode 100644 lib/services/timeline-profiler-service.ts diff --git a/lib/bootstrap.ts b/lib/bootstrap.ts index a29826aa35..ed1f4b2640 100644 --- a/lib/bootstrap.ts +++ b/lib/bootstrap.ts @@ -154,6 +154,10 @@ injector.require( "./services/android-device-debug-service" ); +injector.require( + "timelineProfilerService", + "./services/timeline-profiler-service" +); injector.require("userSettingsService", "./services/user-settings-service"); injector.requirePublic( "analyticsSettingsService", diff --git a/lib/common/mobile/device-log-provider.ts b/lib/common/mobile/device-log-provider.ts index 8fdf3ec8ac..48110128c3 100644 --- a/lib/common/mobile/device-log-provider.ts +++ b/lib/common/mobile/device-log-provider.ts @@ -6,11 +6,14 @@ import * as chalk from "chalk"; import { LoggerConfigData } from "../../constants"; import { IOptions } from "../../declarations"; +import { ITimelineProfilerService } from "../../services/timeline-profiler-service"; + export class DeviceLogProvider extends DeviceLogProviderBase { constructor( protected $logFilter: Mobile.ILogFilter, protected $logger: ILogger, protected $logSourceMapService: Mobile.ILogSourceMapService, + protected $timelineProfilerService: ITimelineProfilerService, protected $options: IOptions ) { super($logFilter, $logger, $logSourceMapService); @@ -29,7 +32,9 @@ export class DeviceLogProvider extends DeviceLogProviderBase { data, loggingOptions ); + if (data) { + this.$timelineProfilerService.processLogData(data, deviceIdentifier); this.logDataCore(data, deviceIdentifier); this.emit(DEVICE_LOG_EVENT_NAME, lineText, deviceIdentifier, platform); } diff --git a/lib/nativescript-cli.ts b/lib/nativescript-cli.ts index 36f627bc3b..fe48312908 100644 --- a/lib/nativescript-cli.ts +++ b/lib/nativescript-cli.ts @@ -22,20 +22,20 @@ installUncaughtExceptionListener( ); const logger: ILogger = injector.resolve("logger"); -const originalProcessOn = process.on; +// const originalProcessOn = process.on; -process.on = (event: string, listener: any): any => { - if (event === "SIGINT") { - logger.trace( - `Trying to handle SIGINT event. CLI overrides this behavior and does not allow handling SIGINT as this causes issues with Ctrl + C in terminal.` - ); - const msg = "The stackTrace of the location trying to handle SIGINT is:"; - const stackTrace = new Error(msg).stack || ""; - logger.trace(stackTrace.replace(`Error: ${msg}`, msg)); - } else { - return originalProcessOn.apply(process, [event, listener]); - } -}; +// process.on = (event: string, listener: any): any => { +// if (event === "SIGINT") { +// logger.trace( +// `Trying to handle SIGINT event. CLI overrides this behavior and does not allow handling SIGINT as this causes issues with Ctrl + C in terminal.` +// ); +// const msg = "The stackTrace of the location trying to handle SIGINT is:"; +// const stackTrace = new Error(msg).stack || ""; +// logger.trace(stackTrace.replace(`Error: ${msg}`, msg)); +// } else { +// return originalProcessOn.apply(process, [event, listener]); +// } +// }; /* tslint:disable:no-floating-promises */ (async () => { diff --git a/lib/services/timeline-profiler-service.ts b/lib/services/timeline-profiler-service.ts new file mode 100644 index 0000000000..bfe1a5eef9 --- /dev/null +++ b/lib/services/timeline-profiler-service.ts @@ -0,0 +1,114 @@ +import { IFileSystem } from "../common/declarations"; +import { cache } from "../common/decorators"; +import { injector } from "../common/yok"; +import { IProjectConfigService } from "../definitions/project"; +import * as path from "path"; + +export interface ITimelineProfilerService { + processLogData(data: string, deviceIdentifier: string): void; +} + +const TIMELINE_LOG_RE = /Timeline:\s*(\d*.?\d*ms:\s*)?([^\:]*\:)?(.*)\((\d*.?\d*)ms\.?\s*-\s*(\d*.\d*)ms\.?\)/; + +enum ChromeTraceEventPhase { + BEGIN = "B", + END = "E", + INSTANT = "i", + COMPLETE = "X", +} + +interface ChromeTraceEvent { + ts: number; + pid: number; + tid: number; + /** event phase */ + ph?: ChromeTraceEventPhase | string; + [otherData: string]: any; +} + +interface DeviceTimeline { + startPoint: number; + timeline: ChromeTraceEvent[]; +} + +export class TimelineProfilerService implements ITimelineProfilerService { + private timelines: Map; + constructor( + private $projectConfigService: IProjectConfigService, + private $fs: IFileSystem, + private $logger: ILogger + ) { + this.timelines = new Map(); + + process.on("exit", this.writeTimelines.bind(this)); + process.on("SIGINT", this.writeTimelines.bind(this)); + } + + public processLogData(data: string, deviceIdentifier: string) { + if (!this.isEnabled()) { + return; + } + + if (!this.timelines.has(deviceIdentifier)) { + this.timelines.set(deviceIdentifier, { + startPoint: null, + timeline: [], + }); + } + + const deviceTimeline = this.timelines.get(deviceIdentifier); + + data.split("\n").forEach((line) => { + const trace = this.toTrace(line.trim()); + if (trace) { + deviceTimeline.startPoint ??= trace.from; + deviceTimeline.timeline.push(trace); + } + }); + } + + @cache() + private isEnabled() { + return this.$projectConfigService.getValue("profiling") === "timeline"; + } + + private toTrace(text: string): ChromeTraceEvent | undefined { + const result = text.match(TIMELINE_LOG_RE); + if (!result) { + return; + } + + const trace = { + domain: result[2]?.trim().replace(":", ""), + name: result[3].trim(), + from: parseFloat(result[4]), + to: parseFloat(result[5]), + }; + + return { + pid: 1, + tid: 1, + ts: trace.from * 1000, + dur: (trace.to - trace.from) * 1000, + name: trace.name, + cat: trace.domain ?? "default", + ph: ChromeTraceEventPhase.COMPLETE, + }; + } + + private writeTimelines() { + if (this.isEnabled()) { + this.$logger.info("Writing timeline data to json..."); + this.timelines.forEach((deviceTimeline, deviceIdentifier) => { + this.$fs.writeJson( + path.resolve(process.cwd(), `timeline-${deviceIdentifier}.json`), + deviceTimeline.timeline + ); + }); + } + + process.exit(); + } +} + +injector.register("timelineProfilerService", TimelineProfilerService); From 9409243c990d1e710ddd013a043e3f74d00b3146 Mon Sep 17 00:00:00 2001 From: Igor Randjelovic Date: Sat, 25 Mar 2023 15:22:24 +0100 Subject: [PATCH 2/4] revert: process.on override removal --- lib/nativescript-cli.ts | 26 +++++++++++++------------- 1 file changed, 13 insertions(+), 13 deletions(-) diff --git a/lib/nativescript-cli.ts b/lib/nativescript-cli.ts index fe48312908..36f627bc3b 100644 --- a/lib/nativescript-cli.ts +++ b/lib/nativescript-cli.ts @@ -22,20 +22,20 @@ installUncaughtExceptionListener( ); const logger: ILogger = injector.resolve("logger"); -// const originalProcessOn = process.on; +const originalProcessOn = process.on; -// process.on = (event: string, listener: any): any => { -// if (event === "SIGINT") { -// logger.trace( -// `Trying to handle SIGINT event. CLI overrides this behavior and does not allow handling SIGINT as this causes issues with Ctrl + C in terminal.` -// ); -// const msg = "The stackTrace of the location trying to handle SIGINT is:"; -// const stackTrace = new Error(msg).stack || ""; -// logger.trace(stackTrace.replace(`Error: ${msg}`, msg)); -// } else { -// return originalProcessOn.apply(process, [event, listener]); -// } -// }; +process.on = (event: string, listener: any): any => { + if (event === "SIGINT") { + logger.trace( + `Trying to handle SIGINT event. CLI overrides this behavior and does not allow handling SIGINT as this causes issues with Ctrl + C in terminal.` + ); + const msg = "The stackTrace of the location trying to handle SIGINT is:"; + const stackTrace = new Error(msg).stack || ""; + logger.trace(stackTrace.replace(`Error: ${msg}`, msg)); + } else { + return originalProcessOn.apply(process, [event, listener]); + } +}; /* tslint:disable:no-floating-promises */ (async () => { From 5ba218c95bc51781404cbecd7208c6310436186e Mon Sep 17 00:00:00 2001 From: Igor Randjelovic Date: Sat, 25 Mar 2023 16:09:22 +0100 Subject: [PATCH 3/4] refactor: only attach SIGINT when actually profiling --- lib/nativescript-cli.ts | 4 +-- lib/services/timeline-profiler-service.ts | 36 ++++++++++++++--------- test/ios-project-service.ts | 1 + 3 files changed, 25 insertions(+), 16 deletions(-) diff --git a/lib/nativescript-cli.ts b/lib/nativescript-cli.ts index 36f627bc3b..36b56a5892 100644 --- a/lib/nativescript-cli.ts +++ b/lib/nativescript-cli.ts @@ -22,7 +22,7 @@ installUncaughtExceptionListener( ); const logger: ILogger = injector.resolve("logger"); -const originalProcessOn = process.on; +export const originalProcessOn = process.on.bind(process); process.on = (event: string, listener: any): any => { if (event === "SIGINT") { @@ -33,7 +33,7 @@ process.on = (event: string, listener: any): any => { const stackTrace = new Error(msg).stack || ""; logger.trace(stackTrace.replace(`Error: ${msg}`, msg)); } else { - return originalProcessOn.apply(process, [event, listener]); + return originalProcessOn(event, listener); } }; diff --git a/lib/services/timeline-profiler-service.ts b/lib/services/timeline-profiler-service.ts index bfe1a5eef9..f1d5564f09 100644 --- a/lib/services/timeline-profiler-service.ts +++ b/lib/services/timeline-profiler-service.ts @@ -3,6 +3,7 @@ import { cache } from "../common/decorators"; import { injector } from "../common/yok"; import { IProjectConfigService } from "../definitions/project"; import * as path from "path"; +import { originalProcessOn } from "../nativescript-cli"; export interface ITimelineProfilerService { processLogData(data: string, deviceIdentifier: string): void; @@ -32,22 +33,27 @@ interface DeviceTimeline { } export class TimelineProfilerService implements ITimelineProfilerService { - private timelines: Map; + private timelines: Map = new Map(); + private attachedExitHandler: boolean = false; constructor( private $projectConfigService: IProjectConfigService, private $fs: IFileSystem, private $logger: ILogger - ) { - this.timelines = new Map(); + ) {} - process.on("exit", this.writeTimelines.bind(this)); - process.on("SIGINT", this.writeTimelines.bind(this)); + private attachExitHanlder() { + if (!this.attachedExitHandler) { + this.$logger.info('attached "SIGINT" handler to write timeline data.'); + originalProcessOn("SIGINT", this.writeTimelines.bind(this)); + this.attachedExitHandler = true; + } } public processLogData(data: string, deviceIdentifier: string) { if (!this.isEnabled()) { return; } + this.attachExitHanlder(); if (!this.timelines.has(deviceIdentifier)) { this.timelines.set(deviceIdentifier, { @@ -97,15 +103,17 @@ export class TimelineProfilerService implements ITimelineProfilerService { } private writeTimelines() { - if (this.isEnabled()) { - this.$logger.info("Writing timeline data to json..."); - this.timelines.forEach((deviceTimeline, deviceIdentifier) => { - this.$fs.writeJson( - path.resolve(process.cwd(), `timeline-${deviceIdentifier}.json`), - deviceTimeline.timeline - ); - }); - } + this.$logger.info("\n\nWriting timeline data to json..."); + this.timelines.forEach((deviceTimeline, deviceIdentifier) => { + const deviceTimelineFileName = `timeline-${deviceIdentifier}.json`; + this.$fs.writeJson( + path.resolve(process.cwd(), deviceTimelineFileName), + deviceTimeline.timeline + ); + this.$logger.info( + `Timeline data for device ${deviceIdentifier} written to ${deviceTimelineFileName}` + ); + }); process.exit(); } diff --git a/test/ios-project-service.ts b/test/ios-project-service.ts index 29e110e82a..5c49ef629a 100644 --- a/test/ios-project-service.ts +++ b/test/ios-project-service.ts @@ -129,6 +129,7 @@ function createTestInjector( testInjector.register("messages", Messages); testInjector.register("mobileHelper", MobileHelper); testInjector.register("deviceLogProvider", DeviceLogProvider); + testInjector.register("timelineProfilerService", {}); testInjector.register("logFilter", LogFilter); testInjector.register("loggingLevels", LoggingLevels); testInjector.register("utils", Utils); From 8ae6cc428ed7912cc5b813f9969d1dc9bf5d8aa6 Mon Sep 17 00:00:00 2001 From: Igor Randjelovic Date: Sat, 25 Mar 2023 16:15:33 +0100 Subject: [PATCH 4/4] test: fix tests --- lib/common/test/unit-tests/mobile/device-log-provider.ts | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/lib/common/test/unit-tests/mobile/device-log-provider.ts b/lib/common/test/unit-tests/mobile/device-log-provider.ts index a6d1de94ea..a1a0a76e0c 100644 --- a/lib/common/test/unit-tests/mobile/device-log-provider.ts +++ b/lib/common/test/unit-tests/mobile/device-log-provider.ts @@ -76,6 +76,10 @@ const createTestInjector = (): IInjector => { }, }); + testInjector.register("timelineProfilerService", { + processLogData() {}, + }); + const logger = testInjector.resolve("logger"); logger.info = (...args: any[]): void => { args = args.filter((arg) => Object.keys(arg).indexOf("skipNewLine") === -1);