From 809d56e86cdce7e319b4d9f43312d3900cc442ad Mon Sep 17 00:00:00 2001 From: Mark Vejvoda Date: Thu, 23 Dec 2010 19:47:40 +0000 Subject: [PATCH] - added option to log debug info using a worker thread, by default logging is NOT threaded. To enable: ThreadedLogging=true --- source/glest_game/main/main.cpp | 5 +- .../include/platform/common/simple_threads.h | 35 +++- source/shared_lib/include/util/util.h | 4 +- .../platform/common/simple_threads.cpp | 72 ++++++- source/shared_lib/sources/util/util.cpp | 178 +++++++++++++++++- 5 files changed, 280 insertions(+), 14 deletions(-) diff --git a/source/glest_game/main/main.cpp b/source/glest_game/main/main.cpp index 6a6f62fdb..ab1f420c4 100644 --- a/source/glest_game/main/main.cpp +++ b/source/glest_game/main/main.cpp @@ -643,6 +643,8 @@ int glestMain(int argc, char** argv) { return -1; } + SystemFlags::ENABLE_THREADED_LOGGING = false; + SystemFlags::VERBOSE_MODE_ENABLED = false; if(hasCommandArgument(argc, argv,GAME_ARGS[GAME_ARG_VERBOSE_MODE]) == true) { SystemFlags::VERBOSE_MODE_ENABLED = true; @@ -780,7 +782,8 @@ int glestMain(int argc, char** argv) { std::auto_ptr preCacheThread; Config &config = Config::getInstance(); FontGl::setDefault_fontType(config.getString("DefaultFont",FontGl::getDefault_fontType().c_str())); - Socket::isUPNP = !config.getBool("DisableUPNP","false"); + Socket::isUPNP = !config.getBool("DisableUPNP","false"); + SystemFlags::ENABLE_THREADED_LOGGING = config.getBool("ThreadedLogging","false"); //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); diff --git a/source/shared_lib/include/platform/common/simple_threads.h b/source/shared_lib/include/platform/common/simple_threads.h index 241f6c89b..b81930043 100644 --- a/source/shared_lib/include/platform/common/simple_threads.h +++ b/source/shared_lib/include/platform/common/simple_threads.h @@ -14,9 +14,11 @@ #include "base_thread.h" #include #include +#include "util.h" #include "leak_dumper.h" using namespace std; +using namespace Shared::Util; namespace Shared { namespace PlatformCommon { @@ -66,8 +68,8 @@ protected: public: SimpleTaskThread(); - SimpleTaskThread(SimpleTaskCallbackInterface *simpleTaskInterface, - unsigned int executionCount=0, + SimpleTaskThread(SimpleTaskCallbackInterface *simpleTaskInterface, + unsigned int executionCount=0, unsigned int millisecsBetweenExecutions=0, bool needTaskSignal = false); virtual void execute(); @@ -79,6 +81,35 @@ public: bool getExecutingTask(); }; +// ===================================================== +// class LogFileThread +// ===================================================== + +class LogFileEntry { +public: + SystemFlags::DebugType type; + string entry; + time_t entryDateTime; +}; + +class LogFileThread : public BaseThread +{ +protected: + + Mutex mutexLogList; + vector logList; + time_t lastSaveToDisk; + + void saveToDisk(); + +public: + LogFileThread(); + virtual void execute(); + void addLogEntry(SystemFlags::DebugType type, string logEntry); +}; + + + }}//end namespace #endif diff --git a/source/shared_lib/include/util/util.h b/source/shared_lib/include/util/util.h index 9cadbc90b..1dab803bc 100644 --- a/source/shared_lib/include/util/util.h +++ b/source/shared_lib/include/util/util.h @@ -110,14 +110,13 @@ protected: static int lockFileCountIndex; static std::map debugLogFileList; - static bool haveSpecialOutputCommandLineOption; - public: static CURL *curl_handle; static int DEFAULT_HTTP_TIMEOUT; static bool VERBOSE_MODE_ENABLED; + static bool ENABLE_THREADED_LOGGING; SystemFlags(); ~SystemFlags(); @@ -133,6 +132,7 @@ public: // Let the macro call into this when require.. NEVER call it automatically. static void handleDebug(DebugType type, const char *fmt, ...); + static void logDebugEntry(DebugType type, string debugEntry, time_t debugTime); // If logging is enabled then define the logging method #ifndef UNDEF_DEBUG diff --git a/source/shared_lib/sources/platform/common/simple_threads.cpp b/source/shared_lib/sources/platform/common/simple_threads.cpp index 52cc0f6e9..38611bfb6 100644 --- a/source/shared_lib/sources/platform/common/simple_threads.cpp +++ b/source/shared_lib/sources/platform/common/simple_threads.cpp @@ -41,12 +41,12 @@ void FileCRCPreCacheThread::execute() { string techName = techPaths[idx]; time_t elapsedTime = time(NULL); - printf("In [%s::%s Line: %d] caching CRC value for Tech [%s] [%d of %d]\n",__FILE__,__FUNCTION__,__LINE__,techName.c_str(),idx+1,(int)techPaths.size()); + if(SystemFlags::VERBOSE_MODE_ENABLED) printf("In [%s::%s Line: %d] caching CRC value for Tech [%s] [%d of %d]\n",__FILE__,__FUNCTION__,__LINE__,techName.c_str(),idx+1,(int)techPaths.size()); SystemFlags::OutputDebug(SystemFlags::debugNetwork,"In [%s::%s Line: %d] caching CRC value for Tech [%s] [%d of %d]\n",__FILE__,__FUNCTION__,__LINE__,techName.c_str(),idx+1,techPaths.size()); int32 techCRC = getFolderTreeContentsCheckSumRecursively(techDataPaths, string("/") + techName + string("/*"), ".xml", NULL); - printf("In [%s::%s Line: %d] cached CRC value for Tech [%s] is [%d] [%d of %d] took %.3f seconds.\n",__FILE__,__FUNCTION__,__LINE__,techName.c_str(),techCRC,idx+1,(int)techPaths.size(),difftime(time(NULL),elapsedTime)); + if(SystemFlags::VERBOSE_MODE_ENABLED) printf("In [%s::%s Line: %d] cached CRC value for Tech [%s] is [%d] [%d of %d] took %.3f seconds.\n",__FILE__,__FUNCTION__,__LINE__,techName.c_str(),techCRC,idx+1,(int)techPaths.size(),difftime(time(NULL),elapsedTime)); SystemFlags::OutputDebug(SystemFlags::debugNetwork,"In [%s::%s Line: %d] cached CRC value for Tech [%s] is [%d] [%d of %d] took %.3f seconds.\n",__FILE__,__FUNCTION__,__LINE__,techName.c_str(),techCRC,idx+1,techPaths.size(),difftime(time(NULL),elapsedTime)); if(getQuitStatus() == true) { @@ -189,4 +189,72 @@ bool SimpleTaskThread::getExecutingTask() { return retval; } +// ------------------------------------------------- + +LogFileThread::LogFileThread() : BaseThread() { + logList.clear(); + lastSaveToDisk = time(NULL); +} + +void LogFileThread::addLogEntry(SystemFlags::DebugType type, string logEntry) { + MutexSafeWrapper safeMutex(&mutexLogList); + //logList[type].push_back(make_pair(entry,time(NULL))); + LogFileEntry entry; + entry.type = type; + entry.entry = logEntry; + entry.entryDateTime = time(NULL); + logList.push_back(entry); +} + +void LogFileThread::execute() { + RunningStatusSafeWrapper runningStatus(this); + SystemFlags::OutputDebug(SystemFlags::debugNetwork,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); + + if(getQuitStatus() == true) { + return; + } + + SystemFlags::OutputDebug(SystemFlags::debugNetwork,"LogFile thread is running\n"); + + try { + for(;this->getQuitStatus() == false;) { + if(difftime(time(NULL),lastSaveToDisk) >= 5) { + lastSaveToDisk = time(NULL); + saveToDisk(); + } + if(this->getQuitStatus() == false) { + sleep(100); + } + } + + // Ensure remaining entryies are logged to disk on shutdown + saveToDisk(); + } + catch(const exception &ex) { + //SystemFlags::OutputDebug(SystemFlags::debugError,"In [%s::%s Line: %d] Error [%s]\n",__FILE__,__FUNCTION__,__LINE__,ex.what()); + //SystemFlags::OutputDebug(SystemFlags::debugNetwork,"In [%s::%s Line: %d] error [%s]\n",__FILE__,__FUNCTION__,__LINE__,ex.what()); + if(SystemFlags::VERBOSE_MODE_ENABLED) printf("In [%s::%s Line: %d] Error [%s]\n",__FILE__,__FUNCTION__,__LINE__,ex.what()); + } + catch(...) { + //SystemFlags::OutputDebug(SystemFlags::debugError,"In [%s::%s Line: %d] UNKNOWN Error\n",__FILE__,__FUNCTION__,__LINE__); + //SystemFlags::OutputDebug(SystemFlags::debugNetwork,"In [%s::%s Line: %d] unknown error\n",__FILE__,__FUNCTION__,__LINE__); + if(SystemFlags::VERBOSE_MODE_ENABLED) printf("In [%s::%s Line: %d] UNKNOWN Error\n",__FILE__,__FUNCTION__,__LINE__); + } + + //SystemFlags::OutputDebug(SystemFlags::debugNetwork,"In [%s::%s Line: %d] LogFile thread is exiting\n",__FILE__,__FUNCTION__,__LINE__); + if(SystemFlags::VERBOSE_MODE_ENABLED) printf("In [%s::%s Line: %d] LogFile thread is exiting\n",__FILE__,__FUNCTION__,__LINE__); +} + +void LogFileThread::saveToDisk() { + MutexSafeWrapper safeMutex(&mutexLogList); + if(logList.size() > 0) { + for(int i = 0; i start(); + } } SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line %d]\n",__FILE__,__FUNCTION__,__LINE__); @@ -216,6 +224,16 @@ SystemFlags::~SystemFlags() { } void SystemFlags::Close() { + if(SystemFlags::ENABLE_THREADED_LOGGING) { + if(threadLogger != NULL) { + SystemFlags::ENABLE_THREADED_LOGGING = false; + threadLogger->signalQuit(); + threadLogger->shutdownAndWait(); + delete threadLogger; + threadLogger = NULL; + } + } + if(SystemFlags::debugLogFileList.size() > 0) { if(SystemFlags::haveSpecialOutputCommandLineOption == false) { if(SystemFlags::VERBOSE_MODE_ENABLED) printf("START Closing logfiles\n"); @@ -258,9 +276,9 @@ void SystemFlags::handleDebug(DebugType type, const char *fmt, ...) { return; } - /* Get the current time. */ + // Get the current time. time_t curtime = time (NULL); - /* Convert it to local time representation. */ + // Convert it to local time representation. struct tm *loctime = localtime (&curtime); char szBuf2[100]=""; strftime(szBuf2,100,"%Y-%m-%d %H:%M:%S",loctime); @@ -272,6 +290,7 @@ void SystemFlags::handleDebug(DebugType type, const char *fmt, ...) { char szBuf[max_debug_buffer_size]=""; vsnprintf(szBuf,max_debug_buffer_size-1,fmt, argList); +/* // Either output to a logfile or if(currentDebugLog.debugLogFileName != "") { if( currentDebugLog.fileStream == NULL || @@ -382,6 +401,152 @@ void SystemFlags::handleDebug(DebugType type, const char *fmt, ...) { safeMutex.ReleaseLock(); } } +*/ + + if(SystemFlags::ENABLE_THREADED_LOGGING && + threadLogger != NULL) { + threadLogger->addLogEntry(type, szBuf); + } + else { + logDebugEntry(type, szBuf, curtime); + } + va_end(argList); +} + + +void SystemFlags::logDebugEntry(DebugType type, string debugEntry, time_t debugTime) { + if(SystemFlags::debugLogFileList.size() == 0) { + SystemFlags::init(false); + } + SystemFlags::SystemFlagsType ¤tDebugLog = SystemFlags::debugLogFileList[type]; + if(currentDebugLog.enabled == false) { + return; + } + + // Get the current time. +// time_t curtime = time (NULL); + // Convert it to local time representation. + struct tm *loctime = localtime (&debugTime); + char szBuf2[100]=""; + strftime(szBuf2,100,"%Y-%m-%d %H:%M:%S",loctime); +/* + va_list argList; + va_start(argList, fmt); + + const int max_debug_buffer_size = 8096; + char szBuf[max_debug_buffer_size]=""; + vsnprintf(szBuf,max_debug_buffer_size-1,fmt, argList); +*/ + // Either output to a logfile or + if(currentDebugLog.debugLogFileName != "") { + if( currentDebugLog.fileStream == NULL || + currentDebugLog.fileStream->is_open() == false) { + + // If the file is already open (shared) by another debug type + // do not over-write the file but share the stream pointer + for(std::map::iterator iterMap = SystemFlags::debugLogFileList.begin(); + iterMap != SystemFlags::debugLogFileList.end(); iterMap++) { + SystemFlags::SystemFlagsType ¤tDebugLog2 = iterMap->second; + + if( iterMap->first != type && + currentDebugLog.debugLogFileName == currentDebugLog2.debugLogFileName && + currentDebugLog2.fileStream != NULL) { + currentDebugLog.fileStream = currentDebugLog2.fileStream; + currentDebugLog.fileStreamOwner = false; + currentDebugLog.mutex = currentDebugLog2.mutex; + break; + } + } + + string debugLog = currentDebugLog.debugLogFileName; + + if(SystemFlags::lockFile == -1) { + const string lock_file_name = "debug.lck"; + string lockfile = extractDirectoryPathFromFile(debugLog); + lockfile += lock_file_name; + SystemFlags::lockfilename = lockfile; + +#ifndef WIN32 + //SystemFlags::lockFile = open(lockfile.c_str(), O_WRONLY | O_CREAT | O_EXCL, S_IRUSR|S_IWUSR); + SystemFlags::lockFile = open(lockfile.c_str(), O_WRONLY | O_CREAT, S_IREAD | S_IWRITE); +#else + SystemFlags::lockFile = _open(lockfile.c_str(), O_WRONLY | O_CREAT, S_IREAD | S_IWRITE); +#endif + if (SystemFlags::lockFile < 0 || acquire_file_lock(SystemFlags::lockFile) == false) { + string newlockfile = lockfile; + int idx = 1; + for(idx = 1; idx <= 100; ++idx) { + newlockfile = lockfile + intToStr(idx); + //SystemFlags::lockFile = open(newlockfile.c_str(), O_WRONLY | O_CREAT | O_EXCL, S_IRUSR|S_IWUSR); +#ifndef WIN32 + SystemFlags::lockFile = open(newlockfile.c_str(), O_WRONLY | O_CREAT, S_IREAD | S_IWRITE); +#else + SystemFlags::lockFile = _open(newlockfile.c_str(), O_WRONLY | O_CREAT, S_IREAD | S_IWRITE); + +#endif + if(SystemFlags::lockFile >= 0 && acquire_file_lock(SystemFlags::lockFile) == true) { + break; + } + } + + SystemFlags::lockFileCountIndex = idx; + SystemFlags::lockfilename = newlockfile; + debugLog += intToStr(idx); + + if(SystemFlags::haveSpecialOutputCommandLineOption == false) { + if(SystemFlags::VERBOSE_MODE_ENABLED) printf("Opening additional logfile [%s]\n",debugLog.c_str()); + } + } + } + else if(SystemFlags::lockFileCountIndex > 0) { + debugLog += intToStr(SystemFlags::lockFileCountIndex); + + if(SystemFlags::haveSpecialOutputCommandLineOption == false) { + if(SystemFlags::VERBOSE_MODE_ENABLED) printf("Opening additional logfile [%s]\n",debugLog.c_str()); + } + } + + if(currentDebugLog.fileStream == NULL) { + currentDebugLog.fileStream = new std::ofstream(); + currentDebugLog.fileStream->open(debugLog.c_str(), ios_base::out | ios_base::trunc); + currentDebugLog.fileStreamOwner = true; + currentDebugLog.mutex = new Mutex(); + } + + if(SystemFlags::haveSpecialOutputCommandLineOption == false) { + if(SystemFlags::VERBOSE_MODE_ENABLED) printf("Opening logfile [%s] type = %d, currentDebugLog.fileStreamOwner = %d, file stream open = %d\n",debugLog.c_str(),type, currentDebugLog.fileStreamOwner,currentDebugLog.fileStream->is_open()); + } + + if(currentDebugLog.fileStream->is_open() == true) { + MutexSafeWrapper safeMutex(currentDebugLog.mutex); + + (*currentDebugLog.fileStream) << "Starting Mega-Glest logging for type: " << type << "\n"; + (*currentDebugLog.fileStream).flush(); + + safeMutex.ReleaseLock(); + } + } + + assert(currentDebugLog.fileStream != NULL); + + if(currentDebugLog.fileStream->is_open() == true) { + MutexSafeWrapper safeMutex(currentDebugLog.mutex); + + // All items in the if clause we don't want timestamps + if (type != debugPathFinder && type != debugError && type != debugWorldSynch) { + (*currentDebugLog.fileStream) << "[" << szBuf2 << "] " << debugEntry.c_str(); + } + else if (type == debugError) { + (*currentDebugLog.fileStream) << "[" << szBuf2 << "] *ERROR* " << debugEntry.c_str(); + } + else { + (*currentDebugLog.fileStream) << debugEntry.c_str(); + } + (*currentDebugLog.fileStream).flush(); + + safeMutex.ReleaseLock(); + } + } // output to console if( currentDebugLog.debugLogFileName == "" || @@ -390,19 +555,18 @@ void SystemFlags::handleDebug(DebugType type, const char *fmt, ...) { currentDebugLog.fileStream->is_open() == false))) { if (type != debugPathFinder && type != debugError) { - printf("[%s] %s", szBuf2, szBuf); + printf("[%s] %s", szBuf2, debugEntry.c_str()); } else if (type == debugError) { - printf("[%s] *ERROR* %s", szBuf2, szBuf); + printf("[%s] *ERROR* %s", szBuf2, debugEntry.c_str()); } else { - printf("%s", szBuf); + printf("%s", debugEntry.c_str()); } } - - va_end(argList); } + string lastDir(const string &s){ size_t i= s.find_last_of('/'); size_t j= s.find_last_of('\\');