Merge "Print gl relative functions runtime as nanosecond + Allow to print always" into devel/master

3 files changed, 95 insertions, 134 deletions

diff --git a/dali/internal/graphics/gles/egl-implementation.cpp b/dali/internal/graphics/gles/egl-implementation.cpp
index b53f1db7f..b47898cbe 100644
--- a/dali/internal/graphics/gles/egl-implementation.cpp
+++ b/dali/internal/graphics/gles/egl-implementation.cpp
@@ -22,6 +22,7 @@
 #include <dali/integration-api/debug.h>
 #include <dali/integration-api/trace.h>
 #include <dali/public-api/common/dali-vector.h>
+#include <limits>
 #include <sstream>
 
 // INTERNAL INCLUDES
@@ -57,9 +58,28 @@ DALI_INIT_TRACE_FILTER(gTraceFilter, DALI_TRACE_EGL, true);
 static uint32_t GetPerformanceLogThresholdTime()
 {
   auto     timeString = Dali::EnvironmentVariable::GetEnvironmentVariable(PERFORMANCE_LOG_THRESHOLD_TIME_ENV);
-  uint32_t time       = timeString ? static_cast<uint32_t>(std::atoi(timeString)) : 0u;
+  uint32_t time       = timeString ? static_cast<uint32_t>(std::atoi(timeString)) : std::numeric_limits<uint32_t>::max();
   return time;
 }
+
+#define START_DURATION_CHECK()                         \
+  uint64_t startTimeNanoSeconds = 0ull;                \
+  uint64_t endTimeNanoSeconds   = 0ull;                \
+  if(mLogEnabled)                                      \
+  {                                                    \
+    TimeService::GetNanoseconds(startTimeNanoSeconds); \
+  }
+
+#define FINISH_DURATION_CHECK(functionName)                                                                                                                \
+  if(mLogEnabled)                                                                                                                                          \
+  {                                                                                                                                                        \
+    TimeService::GetNanoseconds(endTimeNanoSeconds);                                                                                                       \
+    if(static_cast<uint32_t>((endTimeNanoSeconds - startTimeNanoSeconds) / 1000000ull) >= mLogThreshold)                                                   \
+    {                                                                                                                                                      \
+      DALI_LOG_RELEASE_INFO("%s takes long time! [%.6lf ms]\n", functionName, static_cast<double>(endTimeNanoSeconds - startTimeNanoSeconds) / 1000000.0); \
+    }                                                                                                                                                      \
+  }
+
 } // namespace
 
 namespace Dali
@@ -196,7 +216,7 @@ bool EglImplementation::InitializeGles(EGLNativeDisplayType display, bool isOwnS
   }
 
   mLogThreshold = GetPerformanceLogThresholdTime();
-  mLogEnabled   = mLogThreshold > 0 ? true : false;
+  mLogEnabled   = mLogThreshold < std::numeric_limits<uint32_t>::max() ? true : false;
 
   mGlesInitialized = true;
 
@@ -402,11 +422,7 @@ void EglImplementation::SwapBuffers(EGLSurface& eglSurface)
 {
   if(eglSurface != EGL_NO_SURFACE) // skip if using surfaceless context
   {
-    uint32_t startTime = 0, endTime = 0;
-    if(mLogEnabled)
-    {
-      startTime = TimeService::GetMilliSeconds();
-    }
+    START_DURATION_CHECK();
 
 #ifndef DALI_PROFILE_UBUNTU
     if(mSwapBufferCountAfterResume < THRESHOLD_SWAPBUFFER_COUNT)
@@ -428,24 +444,13 @@ void EglImplementation::SwapBuffers(EGLSurface& eglSurface)
     }
 #endif //DALI_PROFILE_UBUNTU
 
-    if(mLogEnabled)
-    {
-      endTime = TimeService::GetMilliSeconds();
-      if(endTime - startTime > mLogThreshold)
-      {
-        DALI_LOG_RELEASE_INFO("eglSwapBuffers takes long time! [%u ms]\n", endTime - startTime);
-      }
-    }
+    FINISH_DURATION_CHECK("eglSwapBuffers");
   }
 }
 
 EGLint EglImplementation::GetBufferAge(EGLSurface& eglSurface) const
 {
-  uint32_t startTime = 0, endTime = 0;
-  if(mLogEnabled)
-  {
-    startTime = TimeService::GetMilliSeconds();
-  }
+  START_DURATION_CHECK();
 
   EGLint age = 0;
   eglQuerySurface(mEglDisplay, eglSurface, EGL_BUFFER_AGE_EXT, &age);
@@ -455,14 +460,8 @@ EGLint EglImplementation::GetBufferAge(EGLSurface& eglSurface) const
     age = 0;
   }
 
