Performance counter rework

common/gal/opengl/cached_container.cpp

@@ -342,8 +342,7 @@ void CACHED_CONTAINER::mergeFreeChunks()
         return;
 
 #ifdef __WXDEBUG__
-    prof_counter totalTime;
+    PROF_COUNTER totalTime( "CACHED_CONTAINER::mergeFreeChunks()", true );
-    prof_start( &totalTime );
 #endif /* __WXDEBUG__ */
 
     // Reversed free chunks map - this one stores chunk size with its offset as the key
@@ -387,7 +386,7 @@ void CACHED_CONTAINER::mergeFreeChunks()
     m_freeChunks.insert( std::make_pair( size, offset ) );
 
 #ifdef __WXDEBUG__
-    prof_end( &totalTime );
+    totalTime.stop();
 
     wxLogDebug( wxT( "Merged free chunks / %.1f ms" ), totalTime.msecs() );
 #endif /* __WXDEBUG__ */
@@ -412,8 +411,7 @@ bool CACHED_CONTAINER::defragmentResize( unsigned int aNewSize )
         return false;
 
 #ifdef __WXDEBUG__
-    prof_counter totalTime;
+    PROF_COUNTER totalTime( "CACHED_CONTAINER::defragmentResize()", true );
-    prof_start( &totalTime );
 #endif /* __WXDEBUG__ */
 
     GLuint newBuffer;
@@ -481,7 +479,7 @@ bool CACHED_CONTAINER::defragmentResize( unsigned int aNewSize )
     checkGlError( "switching buffers during defragmentation" );
 
 #ifdef __WXDEBUG__
