Show the compilation phases (#2861)

* Show compilation progress Signed-off-by: Tung D. Le <tung@jp.ibm.com> --------- Signed-off-by: Tung D. Le <tung@jp.ibm.com>
onnx · Jul 8, 2024 · 8109542 · 8109542
1 parent 034b419
commit 8109542
Show file tree

Hide file tree

Showing 7 changed files with 69 additions and 18 deletions.
diff --git a/src/Compiler/CompilerUtils.cpp b/src/Compiler/CompilerUtils.cpp
@@ -14,7 +14,9 @@
 
 #include "CompilerUtils.hpp"
 
+#include <ctime>
 #include <fstream>
+#include <iostream>
 #include <memory>
 #include <regex>
 
@@ -57,6 +59,11 @@ mlir::DefaultTimingManager timingManager;
 mlir::TimingScope rootTimingScope;
 namespace onnx_mlir {
 
+// Values to report the current phase of compilation.
+// Increase TOTAL_COMPILE_PHASE when having more phases.
+uint64_t CURRENT_COMPILE_PHASE = 1;
+uint64_t TOTAL_COMPILE_PHASE = 5;
+
 // Make a function that forces preserving all files using the runtime arguments
 // and/or the overridePreserveFiles enum.
 enum class KeepFilesOfType { All, MLIR, LLVMIR, Bitcode, Object, None };
@@ -162,6 +169,21 @@ int Command::exec(std::string wdir) const {
   return 0;
 }
 
+void showCompilePhase(std::string msg) {
+  time_t rawtime;
+  struct tm *timeinfo;
+  char buffer[80];
+
+  // Get current date.
+  time(&rawtime);
+  timeinfo = localtime(&rawtime);
+  strftime(buffer, 80, "%c", timeinfo);
+  std::string currentTime(buffer);
+
+  llvm::outs() << "[" << CURRENT_COMPILE_PHASE++ << "/" << TOTAL_COMPILE_PHASE
+               << "] " << currentTime << " " << msg << "\n";
+}
+
 } // namespace onnx_mlir
 
 namespace onnx_mlir {
@@ -333,8 +355,10 @@ std::string getTargetFilename(
 // Returns 0 on success, error code on failure.
 static int genLLVMBitcode(const mlir::OwningOpRef<ModuleOp> &module,
     std::string outputNameNoExt, std::string optimizedBitcodeNameWithExt) {
-  auto llvmTiming = rootTimingScope.nest(
-      "[onnx-mlir] Compiling MLIR module to LLVM Optimized Bitcode");
+  std::string msg =
+      "Translating MLIR Module to LLVM and Generating LLVM Optimized Bitcode";
+  showCompilePhase(msg);
+  auto llvmTiming = rootTimingScope.nest("[onnx-mlir] " + msg);
   std::error_code error;
 
   // Write bitcode to a file.
@@ -405,8 +429,9 @@ static int genLLVMBitcode(const mlir::OwningOpRef<ModuleOp> &module,
 // Return 0 on success, error code on failure.
 static int genModelObject(
     std::string bitcodeNameWithExt, std::string &modelObjNameWithExt) {
-  auto objectTiming =
-      rootTimingScope.nest("[onnx-mlir] Compiling LLVM Bitcode to Object File");
+  std::string msg = "Generating Object from LLVM Bitcode";
+  showCompilePhase(msg);
+  auto objectTiming = rootTimingScope.nest("[onnx-mlir] " + msg);
   std::string llcPath = getToolPath("llc");
   Command llvmToObj(/*exePath=*/llcPath);
   setXllcOption({"--code-model", modelSizeStr[modelSize]});
@@ -427,8 +452,9 @@ static int genModelObject(
 // Return 0 on success, error code on failure.
 static int genJniObject(const mlir::OwningOpRef<ModuleOp> &module,
     std::string jniSharedLibPath, std::string jniObjPath) {
-  auto jniTiming =
-      rootTimingScope.nest("[onnx-mlir] Compiling JNI Object File");
+  std::string msg = "Generating JNI Object";
+  showCompilePhase(msg);
+  auto jniTiming = rootTimingScope.nest("[onnx-mlir] " + msg);
   Command ar(/*exePath=*/getToolPath("ar", true));
   int rc = ar.appendStr("x")
                // old version of ar does not support --output so comment out
@@ -447,8 +473,9 @@ static int genJniObject(const mlir::OwningOpRef<ModuleOp> &module,
 static int genSharedLib(std::string sharedLibNameWithExt,
     std::vector<std::string> opts, std::vector<std::string> objs,
     std::vector<std::string> libs, std::vector<std::string> libDirs) {
-  auto sharedLibTiming =
-      rootTimingScope.nest("[onnx-mlir] Linking Shared Library");
+  std::string msg = "Linking and Generating the Output Shared Library";
+  showCompilePhase(msg);
+  auto sharedLibTiming = rootTimingScope.nest("[onnx-mlir] " + msg);
 #ifdef _WIN32
   std::vector<std::string> outputOpt = {"/Fe:" + sharedLibNameWithExt};
   // link has to be before libpath since they need to be passed through to the
@@ -498,7 +525,9 @@ static int genSharedLib(std::string sharedLibNameWithExt,
 // Return 0 on success, error code on failure.
 static int genJniJar(const mlir::OwningOpRef<ModuleOp> &module,
     std::string modelSharedLibPath, std::string modelJniJarPath) {
-  auto jniJarTiming = rootTimingScope.nest("[onnx-mlir] Creating JNI Jar");
+  std::string msg = "Creating JNI Jar";
+  showCompilePhase(msg);
+  auto jniJarTiming = rootTimingScope.nest("[onnx-mlir] " + msg);
   llvm::SmallString<8> libraryPath(getLibraryPath());
   llvm::sys::path::append(libraryPath, "javaruntime.jar");
   std::string javaRuntimeJarPath = llvm::StringRef(libraryPath).str();
@@ -893,8 +922,9 @@ static int emitOutput(mlir::OwningOpRef<ModuleOp> &module,
 int compileModule(mlir::OwningOpRef<ModuleOp> &module,
     mlir::MLIRContext &context, std::string outputNameNoExt,
     EmissionTargetType emissionTarget) {
-  auto compileModuleTiming =
-      rootTimingScope.nest("[onnx-mlir] Compiling Module using MLIR");
+  std::string msg = "Compiling and Optimizing MLIR Module";
+  showCompilePhase(msg);
+  auto compileModuleTiming = rootTimingScope.nest("[onnx-mlir] " + msg);
 
   int rc = setupModule(module, context, outputNameNoExt);
   if (rc != CompilerSuccess)

diff --git a/src/Compiler/CompilerUtils.hpp b/src/Compiler/CompilerUtils.hpp
@@ -31,6 +31,11 @@ extern mlir::TimingScope rootTimingScope;
 
 namespace onnx_mlir {
 
+// Values to report the current phase of compilation.
+// Increase TOTAL_COMPILE_PHASE when having more phases.
+extern uint64_t CURRENT_COMPILE_PHASE;
+extern uint64_t TOTAL_COMPILE_PHASE;
+
 struct Command {
 
   std::string _path;
@@ -47,6 +52,8 @@ struct Command {
   int exec(std::string wdir = "") const;
 };
 
+void showCompilePhase(std::string msg);
+
 // Registers and loads the mlir and onnx-mlir dialects needed to compile
 // end to end. Initializes accelerator(s) if required.
 void loadDialects(mlir::MLIRContext &context);

diff --git a/src/onnx-mlir.cpp b/src/onnx-mlir.cpp
@@ -74,8 +74,9 @@ int main(int argc, char *argv[]) {
   }
   loadDialects(context);
   setupTiming.stop();
-  auto inputFileTiming =
-      rootTimingScope.nest("[onnx-mlir] Importing Input Model to MLIR");
+  std::string msg = "Importing ONNX Model to MLIR Module";
+  showCompilePhase(msg);
+  auto inputFileTiming = rootTimingScope.nest("[onnx-mlir] " + msg);
   mlir::OwningOpRef<mlir::ModuleOp> module;
   std::string errorMessage;
   int rc = processInputFile(inputFilename, context, module, &errorMessage);

diff --git a/test/mlir/accelerators/nnpa/module_op_be/compiler-config.mlir b/test/mlir/accelerators/nnpa/module_op_be/compiler-config.mlir
@@ -12,5 +12,5 @@ module {
   "onnx.EntryPoint"() {func = @main_graph} : () -> ()
 }
 // CHECK: {{.*}} opt {{.*}} -o {{.*}}.bc
-// CHECK-NEXT: {{.*}} llc {{.*}}  {{.*}} {{.*}}.bc
-// CHECK-NEXT: {{.*}} {{clang|c|g}}++{{.*}} {{.*}}.o -o {{.*}}.so -shared -fPIC -L{{.*}}/lib -lRuntimeNNPA -lzdnn -lcruntime
+// CHECK: {{.*}} llc {{.*}}  {{.*}} {{.*}}.bc
+// CHECK: {{.*}} {{clang|c|g}}++{{.*}} {{.*}}.o -o {{.*}}.so -shared -fPIC -L{{.*}}/lib -lRuntimeNNPA -lzdnn -lcruntime
diff --git a/test/mlir/driver/check_passthrough_options.mlir b/test/mlir/driver/check_passthrough_options.mlir
@@ -7,7 +7,7 @@
 // LLC-NOT:   opt{{.*}} --data-sections -o {{.*}}check_passthrough_options{{.*}}.bc
 // LLC:       llc{{.*}} --data-sections {{.*}}
 // LLVM:      opt{{.*}} --data-sections -o {{.*}}check_passthrough_options{{.*}}.bc
-// LLVM-NEXT: llc{{.*}} --data-sections {{.*}}
+// LLVM:      llc{{.*}} --data-sections {{.*}}
 module {
   func.func @main_graph(%arg0: tensor<1x1xf32>, %arg1: tensor<1x1xf32>) -> tensor<1x1xf32> {
     %0 = "onnx.MatMul"(%arg0, %arg1) : (tensor<1x1xf32>, tensor<1x1xf32>) -> tensor<1x1xf32>

diff --git a/test/mlir/driver/compile_phases.mlir b/test/mlir/driver/compile_phases.mlir
@@ -0,0 +1,13 @@
+// RUN: onnx-mlir %s | FileCheck %s
+
+// CHECK: [1/5] {{.*}} Importing ONNX Model to MLIR Module
+// CHECK: [2/5] {{.*}} Compiling and Optimizing MLIR Module
+// CHECK: [3/5] {{.*}} Translating MLIR Module to LLVM and Generating LLVM Optimized Bitcode
+// CHECK: [4/5] {{.*}} Generating Object from LLVM Bitcode
+// CHECK: [5/5] {{.*}} Linking and Generating the Output Shared Library
+module {
+  func.func @main_graph(%arg0: tensor<?xf32>) -> tensor<?xf32> {
+    onnx.Return %arg0 : tensor<?xf32>
+  }
+  "onnx.EntryPoint"() {func = @main_graph} : () -> ()
+}
diff --git a/test/mlir/driver/unix/check_verbosity.mlir b/test/mlir/driver/unix/check_verbosity.mlir
@@ -2,8 +2,8 @@
 
 // REQUIRES: system-linux
 // CHECK:      opt {{.*}} -o {{.*}}check_verbosity{{.*}}.bc
-// CHECK-NEXT: llc {{.*}} -filetype=obj {{.*}} -o {{.*}}check_verbosity{{.*}}.o {{.*}}check_verbosity{{.*}}.bc
-// CHECK-NEXT: {{clang|c|g}}++{{.*}} {{.*}}check_verbosity{{.*}}.o -o {{.*}}check_verbosity{{.*}}.so -shared -fPIC -L{{.*}}/lib -lcruntime
+// CHECK:      llc {{.*}} -filetype=obj {{.*}} -o {{.*}}check_verbosity{{.*}}.o {{.*}}check_verbosity{{.*}}.bc
+// CHECK:      {{clang|c|g}}++{{.*}} {{.*}}check_verbosity{{.*}}.o -o {{.*}}check_verbosity{{.*}}.so -shared -fPIC -L{{.*}}/lib -lcruntime
 module {
   func.func @main_graph(%arg0: tensor<1x1xf32>, %arg1: tensor<1x1xf32>) -> tensor<1x1xf32> {
     %0 = "onnx.MatMul"(%arg0, %arg1) : (tensor<1x1xf32>, tensor<1x1xf32>) -> tensor<1x1xf32>