-  if(mLogEnabled)
-  {
-    endTime = TimeService::GetMilliSeconds();
-    if(endTime - startTime > mLogThreshold)
-    {
-      DALI_LOG_RELEASE_INFO("eglQuerySurface takes long time! [%u ms]\n", endTime - startTime);
-    }
-  }
+  FINISH_DURATION_CHECK("eglQuerySurface");
+
   return age;
 }
 
@@ -493,11 +492,7 @@ void EglImplementation::SwapBuffers(EGLSurface& eglSurface, const std::vector<Re
       return;
     }
 
-    uint32_t startTime = 0, endTime = 0;
-    if(mLogEnabled)
-    {
-      startTime = TimeService::GetMilliSeconds();
-    }
+    START_DURATION_CHECK();
 
 #ifndef DALI_PROFILE_UBUNTU
     if(mSwapBufferCountAfterResume < THRESHOLD_SWAPBUFFER_COUNT)
@@ -522,14 +517,7 @@ void EglImplementation::SwapBuffers(EGLSurface& eglSurface, const std::vector<Re
     }
 #endif //DALI_PROFILE_UBUNTU
 
-    if(mLogEnabled)
-    {
-      endTime = TimeService::GetMilliSeconds();
-      if(endTime - startTime > mLogThreshold)
-      {
-        DALI_LOG_RELEASE_INFO("eglSwapBuffersWithDamageKHR takes long time! [%u ms]\n", endTime - startTime);
-      }
-    }
+    FINISH_DURATION_CHECK("eglSwapBuffersWithDamageKHR");
   }
 }
 
diff --git a/dali/internal/graphics/gles/gl-implementation.cpp b/dali/internal/graphics/gles/gl-implementation.cpp
index dcee7a034..ac4521433 100644
--- a/dali/internal/graphics/gles/gl-implementation.cpp
+++ b/dali/internal/graphics/gles/gl-implementation.cpp
@@ -18,6 +18,9 @@
 // CLASS HEADER
 #include <dali/internal/graphics/gles/gl-implementation.h>
 
+// EXTERNAL INCLUDES
+#include <limits>
+
 namespace Dali
 {
 namespace Internal
@@ -57,7 +60,7 @@ constexpr auto PERFORMANCE_LOG_THRESHOLD_TIME_ENV = "DALI_EGL_PERFORMANCE_LOG_TH
 static uint32_t GetPerformanceLogThresholdTime()
 {
   auto     timeString = Dali::EnvironmentVariable::GetEnvironmentVariable(PERFORMANCE_LOG_THRESHOLD_TIME_ENV);
-  uint32_t time       = timeString ? static_cast<uint32_t>(std::atoi(timeString)) : 0u;
+  uint32_t time       = timeString ? static_cast<uint32_t>(std::atoi(timeString)) : std::numeric_limits<uint32_t>::max();
   return time;
 }
 } // namespace
@@ -141,7 +144,7 @@ void GlImplementation::ContextCreated()
   }
 
   mLogThreshold = GetPerformanceLogThresholdTime();
