Skip to content

Commit 8f37207

Browse files
NathanWalkerNathanWalker
committed
test: debugging with profiling
1 parent 6173467 commit 8f37207

File tree

1 file changed

+159
-46
lines changed

1 file changed

+159
-46
lines changed

‎packages/core/profiling/index.ts‎

Lines changed: 159 additions & 46 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,19 @@ import appConfig from '~/package.json';
33
/* eslint-disable prefer-rest-params */
44
declare let __startCPUProfiler: any;
55
declare let __stopCPUProfiler: any;
6+
declare const __NS_PROFILING_DEBUG__: boolean | undefined;
7+
declare const __NS_PROFILING_DEBUG_CONSOLE__: boolean | undefined;
8+
9+
const enum MemberType {
10+
Static,
11+
Instance,
12+
}
13+
14+
export enum Level {
15+
none,
16+
lifecycle,
17+
timeline,
18+
}
619

720
export function uptime(): number {
821
return global.android ? (<any>org).nativescript.Process.getUpTime() : global.__tns_uptime();
@@ -28,19 +41,92 @@ export interface TimerInfo {
2841
runCount: number;
2942
}
3043

31-
// Use object instead of map as it is a bit faster
32-
const timers: { [index: string]: TimerInfo } = {};
44+
// Global singleton state (prevents duplication under multiple module instances)
3345
const anyGlobal = <any>global;
34-
const profileNames: string[] = [];
46+
type ProfilingDebugPhase = 'timer-start' | 'timer-stop' | 'timer-stop-pending' | 'timer-reset' | 'wrap-instance' | 'wrap-static' | 'wrap-named' | 'wrap-function';
47+
48+
export interface ProfilingDebugEntry {
49+
phase: ProfilingDebugPhase;
50+
name: string;
51+
timestamp: number;
52+
detail?: { runCount?: number; count?: number; totalTime?: number; note?: string };
53+
}
54+
55+
type ProfilerState = {
56+
timers: { [index: string]: TimerInfo };
57+
profileNames: string[];
58+
tracingLevel: Level;
59+
profileFunctionFactory?: <F extends Function>(fn: F, name: string, type?: MemberType) => F;
60+
debug?: boolean;
61+
debugEvents?: ProfilingDebugEntry[];
62+
debugConsole?: boolean;
63+
};
64+
const __nsProfiling: ProfilerState = (anyGlobal.__nsProfiling ||= {
65+
timers: {},
66+
profileNames: [],
67+
tracingLevel: undefined as any,
68+
profileFunctionFactory: undefined,
69+
});
70+
// Initialize default tracing level if first load
71+
if (__nsProfiling.tracingLevel === undefined) {
72+
__nsProfiling.tracingLevel = Level.none;
73+
}
74+
const debugEnabledFromDefine = typeof __NS_PROFILING_DEBUG__ !== 'undefined' ? __NS_PROFILING_DEBUG__ : undefined;
75+
const debugConsoleFromDefine = typeof __NS_PROFILING_DEBUG_CONSOLE__ !== 'undefined' ? __NS_PROFILING_DEBUG_CONSOLE__ : undefined;
76+
if (typeof __nsProfiling.debug !== 'boolean') {
77+
__nsProfiling.debug = debugEnabledFromDefine ?? false;
78+
}
79+
if (!Array.isArray(__nsProfiling.debugEvents)) {
80+
__nsProfiling.debugEvents = [];
81+
}
82+
if (typeof __nsProfiling.debugConsole !== 'boolean') {
83+
__nsProfiling.debugConsole = debugConsoleFromDefine ?? true;
84+
}
85+
// Use object instead of map as it is a bit faster
86+
const timers: { [index: string]: TimerInfo } = __nsProfiling.timers;
87+
const profileNames: string[] = __nsProfiling.profileNames;
88+
const debugEvents = __nsProfiling.debugEvents!;
3589

3690
export const time = (global.__time || Date.now) as () => number;
3791

92+
function recordDebugEvent(phase: ProfilingDebugPhase, name: string, detail?: ProfilingDebugEntry['detail']): void {
93+
if (!__nsProfiling.debug) {
94+
return;
95+
}
96+
const entry: ProfilingDebugEntry = {
97+
phase,
98+
name,
99+
timestamp: time(),
100+
detail,
101+
};
102+
debugEvents.push(entry);
103+
if (__nsProfiling.debugConsole !== false) {
104+
const summary = detail
105+
? Object.entries(detail)
106+
.map(([key, value]) => `${key}=${value}`)
107+
.join(' ')
108+
: '';
109+
console.log(`[profiling:${phase}] ${name}${summary ? ' ' + summary : ''}`);
110+
}
111+
}
112+
113+
function summarizeTimerInfo(info: TimerInfo | undefined) {
114+
return info
115+
? {
116+
runCount: info.runCount,
117+
count: info.count,
118+
totalTime: info.totalTime,
119+
}
120+
: undefined;
121+
}
122+
38123
export function start(name: string): void {
39124
let info = timers[name];
40125

41126
if (info) {
42127
info.currentStart = time();
43128
info.runCount++;
129+
recordDebugEvent('timer-start', name, summarizeTimerInfo(info));
44130
} else {
45131
info = {
46132
totalTime: 0,
@@ -50,6 +136,7 @@ export function start(name: string): void {
50136
};
51137
timers[name] = info;
52138
profileNames.push(name);
139+
recordDebugEvent('timer-start', name, summarizeTimerInfo(info));
53140
}
54141
}
55142

@@ -64,11 +151,13 @@ export function stop(name: string): TimerInfo {
64151
info.runCount--;
65152
if (info.runCount) {
66153
info.count++;
154+
recordDebugEvent('timer-stop-pending', name, summarizeTimerInfo(info));
67155
} else {
68156
info.lastTime = time() - info.currentStart;
69157
info.totalTime += info.lastTime;
70158
info.count++;
71159
info.currentStart = 0;
160+
recordDebugEvent('timer-stop', name, summarizeTimerInfo(info));
72161
}
73162
} else {
74163
throw new Error(`Timer ${name} paused more times than started.`);
@@ -131,19 +220,9 @@ function timelineProfileFunctionFactory<F extends Function>(fn: F, name: string,
131220
};
132221
}
133222

134-
const enum MemberType {
135-
Static,
136-
Instance,
137-
}
138-
139-
export enum Level {
140-
none,
141-
lifecycle,
142-
timeline,
143-
}
144-
let tracingLevel: Level = Level.none;
223+
let tracingLevel: Level = __nsProfiling.tracingLevel;
145224

146-
let profileFunctionFactory: <F extends Function>(fn: F, name: string, type?: MemberType) => F;
225+
let profileFunctionFactory: <F extends Function>(fn: F, name: string, type?: MemberType) => F = __nsProfiling.profileFunctionFactory;
147226
export function enable(mode: InstrumentationMode = 'counters') {
148227
profileFunctionFactory =
149228
mode &&
@@ -157,6 +236,10 @@ export function enable(mode: InstrumentationMode = 'counters') {
157236
lifecycle: Level.lifecycle,
158237
timeline: Level.timeline,
159238
}[mode] || Level.none;
239+
240+
// persist to global singleton so other module instances share the same state
241+
__nsProfiling.profileFunctionFactory = profileFunctionFactory;
242+
__nsProfiling.tracingLevel = tracingLevel;
160243
}
161244

162245
try {
@@ -173,10 +256,24 @@ try {
173256

174257
export function disable() {
175258
profileFunctionFactory = undefined;
259+
__nsProfiling.profileFunctionFactory = undefined;
176260
}
177261

178262
function profileFunction<F extends Function>(fn: F, customName?: string): F {
179-
return profileFunctionFactory<F>(fn, customName || fn.name);
263+
const name = customName || fn.name;
264+
recordDebugEvent('wrap-function', name);
265+
if (profileFunctionFactory) {
266+
return profileFunctionFactory<F>(fn, name);
267+
}
268+
// Lazy wrapper: if factory not available at decoration time, defer to runtime
269+
return <any>function () {
270+
const fac = (anyGlobal.__nsProfiling && anyGlobal.__nsProfiling.profileFunctionFactory) || profileFunctionFactory;
271+
if (fac) {
272+
const wrapped = fac(fn, name);
273+
return wrapped.apply(this, arguments);
274+
}
275+
return fn.apply(this, arguments);
276+
};
180277
}
181278

182279
const profileMethodUnnamed = (target: Object, key: symbol | string, descriptor) => {
@@ -194,8 +291,22 @@ const profileMethodUnnamed = (target: Object, key: symbol | string, descriptor)
194291

195292
const name = className + key?.toString();
196293

197-
//editing the descriptor/value parameter
198-
descriptor.value = profileFunctionFactory(originalMethod, name, MemberType.Instance);
294+
// editing the descriptor/value parameter
295+
// Always install a wrapper that records timing regardless of current factory state to match webpack behavior.
296+
// If a profiling factory is active use it; otherwise fallback to counters start/stop directly.
297+
if (profileFunctionFactory) {
298+
descriptor.value = profileFunctionFactory(originalMethod, name, MemberType.Instance);
299+
} else {
300+
descriptor.value = function () {
301+
start(name);
302+
try {
303+
return originalMethod.apply(this, arguments);
304+
} finally {
305+
stop(name);
306+
}
307+
};
308+
}
309+
recordDebugEvent('wrap-instance', name);
199310

200311
// return edited descriptor as opposed to overwriting the descriptor
201312
return descriptor;
@@ -215,8 +326,20 @@ const profileStaticMethodUnnamed = <F extends Function>(ctor: F, key: symbol | s
215326
}
216327
const name = className + key?.toString();
217328

218-
//editing the descriptor/value parameter
219-
descriptor.value = profileFunctionFactory(originalMethod, name, MemberType.Static);
329+
// editing the descriptor/value parameter
330+
if (profileFunctionFactory) {
331+
descriptor.value = profileFunctionFactory(originalMethod, name, MemberType.Static);
332+
} else {
333+
descriptor.value = function () {
334+
start(name);
335+
try {
336+
return originalMethod.apply(this, arguments);
337+
} finally {
338+
stop(name);
339+
}
340+
};
341+
}
342+
recordDebugEvent('wrap-static', name);
220343

221344
// return edited descriptor as opposed to overwriting the descriptor
222345
return descriptor;
@@ -231,10 +354,22 @@ function profileMethodNamed(name: string): MethodDecorator {
231354
}
232355
const originalMethod = descriptor.value;
233356

234-
//editing the descriptor/value parameter
235-
descriptor.value = profileFunctionFactory(originalMethod, name);
357+
// editing the descriptor/value parameter
358+
if (profileFunctionFactory) {
359+
descriptor.value = profileFunctionFactory(originalMethod, name);
360+
} else {
361+
descriptor.value = function () {
362+
start(name);
363+
try {
364+
return originalMethod.apply(this, arguments);
365+
} finally {
366+
stop(name);
367+
}
368+
};
369+
}
236370

237371
// return edited descriptor as opposed to overwriting the descriptor
372+
recordDebugEvent('wrap-named', name);
238373
return descriptor;
239374
};
240375
}
@@ -245,40 +380,16 @@ const voidMethodDecorator = () => {
245380

246381
export function profile(nameFnOrTarget?: string | Function | Object, fnOrKey?: Function | string | symbol, descriptor?: PropertyDescriptor, attrs?: any): any {
247382
if (typeof nameFnOrTarget === 'object' && (typeof fnOrKey === 'string' || typeof fnOrKey === 'symbol')) {
248-
if (!profileFunctionFactory) {
249-
return;
250-
}
251-
252383
return profileMethodUnnamed(nameFnOrTarget, fnOrKey, descriptor);
253384
} else if (typeof nameFnOrTarget === 'function' && (typeof fnOrKey === 'string' || typeof fnOrKey === 'symbol')) {
254-
if (!profileFunctionFactory) {
255-
return;
256-
}
257-
258385
return profileStaticMethodUnnamed(nameFnOrTarget, fnOrKey, descriptor);
259386
} else if (typeof nameFnOrTarget === 'string' && typeof fnOrKey === 'function') {
260-
if (!profileFunctionFactory) {
261-
return fnOrKey;
262-
}
263-
264387
return profileFunction(fnOrKey, nameFnOrTarget);
265388
} else if (typeof nameFnOrTarget === 'function') {
266-
if (!profileFunctionFactory) {
267-
return nameFnOrTarget;
268-
}
269-
270389
return profileFunction(nameFnOrTarget);
271390
} else if (typeof nameFnOrTarget === 'string') {
272-
if (!profileFunctionFactory) {
273-
return voidMethodDecorator;
274-
}
275-
276391
return profileMethodNamed(nameFnOrTarget);
277392
} else {
278-
if (!profileFunctionFactory) {
279-
return voidMethodDecorator;
280-
}
281-
282393
return profileMethodUnnamed;
283394
}
284395
}
@@ -300,8 +411,10 @@ export function resetProfiles(): void {
300411
if (info) {
301412
if (info.runCount) {
302413
console.log('---- timer with name [' + name + "] is currently running and won't be reset");
414+
recordDebugEvent('timer-reset', name, summarizeTimerInfo(info));
303415
} else {
304416
timers[name] = undefined;
417+
recordDebugEvent('timer-reset', name, summarizeTimerInfo(info));
305418
}
306419
}
307420
});

0 commit comments

Comments
 (0)