Support timer queries for phases.
authorSteinar H. Gunderson <sgunderson@bigfoot.com>
Mon, 31 Aug 2015 17:11:00 +0000 (19:11 +0200)
committerSteinar H. Gunderson <sgunderson@bigfoot.com>
Mon, 31 Aug 2015 17:12:19 +0000 (19:12 +0200)
This is useful for debugging slow chains; it can give information
about which phase takes the most time. Right now there seems to be
~5 ms in one of my test chains that disappear into nothing
(ie. show up in the fps counter with vsync off, but not in any
phase), but hopefully we can eventually solve that discrepancy.

Note that this is an ABI break.

effect_chain.cpp
effect_chain.h
init.cpp
init.h

index b00f214..d33cdae 100644 (file)
@@ -36,7 +36,8 @@ EffectChain::EffectChain(float aspect_nom, float aspect_denom, ResourcePool *res
          dither_effect(NULL),
          num_dither_bits(0),
          finalized(false),
-         resource_pool(resource_pool) {
+         resource_pool(resource_pool),
+         do_phase_timing(false) {
        if (resource_pool == NULL) {
                this->resource_pool = new ResourcePool();
                owns_resource_pool = true;
@@ -421,6 +422,13 @@ Phase *EffectChain::construct_phase(Node *output, map<Node *, Phase *> *complete
        // Actually make the shader for this phase.
        compile_glsl_program(phase);
 
+       // Initialize timer objects.
+       if (movit_timer_queries_supported) {
+               glGenQueries(1, &phase->timer_query_object);
+               phase->time_elapsed_ns = 0;
+               phase->num_measured_iterations = 0;
+       }
+
        assert(completed_effects->count(output) == 0);
        completed_effects->insert(make_pair(output, phase));
        phases.push_back(phase);
@@ -1448,6 +1456,9 @@ void EffectChain::render_to_fbo(GLuint dest_fbo, unsigned width, unsigned height
        for (unsigned phase_num = 0; phase_num < phases.size(); ++phase_num) {
                Phase *phase = phases[phase_num];
 
+               if (do_phase_timing) {
+                       glBeginQuery(GL_TIME_ELAPSED, phase->timer_query_object);
+               }
                if (phase_num == phases.size() - 1) {
                        // Last phase goes to the output the user specified.
                        glBindFramebuffer(GL_FRAMEBUFFER, dest_fbo);
@@ -1461,6 +1472,9 @@ void EffectChain::render_to_fbo(GLuint dest_fbo, unsigned width, unsigned height
                        }
                }
                execute_phase(phase, phase_num == phases.size() - 1, &output_textures, &generated_mipmaps);
+               if (do_phase_timing) {
+                       glEndQuery(GL_TIME_ELAPSED);
+               }
        }
 
        for (map<Phase *, GLuint>::const_iterator texture_it = output_textures.begin();
@@ -1473,6 +1487,57 @@ void EffectChain::render_to_fbo(GLuint dest_fbo, unsigned width, unsigned height
        check_error();
        glUseProgram(0);
        check_error();
+
+       if (do_phase_timing) {
+               // Get back the timer queries.
+               for (unsigned phase_num = 0; phase_num < phases.size(); ++phase_num) {
+                       Phase *phase = phases[phase_num];
+                       GLint available = 0;
+                       while (!available) {
+                               glGetQueryObjectiv(phase->timer_query_object, GL_QUERY_RESULT_AVAILABLE, &available);
+                       }
+                       GLuint64 time_elapsed;
+                       glGetQueryObjectui64v(phase->timer_query_object, GL_QUERY_RESULT, &time_elapsed);
+                       phase->time_elapsed_ns += time_elapsed;
+                       ++phase->num_measured_iterations;
+               }
+       }
+}
+
+void EffectChain::enable_phase_timing(bool enable)
+{
+       if (enable) {
+               assert(movit_timer_queries_supported);
+       }
+       this->do_phase_timing = enable;
+}
+
+void EffectChain::reset_phase_timing()
+{
+       for (unsigned phase_num = 0; phase_num < phases.size(); ++phase_num) {
+               Phase *phase = phases[phase_num];
+               phase->time_elapsed_ns = 0;
+               phase->num_measured_iterations = 0;
+       }
+}
+
+void EffectChain::print_phase_timing()
+{
+       double total_time_ms = 0.0;
+       for (unsigned phase_num = 0; phase_num < phases.size(); ++phase_num) {
+               Phase *phase = phases[phase_num];
+               double avg_time_ms = phase->time_elapsed_ns * 1e-6 / phase->num_measured_iterations;
+               printf("Phase %d: %5.1f ms  [", phase_num, avg_time_ms);
+               for (unsigned effect_num = 0; effect_num < phase->effects.size(); ++effect_num) {
+                       if (effect_num != 0) {
+                               printf(", ");
+                       }
+                       printf("%s", phase->effects[effect_num]->effect->effect_type_id().c_str());
+               }
+               printf("]\n");
+               total_time_ms += avg_time_ms;
+       }
+       printf("Total:   %5.1f ms\n", total_time_ms);
 }
 
 void EffectChain::execute_phase(Phase *phase, bool last_phase, map<Phase *, GLuint> *output_textures, set<Phase *> *generated_mipmaps)
index 358deed..b87fce7 100644 (file)
@@ -104,6 +104,11 @@ struct Phase {
        // Identifier used to create unique variables in GLSL.
        // Unique per-phase to increase cacheability of compiled shaders.
        std::map<Node *, std::string> effect_ids;
+
+       // For measurement of GPU time used.
+       GLuint timer_query_object;
+       uint64_t time_elapsed_ns;
+       uint64_t num_measured_iterations;
 };
 
 class EffectChain {
@@ -161,6 +166,14 @@ public:
 
        void finalize();
 
+       // Measure the GPU time used for each actual phase during rendering.
+       // Note that this is only available if GL_ARB_timer_query
+       // (or, equivalently, OpenGL 3.3) is available. Also note that measurement
+       // will incur a performance cost, as we wait for the measurements to
+       // complete at the end of rendering.
+       void enable_phase_timing(bool enable);
+       void reset_phase_timing();
+       void print_phase_timing();
 
        //void render(unsigned char *src, unsigned char *dst);
        void render_to_screen()
@@ -300,6 +313,8 @@ private:
 
        ResourcePool *resource_pool;
        bool owns_resource_pool;
+
+       bool do_phase_timing;
 };
 
 }  // namespace movit
index a7bd1e3..f9e7f15 100644 (file)
--- a/init.cpp
+++ b/init.cpp
@@ -16,6 +16,7 @@ bool movit_initialized = false;
 MovitDebugLevel movit_debug_level = MOVIT_DEBUG_ON;
 float movit_texel_subpixel_precision;
 bool movit_srgb_textures_supported;
+bool movit_timer_queries_supported;
 int movit_num_wrongly_rounded;
 bool movit_shader_rounding_supported;
 MovitShaderModel movit_shader_model;
@@ -355,6 +356,12 @@ bool check_extensions()
        movit_shader_rounding_supported =
                (epoxy_gl_version() >= 30 || epoxy_has_gl_extension("GL_EXT_gpu_shader4"));
 
+       // The user can specify that they want a timing report for each
+       // phase in an effect chain. However, that depends on this extension;
+       // without it, we do cannot even create the query objects.
+       movit_timer_queries_supported =
+               (epoxy_gl_version() >= 33 || epoxy_has_gl_extension("GL_ARB_timer_query"));
+
        return true;
 }
 
diff --git a/init.h b/init.h
index 628915d..3ecc29b 100644 (file)
--- a/init.h
+++ b/init.h
@@ -67,6 +67,9 @@ extern bool movit_shader_rounding_supported;
 // Whether the GPU in use supports GL_EXT_texture_sRGB.
 extern bool movit_srgb_textures_supported;
 
+// Whether the OpenGL driver (or GPU) in use supports GL_ARB_timer_query.
+extern bool movit_timer_queries_supported;
+
 // What shader model we are compiling for. This only affects the choice
 // of a few files (like header.frag); most of the shaders are the same.
 enum MovitShaderModel {