title: Android GLSurfaceView, GL20 - ~15 ms lost in Renderer.onDrawFrame
body: <p>I've found out something interesting on Android Gl20 which I've been able to reproduce in the "Hello Gl20" Android Studio sample and I would love to hear any opinions on that matter.</p>
  
  <p>In a nutshell, on S5(and other devices) there's ~15ms wasted by the first use of gl* function (I would say gl context but I just want to show the facts and not my interpretation).</p>
  
  <p>The way I got this ms troll to show its face, is: In the GLSufaceView Renderer.onDraw (on GLThread), I call the native func GL2JNILib.step (that draws a simple triangle) 2 times and each call has a different id (int). For the first call the id is 0 and for the second one the id is 1.
  In the native function, I've setup a simple time measurement based on CLOCK_MONOTONIC.
  First call (call with id 0) takes 16ms and the second call takes(call with id 1) takes 0ms. And this thing repeats next frame somehow the same and so on.</p>
  
  <p>Furthermore, in the native function GL2JNILib.step, I've group instructions together in blocks and measure those blocks individually (without changing the execution order) and it turns out that those ~15 ms that are wasted, are wasted in the clear block.</p>
  
  <p>Here are some snippets of the modification:</p>
  
  <p>GL2JNIView.java</p>
  
  <pre><code>....
  
      private static class Renderer implements GLSurfaceView.Renderer {
          public void onDrawFrame(GL10 gl) {
              GL2JNILib.step(0);
              GL2JNILib.step(1);
          }
  
  ...
  </code></pre>
  
  <p>ATime.h (a simple timer - header)</p>
  
  <pre><code>#ifndef TIME_H__
  #define TIME_H__
  
  #include "ATypes.h"
  
  namespace ATime {
      void init ();
  
      u64             ms ();
      f64             s();
      void            waste (u64 const wasteMs);
  
  };
  </code></pre>
  
  <p>ATime.cpp (a simple timer - implementation)</p>
  
  <pre><code>#include "ATime.h"
  #include &lt;time.h&gt;
  
  #define CLOCK CLOCK_MONOTONIC
  
  namespace ATime {
      long mStartSec = 0;
  
      void init() {
          struct timespec res;
          clock_gettime(CLOCK, &amp;res);
          mStartSec = res.tv_sec;
      }
  
      u64 ms() {
          struct timespec res;
          clock_gettime(CLOCK, &amp;res);
          u64 ms = static_cast&lt;u64&gt;(res.tv_sec - mStartSec) * 1000 + res.tv_nsec / 1000000;
          return ms;
      }
  
      f64 s() {
          struct timespec res;
          clock_gettime(CLOCK, &amp;res);
          f64 ms = 1000.0 * (res.tv_sec - mStartSec) + (f64) res.tv_nsec / 1000000.0;
          return ms / 1000.0;
      }
  
      void waste(u64 const wasteMs) {
          f64 t = s();
          f64 e = t + static_cast&lt;f64&gt;(wasteMs) / 1000.0f;
          while (t &lt; e){
              t = s ();
          }
      }
  }
  </code></pre>
  
  <p>and in gl_code.cpp, I've modified the renderFrame() function to receive the id(int) and now, it looks something like this</p>
  
  <pre><code>...
  class MeasureBlock {
  public:
      MeasureBlock (i32 id, char const *const tag) : mId(id), mName (tag){
          mStart = ATime::ms();
      }
      ~MeasureBlock(){
          auto duration = ATime::ms() - mStart;
          LOGI ("%s - %d duration %d", mName, mId, static_cast&lt;u32&gt;(duration));
      }
  protected:
      u64 mStart;
      char const * const mName;
      i32 mId;
  };
  
  void renderFrame(i32 id) {
      MeasureBlock total (id, "total");
  
      static float grey;
      grey += 0.01f;
      if (grey &gt; 1.0f) {
          grey = 0.0f;
      }
  
      {
          MeasureBlock clear (id, "clear");
  
          glClearColor(grey, grey, grey, 1.0f);
          checkGlError("glClearColor");
          glClear( GL_DEPTH_BUFFER_BIT | GL_COLOR_BUFFER_BIT);
          checkGlError("glClear");
      }
  
      {
          MeasureBlock actualDraw(id, "actualDraw");
  
          glUseProgram(gProgram);
          checkGlError("glUseProgram");
  
          glVertexAttribPointer(gvPositionHandle, 2, GL_FLOAT, GL_FALSE, 0, gTriangleVertices);
          checkGlError("glVertexAttribPointer");
          glEnableVertexAttribArray(gvPositionHandle);
          checkGlError("glEnableVertexAttribArray");
          glDrawArrays(GL_TRIANGLES, 0, 3);
          checkGlError("glDrawArrays");
      }
  }
  ...
  </code></pre>
  
  <p>Here's the outcome of this magic afair:</p>
  
  <pre><code>...
  clear - 0 duration 15
  actualDraw - 0 duration 0
  total - 0 duration 15
  clear - 1 duration 0
  actualDraw - 1 duration 0
  total - 1 duration 0
  ...
  </code></pre>
  
  <p>It's worth mentioning that the clear - 0 duration, goes funky like: 13, 16, 15..15, 18 and so on:)</p>
  
  <p>To me it looks like the gl context is locked in another thread and the GLThred has to wait until the gl context is released. This so called "theory" seems to be confirmed by timing based on CLOCK_THREAD_CPUTIME_ID and having no ms troll showing it's face in the GLThread (if measured without the idle or sleep time - unlike in the real world). I mean all the measurements are as expected 0ms. 
  I can't wrap my head around how to get rid of this ms troll, because what's left is not much.</p>
  
  <p>Funny thing there's nothing else on the screen, activity is full screen, and 16 ms seems a lot of time for all that nothing.</p>
  
  <p>Does anyone has any ideas how to get rid of those wasted ms, to kick the ms troll out sort of speak, or can bring any type and/or form of light to the issue?</p>
  
  <p>With great anticipation and appreciation,</p>
  
  <p>Jean-Arthur Deda.</p>