Improved performance logging
[platform/core/uifw/dali-adaptor.git] / adaptors / base / performance-logging / performance-server.cpp
index 5187387..2736ad2 100644 (file)
@@ -31,40 +31,19 @@ namespace Internal
 namespace Adaptor
 {
 
-#define TIME_FMT "%0.2f ms" // 2 decimal places, e.g. 5.34 ms
-#define TOTAL_TIME_FMT "%0.1f secs" // 1 decimal place, e.g. 4.5 seconds
-
-
-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)
 :mPlatformAbstraction( adaptorServices.GetPlatformAbstractionInterface() ),
  mEnvironmentOptions( environmentOptions ),
  mKernelTrace( adaptorServices.GetKernelTraceInterface() ),
- mLogLevel( 0 ),
- mNextContextId( 0 ),
+ mStatContextManager( *this ),
+ mStatisticsLogBitmask( 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());
+  SetLogging( mEnvironmentOptions.GetPerformanceStatsLoggingOptions(),
+              mEnvironmentOptions.GetPerformanceTimeStampOutput(),
+              mEnvironmentOptions.GetPerformanceStatsLoggingFrequency());
 }
 
 PerformanceServer::~PerformanceServer()
@@ -73,332 +52,148 @@ 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 logFrequency)
+void PerformanceServer::SetLogging( unsigned int statisticsLogOptions,
+                                    unsigned int timeStampOutput,
+                                    unsigned int logFrequency )
 {
-  if( level == 0 )
+  if( ( statisticsLogOptions == 0) && ( timeStampOutput == 0 ))
   {
     mLoggingEnabled = false;
     return;
   }
-  mLogLevel = level;
 
-  EnableLogging( mLogLevel & LOG_UPDATE_RENDER, mUpdateStats );
-  EnableLogging( mLogLevel & LOG_UPDATE_RENDER, mRenderStats );
-  EnableLogging( mLogLevel & LOG_EVENT_PROCESS, mEventStats );
+  mStatisticsLogBitmask = statisticsLogOptions;
+  mPerformanceOutputBitmask = timeStampOutput;
 
-  SetLoggingFrequency( logFrequency, mUpdateStats );
-  SetLoggingFrequency( logFrequency, mRenderStats );
-  SetLoggingFrequency( logFrequency, mEventStats );
+  mStatContextManager.SetLoggingLevel( mStatisticsLogBitmask, logFrequency);
 
   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 );
-  }
+  mStatContextManager.SetLoggingFrequency( logFrequency, contextId );
 }
 
 void PerformanceServer::EnableLogging( bool enable, ContextId contextId )
 {
-  StatContext* context = GetContext( contextId );
-  if( context )
-  {
-    context->EnableLogging( enable );
-  }
-}
-
-PerformanceServer::StatContext::StatContext()
-: mName( NULL ),
-  mId( 0 ),
-  mLogFrequencyMicroseconds( DEFAULT_LOG_FREQUENCEY * MICROSECONDS_PER_SECOND ),
-  mLog( true )
-{
-}
-
-PerformanceServer::StatContext::StatContext( unsigned int id, const char* contextName )
-: mName( contextName ),
-  mId( id ),
-  mLogFrequencyMicroseconds( DEFAULT_LOG_FREQUENCEY * MICROSECONDS_PER_SECOND ),
-  mLog( true )
-{
+  mStatContextManager.EnableLogging( enable, contextId );
 }
 
 PerformanceInterface::ContextId PerformanceServer::AddContext( const char* name )
 {
-  unsigned int contextId = mNextContextId++;
-
-  DALI_ASSERT_DEBUG( !GetContext( contextId ) );
-
-  mStatContexts.PushBack( new StatContext( contextId, name ) );
-
-  return contextId;
+  // for adding custom contexts
+  return mStatContextManager.AddContext( name, PerformanceMarker::CUSTOM_EVENTS );
 }
 
 void PerformanceServer::RemoveContext( ContextId contextId )
 {
-  for( StatContexts::Iterator it = mStatContexts.Begin(), itEnd = mStatContexts.End(); it != itEnd; ++it )
-  {
-    StatContext* context = *it;
-
-    if( context->GetId() == contextId )
-    {
-      delete context;
-
-      mStatContexts.Erase( it );
-      break;
-    }
-  }
-}
-
-PerformanceServer::StatContext* PerformanceServer::GetContext( ContextId contextId )
-{
-  for( StatContexts::Iterator it = mStatContexts.Begin(), itEnd = mStatContexts.End(); it != itEnd; ++it )
-  {
-    StatContext* context = *it;
-
-    if( context->GetId() == contextId )
-    {
-      return context;
-    }
-  }
-
-  return NULL;
-}
-
-void PerformanceServer::AddMarker( MarkerType markerType )
-{
-  switch( markerType )
-  {
-    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;
-    }
-  }
+  mStatContextManager.RemoveContext( contextId );
 }
 
 void PerformanceServer::AddMarker( MarkerType markerType, ContextId contextId )
 {
+  // called only for custom markers
+
   if( !mLoggingEnabled )
   {
     return;
   }
 
-  // Get the time
+  // This is only called from main event thread, but may overlap with internal AddMarker calls
+  // from other threads ( update, render etc).
+  boost::mutex::scoped_lock sharedDatalock( mDataMutex );
+
+  // Get the time stamp
   unsigned int seconds = 0;
   unsigned int microseconds = 0;
   mPlatformAbstraction.GetTimeMicroseconds( seconds, microseconds );
 
-  // Create a marker and add it to the log
+  // Create a marker
   PerformanceMarker marker( markerType, FrameTimeStamp( 0, seconds, microseconds ) );
-  AddMarkerToLog( marker, contextId );
-}
 
