Expose custom performance timers
[platform/core/uifw/dali-adaptor.git] / adaptors / base / performance-logging / performance-server.cpp
index 6634eec..5187387 100644 (file)
@@ -37,21 +37,33 @@ namespace Adaptor
 
 namespace
 {
+
 const unsigned int DEFAULT_LOG_FREQUENCEY = 2;        ///< default log frequency = 2
 const unsigned int MILLISECONDS_PER_SECOND = 1000;    ///< 1000 milliseconds per second
 const unsigned int MICROSECONDS_PER_SECOND = 1000000; ///< 1000000 microseconds per second
-}
+
+const char* UPDATE_CONTEXT_NAME = "Update";
+const char* RENDER_CONTEXT_NAME = "Render";
+const char* EVENT_CONTEXT_NAME = "Event";
+
+} // Anonymous namespace
 
 
 PerformanceServer::PerformanceServer( AdaptorInternalServices& adaptorServices,
                                       const EnvironmentOptions& environmentOptions)
-:mLoggingEnabled( false),
- mLogFunctionInstalled( false ),
- mLogFrequencyMicroseconds( 0),
- mPlatformAbstraction( adaptorServices.GetPlatformAbstractionInterface() ),
- mEnvironmentOptions(environmentOptions),
- mKernelTrace( adaptorServices.GetKernelTraceInterface() )
+:mPlatformAbstraction( adaptorServices.GetPlatformAbstractionInterface() ),
+ mEnvironmentOptions( environmentOptions ),
+ mKernelTrace( adaptorServices.GetKernelTraceInterface() ),
+ mLogLevel( 0 ),
+ mNextContextId( 0 ),
+ mLoggingEnabled( false ),
+ mLogFunctionInstalled( false )
 {
+  // Add defaults
+  mUpdateStats = AddContext( UPDATE_CONTEXT_NAME );
+  mRenderStats = AddContext( RENDER_CONTEXT_NAME );
+  mEventStats = AddContext( EVENT_CONTEXT_NAME );
+
   SetLogging( mEnvironmentOptions.GetPerformanceLoggingLevel(), mEnvironmentOptions.GetFrameRateLoggingFrequency());
 }
 
@@ -61,101 +73,231 @@ PerformanceServer::~PerformanceServer()
   {
     mEnvironmentOptions.UnInstallLogFunction();
   }
+
+  for( StatContexts::Iterator it = mStatContexts.Begin(), itEnd = mStatContexts.End(); it != itEnd; ++it )
+  {
+    StatContext* context = *it;
+
+    delete context;
+  }
 }
-void PerformanceServer::SetLogging( unsigned int level, unsigned int interval)
+
+void PerformanceServer::SetLogging( unsigned int level, unsigned int logFrequency)
 {
-  if( level == 0)
+  if( level == 0 )
   {
     mLoggingEnabled = false;
     return;
   }
   mLogLevel = level;
 
-  mLogFrequencyMicroseconds = interval * MICROSECONDS_PER_SECOND;
+  EnableLogging( mLogLevel & LOG_UPDATE_RENDER, mUpdateStats );
+  EnableLogging( mLogLevel & LOG_UPDATE_RENDER, mRenderStats );
+  EnableLogging( mLogLevel & LOG_EVENT_PROCESS, mEventStats );
+
+  SetLoggingFrequency( logFrequency, mUpdateStats );
+  SetLoggingFrequency( logFrequency, mRenderStats );
+  SetLoggingFrequency( logFrequency, mEventStats );
 
-  if( mLogFrequencyMicroseconds == 0 )
-  {
-    mLogFrequencyMicroseconds = DEFAULT_LOG_FREQUENCEY * MICROSECONDS_PER_SECOND;
-  }
   mLoggingEnabled = true;
+}
 
