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

@@ -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")

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}"

include/utils/Logger.h

@@ -0,0 +1,48 @@
+#pragma once
+
+#include <string>
+#include <stdio.h>
+#include <stdarg.h>
+#include <map>
+
+// 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<std::string,Logger*> *LoggerMap;
+
+	std::string _name;
+	std::string _appname;
+	LogLevel    _minLevel;
+	bool        _syslogEnabled;
+	unsigned int _loggerId;
+};
+

include/utils/Profiler.h

@@ -0,0 +1,37 @@
+#include "utils/Logger.h"
+#include <string>
+#include <stdio.h>
+#include <stdarg.h>
+#include <time.h>
+#include <map>
+
+#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;
+};

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
 

libsrc/utils/Logger.cpp

@@ -0,0 +1,100 @@
+#include "utils/Logger.h"
+
+#include <iostream>
+#include <algorithm>
+#include <syslog.h>
+#include <map>
+#include <QFileInfo>
+#include <QString>
+
+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<std::string,Logger*> *Logger::LoggerMap = nullptr;
+
+
+Logger* Logger::getInstance(std::string name, Logger::LogLevel minLevel)
+{
+	if (Logger::LoggerMap == nullptr)
+	{
+		Logger::LoggerMap = new std::map<std::string,Logger*>;
+	}
+	
+	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<unsigned int,Logger*>;
+// 
+// 	
+	
+	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);
+}
+
+

libsrc/utils/Profiler.cpp

@@ -0,0 +1,98 @@
+#include "HyperionConfig.h"
+#include "utils/Profiler.h"
+
+#include <QFileInfo>
+#include <QString>
+
+struct StopWatchItem {
+	const char* sourceFile;
+	const char* func;
+	unsigned int line;
+	clock_t startTime;
+};
+
+static unsigned int blockCounter = 0;
+static std::map<std::string,StopWatchItem> 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<std::map<std::string,StopWatchItem>::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<std::string,StopWatchItem>::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() );
+	}
+}
+