perf(schema-compiler): Improve yaml compilation speed

packages/cubejs-backend-shared/src/FileRepository.ts

@@ -6,6 +6,7 @@ export interface FileContent {
   content: string;
   readOnly?: boolean;
   isModule?: boolean;
+  convertedToJs?: boolean;
 }
 
 export interface SchemaFileRepository {

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

@@ -23,6 +23,7 @@ import { CompilerInterface } from './PrepareCompiler';
 import { YamlCompiler } from './YamlCompiler';
 import { CubeDictionary } from './CubeDictionary';
 import { CompilerCache } from './CompilerCache';
+import { perfTracker } from './PerfTracker';
 
 const ctxFileStorage = new AsyncLocalStorage<FileContent>();
 
@@ -88,6 +89,8 @@ type CompileCubeFilesCompilers = {
   contextCompilers?: CompilerInterface[];
 };
 
+export type CompileContext = any;
+
 export class DataSchemaCompiler {
   private readonly repository: SchemaFileRepository;
 
@@ -123,7 +126,7 @@ export class DataSchemaCompiler {
 
   private readonly compilerCache: CompilerCache;
 
-  private readonly compileContext: any;
+  private readonly compileContext: CompileContext;
 
   private errorReportOptions: ErrorReporterOptions | undefined;
 
@@ -172,14 +175,13 @@ export class DataSchemaCompiler {
     this.standalone = options.standalone || false;
     this.nativeInstance = options.nativeInstance;
     this.yamlCompiler = options.yamlCompiler;
-    this.yamlCompiler.dataSchemaCompiler = this;
     this.pythonContext = null;
     this.workerPool = null;
     this.compilerId = options.compilerId || 'default';
     this.compiledScriptCache = options.compiledScriptCache;
   }
 
-  public compileObjects(compileServices, objects, errorsReport: ErrorReporter) {
+  public compileObjects(compileServices: CompilerInterface[], objects, errorsReport: ErrorReporter) {
     try {
       return compileServices
         .map((compileService) => (() => compileService.compile(objects, errorsReport)))
@@ -193,7 +195,7 @@ export class DataSchemaCompiler {
     }
   }
 
-  protected async loadPythonContext(files, nsFileName) {
+  protected async loadPythonContext(files: FileContent[], nsFileName: string): Promise<PythonCtx> {
     const ns = files.find((f) => f.fileName === nsFileName);
     if (ns) {
       return this.nativeInstance.loadPythonContext(
@@ -213,10 +215,23 @@ export class DataSchemaCompiler {
   protected async doCompile() {
     const files = await this.repository.dataSchemaFiles();
 
+    console.log(`Compiling ${files.length} files...`);
+    const compileTimer = perfTracker.start('doCompile', true);
+
     this.pythonContext = await this.loadPythonContext(files, 'globals.py');
     this.yamlCompiler.initFromPythonContext(this.pythonContext);
 
-    const toCompile = files.filter((f) => !this.filesToCompile || !this.filesToCompile.length || this.filesToCompile.indexOf(f.fileName) !== -1);
+    const toCompile = this.filesToCompile?.length
+      ? files.filter(f => this.filesToCompile.includes(f.fileName))
+      : files;
+
+    const jinjaTemplatedFiles = toCompile.filter((file) => file.fileName.endsWith('.jinja') ||
+      (file.fileName.endsWith('.yml') || file.fileName.endsWith('.yaml')) && file.content.match(JINJA_SYNTAX));
+
+    if (jinjaTemplatedFiles.length > 0) {
+      // Preload Jinja templates to the engine
+      this.loadJinjaTemplates(jinjaTemplatedFiles);
+    }
 
     const errorsReport = new ErrorReporter(null, [], this.errorReportOptions);
     this.errorsReporter = errorsReport;
@@ -235,6 +250,8 @@ export class DataSchemaCompiler {
     }
 
     const transpile = async (stage: CompileStage): Promise<FileContent[]> => {
+      const transpileTimer = perfTracker.start(`transpilation-stage-${stage}`);
+
       let cubeNames: string[] = [];
       let cubeSymbols: Record<string, Record<string, boolean>> = {};
       let transpilerNames: string[] = [];
@@ -271,10 +288,10 @@ export class DataSchemaCompiler {
 
         await this.transpileJsFile(dummyFile, errorsReport, { cubeNames, cubeSymbols, transpilerNames, contextSymbols: CONTEXT_SYMBOLS, compilerId, stage });
 
-        const nonJsFilesTasks = toCompile.filter(file => !file.fileName.endsWith('.js'))
+        const nonJsFilesTasks = toCompile.filter(file => !file.fileName.endsWith('.js') && !file.convertedToJs)
           .map(f => this.transpileFile(f, errorsReport, { transpilerNames, compilerId }));
 
-        const jsFiles = toCompile.filter(file => file.fileName.endsWith('.js'));
+        const jsFiles = toCompile.filter(file => file.fileName.endsWith('.js') || file.convertedToJs);
         let JsFilesTasks = [];
 
         if (jsFiles.length > 0) {
@@ -301,6 +318,8 @@ export class DataSchemaCompiler {
         results = await Promise.all(toCompile.map(f => this.transpileFile(f, errorsReport, {})));
       }
 
+      transpileTimer.end();
+
       return results.filter(f => !!f) as FileContent[];
     };
 
@@ -387,7 +406,6 @@ export class DataSchemaCompiler {
             foundFile,
             errorsReport,
             compiledFiles,
-            [],
             { doSyntaxCheck: true }
           );
           exports[foundFile.fileName] = exports[foundFile.fileName] || {};
@@ -398,6 +416,8 @@ export class DataSchemaCompiler {
     });
 
     const compilePhase = async (compilers: CompileCubeFilesCompilers, stage: 0 | 1 | 2 | 3) => {
+      const compilePhaseTimer = perfTracker.start(`compilation-phase-${stage}`);
+
       // clear the objects for the next phase
       cubes = [];
       exports = {};
@@ -406,7 +426,9 @@ export class DataSchemaCompiler {
       asyncModules = [];
       transpiledFiles = await transpile(stage);
 
-      return this.compileCubeFiles(cubes, contexts, compiledFiles, asyncModules, compilers, transpiledFiles, errorsReport);
+      const res = this.compileCubeFiles(cubes, contexts, compiledFiles, asyncModules, compilers, transpiledFiles, errorsReport);
+      compilePhaseTimer.end();
+      return res;
     };
 
     return compilePhase({ cubeCompilers: this.cubeNameCompilers }, 0)
@@ -442,6 +464,12 @@ export class DataSchemaCompiler {
         } else if (transpilationWorkerThreads && this.workerPool) {
           this.workerPool.terminate();
         }
+
+        // End overall compilation timing and print performance report
+        compileTimer.end();
+        setImmediate(() => {
+          perfTracker.printReport();
+        });
       });
   }
 
@@ -462,30 +490,60 @@ export class DataSchemaCompiler {
     return this.compilePromise;
   }
 
+  private loadJinjaTemplates(files: FileContent[]): void {
+    if (NATIVE_IS_SUPPORTED !== true) {
+      throw new Error(
+        `Native extension is required to process jinja files. ${NATIVE_IS_SUPPORTED.reason}. Read more: ` +
+        'https://github.com/cube-js/cube/blob/master/packages/cubejs-backend-native/README.md#supported-architectures-and-platforms'
+      );
+    }
+
+    const jinjaEngine = this.yamlCompiler.getJinjaEngine();
+
+    // XXX: Make this as bulk operation in the native side
+    files.forEach((file) => {
+      jinjaEngine.loadTemplate(file.fileName, file.content);
+    });
+  }
+
   private async transpileFile(
     file: FileContent,
     errorsReport: ErrorReporter,
     options: TranspileOptions = {}
   ): Promise<(FileContent | undefined)> {
-    if (file.fileName.endsWith('.jinja') ||
+    if (file.fileName.endsWith('.js') || file.convertedToJs) {
+      return this.transpileJsFile(file, errorsReport, options);
+    } else if (file.fileName.endsWith('.jinja') ||
       (file.fileName.endsWith('.yml') || file.fileName.endsWith('.yaml'))
-      // TODO do Jinja syntax check with jinja compiler
       && file.content.match(JINJA_SYNTAX)
     ) {
-      if (NATIVE_IS_SUPPORTED !== true) {
-        throw new Error(
-          `Native extension is required to process jinja files. ${NATIVE_IS_SUPPORTED.reason}. Read more: ` +
-          'https://github.com/cube-js/cube/blob/master/packages/cubejs-backend-native/README.md#supported-architectures-and-platforms'
-        );
+      const transpiledFile = await this.yamlCompiler.compileYamlWithJinjaFile(
+        file,
+        errorsReport,
+        this.standalone ? {} : this.cloneCompileContextWithGetterAlias(this.compileContext),
+        this.pythonContext!
+      );
+      if (transpiledFile) {
+        // We update the jinja/yaml file content to the transpiled js content
+        // and raise related flag so it will go JS transpilation flow afterward
+        // avoiding costly YAML/Python parsing again.
+        file.content = transpiledFile.content;
+        file.convertedToJs = true;
       }
 
-      this.yamlCompiler.getJinjaEngine().loadTemplate(file.fileName, file.content);
-
-      return file;
+      return transpiledFile;
     } else if (file.fileName.endsWith('.yml') || file.fileName.endsWith('.yaml')) {
-      return file;
-    } else if (file.fileName.endsWith('.js')) {
-      return this.transpileJsFile(file, errorsReport, options);
+      const transpiledFile = this.yamlCompiler.transpileYamlFile(file, errorsReport);
+
+      if (transpiledFile) {
+        // We update the yaml file content to the transpiled js content
+        // and raise related flag so it will go JS transpilation flow afterward
+        // avoiding costly YAML/Python parsing again.
+        file.content = transpiledFile.content;
+        file.convertedToJs = true;
+      }
+
+      return transpiledFile;
     } else {
       return file;
     }
@@ -628,16 +686,15 @@ export class DataSchemaCompiler {
     compiledFiles: Record<string, boolean>,
     asyncModules: CallableFunction[],
     compilers: CompileCubeFilesCompilers,
-    toCompile: FileContent[],
+    transpiledFiles: FileContent[],
     errorsReport: ErrorReporter
   ) {
-    toCompile
+    transpiledFiles
       .forEach((file) => {
         this.compileFile(
           file,
           errorsReport,
           compiledFiles,
-          asyncModules
         );
       });
     await asyncModules.reduce((a: Promise<void>, b: CallableFunction) => a.then(() => b()), Promise.resolve());
@@ -653,7 +710,6 @@ export class DataSchemaCompiler {
     file: FileContent,
     errorsReport: ErrorReporter,
     compiledFiles: Record<string, boolean>,
-    asyncModules: CallableFunction[],
     { doSyntaxCheck } = { doSyntaxCheck: false }
   ) {
     if (compiledFiles[file.fileName]) {
@@ -662,22 +718,25 @@ export class DataSchemaCompiler {
 
     compiledFiles[file.fileName] = true;
 
-    if (file.fileName.endsWith('.js')) {
+    if (file.convertedToJs) {
+      this.compileJsFile(file, errorsReport);
+    } else if (file.fileName.endsWith('.js')) {
+      const compileJsFileTimer = perfTracker.start('compileJsFile');
       this.compileJsFile(file, errorsReport, { doSyntaxCheck });
+      compileJsFileTimer.end();
     } else if (file.fileName.endsWith('.yml.jinja') || file.fileName.endsWith('.yaml.jinja') ||
-      (
-        file.fileName.endsWith('.yml') || file.fileName.endsWith('.yaml')
-        // TODO do Jinja syntax check with jinja compiler
-      ) && file.content.match(JINJA_SYNTAX)
+      (file.fileName.endsWith('.yml') || file.fileName.endsWith('.yaml')) &&
+      file.content.match(JINJA_SYNTAX)
     ) {
-      asyncModules.push(() => this.yamlCompiler.compileYamlWithJinjaFile(
-        file,
-        errorsReport,
-        this.standalone ? {} : this.cloneCompileContextWithGetterAlias(this.compileContext),
-        this.pythonContext!
-      ));
+      const compileJinjaFileTimer = perfTracker.start('compileJinjaFile (actually js)');
+      // original jinja/yaml file was already transpiled into js
+      this.compileJsFile(file, errorsReport);
+      compileJinjaFileTimer.end();
     } else if (file.fileName.endsWith('.yml') || file.fileName.endsWith('.yaml')) {
-      this.yamlCompiler.compileYamlFile(file, errorsReport);
+      const compileYamlFileTimer = perfTracker.start('compileYamlFile (actually js)');
+      // original yaml file was already transpiled into js
+      this.compileJsFile(file, errorsReport);
+      compileYamlFileTimer.end();
     }
   }
 

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

@@ -0,0 +1,88 @@
+import { performance, PerformanceObserver } from 'perf_hooks';
+
+interface PerfMetric {
+  count: number;
+  totalTime: number;
+  avgTime: number;
+}
+
+interface PerfStats {
+  [key: string]: PerfMetric;
+}
+
+class PerfTracker {
+  private metrics: PerfStats = {};
+
+  private globalMetric: string | null = null;
+
+  public constructor() {
+    const obs = new PerformanceObserver((items) => {
+      for (const entry of items.getEntries()) {
+        const { name } = entry;
+        if (!this.metrics[name]) {
+          this.metrics[name] = { count: 0, totalTime: 0, avgTime: 0 };
+        }
+        const m = this.metrics[name];
+        m.count++;
+        m.totalTime += entry.duration;
+        m.avgTime = m.totalTime / m.count;
+      }
+    });
+    obs.observe({ entryTypes: ['measure'] });
+  }
+
+  public start(name: string, global: boolean = false): { end: () => void } {
+    const uid = `${name}-${performance.now()}`;
+    const startMark = `${uid}-start`;
+    const endMark = `${uid}-end`;
+    performance.mark(startMark);
+
+    if (global && !this.globalMetric) {
+      this.globalMetric = name;
+    }
+
+    let ended = false;
+
+    return {
+      end: () => {
+        if (ended) return;
+        performance.mark(endMark);
+        performance.measure(name, startMark, endMark);
+        ended = true;
+      }
+    };
+  }
+
+  public printReport() {
+    console.log('\n🚀 PERFORMANCE REPORT 🚀\n');
+    console.log('═'.repeat(90));
+
+    const sorted = Object.entries(this.metrics)
+      .sort(([, a], [, b]) => b.totalTime - a.totalTime);
+
+    if (!sorted.length) {
+      console.log('No performance data collected.');
+      return;
+    }
+
+    let totalTime: number = 0;
+
+    if (this.globalMetric) {
+      totalTime = this.metrics[this.globalMetric]?.totalTime;
+    } else {
+      totalTime = sorted.reduce((sum, [, m]) => sum + m.totalTime, 0);
+    }
+
+    console.log(`⏱️  TOTAL TIME: ${totalTime.toFixed(2)}ms\n`);
+
+    sorted.forEach(([name, m]) => {
+      const pct = totalTime > 0 ? (m.totalTime / totalTime * 100) : 0;
+      console.log(`  ${name.padEnd(40)} │ ${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`);
+    });
+
+    console.log('═'.repeat(90));
+    console.log('🎯 End of Performance Report\n');
+  }
+}
+
+export const perfTracker = new PerfTracker();

packages/cubejs-schema-compiler/src/compiler/ViewCompilationGate.ts

@@ -6,10 +6,10 @@ export class ViewCompilationGate {
   }
 
   public compile(cubes: any[]) {
-    // When developing Data Access Policies feature, we've came across a
+    // When developing Data Access Policies feature, we've come across a
     // limitation that Cube members can't be referenced in access policies defined on Views,
     // because views aren't (yet) compiled at the time of access policy evaluation.
-    // To workaround this limitation and additional compilation pass is necessary,
+    // To work around this limitation and additional compilation pass is necessary,
     // however it comes with a significant performance penalty.
     // This gate check whether the data model contains views with access policies,
     // and only then allows the additional compilation pass.