+void PerformanceServer::SetLoggingFrequency( unsigned int logFrequency, ContextId contextId )
+{
+  StatContext* context = GetContext( contextId );
+  if( context )
+  {
+    unsigned int logFrequencyMicroseconds = logFrequency * MICROSECONDS_PER_SECOND;
+
+    if( logFrequencyMicroseconds == 0 )
+    {
+      logFrequencyMicroseconds = DEFAULT_LOG_FREQUENCEY * MICROSECONDS_PER_SECOND;
+    }
+
+    context->SetLogFrequency( logFrequencyMicroseconds );
+  }
 }
 
-void PerformanceServer::AddMarker( PerformanceMarker::MarkerType markerType )
+void PerformanceServer::EnableLogging( bool enable, ContextId contextId )
 {
-  if( !mLoggingEnabled )
+  StatContext* context = GetContext( contextId );
+  if( context )
   {
-    return;
+    context->EnableLogging( enable );
   }
+}
 
-  unsigned int seconds(0);
-  unsigned int microseconds(0);
+PerformanceServer::StatContext::StatContext()
+: mName( NULL ),
+  mId( 0 ),
+  mLogFrequencyMicroseconds( DEFAULT_LOG_FREQUENCEY * MICROSECONDS_PER_SECOND ),
+  mLog( true )
+{
+}
 
-  // get the time
-  mPlatformAbstraction.GetTimeMicroseconds( seconds, microseconds );
+PerformanceServer::StatContext::StatContext( unsigned int id, const char* contextName )
+: mName( contextName ),
+  mId( id ),
+  mLogFrequencyMicroseconds( DEFAULT_LOG_FREQUENCEY * MICROSECONDS_PER_SECOND ),
+  mLog( true )
+{
+}
+
+PerformanceInterface::ContextId PerformanceServer::AddContext( const char* name )
+{
+  unsigned int contextId = mNextContextId++;
 
-  // create a marker
-  PerformanceMarker marker( markerType, FrameTimeStamp( 0, seconds, microseconds ));
+  DALI_ASSERT_DEBUG( !GetContext( contextId ) );
 
-  AddMarkerToLog( marker );
+  mStatContexts.PushBack( new StatContext( contextId, name ) );
+
+  return contextId;
 }
 
