Support timer queries for phases.

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.

diff --git a/effect_chain.cpp b/effect_chain.cpp
index b00f214aa0f535e26570bca1f0df258814cc9858..d33cdaeb4a42e6aab680b62c684ccf8dbac2bf4e 100644 (file)
--- a/effect_chain.cpp
+++ b/effect_chain.cpp
@@ -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)

diff --git a/effect_chain.h b/effect_chain.h
index 358deedbb5e34064e4d2c52119db4c4c30413dca..b87fce7e5bf651d811bd424d6386ec848c764a7a 100644 (file)
--- a/effect_chain.h
+++ b/effect_chain.h
@@ -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

diff --git a/init.cpp b/init.cpp
index a7bd1e3ea5d4e247722c04f3d1a6d1aabd2b33a4..f9e7f1580a91e44be43aaef306e0b10823a4f468 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 628915d6a68882722847d0beb0c60e7ad80b024d..3ecc29b6270242c4fb43390c75bc15de3fd646c5 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 {