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

[Jose Fonseca]

Series looks good to me.

Jose

----- Original Message -----
> 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
>