-void PerformanceServer::AddMarkerToLog( PerformanceMarker marker )
+void PerformanceServer::RemoveContext( ContextId contextId )
 {
-  // Add Marker can be called from any thread
-  boost::mutex::scoped_lock sharedDatalock( mDataMutex );
+  for( StatContexts::Iterator it = mStatContexts.Begin(), itEnd = mStatContexts.End(); it != itEnd; ++it )
+  {
+    StatContext* context = *it;
 
-  // store the marker
-  mMarkers.PushBack( marker );
+    if( context->GetId() == contextId )
+    {
+      delete context;
 
-  if( mLogLevel & LOG_EVENTS_TO_KERNEL )
-  {
-    mKernelTrace.Trace(marker.GetName());
+      mStatContexts.Erase( it );
+      break;
+    }
   }
+}
 
-  // only log on the v-sync thread, so we have less impact on update/render
-  if( marker.GetType() != PerformanceMarker::V_SYNC )
+PerformanceServer::StatContext* PerformanceServer::GetContext( ContextId contextId )
+{
+  for( StatContexts::Iterator it = mStatContexts.Begin(), itEnd = mStatContexts.End(); it != itEnd; ++it )
   {
-    return;
+    StatContext* context = *it;
+
+    if( context->GetId() == contextId )
+    {
+      return context;
+    }
   }
 
-  // log out every mLogFrequency.
-  // check difference between first and last frame
-  unsigned int microseconds = PerformanceMarker::MicrosecondDiff( mMarkers[0], marker );
+  return NULL;
+}
 
-  if( microseconds  >=  mLogFrequencyMicroseconds )
+void PerformanceServer::AddMarker( MarkerType markerType )
+{
+  switch( markerType )
   {
-    LogMarkers( );
-    mMarkers.Clear();
+    case VSYNC:
+    {
+      for( StatContexts::Iterator it = mStatContexts.Begin(), itEnd = mStatContexts.End(); it != itEnd; ++it )
+      {
+        StatContext* context = *it;
+
+        AddMarker( VSYNC, context->GetId() );
+      }
+      break;
+    }
+    case UPDATE_START:
+    {
+      AddMarker( START, mUpdateStats );
+      break;
+    }
+    case UPDATE_END:
+    {
+      AddMarker( END, mUpdateStats );
+      break;
+    }
+    case RENDER_START:
+    {
+      AddMarker( START, mRenderStats );
+      break;
+    }
+    case RENDER_END:
+    {
+      AddMarker( END, mRenderStats );
+      break;
+    }
+    case PROCESS_EVENTS_START:
+    {
+      AddMarker( START, mEventStats );
+      break;
+    }
+    case PROCESS_EVENTS_END:
+    {
+      AddMarker( END, mEventStats );
+      break;
+    }
+    default:
+    {
+      break;
+    }
+  }
+}
 
-    // reset data for update / render statistics
-    mUpdateStats.Reset();
-    mRenderStats.Reset();
-    mEventStats.Reset();
+void PerformanceServer::AddMarker( MarkerType markerType, ContextId contextId )
+{
+  if( !mLoggingEnabled )
+  {
+    return;
   }
+
+  // Get the time
+  unsigned int seconds = 0;
+  unsigned int microseconds = 0;
+  mPlatformAbstraction.GetTimeMicroseconds( seconds, microseconds );
+
+  // Create a marker and add it to the log
+  PerformanceMarker marker( markerType, FrameTimeStamp( 0, seconds, microseconds ) );
+  AddMarkerToLog( marker, contextId );
 }
 
-void PerformanceServer::LogMarker(const char* name, const FrameTimeStats& frameStats)
+void PerformanceServer::AddMarkerToLog( const PerformanceMarker& marker, ContextId contextId )
 {
-  // make sure log function is installed, note this will be called only from v-sync thread
-  // if the v-sync thread has already installed one, it won't make any difference.
-  if(! mLogFunctionInstalled )
+  StatContext* context = GetContext( contextId );
+  if( context )
   {
-    mEnvironmentOptions.InstallLogFunction();
-    mLogFunctionInstalled = true;
+    if( mLogLevel & LOG_EVENTS_TO_KERNEL )
+    {
+      std::stringstream ss;
+      ss << GetMarkerName( marker.GetType() ) << ":" << ( ( context->GetName() ) ? context->GetName() : "" );
+      mKernelTrace.Trace( ss.str() );
+    }
+
+    // Only log on the v-sync thread, so we have less impact on update/render
+    if( marker.GetType() == VSYNC )
+    {
+      // make sure log function is installed, note this will be called only from v-sync thread
+      // if the v-sync thread has already installed one, it won't make any difference.
+      if( !mLogFunctionInstalled )
+      {
+        mEnvironmentOptions.InstallLogFunction();
+        mLogFunctionInstalled = true;
+      }
+    }
+
+    context->LogMarker( marker );
   }
+}
+
+void PerformanceServer::StatContext::LogMarker()
+{
+  float mean, standardDeviation;
+  mStats.CalculateMean( mean, standardDeviation );
 
   // this will always log regardless of debug / release mode
   Integration::Log::LogMessage( Dali::Integration::Log::DebugInfo,
-                                    "%s , min " TIME_FMT ", max " TIME_FMT ", total (" TOTAL_TIME_FMT "), avg " TIME_FMT "\n",
-                                     name,
-                                     frameStats.GetMinTime() * MILLISECONDS_PER_SECOND,
-                                     frameStats.GetMaxTime() * MILLISECONDS_PER_SECOND,
-                                     frameStats.GetTotalTime(),
-                                     frameStats.GetRollingAverageTime() * MILLISECONDS_PER_SECOND);
+                                    "%s, min " TIME_FMT ", max " TIME_FMT ", total (" TOTAL_TIME_FMT "), avg " TIME_FMT ", std dev " TIME_FMT "\n",
+                                     ( mName ) ? mName : "",
+                                     mStats.GetMinTime() * MILLISECONDS_PER_SECOND,
+                                     mStats.GetMaxTime() * MILLISECONDS_PER_SECOND,
+                                     mStats.GetTotalTime(),
+                                     mean * MILLISECONDS_PER_SECOND,
+                                     standardDeviation * MILLISECONDS_PER_SECOND);
 }
 
