[Mesa-dev] [PATCH 2/2] gallivm: print out how long it takes to optimize shader IR.

[sroland at vmware.com]

From: Roland Scheidegger <sroland at vmware.com>

Enabled with GALLIVM_DEBUG=perf (which up to now was only used to print
warnings for unoptimized code).

While some unexpectedly long shader compile times for some shaders were fixed
with 8a9f5ecdb116d0449d63f7b94efbfa8b205d826f this should help recognize such
problems in the future. For now though only available in debug builds (which
are not always suitable for such analysis). And since this uses system time,
it might not be all that accurate (even llvmpipe's own rasterization threads
might be running at the same time, or just other tasks).
(llvmpipe also has LP_DEBUG=counters but this only gives an average per shader
and the the total time for all shaders.)
This prints information like this:
optimizing module fs17_variant0 took 1 msec
optimizing module setup_variant_0 took 0 msec
optimizing module draw_llvm_vs_variant0 took 9 msec
optimizing module draw_llvm_vs_variant0 took 12 msec
optimizing module fs17_variant1 took 2 msec

v2: rebase for recent gallivm compilation changes, and print time for whole
modules instead of functions (otherwise it would be very spammy since it would
include all trivial inline sse2 functions), using the shiny new module names,
prying them off LLVM using new helper (not available through C bindings).
Per function timings, while possibly giving more information (if there'd be
a problem only in for instance the partial not the whole function), don't seem
all that useful for now.
---
 src/gallium/auxiliary/gallivm/lp_bld_debug.cpp |  9 +++++++++
 src/gallium/auxiliary/gallivm/lp_bld_debug.h   |  4 ++++
 src/gallium/auxiliary/gallivm/lp_bld_init.c    | 19 ++++++++++++++++++-
 3 files changed, 31 insertions(+), 1 deletion(-)

diff --git a/src/gallium/auxiliary/gallivm/lp_bld_debug.cpp b/src/gallium/auxiliary/gallivm/lp_bld_debug.cpp
index 5d6d45d..621290f 100644
--- a/src/gallium/auxiliary/gallivm/lp_bld_debug.cpp
+++ b/src/gallium/auxiliary/gallivm/lp_bld_debug.cpp
@@ -39,6 +39,8 @@
 
 #include <llvm/Support/Host.h>
 
+#include <llvm/IR/Module.h>
+
 #include <llvm/MC/MCDisassembler.h>
 #include <llvm/MC/MCAsmInfo.h>
 #include <llvm/MC/MCInst.h>
@@ -111,6 +113,13 @@ raw_debug_ostream::write_impl(const char *Ptr, size_t Size)
 }
 
 
+extern "C" const char *
+lp_get_module_id(LLVMModuleRef module)
+{
+   return llvm::unwrap(module)->getModuleIdentifier().c_str();
+}
+
+
 /**
  * Same as LLVMDumpValue, but through our debugging channels.
  */
diff --git a/src/gallium/auxiliary/gallivm/lp_bld_debug.h b/src/gallium/auxiliary/gallivm/lp_bld_debug.h
index 76c39af..321e09d 100644
--- a/src/gallium/auxiliary/gallivm/lp_bld_debug.h
+++ b/src/gallium/auxiliary/gallivm/lp_bld_debug.h
@@ -76,6 +76,10 @@ lp_build_name(LLVMValueRef val, const char *format, ...)
 }
 
 
+const char *
+lp_get_module_id(LLVMModuleRef module);
+
+
 void
 lp_debug_dump_value(LLVMValueRef value);
 
diff --git a/src/gallium/auxiliary/gallivm/lp_bld_init.c b/src/gallium/auxiliary/gallivm/lp_bld_init.c
index 7aebebb..8b8686d 100644
--- a/src/gallium/auxiliary/gallivm/lp_bld_init.c
+++ b/src/gallium/auxiliary/gallivm/lp_bld_init.c
@@ -32,6 +32,7 @@
 #include "util/u_debug.h"
 #include "util/u_memory.h"
 #include "util/u_simple_list.h"
+#include "os/os_time.h"
 #include "lp_bld.h"
 #include "lp_bld_debug.h"
 #include "lp_bld_misc.h"
@@ -498,6 +499,7 @@ gallivm_destroy(struct gallivm_state *gallivm)
 
 /**
  * Validate a function.
+ * Verification is only done with debug builds.
  */
 void
 gallivm_verify_function(struct gallivm_state *gallivm,
@@ -520,10 +522,15 @@ gallivm_verify_function(struct gallivm_state *gallivm,
 }
 
 
+/**
+ * Compile a module.
+ * This does IR optimization on all functions in the module.
+ */
 void
 gallivm_compile_module(struct gallivm_state *gallivm)
 {
    LLVMValueRef func;
+   int64_t time_begin;
 
    assert(!gallivm->compiled);
 
@@ -532,18 +539,28 @@ gallivm_compile_module(struct gallivm_state *gallivm)
       gallivm->builder = NULL;
    }
 
+   if (gallivm_debug & GALLIVM_DEBUG_PERF)
+      time_begin = os_time_get();
+
    /* Run optimization passes */
    LLVMInitializeFunctionPassManager(gallivm->passmgr);
    func = LLVMGetFirstFunction(gallivm->module);
    while (func) {
       if (0) {
-	 debug_printf("optimizing %s...\n", LLVMGetValueName(func));
+         debug_printf("optimizing func %s...\n", LLVMGetValueName(func));
       }
       LLVMRunFunctionPassManager(gallivm->passmgr, func);
       func = LLVMGetNextFunction(func);
    }
    LLVMFinalizeFunctionPassManager(gallivm->passmgr);
 
+   if (gallivm_debug & GALLIVM_DEBUG_PERF) {
+      int64_t time_end = os_time_get();
+      int time_msec = (int)(time_end - time_begin) / 1000;
+      debug_printf("optimizing module %s took %d msec\n",
+                   lp_get_module_id(gallivm->module), time_msec);
+   }
+
    /* Dump byte code to a file */
    if (0) {
       LLVMWriteBitcodeToFile(gallivm->module, "llvmpipe.bc");
-- 
1.9.1