Improved performance logging
[platform/core/uifw/dali-adaptor.git] / adaptors / base / performance-logging / performance-server.cpp
index 03202aa..2736ad2 100644 (file)
@@ -20,6 +20,7 @@
 
 // INTERNAL INCLUDES
 #include <base/environment-options.h>
+#include <dali/integration-api/platform-abstraction.h>
 
 namespace Dali
 {
@@ -30,28 +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
-}
-
-
 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() ),
+ mStatContextManager( *this ),
+ mStatisticsLogBitmask( 0 ),
+ mLoggingEnabled( false ),
+ mLogFunctionInstalled( false )
 {
-  SetLogging( mEnvironmentOptions.GetPerformanceLoggingLevel(), mEnvironmentOptions.GetFrameRateLoggingFrequency());
+  SetLogging( mEnvironmentOptions.GetPerformanceStatsLoggingOptions(),
+              mEnvironmentOptions.GetPerformanceTimeStampOutput(),
+              mEnvironmentOptions.GetPerformanceStatsLoggingFrequency());
 }
 
 PerformanceServer::~PerformanceServer()
@@ -61,155 +53,147 @@ PerformanceServer::~PerformanceServer()
     mEnvironmentOptions.UnInstallLogFunction();
   }
 }
-void PerformanceServer::SetLogging( unsigned int level, unsigned int interval)
+
+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;
 
-  mLogFrequencyMicroseconds = interval * MICROSECONDS_PER_SECOND;
+  mStatisticsLogBitmask = statisticsLogOptions;
+  mPerformanceOutputBitmask = timeStampOutput;
+
+  mStatContextManager.SetLoggingLevel( mStatisticsLogBitmask, logFrequency);
 
-  if( mLogFrequencyMicroseconds == 0 )
-  {
-    mLogFrequencyMicroseconds = DEFAULT_LOG_FREQUENCEY * MICROSECONDS_PER_SECOND;
-  }
   mLoggingEnabled = true;
+}
 
+void PerformanceServer::SetLoggingFrequency( unsigned int logFrequency, ContextId contextId )
+{
+  mStatContextManager.SetLoggingFrequency( logFrequency, contextId );
 }
 
-void PerformanceServer::AddMarker( PerformanceMarker::MarkerType markerType )
+void PerformanceServer::EnableLogging( bool enable, ContextId contextId )
 {
+  mStatContextManager.EnableLogging( enable, contextId );
+}
+
+PerformanceInterface::ContextId PerformanceServer::AddContext( const char* name )
+{
+  // for adding custom contexts
+  return mStatContextManager.AddContext( name, PerformanceMarker::CUSTOM_EVENTS );
+}
+
+void PerformanceServer::RemoveContext( ContextId contextId )
+{
+  mStatContextManager.RemoveContext( contextId );
+}
+
+void PerformanceServer::AddMarker( MarkerType markerType, ContextId contextId )
+{
+  // called only for custom markers
+
   if( !mLoggingEnabled )
   {
     return;
   }
 
-  unsigned int seconds(0);
-  unsigned int microseconds(0);
+  // 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
+  // Get the time stamp
+  unsigned int seconds = 0;
+  unsigned int microseconds = 0;
   mPlatformAbstraction.GetTimeMicroseconds( seconds, microseconds );
 
-  // create a marker
-  PerformanceMarker marker( markerType, FrameTimeStamp( 0, seconds, microseconds ));
+  // Create a marker
+  PerformanceMarker marker( markerType, FrameTimeStamp( 0, seconds, microseconds ) );
+
+  // get the marker description for this context, e.g SIZE_NEGOTIATION_START
+  const char* const description = mStatContextManager.GetMarkerDescription( markerType, contextId );
+
+  // log it
+  LogMarker( marker, description );
+
+  // Add custom marker to statistics context manager
+  mStatContextManager.AddCustomMarker( marker, contextId );
 
-  AddMarkerToLog( marker );
 }
 
