Skip to content

Commit 17d11d4

Browse files
KSDaemonKSDaemon
committed
inject PerfTracker for tracking
1 parent 119cb4f commit 17d11d4

File tree

2 files changed

+224
-99
lines changed

2 files changed

+224
-99
lines changed

‎packages/cubejs-schema-compiler/src/compiler/DataSchemaCompiler.ts‎

Lines changed: 136 additions & 99 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@ import { CompilerInterface } from './PrepareCompiler';
2222
import { YamlCompiler } from './YamlCompiler';
2323
import { CubeDictionary } from './CubeDictionary';
2424
import { CompilerCache } from './CompilerCache';
25+
import { perfTracker } from './PerfTracker';
2526

2627
const NATIVE_IS_SUPPORTED = isNativeSupported();
2728

@@ -206,127 +207,157 @@ export class DataSchemaCompiler {
206207
}
207208

208209
protected async doCompile() {
209-
const files = await this.repository.dataSchemaFiles();
210+
// Start overall compilation timing
211+
const compileTimer = perfTracker.start('doCompile', true);
210212

211-
this.pythonContext = await this.loadPythonContext(files, 'globals.py');
212-
this.yamlCompiler.initFromPythonContext(this.pythonContext);
213+
try {
214+
const files = await this.repository.dataSchemaFiles();
213215

214-
const toCompile = files.filter((f) => !this.filesToCompile || !this.filesToCompile.length || this.filesToCompile.indexOf(f.fileName) !== -1);
216+
console.log(`Compiling ${files.length} files...`);
215217

216-
const errorsReport = new ErrorReporter(null, [], this.errorReportOptions);
217-
this.errorsReporter = errorsReport;
218+
this.pythonContext = await this.loadPythonContext(files, 'globals.py');
219+
this.yamlCompiler.initFromPythonContext(this.pythonContext);
218220

219-
const transpilationWorkerThreads = getEnv('transpilationWorkerThreads');
220-
const transpilationNative = getEnv('transpilationNative');
221-
const transpilationNativeThreadsCount = getThreadsCount();
222-
const { compilerId } = this;
221+
const toCompile = files.filter((f) => !this.filesToCompile || !this.filesToCompile.length || this.filesToCompile.indexOf(f.fileName) !== -1);
223222

224-
if (!transpilationNative && transpilationWorkerThreads) {
225-
const wc = getEnv('transpilationWorkerThreadsCount');
226-
this.workerPool = workerpool.pool(
227-
path.join(__dirname, 'transpilers/transpiler_worker'),
228-
wc > 0 ? { maxWorkers: wc } : undefined,
229-
);
230-
}
223+
const errorsReport = new ErrorReporter(null, [], this.errorReportOptions);
224+
this.errorsReporter = errorsReport;
231225

232-
const transpile = async (stage: CompileStage) => {
233-
let cubeNames: string[] = [];
234-
let cubeSymbols: Record<string, Record<string, boolean>> = {};
235-
let transpilerNames: string[] = [];
236-
let results;
237-
238-
if (transpilationNative || transpilationWorkerThreads) {
239-
cubeNames = Object.keys(this.cubeDictionary.byId);
240-
// We need only cubes and all its member names for transpiling.
241-
// Cubes doesn't change during transpiling, but are changed during compilation phase,
242-
// so we can prepare them once for every phase.
243-
// Communication between main and worker threads uses
244-
// The structured clone algorithm (@see https://developer.mozilla.org/en-US/docs/Web/API/Web_Workers_API/Structured_clone_algorithm)
245-
// which doesn't allow passing any function objects, so we need to sanitize the symbols.
246-
// Communication with native backend also involves deserialization.
247-
cubeSymbols = Object.fromEntries(
248-
Object.entries(this.cubeSymbols.symbols as Record<string, Record<string, any>>)
249-
.map(
250-
([key, value]: [string, Record<string, any>]) => [key, Object.fromEntries(
251-
Object.keys(value).map((k) => [k, true]),
252-
)],
253-
),
254-
);
226+
const transpilationWorkerThreads = getEnv('transpilationWorkerThreads');
227+
const transpilationNative = getEnv('transpilationNative');
228+
const transpilationNativeThreadsCount = getThreadsCount();
229+
const { compilerId } = this;
255230

256-
// Transpilers are the same for all files within phase.
257-
transpilerNames = this.transpilers.map(t => t.constructor.name);
231+
if (!transpilationNative && transpilationWorkerThreads) {
232+
const wc = getEnv('transpilationWorkerThreadsCount');
233+
this.workerPool = workerpool.pool(
234+
path.join(__dirname, 'transpilers/transpiler_worker'),
235+
wc > 0 ? { maxWorkers: wc } : undefined,
236+
);
258237
}
259238

260-
if (transpilationNative) {
239+
const transpile = async (stage: CompileStage) => {
240+
// Time transpilation stage
241+
const transpileTimer = perfTracker.start(`transpilation-stage-${stage}`);
242+
243+
let cubeNames: string[] = [];
244+
let cubeSymbols: Record<string, Record<string, boolean>> = {};
245+
let transpilerNames: string[] = [];
246+
let results;
247+
248+
if (transpilationNative || transpilationWorkerThreads) {
249+
cubeNames = Object.keys(this.cubeDictionary.byId);
250+
// We need only cubes and all its member names for transpiling.
251+
// Cubes doesn't change during transpiling, but are changed during compilation phase,
252+
// so we can prepare them once for every phase.
253+
// Communication between main and worker threads uses
254+
// The structured clone algorithm (@see https://developer.mozilla.org/en-US/docs/Web/API/Web_Workers_API/Structured_clone_algorithm)
255+
// which doesn't allow passing any function objects, so we need to sanitize the symbols.
256+
// Communication with native backend also involves deserialization.
257+
cubeSymbols = Object.fromEntries(
258+
Object.entries(this.cubeSymbols.symbols as Record<string, Record<string, any>>)
259+
.map(
260+
([key, value]: [string, Record<string, any>]) => [key, Object.fromEntries(
261+
Object.keys(value).map((k) => [k, true]),
262+
)],
263+
),
264+
);
265+
266+
// Transpilers are the same for all files within phase.
267+
transpilerNames = this.transpilers.map(t => t.constructor.name);
268+
}
269+
270+
if (transpilationNative) {
261271
// Warming up swc compiler cache
262-
const dummyFile = {
263-
fileName: 'dummy.js',
264-
content: ';',
265-
};
272+
const dummyFile = {
273+
fileName: 'dummy.js',
274+
content: ';',
275+
};
266276

267-
await this.transpileJsFile(dummyFile, errorsReport, { cubeNames, cubeSymbols, transpilerNames, contextSymbols: CONTEXT_SYMBOLS, compilerId, stage });
277+
await this.transpileJsFile(dummyFile, errorsReport, { cubeNames, cubeSymbols, transpilerNames, contextSymbols: CONTEXT_SYMBOLS, compilerId, stage });
268278

269-
const nonJsFilesTasks = toCompile.filter(file => !file.fileName.endsWith('.js'))
270-
.map(f => this.transpileFile(f, errorsReport, { transpilerNames, compilerId }));
279+
const nonJsFilesTasks = toCompile.filter(file => !file.fileName.endsWith('.js'))
280+
.map(f => this.transpileFile(f, errorsReport, { transpilerNames, compilerId }));
271281

272-
const jsFiles = toCompile.filter(file => file.fileName.endsWith('.js'));
273-
let JsFilesTasks = [];
282+
const jsFiles = toCompile.filter(file => file.fileName.endsWith('.js'));
283+
let JsFilesTasks = [];
274284

275-
if (jsFiles.length > 0) {
276-
let jsChunks;
277-
if (jsFiles.length < transpilationNativeThreadsCount * transpilationNativeThreadsCount) {
278-
jsChunks = [jsFiles];
279-
} else {
280-
const baseSize = Math.floor(jsFiles.length / transpilationNativeThreadsCount);
281-
jsChunks = [];
282-
for (let i = 0; i < transpilationNativeThreadsCount; i++) {
285+
if (jsFiles.length > 0) {
286+
let jsChunks;
287+
if (jsFiles.length < transpilationNativeThreadsCount * transpilationNativeThreadsCount) {
288+
jsChunks = [jsFiles];
289+
} else {
290+
const baseSize = Math.floor(jsFiles.length / transpilationNativeThreadsCount);
291+
jsChunks = [];
292+
for (let i = 0; i < transpilationNativeThreadsCount; i++) {
283293
// For the last part, we take the remaining files so we don't lose the extra ones.
284-
const start = i * baseSize;
285-
const end = (i === transpilationNativeThreadsCount - 1) ? jsFiles.length : start + baseSize;
286-
jsChunks.push(jsFiles.slice(start, end));
294+
const start = i * baseSize;
295+
const end = (i === transpilationNativeThreadsCount - 1) ? jsFiles.length : start + baseSize;
296+
jsChunks.push(jsFiles.slice(start, end));
297+
}
287298
}
299+
JsFilesTasks = jsChunks.map(chunk => this.transpileJsFilesBulk(chunk, errorsReport, { transpilerNames, compilerId }));
288300
}
289-
JsFilesTasks = jsChunks.map(chunk => this.transpileJsFilesBulk(chunk, errorsReport, { transpilerNames, compilerId }));
301+
302+
results = (await Promise.all([...nonJsFilesTasks, ...JsFilesTasks])).flat();
303+
} else if (transpilationWorkerThreads) {
304+
results = await Promise.all(toCompile.map(f => this.transpileFile(f, errorsReport, { cubeNames, cubeSymbols, transpilerNames })));
305+
} else {
306+
results = await Promise.all(toCompile.map(f => this.transpileFile(f, errorsReport, {})));
290307
}
291308

292-
results = (await Promise.all([...nonJsFilesTasks, ...JsFilesTasks])).flat();
293-
} else if (transpilationWorkerThreads) {
294-
results = await Promise.all(toCompile.map(f => this.transpileFile(f, errorsReport, { cubeNames, cubeSymbols, transpilerNames })));
295-
} else {
296-
results = await Promise.all(toCompile.map(f => this.transpileFile(f, errorsReport, {})));
297-
}
309+
// End transpilation stage timing
310+
transpileTimer.end();
298311

299-
return results.filter(f => !!f);
300-
};
301-
302-
const compilePhase = async (compilers: CompileCubeFilesCompilers, stage: 0 | 1 | 2 | 3) => this.compileCubeFiles(compilers, await transpile(stage), errorsReport);
303-
304-
return compilePhase({ cubeCompilers: this.cubeNameCompilers }, 0)
305-
.then(() => compilePhase({ cubeCompilers: this.preTranspileCubeCompilers.concat([this.viewCompilationGate]) }, 1))
306-
.then(() => (this.viewCompilationGate.shouldCompileViews() ?
307-
compilePhase({ cubeCompilers: this.viewCompilers }, 2)
308-
: Promise.resolve()))
309-
.then(() => compilePhase({
310-
cubeCompilers: this.cubeCompilers,
311-
contextCompilers: this.contextCompilers,
312-
}, 3))
313-
.then(() => {
314-
if (transpilationNative) {
315-
// Clean up cache
316-
const dummyFile = {
317-
fileName: 'terminate.js',
318-
content: ';',
319-
};
312+
return results.filter(f => !!f);
313+
};
320314

321-
this.transpileJsFile(
322-
dummyFile,
323-
errorsReport,
324-
{ cubeNames: [], cubeSymbols: {}, transpilerNames: [], contextSymbols: {}, compilerId: this.compilerId, stage: 0 }
325-
).then(() => undefined);
326-
} else if (transpilationWorkerThreads && this.workerPool) {
327-
this.workerPool.terminate();
315+
const compilePhase = async (compilers: CompileCubeFilesCompilers, stage: 0 | 1 | 2 | 3) => {
316+
const compilePhaseTimer = perfTracker.start(`compilation-phase-${stage}`);
317+
try {
318+
return await this.compileCubeFiles(compilers, await transpile(stage), errorsReport);
319+
} finally {
320+
compilePhaseTimer.end();
328321
}
329-
});
322+
};
323+
324+
return compilePhase({ cubeCompilers: this.cubeNameCompilers }, 0)
325+
.then(() => compilePhase({ cubeCompilers: this.preTranspileCubeCompilers.concat([this.viewCompilationGate]) }, 1))
326+
.then(() => (this.viewCompilationGate.shouldCompileViews() ?
327+
compilePhase({ cubeCompilers: this.viewCompilers }, 2)
328+
: Promise.resolve()))
329+
.then(() => compilePhase({
330+
cubeCompilers: this.cubeCompilers,
331+
contextCompilers: this.contextCompilers,
332+
}, 3))
333+
.then(() => {
334+
if (transpilationNative) {
335+
// Clean up cache
336+
const dummyFile = {
337+
fileName: 'terminate.js',
338+
content: ';',
339+
};
340+
341+
this.transpileJsFile(
342+
dummyFile,
343+
errorsReport,
344+
{ cubeNames: [], cubeSymbols: {}, transpilerNames: [], contextSymbols: {}, compilerId: this.compilerId, stage: 0 }
345+
).then(() => undefined);
346+
} else if (transpilationWorkerThreads && this.workerPool) {
347+
this.workerPool.terminate();
348+
}
349+
350+
// End overall compilation timing and print performance report
351+
compileTimer.end();
352+
setImmediate(() => {
353+
perfTracker.printReport();
354+
});
355+
});
356+
} catch (error) {
357+
// End timing even on error
358+
compileTimer.end();
359+
throw error;
360+
}
330361
}
331362

332363
public compile() {
@@ -513,7 +544,9 @@ export class DataSchemaCompiler {
513544
asyncModules
514545
);
515546
});
547+
const asyncModulesTimer = perfTracker.start('asyncModules.reduce (jinja)');
516548
await asyncModules.reduce((a: Promise<void>, b: CallableFunction) => a.then(() => b()), Promise.resolve());
549+
asyncModulesTimer.end();
517550
return this.compileObjects(compilers.cubeCompilers || [], cubes, errorsReport)
518551
.then(() => this.compileObjects(compilers.contextCompilers || [], contexts, errorsReport));
519552
}
@@ -532,7 +565,9 @@ export class DataSchemaCompiler {
532565
compiledFiles[file.fileName] = true;
533566

534567
if (file.fileName.endsWith('.js')) {
568+
const compileJsFileTimer = perfTracker.start('compileJsFile');
535569
this.compileJsFile(file, errorsReport, cubes, contexts, exports, asyncModules, toCompile, compiledFiles, { doSyntaxCheck });
570+
compileJsFileTimer.end();
536571
} else if (file.fileName.endsWith('.yml.jinja') || file.fileName.endsWith('.yaml.jinja') ||
537572
(
538573
file.fileName.endsWith('.yml') || file.fileName.endsWith('.yaml')
@@ -552,7 +587,9 @@ export class DataSchemaCompiler {
552587
this.pythonContext!
553588
));
554589
} else if (file.fileName.endsWith('.yml') || file.fileName.endsWith('.yaml')) {
590+
const compileYamlFileTimer = perfTracker.start('compileYamlFile');
555591
this.yamlCompiler.compileYamlFile(file, errorsReport, cubes, contexts, exports, asyncModules, toCompile, compiledFiles);
592+
compileYamlFileTimer.end();
556593
}
557594
}
558595

‎packages/cubejs-schema-compiler/src/compiler/PerfTracker.ts‎

Lines changed: 88 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,88 @@
1+
import { performance, PerformanceObserver } from 'perf_hooks';
2+
3+
interface PerfMetric {
4+
count: number;
5+
totalTime: number;
6+
avgTime: number;
7+
}
8+
9+
interface PerfStats {
10+
[key: string]: PerfMetric;
11+
}
12+
13+
class PerfTracker {
14+
private metrics: PerfStats = {};
15+
16+
private globalMetric: string | null = null;
17+
18+
public constructor() {
19+
const obs = new PerformanceObserver((items) => {
20+
for (const entry of items.getEntries()) {
21+
const { name } = entry;
22+
if (!this.metrics[name]) {
23+
this.metrics[name] = { count: 0, totalTime: 0, avgTime: 0 };
24+
}
25+
const m = this.metrics[name];
26+
m.count++;
27+
m.totalTime += entry.duration;
28+
m.avgTime = m.totalTime / m.count;
29+
}
30+
});
31+
obs.observe({ entryTypes: ['measure'] });
32+
}
33+
34+
public start(name: string, global: boolean = false): { end: () => void } {
35+
const uid = `${name}-${performance.now()}`;
36+
const startMark = `${uid}-start`;
37+
const endMark = `${uid}-end`;
38+
performance.mark(startMark);
39+
40+
if (global && !this.globalMetric) {
41+
this.globalMetric = name;
42+
}
43+
44+
let ended = false;
45+
46+
return {
47+
end: () => {
48+
if (ended) return;
49+
performance.mark(endMark);
50+
performance.measure(name, startMark, endMark);
51+
ended = true;
52+
}
53+
};
54+
}
55+
56+
public printReport() {
57+
console.log('\n🚀 PERFORMANCE REPORT 🚀\n');
58+
console.log('═'.repeat(80));
59+
60+
const sorted = Object.entries(this.metrics)
61+
.sort(([, a], [, b]) => b.totalTime - a.totalTime);
62+
63+
if (!sorted.length) {
64+
console.log('No performance data collected.');
65+
return;
66+
}
67+
68+
let totalTime: number = 0;
69+
70+
if (this.globalMetric) {
71+
totalTime = this.metrics[this.globalMetric]?.totalTime;
72+
} else {
73+
totalTime = sorted.reduce((sum, [, m]) => sum + m.totalTime, 0);
74+
}
75+
76+
console.log(`⏱️ TOTAL TIME: ${totalTime.toFixed(2)}ms\n`);
77+
78+
sorted.forEach(([name, m]) => {
79+
const pct = totalTime > 0 ? (m.totalTime / totalTime * 100) : 0;
80+
console.log(` ${name.padEnd(30)} │ ${m.totalTime.toFixed(2).padStart(8)}ms │ ${m.avgTime.toFixed(2).padStart(7)}ms avg │ ${pct.toFixed(1).padStart(5)}% │ ${m.count.toString().padStart(4)} calls`);
81+
});
82+
83+
console.log('═'.repeat(80));
84+
console.log('🎯 End of Performance Report\n');
85+
}
86+
}
87+
88+
export const perfTracker = new PerfTracker();

0 commit comments

Comments
 (0)