From f39f074dcffce544ea4fef741f861a20b3992a77 Mon Sep 17 00:00:00 2001 From: redPanther Date: Sun, 5 Jun 2016 16:08:55 +0200 Subject: [PATCH] add logger/compiler class (#680) * implement make install set CMAKE_INSTALL_PREFIX e.g. to /opt to install to /opt/hyperion set ENABLE_SYSTEM_INSTALL to ON to activate installation after compiling use make install or make install/strip (for performance/size optimized binaries - compile in Release to get best performance) * cleanup cmake files use cmake -DINSTALL_PREFIX=/opt/hyperion .. to install all files to hyperion or cmake -DINSTALL_PREFIX=/usr/ to install to usr. install folders are linux standard. bin go to bin folder and additionals (effects) go to share/hyperion * add uninstall target - be patient with that, this will remove files from your system install service files to share/hyperion - if you want to use them you have to make a symlink to your location of service files * optimize build release script install service files into hyperion share folder (services not activated, this must be done by distribution package script) initial support of cmake option -DPLATFORM= option. This selects platform specific cmake flags. no need for -DENABLE_... options (unless you want some special things) automatic detect for apple build * update submodule * fix cmake error when no platform is given * initial support for deb,rpm and tgz packages - no usefull content atm! * make packeages contain usefull stuff * add license make packes more functional. package specific install missing yet * implement debian postinstall * disable rpm generation until it has a working state * add hypercon compat * add posibility for multiple config files. first one found is taken * remove hyperion comaptlayer services is not started automaticly * rework debian postinstall: - remove /opt compatibility complety. This makes more trouble as it is usefull - when hyperiond already started, restart it - cleanup * add deb package dependencies * wipe out last support for /opt installation * change default effect path in config to /usr * revert service files and config files * remove last occurences of ENABLE_PROTOBUF fix cmake warnings and make it ready for cmake 3 fix refactoring of hyperiond.cpp creates no objects for network services * all arguments via reference ... * fix xbmcchecker not working * add logger class * - profiler must be activated with ENABLE_PROFILER, otherwise an error will raise -> this should prevent profiler gets into release code * fix profiler Former-commit-id: b716dd40dbf5b837356eec876d85ec71c86d5c6c --- CMakeLists.txt | 3 ++ HyperionConfig.h.in | 4 ++ include/utils/Logger.h | 48 +++++++++++++++++ include/utils/Profiler.h | 37 +++++++++++++ libsrc/utils/CMakeLists.txt | 8 +++ libsrc/utils/Logger.cpp | 100 ++++++++++++++++++++++++++++++++++++ libsrc/utils/Profiler.cpp | 98 +++++++++++++++++++++++++++++++++++ 7 files changed, 298 insertions(+) create mode 100644 include/utils/Logger.h create mode 100644 include/utils/Profiler.h create mode 100644 libsrc/utils/Logger.cpp create mode 100644 libsrc/utils/Profiler.cpp diff --git a/CMakeLists.txt b/CMakeLists.txt index b86f4f15..b94e3068 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -81,6 +81,9 @@ message(STATUS "ENABLE_QT5 = " ${ENABLE_QT5}) option(ENABLE_TESTS "Compile additional test applications" OFF) message(STATUS "ENABLE_TESTS = " ${ENABLE_TESTS}) +option(ENABLE_PROFILER "enable profiler capabilities - not for release code" OFF) +message(STATUS "ENABLE_PROFILER = " ${ENABLE_PROFILER}) + if(ENABLE_FB AND ENABLE_DISPMANX) message(FATAL_ERROR "dispmanx grabber and framebuffer grabber cannot be used at the same time") diff --git a/HyperionConfig.h.in b/HyperionConfig.h.in index 135e41f9..3ce776b5 100644 --- a/HyperionConfig.h.in +++ b/HyperionConfig.h.in @@ -30,4 +30,8 @@ // Define to enable the bonjour/zeroconf publishing #cmakedefine ENABLE_ZEROCONF +// Define to enable profiler for development purpose +#cmakedefine ENABLE_PROFILER + +// the hyperion build id string #define HYPERION_VERSION_ID "${HYPERION_VERSION_ID}" diff --git a/include/utils/Logger.h b/include/utils/Logger.h new file mode 100644 index 00000000..77413150 --- /dev/null +++ b/include/utils/Logger.h @@ -0,0 +1,48 @@ +#pragma once + +#include +#include +#include +#include + +// standard log messages +//#define _FUNCNAME_ __PRETTY_FUNCTION__ +#define _FUNCNAME_ __FUNCTION__ + +#define Debug(logger, ...) { (logger)->Message(Logger::DEBUG , __FILE__, _FUNCNAME_, __LINE__, __VA_ARGS__); } +#define Info(logger, ...) { (logger)->Message(Logger::INFO , __FILE__, _FUNCNAME_, __LINE__, __VA_ARGS__); } +#define Warning(logger, ...) { (logger)->Message(Logger::WARNING, __FILE__, _FUNCNAME_, __LINE__, __VA_ARGS__); } +#define Error(logger, ...) { (logger)->Message(Logger::ERROR , __FILE__, _FUNCNAME_, __LINE__, __VA_ARGS__); } + +// conditional log messages +#define DebugIf(condition, logger, ...) { if (condition) {(logger)->Message(Logger::DEBUG , __FILE__, _FUNCNAME_, __LINE__, __VA_ARGS__);} } +#define InfoIf(condition, logger, ...) { if (condition) {(logger)->Message(Logger::INFO , __FILE__, _FUNCNAME_, __LINE__, __VA_ARGS__);} } +#define WarningIf(condition, logger, ...) { if (condition) {(logger)->Message(Logger::WARNING , __FILE__, _FUNCNAME_, __LINE__, __VA_ARGS__);} } +#define ErrorIf(condition, logger, ...) { if (condition) {(logger)->Message(Logger::ERROR , __FILE__, _FUNCNAME_, __LINE__, __VA_ARGS__);} } + +// ================================================================ + +class Logger +{ +public: + enum LogLevel { DEBUG=0, INFO=1,WARNING=2,ERROR=3 }; + + static Logger* getInstance(std::string name="", LogLevel minLevel=Logger::INFO); + + void Message(LogLevel level, const char* sourceFile, const char* func, unsigned int line, const char* fmt, ...); + void setMinLevel(LogLevel level) { _minLevel = level; }; + +protected: + Logger( std::string name="", LogLevel minLevel=INFO); + ~Logger(); + +private: + static std::map *LoggerMap; + + std::string _name; + std::string _appname; + LogLevel _minLevel; + bool _syslogEnabled; + unsigned int _loggerId; +}; + diff --git a/include/utils/Profiler.h b/include/utils/Profiler.h new file mode 100644 index 00000000..0b76f1c9 --- /dev/null +++ b/include/utils/Profiler.h @@ -0,0 +1,37 @@ +#include "utils/Logger.h" +#include +#include +#include +#include +#include + +#ifndef ENABLE_PROFILER + #error "Profiler is not for productive code, enable it via cmake or remove header include" +#endif + +// profiler +#define PROFILER_BLOCK_EXECUTION_TIME Profiler DEBUG_PROFILE__BLOCK__EXECUTION__TIME_messure_object(__FILE__, _FUNCNAME_, __LINE__ ); +#define PROFILER_TIMER_START(stopWatchName) Profiler::TimerStart(stopWatchName, __FILE__, _FUNCNAME_, __LINE__); +#define PROFILER_TIMER_GET(stopWatchName) Profiler::TimerGetTime(stopWatchName, __FILE__, _FUNCNAME_, __LINE__); +#define PROFILER_TIMER_GET_IF(condition, stopWatchName) { if (condition) {Profiler::TimerGetTime(stopWatchName, __FILE__, _FUNCNAME_, __LINE__);} } + + +class Profiler +{ +public: + Profiler(const char* sourceFile, const char* func, unsigned int line); + ~Profiler(); + + static void TimerStart(const std::string stopWatchName, const char* sourceFile, const char* func, unsigned int line); + static void TimerGetTime(const std::string stopWatchName, const char* sourceFile, const char* func, unsigned int line); + +private: + static void initLogger(); + + static Logger* _logger; + const char* _file; + const char* _func; + unsigned int _line; + unsigned int _blockId; + clock_t _startTime; +}; diff --git a/libsrc/utils/CMakeLists.txt b/libsrc/utils/CMakeLists.txt index caf0aabe..3e02ec6b 100644 --- a/libsrc/utils/CMakeLists.txt +++ b/libsrc/utils/CMakeLists.txt @@ -2,6 +2,10 @@ SET(CURRENT_HEADER_DIR ${CMAKE_SOURCE_DIR}/include/utils) SET(CURRENT_SOURCE_DIR ${CMAKE_SOURCE_DIR}/libsrc/utils) +if ( ENABLE_PROFILER ) + SET ( PROFILER_SOURCE ${CURRENT_HEADER_DIR}/Profiler.h ${CURRENT_SOURCE_DIR}/Profiler.cpp ) +endif() + add_library(hyperion-utils ${CURRENT_HEADER_DIR}/ColorArgb.h ${CURRENT_SOURCE_DIR}/ColorArgb.cpp @@ -16,6 +20,10 @@ add_library(hyperion-utils ${CURRENT_HEADER_DIR}/Image.h ${CURRENT_HEADER_DIR}/Sleep.h + ${CURRENT_HEADER_DIR}/Logger.h + ${CURRENT_SOURCE_DIR}/Logger.cpp + ${PROFILER_SOURCE} + ${CURRENT_HEADER_DIR}/PixelFormat.h ${CURRENT_HEADER_DIR}/VideoMode.h diff --git a/libsrc/utils/Logger.cpp b/libsrc/utils/Logger.cpp new file mode 100644 index 00000000..1b865d43 --- /dev/null +++ b/libsrc/utils/Logger.cpp @@ -0,0 +1,100 @@ +#include "utils/Logger.h" + +#include +#include +#include +#include +#include +#include + +std::string getBaseName( std::string sourceFile) +{ + QFileInfo fi( sourceFile.c_str() ); + return fi.fileName().toStdString(); +} + +static const char * LogLevelStrings[] = { "DEBUG", "INFO", "WARNING", "ERROR" }; +static const int LogLevelSysLog[] = { LOG_DEBUG, LOG_INFO, LOG_WARNING, LOG_ERR }; +static unsigned int loggerCount = 0; +static unsigned int loggerId = 0; +std::map *Logger::LoggerMap = nullptr; + + +Logger* Logger::getInstance(std::string name, Logger::LogLevel minLevel) +{ + if (Logger::LoggerMap == nullptr) + { + Logger::LoggerMap = new std::map; + } + + if ( LoggerMap->find(name) == LoggerMap->end() ) + { + Logger* log = new Logger(name,minLevel); + Logger::LoggerMap->emplace(name,log); + return log; + } + + return Logger::LoggerMap->at(name); +} + + + +Logger::Logger ( std::string name, LogLevel minLevel ): + _name(name), + _minLevel(minLevel), + _syslogEnabled(true), + _loggerId(loggerId++) +{ + _appname = std::string(program_invocation_short_name); + std::transform(_appname.begin(), _appname.end(),_appname.begin(), ::toupper); + + loggerCount++; + +// if (pLoggerMap == NULL) +// pLoggerMap = new std::map; +// +// + + if (_syslogEnabled && loggerCount == 1 ) + { + openlog (program_invocation_short_name, LOG_CONS | LOG_PID | LOG_NDELAY, LOG_LOCAL0); + } +} + +Logger::~Logger() +{ + //LoggerMap.erase(_loggerId); + loggerCount--; + if ( loggerCount == 0 ) + closelog(); +} + + +void Logger::Message(LogLevel level, const char* sourceFile, const char* func, unsigned int line, const char* fmt, ...) +{ + if ( level < _minLevel ) + return; + + char msg[512]; + va_list args; + va_start (args, fmt); + vsprintf (msg,fmt, args); + va_end (args); + + std::string location; + std::string function(func); + if ( level == Logger::DEBUG ) + { + location = "<" + getBaseName(sourceFile) + ":" + QString::number(line).toStdString()+":"+ function + "()> "; + } + + std::cout + << "[" << _appname << " " << _name << "] <" + << LogLevelStrings[level] << "> " << location << msg + << std::endl; + + if ( _syslogEnabled && level >= Logger::WARNING ) + syslog (LogLevelSysLog[level], "%s", msg); +} + + diff --git a/libsrc/utils/Profiler.cpp b/libsrc/utils/Profiler.cpp new file mode 100644 index 00000000..2c076c43 --- /dev/null +++ b/libsrc/utils/Profiler.cpp @@ -0,0 +1,98 @@ +#include "HyperionConfig.h" +#include "utils/Profiler.h" + +#include +#include + +struct StopWatchItem { + const char* sourceFile; + const char* func; + unsigned int line; + clock_t startTime; +}; + +static unsigned int blockCounter = 0; +static std::map GlobalProfilerMap; +Logger* Profiler::_logger = nullptr; + + + +std::string profiler_getBaseName( std::string sourceFile) +{ + QFileInfo fi( sourceFile.c_str() ); + return fi.fileName().toStdString(); +} + +double getClockDelta(clock_t start) +{ + return ((double)(clock() - start) / CLOCKS_PER_SEC) ; +} + + + +Profiler::Profiler(const char* sourceFile, const char* func, unsigned int line) : + _file(sourceFile), + _func(func), + _line(line), + _blockId(blockCounter++), + _startTime(clock()) +{ + Profiler::initLogger(); + _logger->Message(Logger::DEBUG,_file,_func,_line,">>> enter block %d", _blockId); +} + + +Profiler::~Profiler() +{ + _logger->Message( Logger::DEBUG, _file,_func, _line, "<<< exit block %d, executed for %f s", _blockId, getClockDelta(_startTime) ); +} + +void Profiler::initLogger() +{ + if (_logger == nullptr ) + _logger = Logger::getInstance("PROFILER", Logger::DEBUG); +} + +void Profiler::TimerStart(const std::string timerName, const char* sourceFile, const char* func, unsigned int line) +{ + std::pair::iterator,bool> ret; + Profiler::initLogger(); + + StopWatchItem item = {sourceFile, func, line}; + + ret = GlobalProfilerMap.emplace(timerName, item); + if ( ! ret.second ) + { + if ( ret.first->second.sourceFile == sourceFile && ret.first->second.func == func && ret.first->second.line == line ) + { + _logger->Message(Logger::DEBUG, sourceFile, func, line, "restart timer '%s'", timerName.c_str() ); + ret.first->second.startTime = clock(); + } + else + { + _logger->Message(Logger::DEBUG, sourceFile, func, line, "ERROR timer '%s' started in multiple locations. First occurence %s:%d:%s()", + timerName.c_str(), profiler_getBaseName(ret.first->second.sourceFile).c_str(), ret.first->second.line, ret.first->second.func ); + } + } + else + { + _logger->Message(Logger::DEBUG, sourceFile, func, line, "start timer '%s'", timerName.c_str() ); + } +} + + +void Profiler::TimerGetTime(const std::string timerName, const char* sourceFile, const char* func, unsigned int line) +{ + std::map::iterator ret = GlobalProfilerMap.find(timerName); + Profiler::initLogger(); + if (ret != GlobalProfilerMap.end()) + { + _logger->Message(Logger::DEBUG, sourceFile, func, line, "timer '%s' started at %s:%d:%s() took %f s execution time until here", timerName.c_str(), + profiler_getBaseName(ret->second.sourceFile).c_str(), ret->second.line, ret->second.func, getClockDelta(ret->second.startTime) ); + } + else + { + _logger->Message(Logger::DEBUG, sourceFile, func, line, "ERROR timer '%s' not started", timerName.c_str() ); + } +} +