[Tizen] Print top5 longest time spend animation finished callbacks + Minor code clean

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

diff --git a/dali/internal/event/animation/animation-playlist.cpp b/dali/internal/event/animation/animation-playlist.cpp
index 60521d46b0ef7aa0a50c48798b120fa3f2e111b2..c7791f1f5d3e622662d18475454e9a85ec958f5f 100644 (file)
--- a/dali/internal/event/animation/animation-playlist.cpp
+++ b/dali/internal/event/animation/animation-playlist.cpp
@@ -20,10 +20,34 @@
 
 // INTERNAL INCLUDES
 #include <dali/integration-api/debug.h>
+#include <dali/integration-api/trace.h>
 #include <dali/internal/event/animation/animation-impl.h>
 #include <dali/internal/update/animation/scene-graph-animation.h>
 #include <dali/public-api/common/vector-wrapper.h>
 
+#ifdef TRACE_ENABLED
+#include <chrono>
+#include <thread>
+#include <cmath>
+#endif
+
+namespace
+{
+DALI_INIT_TRACE_FILTER(gTraceFilter, DALI_TRACE_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 Dali
 {
 namespace Internal
@@ -100,6 +124,17 @@ void AnimationPlaylist::NotifyCompleted(CompleteNotificationInterface::Parameter
 {
   std::vector<Dali::Animation> finishedAnimations; // Will own handle until all emits have been done.
 
+#ifdef TRACE_ENABLED
+  std::vector<std::pair<uint64_t, uint32_t>> animationFinishedTimeChecker;
+
+  uint64_t start = 0u;
+  uint64_t end = 0u;
+#endif
+
+  DALI_TRACE_BEGIN_WITH_MESSAGE_GENERATOR(gTraceFilter, "DALI_ANIMATION_FINISHED", [&](std::ostringstream& oss) {
+    oss << "[n:" << notifierIdList.Count() << "]";
+  });
+
   for(const auto& notifierId : notifierIdList)
   {
     auto* animation = GetEventObject(notifierId);
@@ -123,8 +158,36 @@ void AnimationPlaylist::NotifyCompleted(CompleteNotificationInterface::Parameter
   // Now it's safe to emit the signals
   for(auto& animation : finishedAnimations)
   {
+#ifdef TRACE_ENABLED
+    if(gTraceFilter && gTraceFilter->IsTraceEnabled())
+    {
+      start = GetNanoseconds();
+    }
+#endif
     GetImplementation(animation).EmitSignalFinish();
+#ifdef TRACE_ENABLED
+    if(gTraceFilter && gTraceFilter->IsTraceEnabled())
+    {
+      end = GetNanoseconds();
+      animationFinishedTimeChecker.emplace_back(end - start, GetImplementation(animation).GetSceneObject()->GetNotifyId());
+    }
+#endif
   }
+
+  DALI_TRACE_END_WITH_MESSAGE_GENERATOR(gTraceFilter, "DALI_ANIMATION_FINISHED", [&](std::ostringstream& oss) {
+    oss << "[f:" << finishedAnimations.size() << ",";
+
+    std::sort(animationFinishedTimeChecker.rbegin(), animationFinishedTimeChecker.rend());
+    auto topCount = std::min(5u, static_cast<uint32_t>(animationFinishedTimeChecker.size()));
+
+    oss << "top" << topCount;
+    for(auto i = 0u; i < topCount; ++i)
+    {
+      oss << "(" << static_cast<float>(animationFinishedTimeChecker[i].first) / 1000000.0f << "ms,";
+      oss << animationFinishedTimeChecker[i].second << ")";
+    }
+    oss << "]";
+  });
 }
 
 uint32_t AnimationPlaylist::GetAnimationCount()

diff --git a/dali/internal/update/manager/frame-callback-processor.cpp b/dali/internal/update/manager/frame-callback-processor.cpp
index fb66c62e319f1650dd2bf850adfa1ff04241f56c..0535137de0856a5cf100fcfd814e303ccf69dc3e 100644 (file)
--- a/dali/internal/update/manager/frame-callback-processor.cpp
+++ b/dali/internal/update/manager/frame-callback-processor.cpp
@@ -37,7 +37,7 @@ namespace
 DALI_INIT_TRACE_FILTER(gTraceFilter, DALI_TRACE_PERFORMANCE_MARKER, false);
 
 #ifdef TRACE_ENABLED
-uint64_t GetNanoSeconds()
+uint64_t GetNanoseconds()
 {
   // Get the time of a monotonic clock since its epoch.
   auto epoch = std::chrono::steady_clock::now().time_since_epoch();
@@ -142,14 +142,14 @@ bool FrameCallbackProcessor::Update(BufferIndex bufferIndex, float elapsedSecond
 #ifdef TRACE_ENABLED
         if(gTraceFilter && gTraceFilter->IsTraceEnabled())
         {
-          start = GetNanoSeconds();
+          start = GetNanoseconds();
         }
 #endif
         FrameCallback::RequestFlags requests = frameCallback->Update(bufferIndex, elapsedSeconds, mNodeHierarchyChanged);
 #ifdef TRACE_ENABLED
         if(gTraceFilter && gTraceFilter->IsTraceEnabled())
         {
-          end = GetNanoSeconds();
+          end = GetNanoseconds();
           frameCallbackTimeChecker.emplace_back(end - start, ++frameIndex);
         }
 #endif
@@ -167,7 +167,7 @@ bool FrameCallbackProcessor::Update(BufferIndex bufferIndex, float elapsedSecond
       std::sort(frameCallbackTimeChecker.rbegin(), frameCallbackTimeChecker.rend());
       auto topCount = std::min(5u, static_cast<uint32_t>(frameCallbackTimeChecker.size()));
 
-      oss << "top" << topCount << "[";
+      oss << "top" << topCount;
       for(auto i = 0u; i < topCount; ++i)
       {
         oss << "(" << static_cast<float>(frameCallbackTimeChecker[i].first) / 1000000.0f << "ms,";