-void PerformanceServer::LogMarkers()
+void PerformanceServer::StatContext::TimeMarkers()
 {
   // insert time stamps into a frame-time-stats object, based on type
   for( MarkerVector::SizeType i = 0; i < mMarkers.Size(); ++i)
@@ -163,34 +305,14 @@ void PerformanceServer::LogMarkers()
     const PerformanceMarker& marker = mMarkers[i];
     switch( marker.GetType() )
     {
-      case PerformanceMarker::UPDATE_START:
+      case START:
       {
-        mUpdateStats.StartTime( marker.GetTimeStamp() );
+        mStats.StartTime( marker.GetTimeStamp() );
         break;
       }
-      case PerformanceMarker::UPDATE_END:
+      case END:
       {
-        mUpdateStats.EndTime( marker.GetTimeStamp() );
-        break;
-      }
-      case PerformanceMarker::RENDER_START:
-      {
-        mRenderStats.StartTime( marker.GetTimeStamp() );
-        break;
-      }
-      case PerformanceMarker::RENDER_END:
-      {
-        mRenderStats.EndTime( marker.GetTimeStamp() );
-        break;
-      }
-      case PerformanceMarker::PROCESS_EVENTS_START:
-      {
-        mEventStats.StartTime( marker.GetTimeStamp() );
-        break;
-      }
-      case PerformanceMarker::PROCESS_EVENTS_END:
-      {
-        mEventStats.EndTime( marker.GetTimeStamp() );
+        mStats.EndTime( marker.GetTimeStamp() );
         break;
       }
       default:
@@ -199,16 +321,82 @@ void PerformanceServer::LogMarkers()
       }
     }
   }
-  if( mLogLevel & LOG_UPDATE_RENDER )
+
+  mMarkers.Clear();
+}
+
+const char* PerformanceServer::GetMarkerName( MarkerType type ) const
+{
+  switch( type )
   {
-    LogMarker("Update",mUpdateStats);
-    LogMarker("Render",mRenderStats);
+    case VSYNC:
+    {
+      return "VSYNC";
+    }
+
+    case START:
+    {
+      return "START";
+    }
+
+    case END:
+    {
+      return "END";
+    }
+
+    default:
+    {
+      DALI_ASSERT_DEBUG( !"Unsupported MarkerType" );
+      return "";
+    }
   }
-  if( mLogLevel & LOG_EVENT_PROCESS )
+}
+
+void PerformanceServer::StatContext::LogMarker( const PerformanceMarker& marker )
+{
+  // Add Marker can be called from any thread
+  boost::mutex::scoped_lock sharedDatalock( mDataMutex );
+
+  mMarkers.PushBack( marker );
+
+  // Only log on the v-sync thread, so we have less impact on update/render
+  if( marker.GetType() == VSYNC )
   {
-    LogMarker("Event",mEventStats);
+    // log out every mLogFrequency.
+    // check difference between first and last frame
+    unsigned int microseconds = PerformanceMarker::MicrosecondDiff( mMarkers[0], marker );
+    if( microseconds >= mLogFrequencyMicroseconds )
+    {
+      TimeMarkers();
+
+      if( mLog )
+      {
+        LogMarker();
+      }
+
+      mStats.Reset();     // reset data for statistics
+    }
   }
+}
 
+void PerformanceServer::StatContext::SetLogFrequency( unsigned int frequencyMicroseconds )
+{
+  mLogFrequencyMicroseconds = frequencyMicroseconds;
+}
+
+void PerformanceServer::StatContext::EnableLogging( bool enableLogging )
+{
+  mLog = enableLogging;
+}
+
+const char* PerformanceServer::StatContext::GetName() const
+{
+  return mName;
+}
+
+unsigned int PerformanceServer::StatContext::GetId() const
+{
+  return mId;
 }
 
 } // namespace Internal