-    prof_end( &totalTime );
+    totalTime.stop();
 
     wxLogTrace( "GAL_CACHED_CONTAINER",
             wxT( "Defragmented container storing %d vertices / %.1f ms" ),
@@ -512,8 +510,7 @@ bool CACHED_CONTAINER::defragmentResizeMemcpy( unsigned int aNewSize )
         return false;
 
 #ifdef __WXDEBUG__
-    prof_counter totalTime;
+    PROF_COUNTER totalTime( "CACHED_CONTAINER::defragmentResizeMemcpy()", true );
-    prof_start( &totalTime );
 #endif /* __WXDEBUG__ */
 
     GLuint newBuffer;
@@ -575,7 +572,7 @@ bool CACHED_CONTAINER::defragmentResizeMemcpy( unsigned int aNewSize )
     checkGlError( "switching buffers during defragmentation" );
 
 #ifdef __WXDEBUG__
-    prof_end( &totalTime );
+    totalTime.stop();
 
     wxLogTrace( "GAL_CACHED_CONTAINER",
             wxT( "Defragmented container storing %d vertices / %.1f ms" ),

common/gal/opengl/gpu_manager.cpp

@@ -145,8 +145,7 @@ void GPU_CACHED_MANAGER::DrawAll()
 void GPU_CACHED_MANAGER::EndDrawing()
 {
 #ifdef __WXDEBUG__
-    prof_counter totalRealTime;
+    PROF_COUNTER totalRealTime( "GPU_CACHED_MANAGER::EndDrawing()", true );
-    prof_start( &totalRealTime );
 #endif /* __WXDEBUG__ */
 
     wxASSERT( m_isDrawing );
@@ -205,7 +204,7 @@ void GPU_CACHED_MANAGER::EndDrawing()
     m_isDrawing = false;
 
 #ifdef __WXDEBUG__
-    prof_end( &totalRealTime );
+    totalRealTime.stop();
     wxLogTrace( "GAL_PROFILE",
                 wxT( "GPU_CACHED_MANAGER::EndDrawing(): %.1f ms" ), totalRealTime.msecs() );
 #endif /* __WXDEBUG__ */
@@ -251,8 +250,7 @@ void GPU_NONCACHED_MANAGER::DrawAll()
 void GPU_NONCACHED_MANAGER::EndDrawing()
 {
 #ifdef __WXDEBUG__
-    prof_counter totalRealTime;
+    PROF_COUNTER totalRealTime( "GPU_NONCACHED_MANAGER::EndDrawing()", true );
-    prof_start( &totalRealTime );
 #endif /* __WXDEBUG__ */
 
     if( m_container->GetSize() == 0 )
@@ -296,7 +294,7 @@ void GPU_NONCACHED_MANAGER::EndDrawing()
     }
 
 #ifdef __WXDEBUG__
-    prof_end( &totalRealTime );
+    totalRealTime.stop();
     wxLogTrace( "GAL_PROFILE",
                 wxT( "GPU_NONCACHED_MANAGER::EndDrawing(): %.1f ms" ), totalRealTime.msecs() );
 #endif /* __WXDEBUG__ */

common/gal/opengl/opengl_gal.cpp

@@ -193,8 +193,7 @@ void OPENGL_GAL::BeginDrawing()
         return;
 
 #ifdef __WXDEBUG__
-    prof_counter totalRealTime;
+    PROF_COUNTER totalRealTime( "OPENGL_GAL::BeginDrawing()", true );
-    prof_start( &totalRealTime );
 #endif /* __WXDEBUG__ */
 
     GL_CONTEXT_MANAGER::Get().LockCtx( glPrivContext, this );
@@ -308,7 +307,7 @@ void OPENGL_GAL::BeginDrawing()
     compositor->SetBuffer( OPENGL_COMPOSITOR::DIRECT_RENDERING );
 
 #ifdef __WXDEBUG__
-    prof_end( &totalRealTime );
+    totalRealTime.stop();
     wxLogTrace( "GAL_PROFILE",
                 wxT( "OPENGL_GAL::BeginDrawing(): %.1f ms" ), totalRealTime.msecs() );
 #endif /* __WXDEBUG__ */
@@ -318,8 +317,7 @@ void OPENGL_GAL::BeginDrawing()
 void OPENGL_GAL::EndDrawing()
 {
 #ifdef __WXDEBUG__
-    prof_counter totalRealTime;
+    PROF_COUNTER totalRealTime( "OPENGL_GAL::EndDrawing()", true );
-    prof_start( &totalRealTime );
 #endif /* __WXDEBUG__ */
 
     // Cached & non-cached containers are rendered to the same buffer
@@ -343,7 +341,7 @@ void OPENGL_GAL::EndDrawing()
     GL_CONTEXT_MANAGER::Get().UnlockCtx( glPrivContext );
 
 #ifdef __WXDEBUG__
-    prof_end( &totalRealTime );
+    totalRealTime.stop();
     wxLogTrace( "GAL_PROFILE", wxT( "OPENGL_GAL::EndDrawing(): %.1f ms" ), totalRealTime.msecs() );
 #endif /* __WXDEBUG__ */
 }

common/view/view.cpp

@@ -1000,8 +1000,7 @@ void VIEW::ClearTargets()
 void VIEW::Redraw()
 {
 #ifdef __WXDEBUG__
-    prof_counter totalRealTime;
+    PROF_COUNTER totalRealTime( "VIEW::Redraw()", true );
-    prof_start( &totalRealTime );
 #endif /* __WXDEBUG__ */
 
     VECTOR2D screenSize = m_gal->GetScreenPixelSize();
@@ -1017,7 +1016,7 @@ void VIEW::Redraw()
     markTargetClean( TARGET_OVERLAY );
 
 #ifdef __WXDEBUG__
-    prof_end( &totalRealTime );
+    totalRealTime.stop();
     wxLogTrace( "GAL_PROFILE", wxT( "VIEW::Redraw(): %.1f ms" ), totalRealTime.msecs() );
 #endif /* __WXDEBUG__ */
 }

include/profile.h

@@ -3,6 +3,7 @@
  *
  * Copyright (C) 2013 CERN
  * @author Tomasz Wlostowski <tomasz.wlostowski@cern.ch>
+ * 2016 KiCad Developers, see AUTHORS.txt for contributors.
  *
  * This program is free software; you can redistribute it and/or
  * modify it under the terms of the GNU General Public License
@@ -30,74 +31,18 @@
 #ifndef __TPROFILE_H
 #define __TPROFILE_H
 
-#include <sys/time.h>
+#include <chrono>
-#include <stdint.h>
-
-#include <cstdio>
 #include <string>
-
+#include <iostream>
-/**
+#include <iomanip>
- * Function get_tics
- * Returns the number of microseconds that have elapsed since the system was started.
- * @return uint64_t Number of microseconds.
- */
-static inline uint64_t get_tics()
-{
-    struct timeval tv;
-    gettimeofday( &tv, NULL );
-
-    return (uint64_t) tv.tv_sec * 1000000ULL + (uint64_t) tv.tv_usec;
-}
-
-/**
- * Structure for storing data related to profiling counters.
- */
-struct prof_counter
-{
-    uint64_t start, end;         // Stored timer value
-
-    uint64_t usecs() const
-    {
-        return end - start;
-    }
-
-    float msecs() const
-    {
-        return ( end - start ) / 1000.0;
-    }
-};
-
-/**
- * Function prof_start
- * Begins code execution time counting for a given profiling counter.
- * @param aCnt is the counter which should be started.
- * use_rdtsc tells if processor's time-stamp counter should be used for time counting.
- *      Otherwise is system tics method will be used. IMPORTANT: time-stamp counter should not
- *      be used on multicore machines executing threaded code.
- */
-static inline void prof_start( prof_counter* aCnt )
-{
-    aCnt->start = get_tics();
-}
-
-/**
- * Function prof_stop
- * Ends code execution time counting for a given profiling counter.
- * @param aCnt is the counter which should be stopped.
- */
-static inline void prof_end( prof_counter* aCnt )
-{
-    aCnt->end = get_tics();
-}
 
 class PROF_COUNTER
 {
 public:
-    PROF_COUNTER( const std::string& name, bool autostart = true )
+    PROF_COUNTER( const std::string& name, bool autostart = true ) :
+        m_name( name ),
+        m_running( false )
     {
-        m_name = name;
-        m_running = false;
-
         if( autostart )
             start();
     }
@@ -105,7 +50,7 @@ public:
     void start()
     {
         m_running = true;
-        prof_start( &m_cnt );
+        starttime = std::chrono::system_clock::now();
     }
 
     void stop()
@@ -113,26 +58,35 @@ public:
         if( !m_running )
             return;
 
-        m_running = false;
+        stoptime = std::chrono::system_clock::now();
-        prof_end( &m_cnt );
     }
 
     void show()
     {
-        stop();
+        time_point display_stoptime;
-        fprintf( stderr, "%s took %.1f milliseconds.\n", m_name.c_str(), (double)m_cnt.msecs() );
+
-        start();
+        if( m_running )
+            display_stoptime = std::chrono::system_clock::now();
+        else
+            display_stoptime = stoptime;
+
+        std::chrono::duration<double, std::milli> d = display_stoptime - starttime;
+        std::cerr << m_name << " took " << std::setprecision(1) << d.count() << "milliseconds." << std::endl;
     }
 
     double msecs() const
     {
-        return m_cnt.msecs();
+        std::chrono::duration<double, std::milli> d = stoptime - starttime;
+        return d.count();
     }
 
 private:
     std::string m_name;
-    prof_counter m_cnt;
     bool m_running;
+
+    typedef std::chrono::time_point<std::chrono::high_resolution_clock> time_point;
+
+    time_point starttime, stoptime;
 };