Add trace log to check performance of text update

Change-Id: I054f862085208b58f9a5137abccc8f9a1465513c
Signed-off-by: Bowon Ryu <bowon.ryu@samsung.com>

diff --git a/dali-toolkit/internal/text/controller/text-controller-impl-model-updater.cpp b/dali-toolkit/internal/text/controller/text-controller-impl-model-updater.cpp
index 01e9157..ab005b1 100644 (file)
--- a/dali-toolkit/internal/text/controller/text-controller-impl-model-updater.cpp
+++ b/dali-toolkit/internal/text/controller/text-controller-impl-model-updater.cpp
@@ -43,6 +43,18 @@ Debug::Filter* gLogFilter = Debug::Filter::New(Debug::NoLogging, true, "LOG_TEXT
 
 DALI_INIT_TRACE_FILTER(gTraceFilter, DALI_TRACE_TEXT_PERFORMANCE_MARKER, false);
 
+#if defined(TRACE_ENABLED)
+uint32_t GetMilliSeconds()
+{
+  // 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::milliseconds>(epoch);
+
+  return static_cast<uint32_t>(duration.count());
+}
+#endif
+
 // The relative luminance of a color is defined as (L = 0.2126 * R + 0.7152 * G + 0.0722 * B)
 // based on W3C Recommendations (https://www.w3.org/TR/WCAG20/)
 constexpr float         BRIGHTNESS_THRESHOLD = 0.179f;
@@ -327,6 +339,20 @@ bool ControllerImplModelUpdater::Update(Controller::Impl& impl, OperationsMask o
   newParagraphGlyphs.Reserve(numberOfParagraphs);
 
   const Length currentNumberOfGlyphs = glyphs.Count();
+
+#if defined(TRACE_ENABLED)
+  uint32_t logThreshold = TextAbstraction::FontClient::GetPerformanceLogThresholdTime();
+  bool     logEnabled   = TextAbstraction::FontClient::IsPerformanceLogEnabled();
+
+  uint32_t timeStamps[6];
+  uint32_t timeStampIndex = 0;
+
+  if(logEnabled)
+  {
+    timeStamps[timeStampIndex++] = GetMilliSeconds();
+  }
+#endif
+
   if(Controller::NO_OPERATION != (Controller::SHAPE_TEXT & operations))
   {
     const Vector<Character>& textToShape = textMirrored ? mirroredUtf32Characters : utf32Characters;
@@ -350,6 +376,13 @@ bool ControllerImplModelUpdater::Update(Controller::Impl& impl, OperationsMask o
     updated = true;
   }
 
+#if defined(TRACE_ENABLED)
+  if(logEnabled)
+  {
+    timeStamps[timeStampIndex++] = GetMilliSeconds();
+  }
+#endif
+
   const Length numberOfGlyphs = static_cast<Length>(glyphs.Count()) - currentNumberOfGlyphs;
 
   if(Controller::NO_OPERATION != (Controller::GET_GLYPH_METRICS & operations))
@@ -370,6 +403,13 @@ bool ControllerImplModelUpdater::Update(Controller::Impl& impl, OperationsMask o
     updated = true;
   }
 
+#if defined(TRACE_ENABLED)
+  if(logEnabled)
+  {
+    timeStamps[timeStampIndex++] = GetMilliSeconds();
+  }
+#endif
+
   if((nullptr != impl.mEventData) &&
      impl.mEventData->mPreEditFlag &&
      (0u != impl.mModel->mVisualModel->mCharactersToGlyph.Count()))
@@ -564,6 +604,13 @@ bool ControllerImplModelUpdater::Update(Controller::Impl& impl, OperationsMask o
     updated = true;
   }
 
+#if defined(TRACE_ENABLED)
+  if(logEnabled)
+  {
+    timeStamps[timeStampIndex++] = GetMilliSeconds();
+  }
+#endif
+
   if(Controller::NO_OPERATION != (Controller::COLOR & operations))
   {
     // Set the color runs in glyphs.
@@ -589,6 +636,13 @@ bool ControllerImplModelUpdater::Update(Controller::Impl& impl, OperationsMask o
     updated = true;
   }
 
+#if defined(TRACE_ENABLED)
+  if(logEnabled)
+  {
+    timeStamps[timeStampIndex++] = GetMilliSeconds();
+  }
+#endif
+
   if((Controller::NO_OPERATION != (Controller::SHAPE_TEXT & operations)) &&
      !((nullptr != impl.mEventData) &&
        impl.mEventData->mPreEditFlag &&
@@ -608,6 +662,26 @@ bool ControllerImplModelUpdater::Update(Controller::Impl& impl, OperationsMask o
     updated = true;
   }
 
+#if defined(TRACE_ENABLED)
+  if(logEnabled)
+  {
+    timeStamps[timeStampIndex++] = GetMilliSeconds();
+    uint32_t timeShape   = timeStamps[1] - timeStamps[0];
+    uint32_t timeGlyph   = timeStamps[2] - timeStamps[1];
+    uint32_t timePreedit = timeStamps[3] - timeStamps[2];
+    uint32_t timeColor   = timeStamps[4] - timeStamps[3];
+    uint32_t timeCopy    = timeStamps[5] - timeStamps[4];
+
+    if(timeStamps[5] - timeStamps[0] > logThreshold)
+    {
+      std::string currentText;
+      Utf32ToUtf8(impl.mModel->mLogicalModel->mText.Begin(), numberOfCharacters, currentText);
+      DALI_LOG_DEBUG_INFO("DALI_TEXT_MODEL_UPDATE shape:%u ms, glyph:%u ms, preedit:%u ms, color:%u ms, copy:%u ms\n", timeShape, timeGlyph, timePreedit, timeColor, timeCopy);
+      DALI_LOG_DEBUG_INFO("DALI_TEXT_MODEL_UPDATE chars:%d, text:%s\n", numberOfCharacters, currentText.c_str());
+    }
+  }
+#endif
+
   // The estimated number of lines. Used to avoid reallocations when layouting.
   impl.mTextUpdateInfo.mEstimatedNumberOfLines = std::max(impl.mModel->mVisualModel->mLines.Count(), impl.mModel->mLogicalModel->mParagraphInfo.Count());
 

diff --git a/dali-toolkit/internal/text/shaper.cpp b/dali-toolkit/internal/text/shaper.cpp
index 9d9fc1b..5fbabd4 100644 (file)
--- a/dali-toolkit/internal/text/shaper.cpp
+++ b/dali-toolkit/internal/text/shaper.cpp
@@ -19,7 +19,11 @@
 #include <dali-toolkit/internal/text/shaper.h>
 
 // EXTERNAL INCLUDES
+#include <chrono>
+#include <dali/devel-api/text-abstraction/font-client.h>
 #include <dali/devel-api/text-abstraction/shaping.h>
+#include <dali/integration-api/debug.h>
+#include <dali/integration-api/trace.h>
 
 namespace Dali
 {
@@ -27,12 +31,26 @@ namespace Toolkit
 {
 namespace Text
 {
+DALI_INIT_TRACE_FILTER(gTraceFilter, DALI_TRACE_TEXT_PERFORMANCE_MARKER, false);
+
 CharacterIndex min(CharacterIndex index0,
                    CharacterIndex index1)
 {
   return (index0 < index1) ? index0 : index1;
 }
 
+#if defined(TRACE_ENABLED)
+uint32_t GetMilliSeconds()
+{
+  // 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::milliseconds>(epoch);
+
+  return static_cast<uint32_t>(duration.count());
+}
+#endif
+
 void ShapeText(const Vector<Character>&     text,
                const Vector<LineBreakInfo>& lineBreakInfo,
                const Vector<ScriptRun>&     scripts,
@@ -51,6 +69,15 @@ void ShapeText(const Vector<Character>&     text,
     return;
   }
 
+  DALI_TRACE_SCOPE(gTraceFilter, "DALI_TEXT_SHAPE_TEXT");
+
+#if defined(TRACE_ENABLED)
+  uint32_t sumPre = 0, sumShape = 0, sumPost = 0;
+
+  uint32_t logThreshold = TextAbstraction::FontClient::GetPerformanceLogThresholdTime();
+  bool     logEnabled   = TextAbstraction::FontClient::IsPerformanceLogEnabled();
+#endif
+
 #ifdef DEBUG_ENABLED
   const Length numberOfFontRuns        = fonts.Count();
   const Length numberOfScriptRuns      = scripts.Count();
@@ -132,6 +159,16 @@ void ShapeText(const Vector<Character>&     text,
   const CharacterIndex lastCharacter = startCharacterIndex + numberOfCharacters;
   for(previousIndex = startCharacterIndex; previousIndex < lastCharacter;)
   {
+#if defined(TRACE_ENABLED)
+    uint32_t timeStamps[4];
+    uint32_t timeStampIndex = 0;
+
+    if(logEnabled)
+    {
+      timeStamps[timeStampIndex++] = GetMilliSeconds();
+    }
+#endif
+
     // Get the font id and the script.
     const FontRun&   fontRun   = *fontRunIt;
     const ScriptRun& scriptRun = *scriptRunIt;
@@ -164,12 +201,26 @@ void ShapeText(const Vector<Character>&     text,
       }
     }
 
+#if defined(TRACE_ENABLED)
+    if(logEnabled)
+    {
+      timeStamps[timeStampIndex++] = GetMilliSeconds();
+    }
+#endif
+
     // Shape the text for the current chunk.
     const Length numberOfGlyphs = shaping.Shape(textBuffer + previousIndex,
                                                 (currentIndex - previousIndex), // The number of characters to shape.
                                                 currentFontId,
                                                 currentScript);
 
+#if defined(TRACE_ENABLED)
+    if(logEnabled)
+    {
+      timeStamps[timeStampIndex++] = GetMilliSeconds();
+    }
+#endif
+
     // Retrieve the glyphs and the glyph to character conversion map.
     Vector<GlyphInfo>      tmpGlyphs;
     Vector<CharacterIndex> tmpGlyphToCharacterMap;
@@ -224,6 +275,16 @@ void ShapeText(const Vector<Character>&     text,
 
     // Update the previous index.
     previousIndex = currentIndex;
+
+#if defined(TRACE_ENABLED)
+    if(logEnabled)
+    {
+      timeStamps[timeStampIndex++] = GetMilliSeconds();
+      sumPre   += timeStamps[1] - timeStamps[0];
+      sumShape += timeStamps[2] - timeStamps[1];
+      sumPost  += timeStamps[3] - timeStamps[2];
+    }
+#endif
   }
 
   // Update indices.
@@ -252,6 +313,16 @@ void ShapeText(const Vector<Character>&     text,
   // Resize the vectors to set the right number of items.
   glyphs.Resize(totalNumberOfGlyphs);
   glyphToCharacterMap.Resize(totalNumberOfGlyphs);
+
+#if defined(TRACE_ENABLED)
+  if(logEnabled)
+  {
+    if(sumPre + sumShape + sumPost > logThreshold)
+    {
+      DALI_LOG_DEBUG_INFO("DALI_TEXT_SHAPE_TEXT updated:%u/%u, pre:%u ms, shape:%u ms, post:%u ms\n", numberOfNewGlyphs, totalNumberOfGlyphs, sumPre, sumShape, sumPost);
+    }
+  }
+#endif
 }
 
 } // namespace Text