Measure time for all compile stages

.run/spice.run.xml

@@ -1,5 +1,5 @@
 <component name="ProjectRunConfigurationManager">
-  <configuration default="false" name="spice" type="CMakeRunConfiguration" factoryName="Application" PROGRAM_PARAMS="run -ir -O0 ../../media/test-project/os-test.spice" REDIRECT_INPUT="false" ELEVATE="false" USE_EXTERNAL_CONSOLE="false" PASS_PARENT_ENVS_2="true" PROJECT_NAME="Spice" TARGET_NAME="spice" CONFIG_NAME="Debug" RUN_TARGET_PROJECT_NAME="Spice" RUN_TARGET_NAME="spice">
+  <configuration default="false" name="spice" type="CMakeRunConfiguration" factoryName="Application" PROGRAM_PARAMS="run -O2 -d ../../media/test-project/os-test.spice" REDIRECT_INPUT="false" ELEVATE="false" USE_EXTERNAL_CONSOLE="false" PASS_PARENT_ENVS_2="true" PROJECT_NAME="Spice" TARGET_NAME="spice" CONFIG_NAME="Debug" RUN_TARGET_PROJECT_NAME="Spice" RUN_TARGET_NAME="spice">
     <envs>
       <env name="CONSOLE_WIDTH" value="300" />
       <env name="RUN_TESTS" value="OFF" />

src/SourceFile.cpp

