Print image process duration when we trace it

Change-Id: Ic9dba03a2f18743ea253ccf9e1234bd1bda78239
Signed-off-by: Eunki, Hong <eunkiki.hong@samsung.com>

diff --git a/dali-toolkit/internal/image-loader/fast-track-loading-task.cpp b/dali-toolkit/internal/image-loader/fast-track-loading-task.cpp
index e65ca57..1845ff7 100644 (file)
--- a/dali-toolkit/internal/image-loader/fast-track-loading-task.cpp
+++ b/dali-toolkit/internal/image-loader/fast-track-loading-task.cpp
@@ -27,7 +27,10 @@
 #include <dali/public-api/common/vector-wrapper.h>
 
 #ifdef TRACE_ENABLED
+#include <chrono>
+#include <iomanip>
 #include <sstream>
+#include <thread>
 #endif
 
 namespace Dali
@@ -40,6 +43,16 @@ namespace
 {
 DALI_INIT_TRACE_FILTER(gTraceFilter, DALI_TRACE_IMAGE_PERFORMANCE_MARKER, false);
 
+#ifdef TRACE_ENABLED
+uint64_t GetNanoseconds()
+{
+  // Get the time of a monotonic clock since its epoch.
+  auto epoch    = std::chrono::steady_clock::now().time_since_epoch();
+  auto duration = std::chrono::duration_cast<std::chrono::nanoseconds>(epoch);
+  return static_cast<uint64_t>(duration.count());
+}
+#endif
+
 constexpr uint32_t CHROMINANCE_U_INDEX = 1u;
 constexpr uint32_t CHROMINANCE_V_INDEX = 2u;
 
@@ -146,8 +159,11 @@ bool FastTrackLoadingTask::IsReady()
 void FastTrackLoadingTask::Load()
 {
 #ifdef TRACE_ENABLED
+  uint64_t mStartTimeNanoSceonds = 0;
+  uint64_t mEndTimeNanoSceonds   = 0;
   if(gTraceFilter && gTraceFilter->IsTraceEnabled())
   {
+    mStartTimeNanoSceonds = GetNanoseconds();
     std::ostringstream oss;
     oss << "[u:" << mUrl.GetEllipsedUrl() << "]";
     // DALI_TRACE_BEGIN(gTraceFilter, "DALI_IMAGE_FAST_TRACK_UPLOADING_TASK"); ///< TODO : Open it if we can control trace log level
@@ -219,8 +235,11 @@ void FastTrackLoadingTask::Load()
 #ifdef TRACE_ENABLED
   if(gTraceFilter && gTraceFilter->IsTraceEnabled())
   {
+    mEndTimeNanoSceonds = GetNanoseconds();
     std::ostringstream oss;
+    oss << std::fixed << std::setprecision(3);
     oss << "[";
+    oss << "d:" << static_cast<float>(mEndTimeNanoSceonds - mStartTimeNanoSceonds) / 1000000.0f << "ms ";
     oss << "b:" << pixelBuffers.size() << " ";
     if(!mPixelData.empty())
     {

diff --git a/dali-toolkit/internal/image-loader/loading-task.cpp b/dali-toolkit/internal/image-loader/loading-task.cpp
index 4471344..5cbd16b 100644 (file)
--- a/dali-toolkit/internal/image-loader/loading-task.cpp
+++ b/dali-toolkit/internal/image-loader/loading-task.cpp
@@ -27,7 +27,10 @@
 #include <dali/public-api/adaptor-framework/encoded-image-buffer.h>
 
 #ifdef TRACE_ENABLED
+#include <chrono>
+#include <iomanip>
 #include <sstream>
+#include <thread>
 #endif
 
 namespace Dali
@@ -39,7 +42,17 @@ namespace Internal
 namespace
 {
 DALI_INIT_TRACE_FILTER(gTraceFilter, DALI_TRACE_IMAGE_PERFORMANCE_MARKER, false);
+
+#ifdef TRACE_ENABLED
+uint64_t GetNanoseconds()
+{
+  // Get the time of a monotonic clock since its epoch.
+  auto epoch    = std::chrono::steady_clock::now().time_since_epoch();
+  auto duration = std::chrono::duration_cast<std::chrono::nanoseconds>(epoch);
+  return static_cast<uint64_t>(duration.count());
 }
+#endif
+} // namespace
 
 LoadingTask::LoadingTask(uint32_t id, Dali::AnimatedImageLoading animatedImageLoading, uint32_t frameIndex, DevelAsyncImageLoader::PreMultiplyOnLoad preMultiplyOnLoad, CallbackBase* callback)
 : AsyncTask(callback),
@@ -159,8 +172,11 @@ LoadingTask::~LoadingTask()
 void LoadingTask::Process()
 {
 #ifdef TRACE_ENABLED
+  uint64_t mStartTimeNanoSceonds = 0;
+  uint64_t mEndTimeNanoSceonds   = 0;
   if(gTraceFilter && gTraceFilter->IsTraceEnabled())
   {
+    mStartTimeNanoSceonds = GetNanoseconds();
     std::ostringstream oss;
     oss << "[u:" << (!!(animatedImageLoading) ? animatedImageLoading.GetUrl() : url.GetEllipsedUrl()) << "]";
     // DALI_TRACE_BEGIN(gTraceFilter, "DALI_IMAGE_LOADING_TASK"); ///< TODO : Open it if we can control trace log level
@@ -183,8 +199,11 @@ void LoadingTask::Process()
 #ifdef TRACE_ENABLED
   if(gTraceFilter && gTraceFilter->IsTraceEnabled())
   {
+    mEndTimeNanoSceonds = GetNanoseconds();
     std::ostringstream oss;
+    oss << std::fixed << std::setprecision(3);
     oss << "[";
+    oss << "d:" << static_cast<float>(mEndTimeNanoSceonds - mStartTimeNanoSceonds) / 1000000.0f << "ms ";
     oss << "m:" << isMaskTask << " ";
     oss << "i:" << frameIndex << " ";
     oss << "b:" << pixelBuffers.size() << " ";

diff --git a/dali-toolkit/internal/visuals/animated-vector-image/vector-animation-task.cpp b/dali-toolkit/internal/visuals/animated-vector-image/vector-animation-task.cpp
index a746ba2..59e4e85 100644 (file)
--- a/dali-toolkit/internal/visuals/animated-vector-image/vector-animation-task.cpp
+++ b/dali-toolkit/internal/visuals/animated-vector-image/vector-animation-task.cpp
@@ -31,7 +31,10 @@
 #include <dali-toolkit/internal/visuals/image-visual-shader-factory.h>
 
 #ifdef TRACE_ENABLED
+#include <chrono>
+#include <iomanip>
 #include <sstream>
+#include <thread>
 #endif
 
 namespace Dali
@@ -51,6 +54,16 @@ Debug::Filter* gVectorAnimationLogFilter = Debug::Filter::New(Debug::NoLogging,
 
 DALI_INIT_TRACE_FILTER(gTraceFilter, DALI_TRACE_IMAGE_PERFORMANCE_MARKER, false);
 
+#ifdef TRACE_ENABLED
+uint64_t GetNanoseconds()
+{
+  // Get the time of a monotonic clock since its epoch.
+  auto epoch    = std::chrono::steady_clock::now().time_since_epoch();
+  auto duration = std::chrono::duration_cast<std::chrono::nanoseconds>(epoch);
+  return static_cast<uint64_t>(duration.count());
+}
+#endif
+
 } // unnamed namespace
 
 VectorAnimationTask::VectorAnimationTask(VisualFactoryCache& factoryCache)
@@ -152,8 +165,11 @@ bool VectorAnimationTask::IsAnimating()
 bool VectorAnimationTask::Load(bool synchronousLoading)
 {
 #ifdef TRACE_ENABLED
+  uint64_t mStartTimeNanoSceonds = 0;
+  uint64_t mEndTimeNanoSceonds   = 0;
   if(gTraceFilter && gTraceFilter->IsTraceEnabled())
   {
+    mStartTimeNanoSceonds = GetNanoseconds();
     std::ostringstream oss;
     oss << "[u:" << mImageUrl.GetEllipsedUrl() << "]";
     // DALI_TRACE_BEGIN(gTraceFilter, "DALI_LOTTIE_LOADING_TASK"); ///< TODO : Open it if we can control trace log level
@@ -202,8 +218,12 @@ bool VectorAnimationTask::Load(bool synchronousLoading)
 #ifdef TRACE_ENABLED
     if(gTraceFilter && gTraceFilter->IsTraceEnabled())
     {
+      mEndTimeNanoSceonds = GetNanoseconds();
       std::ostringstream oss;
-      oss << "[u:" << mImageUrl.GetEllipsedUrl() << "]";
+      oss << std::fixed << std::setprecision(3);
+      oss << "[";
+      oss << "d:" << static_cast<float>(mEndTimeNanoSceonds - mStartTimeNanoSceonds) / 1000000.0f << "ms ";
+      oss << "u:" << mImageUrl.GetEllipsedUrl() << "]";
       // DALI_TRACE_END(gTraceFilter, "DALI_LOTTIE_LOADING_TASK"); ///< TODO : Open it if we can control trace log level
       DALI_LOG_RELEASE_INFO("END: DALI_LOTTIE_LOADING_TASK %s", oss.str().c_str());
     }
@@ -232,8 +252,12 @@ bool VectorAnimationTask::Load(bool synchronousLoading)
 #ifdef TRACE_ENABLED
   if(gTraceFilter && gTraceFilter->IsTraceEnabled())
   {
+    mEndTimeNanoSceonds = GetNanoseconds();
     std::ostringstream oss;
-    oss << "[u:" << mImageUrl.GetEllipsedUrl() << "]";
+    oss << std::fixed << std::setprecision(3);
+    oss << "[";
+    oss << "d:" << static_cast<float>(mEndTimeNanoSceonds - mStartTimeNanoSceonds) / 1000000.0f << "ms ";
+    oss << "u:" << mImageUrl.GetEllipsedUrl() << "]";
     // DALI_TRACE_END(gTraceFilter, "DALI_LOTTIE_LOADING_TASK"); ///< TODO : Open it if we can control trace log level
     DALI_LOG_RELEASE_INFO("END: DALI_LOTTIE_LOADING_TASK %s", oss.str().c_str());
   }
@@ -574,7 +598,12 @@ bool VectorAnimationTask::Rasterize()
     return false;
   }
 
+#ifdef TRACE_ENABLED
+  uint64_t mStartTimeNanoSceonds = 0;
+  uint64_t mEndTimeNanoSceonds   = 0;
+#endif
   DALI_TRACE_BEGIN_WITH_MESSAGE_GENERATOR(gTraceFilter, "DALI_LOTTIE_RASTERIZE_TASK", [&](std::ostringstream& oss) {
+    mStartTimeNanoSceonds = GetNanoseconds();
     oss << "[s:" << mWidth << "x" << mHeight << " ";
     oss << "u:" << mImageUrl.GetEllipsedUrl() << "]";
   });
@@ -687,7 +716,11 @@ bool VectorAnimationTask::Rasterize()
   }
 
   DALI_TRACE_END_WITH_MESSAGE_GENERATOR(gTraceFilter, "DALI_LOTTIE_RASTERIZE_TASK", [&](std::ostringstream& oss) {
-    oss << "[s:" << mWidth << "x" << mHeight << " ";
+    mEndTimeNanoSceonds = GetNanoseconds();
+    oss << std::fixed << std::setprecision(3);
+    oss << "[";
+    oss << "d:" << static_cast<float>(mEndTimeNanoSceonds - mStartTimeNanoSceonds) / 1000000.0f << "ms ";
+    oss << "s:" << mWidth << "x" << mHeight << " ";
     oss << "f:" << mCurrentFrame << " ";
     oss << "l:" << mCurrentLoop << " ";
     oss << "p:" << mPlayState << " ";

diff --git a/dali-toolkit/internal/visuals/svg/svg-task.cpp b/dali-toolkit/internal/visuals/svg/svg-task.cpp
index 35c0028..0a4ff89 100644 (file)
--- a/dali-toolkit/internal/visuals/svg/svg-task.cpp
+++ b/dali-toolkit/internal/visuals/svg/svg-task.cpp
@@ -28,7 +28,10 @@
 #include <dali-toolkit/internal/visuals/svg/svg-visual.h>
 
 #ifdef TRACE_ENABLED
+#include <chrono>
+#include <iomanip>
 #include <sstream>
+#include <thread>
 #endif
 
 namespace Dali
@@ -40,7 +43,17 @@ namespace Internal
 namespace
 {
 DALI_INIT_TRACE_FILTER(gTraceFilter, DALI_TRACE_IMAGE_PERFORMANCE_MARKER, false);
+
+#ifdef TRACE_ENABLED
+uint64_t GetNanoseconds()
+{
+  // Get the time of a monotonic clock since its epoch.
+  auto epoch    = std::chrono::steady_clock::now().time_since_epoch();
+  auto duration = std::chrono::duration_cast<std::chrono::nanoseconds>(epoch);
+  return static_cast<uint64_t>(duration.count());
 }
+#endif
+} // namespace
 
 SvgTask::SvgTask(VectorImageRenderer vectorRenderer, CallbackBase* callback, AsyncTask::PriorityType priorityType)
 : AsyncTask(callback, priorityType),
@@ -86,8 +99,11 @@ void SvgLoadingTask::Process()
   }
 
 #ifdef TRACE_ENABLED
+  uint64_t mStartTimeNanoSceonds = 0;
+  uint64_t mEndTimeNanoSceonds   = 0;
   if(gTraceFilter && gTraceFilter->IsTraceEnabled())
   {
+    mStartTimeNanoSceonds = GetNanoseconds();
     std::ostringstream oss;
     oss << "[u:" << mImageUrl.GetEllipsedUrl() << "]";
     // DALI_TRACE_BEGIN(gTraceFilter, "DALI_SVG_LOADING_TASK"); ///< TODO : Open it if we can control trace log level
@@ -141,8 +157,12 @@ void SvgLoadingTask::Process()
 #ifdef TRACE_ENABLED
   if(gTraceFilter && gTraceFilter->IsTraceEnabled())
   {
+    mEndTimeNanoSceonds = GetNanoseconds();
     std::ostringstream oss;
-    oss << "[s:" << mHasSucceeded << " ";
+    oss << std::fixed << std::setprecision(3);
+    oss << "[";
+    oss << "d:" << static_cast<float>(mEndTimeNanoSceonds - mStartTimeNanoSceonds) / 1000000.0f << "ms ";
+    oss << "s:" << mHasSucceeded << " ";
     oss << "u:" << mImageUrl.GetEllipsedUrl() << "]";
     // DALI_TRACE_END(gTraceFilter, "DALI_SVG_LOADING_TASK"); ///< TODO : Open it if we can control trace log level
     DALI_LOG_RELEASE_INFO("END: DALI_SVG_LOADING_TASK %s", oss.str().c_str());
@@ -174,7 +194,12 @@ void SvgRasterizingTask::Process()
     return;
   }
 
+#ifdef TRACE_ENABLED
+  uint64_t mStartTimeNanoSceonds = 0;
+  uint64_t mEndTimeNanoSceonds   = 0;
+#endif
   DALI_TRACE_BEGIN_WITH_MESSAGE_GENERATOR(gTraceFilter, "DALI_SVG_RASTERIZE_TASK", [&](std::ostringstream& oss) {
+    mStartTimeNanoSceonds = GetNanoseconds();
     oss << "[s:" << mWidth << "x" << mHeight << " ";
     oss << "u:" << mImageUrl.GetEllipsedUrl() << "]";
   });
@@ -194,7 +219,11 @@ void SvgRasterizingTask::Process()
   mHasSucceeded = true;
 
   DALI_TRACE_END_WITH_MESSAGE_GENERATOR(gTraceFilter, "DALI_SVG_RASTERIZE_TASK", [&](std::ostringstream& oss) {
-    oss << "[s:" << mWidth << "x" << mHeight << " ";
+    mEndTimeNanoSceonds = GetNanoseconds();
+    oss << std::fixed << std::setprecision(3);
+    oss << "[";
+    oss << "d:" << static_cast<float>(mEndTimeNanoSceonds - mStartTimeNanoSceonds) / 1000000.0f << "ms ";
+    oss << "s:" << mWidth << "x" << mHeight << " ";
     oss << "u:" << mImageUrl.GetEllipsedUrl() << "]";
   });
 }