-  mLogEnabled   = mLogThreshold > 0 ? true : false;
+  mLogEnabled   = mLogThreshold < std::numeric_limits<uint32_t>::max() ? true : false;
 
   {
     ConditionalWait::ScopedLock lock(mContextCreatedWaitCondition);
diff --git a/dali/internal/graphics/gles/gl-implementation.h b/dali/internal/graphics/gles/gl-implementation.h
index 3969bc789..45ecce4ae 100644
--- a/dali/internal/graphics/gles/gl-implementation.h
+++ b/dali/internal/graphics/gles/gl-implementation.h
@@ -43,6 +43,42 @@ namespace Internal
 {
 namespace Adaptor
 {
+namespace
+{
+#ifndef START_DURATION_CHECK
+#define START_DURATION_CHECK()                         \
+  uint64_t startTimeNanoSeconds = 0ull;                \
+  uint64_t endTimeNanoSeconds   = 0ull;                \
+  if(mLogEnabled)                                      \
+  {                                                    \
+    TimeService::GetNanoseconds(startTimeNanoSeconds); \
+  }
+#endif
+
+#ifndef FINISH_DURATION_CHECK
+#define FINISH_DURATION_CHECK(functionName)                                                                                                                \
+  if(mLogEnabled)                                                                                                                                          \
+  {                                                                                                                                                        \
+    TimeService::GetNanoseconds(endTimeNanoSeconds);                                                                                                       \
+    if(static_cast<uint32_t>((endTimeNanoSeconds - startTimeNanoSeconds) / 1000000ull) >= mLogThreshold)                                                   \
+    {                                                                                                                                                      \
+      DALI_LOG_RELEASE_INFO("%s takes long time! [%.6lf ms]\n", functionName, static_cast<double>(endTimeNanoSeconds - startTimeNanoSeconds) / 1000000.0); \
+    }                                                                                                                                                      \
+  }
+#endif
+
+#ifndef FINISH_DURATION_CHECK_WITH_FORMAT
+#define FINISH_DURATION_CHECK_WITH_FORMAT(functionName, format, args...)                                                                                                    \
+  if(mLogEnabled)                                                                                                                                                           \
+  {                                                                                                                                                                         \
+    TimeService::GetNanoseconds(endTimeNanoSeconds);                                                                                                                        \
+    if(static_cast<uint32_t>((endTimeNanoSeconds - startTimeNanoSeconds) / 1000000ull) >= mLogThreshold)                                                                    \
+    {                                                                                                                                                                       \
+      DALI_LOG_RELEASE_INFO("%s takes long time! [%.6lf ms] " format "\n", functionName, static_cast<double>(endTimeNanoSeconds - startTimeNanoSeconds) / 1000000.0, args); \
+    }                                                                                                                                                                       \
+  }
+#endif
+} // namespace
 /**
  * GlImplementation is a concrete implementation for GlAbstraction.
  * The class provides an OpenGL-ES 2.0 or 3.0 implementation.
@@ -359,22 +395,11 @@ public:
 
   void Clear(GLbitfield mask) override
   {
-    uint32_t startTime = 0, endTime = 0;
-    if(mLogEnabled)
-    {
-      startTime = TimeService::GetMilliSeconds();
-    }
+    START_DURATION_CHECK();
 
     glClear(mask);
 
-    if(mLogEnabled)
-    {
-      endTime = TimeService::GetMilliSeconds();
-      if(endTime - startTime > mLogThreshold)
-      {
-        DALI_LOG_RELEASE_INFO("glClear takes long time! [%u ms]\n", endTime - startTime);
-      }
-    }
+    FINISH_DURATION_CHECK("glClear");
   }
 
   void ClearColor(GLclampf red, GLclampf green, GLclampf blue, GLclampf alpha) override
@@ -399,62 +424,29 @@ public:
 
   void CompileShader(GLuint shader) override
   {
-    uint32_t startTime = 0, endTime = 0;
-    if(mLogEnabled)
-    {
-      startTime = TimeService::GetMilliSeconds();
-    }
+    START_DURATION_CHECK();
 
     glCompileShader(shader);
 
-    if(mLogEnabled)
-    {
-      endTime = TimeService::GetMilliSeconds();
-      if(endTime - startTime > mLogThreshold)
-      {
-        DALI_LOG_RELEASE_INFO("glCompileShader takes long time! [%u ms] shader id : %u\n", endTime - startTime, shader);
-      }
-    }
+    FINISH_DURATION_CHECK_WITH_FORMAT("glCompileShader", "shader id : %u", shader);
   }
 
   void CompressedTexImage2D(GLenum target, GLint level, GLenum internalformat, GLsizei width, GLsizei height, GLint border, GLsizei imageSize, const void* data) override
   {
-    uint32_t startTime = 0, endTime = 0;
-    if(mLogEnabled)
-    {
-      startTime = TimeService::GetMilliSeconds();
-    }
+    START_DURATION_CHECK();
 
     glCompressedTexImage2D(target, level, internalformat, width, height, border, imageSize, data);
 
-    if(mLogEnabled)
-    {
-      endTime = TimeService::GetMilliSeconds();
-      if(endTime - startTime > mLogThreshold)
-      {
-        DALI_LOG_RELEASE_INFO("glCompressedTexImage2D takes long time! [%u ms] size : %u x %u\n", endTime - startTime, width, height);
-      }
-    }
+    FINISH_DURATION_CHECK_WITH_FORMAT("glCompressedTexImage2D", "size : %u x %u", width, height);
   }
 
   void CompressedTexSubImage2D(GLenum target, GLint level, GLint xoffset, GLint yoffset, GLsizei width, GLsizei height, GLenum format, GLsizei imageSize, const void* data) override
   {
-    uint32_t startTime = 0, endTime = 0;
-    if(mLogEnabled)
-    {
-      startTime = TimeService::GetMilliSeconds();
-    }
+    START_DURATION_CHECK();
 
     glCompressedTexSubImage2D(target, level, xoffset, yoffset, width, height, format, imageSize, data);
 
-    if(mLogEnabled)
-    {
-      endTime = TimeService::GetMilliSeconds();
-      if(endTime - startTime > mLogThreshold)
-      {
-        DALI_LOG_RELEASE_INFO("glCompressedTexSubImage2D takes long time! [%u ms] size : %u x %u\n", endTime - startTime, width, height);
-      }
-    }
+    FINISH_DURATION_CHECK_WITH_FORMAT("glCompressedTexSubImage2D", "size : %u x %u", width, height);
   }
 
   void CopyTexImage2D(GLenum target, GLint level, GLenum internalformat, GLint x, GLint y, GLsizei width, GLsizei height, GLint border) override
@@ -789,22 +781,11 @@ public:
 
   void LinkProgram(GLuint program) override
   {
-    uint32_t startTime = 0, endTime = 0;
-    if(mLogEnabled)
-    {
-      startTime = TimeService::GetMilliSeconds();
-    }
+    START_DURATION_CHECK();
 
     glLinkProgram(program);
 
-    if(mLogEnabled)
-    {
-      endTime = TimeService::GetMilliSeconds();
-      if(endTime - startTime > mLogThreshold)
-      {
-        DALI_LOG_RELEASE_INFO("glLinkProgram takes long time! [%u ms] program id : %u\n", endTime - startTime, program);
-      }
-    }
+    FINISH_DURATION_CHECK_WITH_FORMAT("glLinkProgram", "program id : %u", program);
   }
 
   void PixelStorei(GLenum pname, GLint param) override
@@ -884,22 +865,11 @@ public:
 
   void TexImage2D(GLenum target, GLint level, GLint internalformat, GLsizei width, GLsizei height, GLint border, GLenum format, GLenum type, const void* pixels) override
   {
-    uint32_t startTime = 0, endTime = 0;
-    if(mLogEnabled)
-    {
-      startTime = TimeService::GetMilliSeconds();
-    }
+    START_DURATION_CHECK();
 
     glTexImage2D(target, level, internalformat, width, height, border, format, type, pixels);
 
-    if(mLogEnabled)
-    {
-      endTime = TimeService::GetMilliSeconds();
-      if(endTime - startTime > mLogThreshold)
-      {
-        DALI_LOG_RELEASE_INFO("glTexImage2D takes long time! [%u ms] size : %u x %u\n", endTime - startTime, width, height);
-      }
-    }
+    FINISH_DURATION_CHECK_WITH_FORMAT("glTexImage2D", "size : %u x %u", width, height);
   }
 
   void TexParameterf(GLenum target, GLenum pname, GLfloat param) override
@@ -924,22 +894,11 @@ public:
 
   void TexSubImage2D(GLenum target, GLint level, GLint xoffset, GLint yoffset, GLsizei width, GLsizei height, GLenum format, GLenum type, const void* pixels) override
   {
-    uint32_t startTime = 0, endTime = 0;
-    if(mLogEnabled)
-    {
-      startTime = TimeService::GetMilliSeconds();
-    }
+    START_DURATION_CHECK();
 
     glTexSubImage2D(target, level, xoffset, yoffset, width, height, format, type, pixels);
 
-    if(mLogEnabled)
-    {
-      endTime = TimeService::GetMilliSeconds();
-      if(endTime - startTime > mLogThreshold)
-      {
-        DALI_LOG_RELEASE_INFO("glTexSubImage2D takes long time! [%u ms] size : %u x %u\n", endTime - startTime, width, height);
-      }
-    }
+    FINISH_DURATION_CHECK_WITH_FORMAT("glTexSubImage2D", "size : %u x %u", width, height);
   }
 
   void Uniform1f(GLint location, GLfloat x) override
@@ -1652,6 +1611,17 @@ private:
   bool            mIsContextCreated;
   bool            mLogEnabled{false};
 };
+#ifdef START_DURATION_CHECK
+#undef START_DURATION_CHECK
+#endif
+
+#ifdef FINISH_DURATION_CHECK
+#undef FINISH_DURATION_CHECK
+#endif
+
+#ifdef FINISH_DURATION_CHECK_WITH_FORMAT
+#undef FINISH_DURATION_CHECK_WITH_FORMAT
+#endif
 
 } // namespace Adaptor