@@ -34,7 +34,8 @@ SourceFile::SourceFile(GlobalResourceManager &resourceManager, SourceFile *paren
 }
 
 void SourceFile::runLexer() {
-  Timer timer; // Start timer, which runs until the end of the current scope
+  Timer timer;
+  timer.start();
 
   // Read from file
   std::ifstream fileInputStream(filePath);
@@ -61,31 +62,35 @@ void SourceFile::runLexer() {
   if (!resourceManager.cliOptions.ignoreCache)
     restoredFromCache = resourceManager.cacheManager.lookupSourceFile(this);
 
-  printStatusMessage("Lexer", IO_CODE, IO_TOKENS);
+  timer.stop();
+  printStatusMessage("Lexer", IO_CODE, IO_TOKENS, &timer);
 }
 
 void SourceFile::runParser() {
   // Skip if restored from cache
   if (restoredFromCache)
     return;
 
-  Timer timer; // Start timer, which runs until the end of the current scope
+  Timer timer;
+  timer.start();
 
   // Parse input
   antlrCtx.parser = std::make_unique<SpiceParser>(antlrCtx.tokenStream.get()); // Check for syntax errors
   antlrCtx.parser->removeErrorListeners();
   antlrCtx.parser->addErrorListener(antlrCtx.parserErrorHandler.get());
   antlrCtx.parser->removeParseListeners();
 
-  printStatusMessage("Parser", IO_TOKENS, IO_CST);
+  timer.stop();
+  printStatusMessage("Parser", IO_TOKENS, IO_CST, &timer);
 }
 
 void SourceFile::runCSTVisualizer() {
   // Only execute if enabled
   if (restoredFromCache || (!resourceManager.cliOptions.dumpCST && !resourceManager.cliOptions.testMode))
     return;
 
-  Timer timer; // Start timer, which runs until the end of the current scope
+  Timer timer;
+  timer.start();
 
   // Generate dot code for this source file
   std::stringstream dotCode;
@@ -101,15 +106,17 @@ void SourceFile::runCSTVisualizer() {
       visualizerOutput("CST", compilerOutput.cstString);
   }
 
-  printStatusMessage("CST Visualizer", IO_CST, IO_CST);
+  timer.stop();
+  printStatusMessage("CST Visualizer", IO_CST, IO_CST, &timer);
 }
 
 void SourceFile::runASTBuilder() {
   // Skip if restored from cache
   if (restoredFromCache)
     return;
 
-  Timer timer; // Start timer, which runs until the end of the current scope
+  Timer timer;
+  timer.start();
 
   // Create AST
   ast = std::make_unique<EntryNode>(nullptr, CodeLoc(1, 1, filePath));
@@ -122,28 +129,32 @@ void SourceFile::runASTBuilder() {
   // Create global scope
   globalScope = std::make_unique<Scope>(nullptr, SCOPE_GLOBAL);
 
-  printStatusMessage("AST Builder", IO_CST, IO_AST);
+  timer.stop();
+  printStatusMessage("AST Builder", IO_CST, IO_AST, &timer);
 }
 
 void SourceFile::runASTOptimizer() {
   // Only execute if enabled
   if (restoredFromCache)
     return;
 
-  Timer timer; // Start timer, which runs until the end of the current scope
+  Timer timer;
+  timer.start();
 
   ASTOptimizer astOptimizer(resourceManager, this);
   astOptimizer.visit(static_cast<EntryNode *>(ast.get()));
 
-  printStatusMessage("AST Optimizer", IO_AST, IO_AST);
+  timer.stop();
+  printStatusMessage("AST Optimizer", IO_AST, IO_AST, &timer);
 }
 
 void SourceFile::runASTVisualizer() {
   // Only execute if enabled
   if (restoredFromCache || (!resourceManager.cliOptions.dumpAST && !resourceManager.cliOptions.testMode))
     return;
 
-  Timer timer; // Start timer, which runs until the end of the current scope
+  Timer timer;
+  timer.start();
 
   // Generate dot code for this source file
   std::stringstream dotCode;
@@ -158,15 +169,17 @@ void SourceFile::runASTVisualizer() {
       visualizerOutput("AST", compilerOutput.astString);
   }
 
-  printStatusMessage("AST Visualizer", IO_AST, IO_AST);
+  timer.stop();
+  printStatusMessage("AST Visualizer", IO_AST, IO_AST, &timer);
 }
 
 void SourceFile::runImportCollector() { // NOLINT(misc-no-recursion)
   // Skip if restored from cache
   if (restoredFromCache)
     return;
 
-  Timer timer; // Start timer, which runs until the end of the current scope
+  Timer timer;
+  timer.start();
 
   // Collect the imports for this source file
   ImportCollector importCollector(resourceManager, this);
@@ -176,15 +189,17 @@ void SourceFile::runImportCollector() { // NOLINT(misc-no-recursion)
   for (const auto &dependency : dependencies)
     dependency.second.first->runFrontEnd();
 
-  printStatusMessage("Import Collector", IO_AST, IO_AST);
+  timer.stop();
+  printStatusMessage("Import Collector", IO_AST, IO_AST, &timer);
 }
 
 void SourceFile::runSymbolTableBuilder() { // NOLINT(misc-no-recursion)
   // Skip if restored from cache
   if (restoredFromCache)
     return;
 
-  Timer timer; // Start timer, which runs until the end of the current scope
+  Timer timer;
+  timer.start();
 
   // Build symbol table of dependencies first
   for (const auto &[importName, sourceFile] : dependencies)
@@ -193,18 +208,23 @@ void SourceFile::runSymbolTableBuilder() { // NOLINT(misc-no-recursion)
   // Then build symbol table of the current file
   SymbolTableBuilder symbolTableBuilder(resourceManager, this);
   symbolTableBuilder.visit(static_cast<EntryNode *>(ast.get()));
+
+  timer.stop();
+  printStatusMessage("Symbol Table Builder", IO_AST, IO_AST, &timer);
 }
 
 void SourceFile::runTypeChecker() { // NOLINT(misc-no-recursion)
-  Timer timer;                      // Start timer, which runs until the end of the current scope
+  Timer timer;
+  timer.start();
 
   // We need two runs here due to generics.
   // The first run to determine all concrete substantiations of potentially generic elements
   runTypeCheckerFirst(); // Visit dependency tree from bottom to top
   // The second run to ensure, also generic scopes are type-checked properly
   runTypeCheckerSecond(); // Visit dependency tree from top to bottom
 
-  printStatusMessage("Type Checker", IO_AST, IO_AST);
+  timer.stop();
+  printStatusMessage("Type Checker", IO_AST, IO_AST, &timer);
 }
 
 void SourceFile::runTypeCheckerFirst() { // NOLINT(misc-no-recursion)
@@ -256,7 +276,8 @@ void SourceFile::runBorrowChecker() { // NOLINT(misc-no-recursion)
   if (restoredFromCache)
     return;
 
-  Timer timer; // Start timer, which runs until the end of the current scope
+  Timer timer;
+  timer.start();
 
   // Borrow-check all dependencies first
   for (const auto &[importName, sourceFile] : dependencies)
@@ -266,15 +287,17 @@ void SourceFile::runBorrowChecker() { // NOLINT(misc-no-recursion)
   BorrowChecker borrowChecker(resourceManager, this);
   borrowChecker.visit(static_cast<EntryNode *>(ast.get()));
 
-  printStatusMessage("Borrow Checker", IO_AST, IO_AST);
+  timer.stop();
+  printStatusMessage("Borrow Checker", IO_AST, IO_AST, &timer);
 }
 
 void SourceFile::runEscapeAnalyzer() { // NOLINT(misc-no-recursion)
   // Skip if restored from cache
   if (restoredFromCache)
     return;
 
-  Timer timer; // Start timer, which runs until the end of the current scope
+  Timer timer;
+  timer.start();
 
   // Escape-analyze all dependencies first
   for (const auto &[importName, sourceFile] : dependencies)
@@ -284,15 +307,17 @@ void SourceFile::runEscapeAnalyzer() { // NOLINT(misc-no-recursion)
   EscapeAnalyzer escapeAnalyzer(resourceManager, this);
   escapeAnalyzer.visit(static_cast<EntryNode *>(ast.get()));
 
-  printStatusMessage("Escape Analyzer", IO_AST, IO_AST);
+  timer.stop();
+  printStatusMessage("Escape Analyzer", IO_AST, IO_AST, &timer);
 }
 
 void SourceFile::runIRGenerator() { // NOLINT(misc-no-recursion)
   // Skip if restored from cache
   if (restoredFromCache)
     return;
 
-  Timer timer; // Start timer, which runs until the end of the current scope
+  Timer timer;
+  timer.start();
 
   // Generate the imported source files
   for (const auto &sourceFile : dependencies)
@@ -315,15 +340,17 @@ void SourceFile::runIRGenerator() { // NOLINT(misc-no-recursion)
     std::cout << "\n";
   } // GCOV_EXCL_STOP
 
-  printStatusMessage("IR Generator", IO_AST, IO_IR);
+  timer.stop();
+  printStatusMessage("IR Generator", IO_AST, IO_IR, &timer);
 }
 
 void SourceFile::runIROptimizer() { // NOLINT(misc-no-recursion)
   // Skip if restored from cache
   if (restoredFromCache)
     return;
 
-  Timer timer; // Start timer, which runs until the end of the current scope
+  Timer timer;
+  timer.start();
 
   // Skip this stage if optimization is disabled
   if (resourceManager.cliOptions.optLevel < 1 || resourceManager.cliOptions.optLevel > 5)
@@ -347,15 +374,17 @@ void SourceFile::runIROptimizer() { // NOLINT(misc-no-recursion)
     std::cout << "\n";
   } // GCOV_EXCL_STOP
 
-  printStatusMessage("IR Optimizer", IO_IR, IO_IR);
+  timer.stop();
+  printStatusMessage("IR Optimizer", IO_IR, IO_IR, &timer);
 }
 
 void SourceFile::runObjectEmitter() { // NOLINT(misc-no-recursion)
   // Skip if restored from cache
   if (restoredFromCache)
     return;
 
-  Timer timer; // Start timer, which runs until the end of the current scope
+  Timer timer;
+  timer.start();
 
   // Emit objects for the imported source files
   for (const auto &sourceFile : dependencies)
@@ -371,7 +400,8 @@ void SourceFile::runObjectEmitter() { // NOLINT(misc-no-recursion)
     objectEmitter.dumpAsm();
   } // GCOV_EXCL_STOP
 
-  printStatusMessage("IR Optimizer", IO_IR, IO_OBJECT_FILE);
+  timer.stop();
+  printStatusMessage("Object Emitter", IO_IR, IO_OBJECT_FILE, &timer);
 }
 
 void SourceFile::concludeCompilation() { // NOLINT(misc-no-recursion)
@@ -499,11 +529,13 @@ void SourceFile::visualizerOutput(std::string outputName, const std::string &out
   std::cout << "done.\nSVG file can be found at: " << fileBasePath << ".svg\n";
 }
 
-void SourceFile::printStatusMessage(const std::string &stage, const CompilerStageIOType &in,
-                                    const CompilerStageIOType &out) const {
+void SourceFile::printStatusMessage(const std::string &stage, const CompilerStageIOType &in, const CompilerStageIOType &out,
+                                    const Timer *timer) const {
   if (resourceManager.cliOptions.printDebugOutput) {
     const char *compilerStageIoTypeName[] = {"Code", "Tokens", "CST", "AST", "IR", "OBJECT_FILE"};
     std::cout << "[" << stage << "] for " << fileName << ": ";
     std::cout << compilerStageIoTypeName[in] << " --> " << compilerStageIoTypeName[out];
+    if (timer != nullptr)
+      std::cout << " (" << std::to_string(timer->getDurationMilliseconds()) << " ms)\n";
   }
 }

src/SourceFile.h

@@ -22,6 +22,7 @@
 class GlobalResourceManager;
 class EntryNode;
 class ASTNode;
+class Timer;
 
 enum CompilerStageIOType {
   IO_CODE = 0,
@@ -130,5 +131,6 @@ class SourceFile {
   // Private methods
   void visualizerPreamble(std::stringstream &output) const;
   void visualizerOutput(std::string outputName, const std::string &output) const;
-  void printStatusMessage(const std::string &stage, const CompilerStageIOType &in, const CompilerStageIOType &out) const;
+  void printStatusMessage(const std::string &stage, const CompilerStageIOType &in, const CompilerStageIOType &out,
+                          const Timer *timer) const;
 };

src/cli/CLIInterface.cpp

@@ -127,12 +127,6 @@ void CLIInterface::enrich() {
     cliOptions.targetOs = triple.getOSName();
     cliOptions.isNativeTarget = triple == defaultTriple;
   }
-  // Dump AST, IR and symbol table if all debug output is enabled
-  if (cliOptions.printDebugOutput) {
-    cliOptions.dumpAST = true;
-    cliOptions.dumpIR = true;
-    cliOptions.dumpSymbolTables = true;
-  }
 }
 
 /**

src/importcollector/ImportCollector.cpp

@@ -15,6 +15,8 @@ std::any ImportCollector::visitEntry(EntryNode *node) {
 
   // Reset the AST
   node->reset();
+
+  return nullptr;
 }
 
 std::any ImportCollector::visitImportStmt(ImportStmtNode *node) {
@@ -60,6 +62,8 @@ std::any ImportCollector::visitImportStmt(ImportStmtNode *node) {
   sourceFile->addDependency(importedSourceFile, node, node->importName, importPath);
   // Register all external names of the imported source file to the current one
   registerExternalGlobalNames(importedSourceFile.get(), node->importName);
+
+  return nullptr;
 }
 
 /**

src/iroptimizer/IROptimizer.cpp

@@ -9,7 +9,7 @@
 #include <llvm/Transforms/IPO/AlwaysInliner.h>
 
 void IROptimizer::optimize() {
-  if (cliOptions.printDebugOutput)
+  if (cliOptions.printDebugOutput && cliOptions.dumpIR)
     std::cout << "\nOptimizing on level " + std::to_string(cliOptions.optLevel) << " ...\n"; // GCOV_EXCL_LINE
 
   llvm::LoopAnalysisManager loopAnalysisMgr;

src/objectemitter/ObjectEmitter.cpp

@@ -11,7 +11,7 @@ void ObjectEmitter::emit() const {
   const std::string &objectFile = sourceFile->objectFilePath;
 
   // GCOV_EXCL_START
-  if (cliOptions.printDebugOutput)
+  if (cliOptions.printDebugOutput && cliOptions.dumpAssembly)
     std::cout << "\nEmitting object file for triplet '" << cliOptions.targetTriple << "' to path: " << objectFile << "\n";
   // GCOV_EXCL_STOP
 
@@ -38,4 +38,4 @@ void ObjectEmitter::dumpAsm() const {
   // Emit object file
   passManager.run(*module);
   llvm::outs().flush();
-}
+}

src/util/Timer.h

@@ -7,14 +7,18 @@
 
 struct Timer {
 public:
-  Timer() { start = std::chrono::high_resolution_clock::now(); }
-  ~Timer() {
-    std::chrono::time_point<std::chrono::system_clock> end = std::chrono::high_resolution_clock::now();
-    std::chrono::duration<double> duration = end - start;
-    double durationSeconds = duration.count() * 1000000;
-    std::cout << durationSeconds << std::endl;
+  // Constructors
+  Timer() = default;
+
+  // Public methods
+  void start() { timeStart = std::chrono::high_resolution_clock::now(); }
+  void stop() { timeStop = std::chrono::high_resolution_clock::now(); }
+  [[nodiscard]] long long getDurationMilliseconds() const {
+    std::chrono::duration<double> duration = timeStop - timeStart;
+    return std::chrono::duration_cast<std::chrono::milliseconds>(duration).count();
   }
 
 private:
-  std::chrono::time_point<std::chrono::system_clock> start;
+  std::chrono::time_point<std::chrono::system_clock> timeStart;
+  std::chrono::time_point<std::chrono::system_clock> timeStop;
 };