-void PerformanceServer::AddMarkerToLog( const PerformanceMarker& marker, ContextId contextId )
-{
-  StatContext* context = GetContext( contextId );
-  if( context )
-  {
-    if( mLogLevel & LOG_EVENTS_TO_KERNEL )
-    {
-      std::stringstream ss;
-      ss << GetMarkerName( marker.GetType() ) << ":" << ( ( context->GetName() ) ? context->GetName() : "" );
-      mKernelTrace.Trace( ss.str() );
-    }
+  // get the marker description for this context, e.g SIZE_NEGOTIATION_START
+  const char* const description = mStatContextManager.GetMarkerDescription( markerType, contextId );
 
-    // 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;
-      }
-    }
+  // log it
+  LogMarker( marker, description );
 
-    context->LogMarker( marker );
-  }
-}
+  // Add custom marker to statistics context manager
+  mStatContextManager.AddCustomMarker( marker, contextId );
 
-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 ", 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::StatContext::TimeMarkers()
+void PerformanceServer::AddMarker( MarkerType markerType )
 {
-  // insert time stamps into a frame-time-stats object, based on type
-  for( MarkerVector::SizeType i = 0; i < mMarkers.Size(); ++i)
+  // called only for internal markers
+
+  if( !mLoggingEnabled )
   {
-    const PerformanceMarker& marker = mMarkers[i];
-    switch( marker.GetType() )
-    {
-      case START:
-      {
-        mStats.StartTime( marker.GetTimeStamp() );
-        break;
-      }
-      case END:
-      {
-        mStats.EndTime( marker.GetTimeStamp() );
-        break;
-      }
-      default:
-      {
-        break;
-      }
-    }
+    return;
   }
 
-  mMarkers.Clear();
-}
+  // AddMarker can be called from multiple threads, to avoid problems
+  // with updating contexts and the kernel trace, lock here.
+  boost::mutex::scoped_lock sharedDatalock( mDataMutex );
 
-const char* PerformanceServer::GetMarkerName( MarkerType type ) const
-{
-  switch( type )
+  if( markerType == VSYNC )
   {
-    case 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 )
     {
-      return "VSYNC";
-    }
-
-    case START:
-    {
-      return "START";
-    }
-
-    case END:
-    {
-      return "END";
-    }
-
-    default:
-    {
-      DALI_ASSERT_DEBUG( !"Unsupported MarkerType" );
-      return "";
+      mEnvironmentOptions.InstallLogFunction();
+      mLogFunctionInstalled = true;
     }
   }
-}
 
-void PerformanceServer::StatContext::LogMarker( const PerformanceMarker& marker )
-{
-  // Add Marker can be called from any thread
-  boost::mutex::scoped_lock sharedDatalock( mDataMutex );
+  // Get the time
+  unsigned int seconds = 0;
+  unsigned int microseconds = 0;
+  mPlatformAbstraction.GetTimeMicroseconds( seconds, microseconds );
 
-  mMarkers.PushBack( marker );
+  // Create a marker
+  PerformanceMarker marker( markerType, FrameTimeStamp( 0, seconds, microseconds ) );
 
-  // Only log on the v-sync thread, so we have less impact on update/render
-  if( marker.GetType() == VSYNC )
-  {
-    // log out every mLogFrequency.
-    // check difference between first and last frame
-    unsigned int microseconds = PerformanceMarker::MicrosecondDiff( mMarkers[0], marker );
-    if( microseconds >= mLogFrequencyMicroseconds )
-    {
-      TimeMarkers();
+  // log it
+  LogMarker(marker, marker.GetName() );
 
-      if( mLog )
-      {
-        LogMarker();
-      }
+  // Add internal marker to statistics context manager
+  mStatContextManager.AddInternalMarker( marker );
 
-      mStats.Reset();     // reset data for statistics
-    }
-  }
 }
 
-void PerformanceServer::StatContext::SetLogFrequency( unsigned int frequencyMicroseconds )
+void PerformanceServer::LogContextStatistics( const char* const text )
 {
-  mLogFrequencyMicroseconds = frequencyMicroseconds;
+  Integration::Log::LogMessage( Dali::Integration::Log::DebugInfo, text );
 }
 
-void PerformanceServer::StatContext::EnableLogging( bool enableLogging )
+void PerformanceServer::LogMarker( const PerformanceMarker& marker, const char* const description )
 {
-  mLog = enableLogging;
-}
 
-const char* PerformanceServer::StatContext::GetName() const
-{
-  return mName;
-}
 
-unsigned int PerformanceServer::StatContext::GetId() const
-{
-  return mId;
+
+  // log to kernel trace
+  if( mPerformanceOutputBitmask & OUTPUT_KERNEL_TRACE )
+  {
+    // name will be something like UPDATE_START or UPDATE_END
+    mKernelTrace.Trace( description );
+  }
+
+  // log to Dali log
+  if ( mPerformanceOutputBitmask & OUTPUT_DALI_LOG )
+  {
+    Integration::Log::LogMessage( Dali::Integration::Log::DebugInfo,
+                                    "%d.%06d (seconds), %s\n",
+                                    marker.GetTimeStamp().seconds,
+                                    marker.GetTimeStamp().microseconds,
+                                    description);
+  }
 }
 
+
 } // namespace Internal
 
 } // namespace Adaptor