adaptors/base/performance-logging/performance-server.cpp

   1 /*
   2  * Copyright (c) 2014 Samsung Electronics Co., Ltd.
   3  *
   4  * Licensed under the Apache License, Version 2.0 (the "License");
   5  * you may not use this file except in compliance with the License.
   6  * You may obtain a copy of the License at
   7  *
   8  * http://www.apache.org/licenses/LICENSE-2.0
   9  *
  10  * Unless required by applicable law or agreed to in writing, software
  11  * distributed under the License is distributed on an "AS IS" BASIS,
  12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  13  * See the License for the specific language governing permissions and
  14  * limitations under the License.
  15  *
  16  */
  17
  18 // CLASS HEADER
  19 #include "performance-server.h"
  20
  21 // INTERNAL INCLUDES
  22 #include <base/environment-options.h>
  23 #include <dali/integration-api/platform-abstraction.h>
  24
  25 namespace Dali
  26 {
  27
  28 namespace Internal
  29 {
  30
  31 namespace Adaptor
  32 {
  33
  34 #define TIME_FMT "%0.2f ms" // 2 decimal places, e.g. 5.34 ms
  35 #define TOTAL_TIME_FMT "%0.1f secs" // 1 decimal place, e.g. 4.5 seconds
  36
  37
  38 namespace
  39 {
  40
  41 const unsigned int DEFAULT_LOG_FREQUENCEY = 2;        ///< default log frequency = 2
  42 const unsigned int MILLISECONDS_PER_SECOND = 1000;    ///< 1000 milliseconds per second
  43 const unsigned int MICROSECONDS_PER_SECOND = 1000000; ///< 1000000 microseconds per second
  44
  45 const char* UPDATE_CONTEXT_NAME = "Update";
  46 const char* RENDER_CONTEXT_NAME = "Render";
  47 const char* EVENT_CONTEXT_NAME = "Event";
  48
  49 } // Anonymous namespace
  50
  51
  52 PerformanceServer::PerformanceServer( AdaptorInternalServices& adaptorServices,
  53                                       const EnvironmentOptions& environmentOptions)
  54 :mPlatformAbstraction( adaptorServices.GetPlatformAbstractionInterface() ),
  55  mEnvironmentOptions( environmentOptions ),
  56  mKernelTrace( adaptorServices.GetKernelTraceInterface() ),
  57  mLogLevel( 0 ),
  58  mNextContextId( 0 ),
  59  mLoggingEnabled( false ),
  60  mLogFunctionInstalled( false )
  61 {
  62   // Add defaults
  63   mUpdateStats = AddContext( UPDATE_CONTEXT_NAME );
  64   mRenderStats = AddContext( RENDER_CONTEXT_NAME );
  65   mEventStats = AddContext( EVENT_CONTEXT_NAME );
  66
  67   SetLogging( mEnvironmentOptions.GetPerformanceLoggingLevel(), mEnvironmentOptions.GetFrameRateLoggingFrequency());
  68 }
  69
  70 PerformanceServer::~PerformanceServer()
  71 {
  72   if( mLogFunctionInstalled )
  73   {
  74     mEnvironmentOptions.UnInstallLogFunction();
  75   }
  76
  77   for( StatContexts::Iterator it = mStatContexts.Begin(), itEnd = mStatContexts.End(); it != itEnd; ++it )
  78   {
  79     StatContext* context = *it;
  80
  81     delete context;
  82   }
  83 }
  84
  85 void PerformanceServer::SetLogging( unsigned int level, unsigned int logFrequency)
  86 {
  87   if( level == 0 )
  88   {
  89     mLoggingEnabled = false;
  90     return;
  91   }
  92   mLogLevel = level;
  93
  94   EnableLogging( mLogLevel & LOG_UPDATE_RENDER, mUpdateStats );
  95   EnableLogging( mLogLevel & LOG_UPDATE_RENDER, mRenderStats );
  96   EnableLogging( mLogLevel & LOG_EVENT_PROCESS, mEventStats );
  97
  98   SetLoggingFrequency( logFrequency, mUpdateStats );
  99   SetLoggingFrequency( logFrequency, mRenderStats );
 100   SetLoggingFrequency( logFrequency, mEventStats );
 101
 102   mLoggingEnabled = true;
 103 }
 104
 105 void PerformanceServer::SetLoggingFrequency( unsigned int logFrequency, ContextId contextId )
 106 {
 107   StatContext* context = GetContext( contextId );
 108   if( context )
 109   {
 110     unsigned int logFrequencyMicroseconds = logFrequency * MICROSECONDS_PER_SECOND;
 111
 112     if( logFrequencyMicroseconds == 0 )
 113     {
 114       logFrequencyMicroseconds = DEFAULT_LOG_FREQUENCEY * MICROSECONDS_PER_SECOND;
 115     }
 116
 117     context->SetLogFrequency( logFrequencyMicroseconds );
 118   }
 119 }
 120
 121 void PerformanceServer::EnableLogging( bool enable, ContextId contextId )
 122 {
 123   StatContext* context = GetContext( contextId );
 124   if( context )
 125   {
 126     context->EnableLogging( enable );
 127   }
 128 }
 129
 130 PerformanceServer::StatContext::StatContext()
 131 : mName( NULL ),
 132   mId( 0 ),
 133   mLogFrequencyMicroseconds( DEFAULT_LOG_FREQUENCEY * MICROSECONDS_PER_SECOND ),
 134   mLog( true )
 135 {
 136 }
 137
 138 PerformanceServer::StatContext::StatContext( unsigned int id, const char* contextName )
 139 : mName( contextName ),
 140   mId( id ),
 141   mLogFrequencyMicroseconds( DEFAULT_LOG_FREQUENCEY * MICROSECONDS_PER_SECOND ),
 142   mLog( true )
 143 {
 144 }
 145
 146 PerformanceInterface::ContextId PerformanceServer::AddContext( const char* name )
 147 {
 148   unsigned int contextId = mNextContextId++;
 149
 150   DALI_ASSERT_DEBUG( !GetContext( contextId ) );
 151
 152   mStatContexts.PushBack( new StatContext( contextId, name ) );
 153
 154   return contextId;
 155 }
 156
 157 void PerformanceServer::RemoveContext( ContextId contextId )
 158 {
 159   for( StatContexts::Iterator it = mStatContexts.Begin(), itEnd = mStatContexts.End(); it != itEnd; ++it )
 160   {
 161     StatContext* context = *it;
 162
 163     if( context->GetId() == contextId )
 164     {
 165       delete context;
 166
 167       mStatContexts.Erase( it );
 168       break;
 169     }
 170   }
 171 }
 172
 173 PerformanceServer::StatContext* PerformanceServer::GetContext( ContextId contextId )
 174 {
 175   for( StatContexts::Iterator it = mStatContexts.Begin(), itEnd = mStatContexts.End(); it != itEnd; ++it )
 176   {
 177     StatContext* context = *it;
 178
 179     if( context->GetId() == contextId )
 180     {
 181       return context;
 182     }
 183   }
 184
 185   return NULL;
 186 }
 187
 188 void PerformanceServer::AddMarker( MarkerType markerType )
 189 {
 190   switch( markerType )
 191   {
 192     case VSYNC:
 193     {
 194       for( StatContexts::Iterator it = mStatContexts.Begin(), itEnd = mStatContexts.End(); it != itEnd; ++it )
 195       {
 196         StatContext* context = *it;
 197
 198         AddMarker( VSYNC, context->GetId() );
 199       }
 200       break;
 201     }
 202     case UPDATE_START:
 203     {
 204       AddMarker( START, mUpdateStats );
 205       break;
 206     }
 207     case UPDATE_END:
 208     {
 209       AddMarker( END, mUpdateStats );
 210       break;
 211     }
 212     case RENDER_START:
 213     {
 214       AddMarker( START, mRenderStats );
 215       break;
 216     }
 217     case RENDER_END:
 218     {
 219       AddMarker( END, mRenderStats );
 220       break;
 221     }
 222     case PROCESS_EVENTS_START:
 223     {
 224       AddMarker( START, mEventStats );
 225       break;
 226     }
 227     case PROCESS_EVENTS_END:
 228     {
 229       AddMarker( END, mEventStats );
 230       break;
 231     }
 232     default:
 233     {
 234       break;
 235     }
 236   }
 237 }
 238
 239 void PerformanceServer::AddMarker( MarkerType markerType, ContextId contextId )
 240 {
 241   if( !mLoggingEnabled )
 242   {
 243     return;
 244   }
 245
 246   // Get the time
 247   unsigned int seconds = 0;
 248   unsigned int microseconds = 0;
 249   mPlatformAbstraction.GetTimeMicroseconds( seconds, microseconds );
 250
 251   // Create a marker and add it to the log
 252   PerformanceMarker marker( markerType, FrameTimeStamp( 0, seconds, microseconds ) );
 253   AddMarkerToLog( marker, contextId );
 254 }
 255
 256 void PerformanceServer::AddMarkerToLog( const PerformanceMarker& marker, ContextId contextId )
 257 {
 258   StatContext* context = GetContext( contextId );
 259   if( context )
 260   {
 261     if( mLogLevel & LOG_EVENTS_TO_KERNEL )
 262     {
 263       std::stringstream ss;
 264       ss << GetMarkerName( marker.GetType() ) << ":" << ( ( context->GetName() ) ? context->GetName() : "" );
 265       mKernelTrace.Trace( ss.str() );
 266     }
 267
 268     // Only log on the v-sync thread, so we have less impact on update/render
 269     if( marker.GetType() == VSYNC )
 270     {
 271       // make sure log function is installed, note this will be called only from v-sync thread
 272       // if the v-sync thread has already installed one, it won't make any difference.
 273       if( !mLogFunctionInstalled )
 274       {
 275         mEnvironmentOptions.InstallLogFunction();
 276         mLogFunctionInstalled = true;
 277       }
 278     }
 279
 280     context->LogMarker( marker );
 281   }
 282 }
 283
 284 void PerformanceServer::StatContext::LogMarker()
 285 {
 286   float mean, standardDeviation;
 287   mStats.CalculateMean( mean, standardDeviation );
 288
 289   // this will always log regardless of debug / release mode
 290   Integration::Log::LogMessage( Dali::Integration::Log::DebugInfo,
 291                                     "%s, min " TIME_FMT ", max " TIME_FMT ", total (" TOTAL_TIME_FMT "), avg " TIME_FMT ", std dev " TIME_FMT "\n",
 292                                      ( mName ) ? mName : "",
 293                                      mStats.GetMinTime() * MILLISECONDS_PER_SECOND,
 294                                      mStats.GetMaxTime() * MILLISECONDS_PER_SECOND,
 295                                      mStats.GetTotalTime(),
 296                                      mean * MILLISECONDS_PER_SECOND,
 297                                      standardDeviation * MILLISECONDS_PER_SECOND);
 298 }
 299
 300 void PerformanceServer::StatContext::TimeMarkers()
 301 {
 302   // insert time stamps into a frame-time-stats object, based on type
 303   for( MarkerVector::SizeType i = 0; i < mMarkers.Size(); ++i)
 304   {
 305     const PerformanceMarker& marker = mMarkers[i];
 306     switch( marker.GetType() )
 307     {
 308       case START:
 309       {
 310         mStats.StartTime( marker.GetTimeStamp() );
 311         break;
 312       }
 313       case END:
 314       {
 315         mStats.EndTime( marker.GetTimeStamp() );
 316         break;
 317       }
 318       default:
 319       {
 320         break;
 321       }
 322     }
 323   }
 324
 325   mMarkers.Clear();
 326 }
 327
 328 const char* PerformanceServer::GetMarkerName( MarkerType type ) const
 329 {
 330   switch( type )
 331   {
 332     case VSYNC:
 333     {
 334       return "VSYNC";
 335     }
 336
 337     case START:
 338     {
 339       return "START";
 340     }
 341
 342     case END:
 343     {
 344       return "END";
 345     }
 346
 347     default:
 348     {
 349       DALI_ASSERT_DEBUG( !"Unsupported MarkerType" );
 350       return "";
 351     }
 352   }
 353 }
 354
 355 void PerformanceServer::StatContext::LogMarker( const PerformanceMarker& marker )
 356 {
 357   // Add Marker can be called from any thread
 358   boost::mutex::scoped_lock sharedDatalock( mDataMutex );
 359
 360   mMarkers.PushBack( marker );
 361
 362   // Only log on the v-sync thread, so we have less impact on update/render
 363   if( marker.GetType() == VSYNC )
 364   {
 365     // log out every mLogFrequency.
 366     // check difference between first and last frame
 367     unsigned int microseconds = PerformanceMarker::MicrosecondDiff( mMarkers[0], marker );
 368     if( microseconds >= mLogFrequencyMicroseconds )
 369     {
 370       TimeMarkers();
 371
 372       if( mLog )
 373       {
 374         LogMarker();
 375       }
 376
 377       mStats.Reset();     // reset data for statistics
 378     }
 379   }
 380 }
 381
 382 void PerformanceServer::StatContext::SetLogFrequency( unsigned int frequencyMicroseconds )
 383 {
 384   mLogFrequencyMicroseconds = frequencyMicroseconds;
 385 }
 386
 387 void PerformanceServer::StatContext::EnableLogging( bool enableLogging )
 388 {
 389   mLog = enableLogging;
 390 }
 391
 392 const char* PerformanceServer::StatContext::GetName() const
 393 {
 394   return mName;
 395 }
 396
 397 unsigned int PerformanceServer::StatContext::GetId() const
 398 {
 399   return mId;
 400 }
 401
 402 } // namespace Internal
 403
 404 } // namespace Adaptor
 405
 406 } // namespace Dali