Added llvm opt pipeline timing info (#4284)

* Added llvm opt pipeline timing info

* Fix naming

* Tweak timing pane and use exec's timing if possible

* Added timing info for processExecutionResult

lib/base-compiler.ts

@@ -432,10 +432,15 @@ export class BaseCompiler {
     }
 
     processExecutionResult(input: UnprocessedExecResult, inputFilename?: string): BasicExecutionResult {
+        const start = performance.now();
+        const stdout = utils.parseOutput(input.stdout, inputFilename);
+        const stderr = utils.parseOutput(input.stderr, inputFilename);
+        const end = performance.now();
         return {
             ...input,
-            stdout: utils.parseOutput(input.stdout, inputFilename),
-            stderr: utils.parseOutput(input.stderr, inputFilename),
+            stdout,
+            stderr,
+            processExecutionResultTime: end - start,
         };
     }
 
@@ -1050,12 +1055,15 @@ export class BaseCompiler {
         const execOptions = this.getDefaultExecOptions();
         execOptions.maxOutput = 1024 * 1024 * 1024;
 
+        const compileStart = performance.now();
         const output = await this.runCompiler(this.compiler.exe, newOptions, this.filename(inputFilename), execOptions);
+        const compileEnd = performance.now();
 
         if (output.timedOut) {
             return {
-                error: 'Compilation timed out',
+                error: 'Clang invocation timed out',
                 results: {},
+                clangTime: output.execTime ? output.execTime : compileEnd - compileStart,
             };
         }
 
@@ -1064,7 +1072,9 @@ export class BaseCompiler {
         }
 
         try {
+            const parseStart = performance.now();
             const llvmOptPipeline = await this.processLLVMOptPipeline(output, filters, llvmOptPipelineOptions);
+            const parseEnd = performance.now();
 
             if (llvmOptPipelineOptions.demangle) {
                 // apply demangles after parsing, would otherwise greatly complicate the parsing of the passes
@@ -1074,16 +1084,21 @@ export class BaseCompiler {
                 await demangler.collect({asm: output.stderr});
                 return {
                     results: await demangler.demangleLLVMPasses(llvmOptPipeline),
+                    clangTime: compileEnd - compileStart,
+                    parseTime: parseEnd - parseStart,
                 };
             } else {
                 return {
                     results: llvmOptPipeline,
+                    clangTime: compileEnd - compileStart,
+                    parseTime: parseEnd - parseStart,
                 };
             }
         } catch (e: any) {
             return {
                 error: e.toString(),
                 results: {},
+                clangTime: compileEnd - compileStart,
             };
         }
     }

static/widgets/timing-info-widget.ts

@@ -26,14 +26,16 @@ import $ from 'jquery';
 import {Settings} from '../settings';
 import {Chart, ChartData, defaults} from 'chart.js';
 import 'chart.js/auto';
+import {CompilationResult} from '../../types/compilation/compilation.interfaces';
+import _ from 'underscore';
 
 type Data = ChartData<'bar', number[], string> & {steps: number};
 
 function pushTimingInfo(data: Data, step: string, time: number | string) {
     if (typeof time === 'string') {
         time = parseInt(time, 10);
     }
-    data.labels?.push(`${step} (${time}ms)`);
+    data.labels?.push(`${step} (${Math.round(time * 100) / 100}ms)`);
     data.datasets[0].data.push(time);
     data.steps += time;
 }
@@ -62,7 +64,7 @@ function addBuildResultToTimings(data: Data, buildResult: any) {
     }
 }
 
-function initializeChartDataFromResult(compileResult: any, totalTime: number): Data {
+function initializeChartDataFromResult(compileResult: CompilationResult, totalTime: number): Data {
     const data: Data = {
         steps: 0,
         labels: [],
@@ -78,10 +80,10 @@ function initializeChartDataFromResult(compileResult: any, totalTime: number): D
     };
 
     if (compileResult.retreivedFromCache) {
-        pushTimingInfo(data, 'Retrieve result from cache', compileResult.retreivedFromCacheTime);
+        pushTimingInfo(data, 'Retrieve result from cache', compileResult.retreivedFromCacheTime as number);
 
         if (compileResult.packageDownloadAndUnzipTime) {
-            pushTimingInfo(data, 'Download binary from cache', compileResult.execTime);
+            pushTimingInfo(data, 'Download binary from cache', compileResult.execTime as string | number);
         }
 
         if (compileResult.execResult && compileResult.execResult.execTime) {
@@ -105,9 +107,23 @@ function initializeChartDataFromResult(compileResult: any, totalTime: number): D
         if (compileResult.execResult && compileResult.execResult.execTime) {
             pushTimingInfo(data, 'Execution', compileResult.execResult.execTime);
         } else {
-            pushTimingInfo(data, 'Execution', compileResult.execTime);
+            pushTimingInfo(data, 'Execution', compileResult.execTime as string | number);
         }
     }
+
+    if (compileResult.processExecutionResultTime !== undefined) {
+        pushTimingInfo(data, 'Process execution result', compileResult.processExecutionResultTime);
+    }
+
+    if (compileResult.hasLLVMOptPipelineOutput && !_.isString(compileResult.llvmOptPipelineOutput)) {
+        if (compileResult.llvmOptPipelineOutput?.clangTime !== undefined) {
+            pushTimingInfo(data, 'Llvm opt pipeline clang time', compileResult.llvmOptPipelineOutput.clangTime);
+        }
+        if (compileResult.llvmOptPipelineOutput?.parseTime !== undefined) {
+            pushTimingInfo(data, 'Llvm opt pipeline parse time', compileResult.llvmOptPipelineOutput.parseTime);
+        }
+    }
+
     const stepsTotal = data.steps;
     pushTimingInfo(data, 'Network, JS, waiting, etc.', totalTime - stepsTotal);
 
@@ -169,7 +185,9 @@ function displayData(data: Data) {
     modal.modal('show');
 }
 
-export function displayCompilationTiming(compileResult: any, totalTime: number) {
-    const data = initializeChartDataFromResult(compileResult, totalTime);
-    displayData(data);
+export function displayCompilationTiming(compileResult: CompilationResult | null, totalTime: number) {
+    if (compileResult) {
+        const data = initializeChartDataFromResult(compileResult, totalTime);
+        displayData(data);
+    }
 }

types/compilation/compilation.interfaces.ts

@@ -28,6 +28,8 @@ import {CompilerInfo} from '../compiler.interfaces';
 import {BasicExecutionResult} from '../execution/execution.interfaces';
 import {ResultLine} from '../resultline/resultline.interfaces';
 
+import {LLVMOptPipelineOutput} from './llvm-opt-pipeline-output.interfaces';
+
 export type CompilationResult = {
     code: number;
     timedOut: boolean;
@@ -45,6 +47,7 @@ export type CompilationResult = {
         code: number;
         didExecute: boolean;
         buildResult?: BuildResult;
+        execTime?: number;
     };
     hasGnatDebugOutput?: boolean;
     gnatDebugOutput?: ResultLine[];
@@ -71,7 +74,7 @@ export type CompilationResult = {
     irOutput?: any;
 
     hasLLVMOptPipelineOutput?: boolean;
-    llvmOptPipelineOutput?: any;
+    llvmOptPipelineOutput?: LLVMOptPipelineOutput | string;
 
     hasRustMirOutput?: boolean;
     rustMirOutput?: any;
@@ -99,6 +102,14 @@ export type CompilationResult = {
     jsnesrom?: string;
 
     hints?: string[];
+
+    retreivedFromCache?: boolean;
+    retreivedFromCacheTime?: number;
+    packageDownloadAndUnzipTime?: number;
+    execTime?: number | string;
+    processExecutionResultTime?: number;
+    objdumpTime?: number;
+    parsingTime?: number;
 };
 
 export type ExecutionOptions = {

types/compilation/llvm-opt-pipeline-output.interfaces.ts

@@ -38,6 +38,8 @@ export type LLVMOptPipelineResults = Record<string, Pass[]>;
 export type LLVMOptPipelineOutput = {
     error?: string;
     results: LLVMOptPipelineResults;
+    clangTime?: number | string;
+    parseTime?: number;
 };
 
 export type LLVMOptPipelineBackendOptions = {

types/execution/execution.interfaces.ts

@@ -26,6 +26,7 @@ export type BasicExecutionResult = {
     stdout: ResultLine[];
     stderr: ResultLine[];
     execTime: string;
+    processExecutionResultTime?: number;
     timedOut: boolean;
 };