-void PerformanceServer::AddMarkerToLog( PerformanceMarker marker )
+void PerformanceServer::AddMarker( MarkerType markerType )
 {
-  // Add Marker can be called from any thread
-  boost::mutex::scoped_lock sharedDatalock( mDataMutex );
+  // called only for internal markers
 
-  // store the marker
-  mMarkers.PushBack( marker );
-
-  if( mLogLevel & LOG_EVENTS_TO_KERNEL )
+  if( !mLoggingEnabled )
   {
-    mKernelTrace.Trace(marker.GetName());
+    return;
   }
 
-  // only log on the v-sync thread, so we have less impact on update/render
-  if( marker.GetType() != PerformanceMarker::V_SYNC )
+  // 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 );
+
+  if( markerType == VSYNC )
   {
-    return;
+    // 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 out every mLogFrequency.
-  // check difference between first and last frame
-  unsigned int microseconds = PerformanceMarker::MicrosecondDiff( mMarkers[0], marker );
+  // Get the time
+  unsigned int seconds = 0;
+  unsigned int microseconds = 0;
+  mPlatformAbstraction.GetTimeMicroseconds( seconds, microseconds );
 
-  if( microseconds  >=  mLogFrequencyMicroseconds )
-  {
-    LogMarkers( );
-    mMarkers.Clear();
+  // Create a marker
+  PerformanceMarker marker( markerType, FrameTimeStamp( 0, seconds, microseconds ) );
+
+  // log it
+  LogMarker(marker, marker.GetName() );
+
+  // Add internal marker to statistics context manager
+  mStatContextManager.AddInternalMarker( marker );
 
-    // reset data for update / render statistics
-    mUpdateStats.Reset();
-    mRenderStats.Reset();
-    mEventStats.Reset();
-  }
 }
 
-void PerformanceServer::LogMarker(const char* name, const FrameTimeStats& frameStats)
+void PerformanceServer::LogContextStatistics( const char* const text )
 {
-  // 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;
-  }
-
-  // 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);
+  Integration::Log::LogMessage( Dali::Integration::Log::DebugInfo, text );
 }
 
-void PerformanceServer::LogMarkers()
+void PerformanceServer::LogMarker( const PerformanceMarker& marker, const char* const description )
 {
-  // insert time stamps into a frame-time-stats object, based on type
-  for( MarkerVector::SizeType i = 0; i < mMarkers.Size(); ++i)
-  {
-    const PerformanceMarker& marker = mMarkers[i];
-    switch( marker.GetType() )
-    {
-      case PerformanceMarker::UPDATE_START:
-      {
-        mUpdateStats.StartTime( marker.GetTimeStamp() );
-        break;
-      }
-      case PerformanceMarker::UPDATE_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() );
-        break;
-      }
-      default:
-      {
-        break;
-      }
-    }
-  }
-  if( mLogLevel & LOG_UPDATE_RENDER )
+
+
+
+  // log to kernel trace
+  if( mPerformanceOutputBitmask & OUTPUT_KERNEL_TRACE )
   {
-    LogMarker("Update",mUpdateStats);
-    LogMarker("Render",mRenderStats);
+    // name will be something like UPDATE_START or UPDATE_END
+    mKernelTrace.Trace( description );
   }
-  if( mLogLevel & LOG_EVENT_PROCESS )
+
+  // log to Dali log
+  if ( mPerformanceOutputBitmask & OUTPUT_DALI_LOG )
   {
-    LogMarker("Event",mEventStats);
+    Integration::Log::LogMessage( Dali::Integration::Log::DebugInfo,
+                                    "%d.%06d (seconds), %s\n",
+                                    marker.GetTimeStamp().seconds,
+                                    marker.GetTimeStamp().microseconds,
+                                    description);
   }
-
 }
 
+
 } // namespace Internal
 
 } // namespace Adaptor