From ac9f8588137ad8331568649139ebef5647f47833 Mon Sep 17 00:00:00 2001 From: Simon Richter Date: Sat, 31 Dec 2016 08:15:20 +0100 Subject: [PATCH] Performance counter rework --- common/gal/opengl/cached_container.cpp | 15 ++-- common/gal/opengl/gpu_manager.cpp | 10 ++- common/gal/opengl/opengl_gal.cpp | 10 ++- common/view/view.cpp | 5 +- include/profile.h | 94 +++++++------------------- 5 files changed, 40 insertions(+), 94 deletions(-) diff --git a/common/gal/opengl/cached_container.cpp b/common/gal/opengl/cached_container.cpp index bea0dec3f7..84fbe51375 100644 --- a/common/gal/opengl/cached_container.cpp +++ b/common/gal/opengl/cached_container.cpp @@ -342,8 +342,7 @@ void CACHED_CONTAINER::mergeFreeChunks() return; #ifdef __WXDEBUG__ - prof_counter totalTime; - prof_start( &totalTime ); + PROF_COUNTER totalTime( "CACHED_CONTAINER::mergeFreeChunks()", true ); #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_start( &totalTime ); + PROF_COUNTER totalTime( "CACHED_CONTAINER::defragmentResize()", true ); #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_start( &totalTime ); + PROF_COUNTER totalTime( "CACHED_CONTAINER::defragmentResizeMemcpy()", true ); #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" ), diff --git a/common/gal/opengl/gpu_manager.cpp b/common/gal/opengl/gpu_manager.cpp index dc4f210094..0ee32d10fc 100644 --- a/common/gal/opengl/gpu_manager.cpp +++ b/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_start( &totalRealTime ); + PROF_COUNTER totalRealTime( "GPU_CACHED_MANAGER::EndDrawing()", true ); #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_start( &totalRealTime ); + PROF_COUNTER totalRealTime( "GPU_NONCACHED_MANAGER::EndDrawing()", true ); #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__ */ diff --git a/common/gal/opengl/opengl_gal.cpp b/common/gal/opengl/opengl_gal.cpp index 3c4cfe2c50..c24e28b344 100644 --- a/common/gal/opengl/opengl_gal.cpp +++ b/common/gal/opengl/opengl_gal.cpp @@ -193,8 +193,7 @@ void OPENGL_GAL::BeginDrawing() return; #ifdef __WXDEBUG__ - prof_counter totalRealTime; - prof_start( &totalRealTime ); + PROF_COUNTER totalRealTime( "OPENGL_GAL::BeginDrawing()", true ); #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_start( &totalRealTime ); + PROF_COUNTER totalRealTime( "OPENGL_GAL::EndDrawing()", true ); #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__ */ } diff --git a/common/view/view.cpp b/common/view/view.cpp index 769d361c29..c4f09f5cf0 100644 --- a/common/view/view.cpp +++ b/common/view/view.cpp @@ -1000,8 +1000,7 @@ void VIEW::ClearTargets() void VIEW::Redraw() { #ifdef __WXDEBUG__ - prof_counter totalRealTime; - prof_start( &totalRealTime ); + PROF_COUNTER totalRealTime( "VIEW::Redraw()", true ); #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__ */ } diff --git a/include/profile.h b/include/profile.h index d3cb30bd29..81d04a023a 100644 --- a/include/profile.h +++ b/include/profile.h @@ -3,6 +3,7 @@ * * Copyright (C) 2013 CERN * @author Tomasz Wlostowski + * 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 -#include - -#include +#include #include - -/** - * 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(); -} +#include +#include 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; - prof_end( &m_cnt ); + stoptime = std::chrono::system_clock::now(); } void show() { - stop(); - fprintf( stderr, "%s took %.1f milliseconds.\n", m_name.c_str(), (double)m_cnt.msecs() ); - start(); + time_point display_stoptime; + + if( m_running ) + display_stoptime = std::chrono::system_clock::now(); + else + display_stoptime = stoptime; + + std::chrono::duration 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 d = stoptime - starttime; + return d.count(); } private: std::string m_name; - prof_counter m_cnt; bool m_running; + + typedef std::chrono::time_point time_point; + + time_point starttime, stoptime; };