From 0134ac732ea33b06335934c81b04f3e8b333f470 Mon Sep 17 00:00:00 2001 From: Dario Date: Fri, 18 Oct 2019 12:01:51 +0200 Subject: [PATCH] adding speed log --- src/cpp/Gradido_LoginServer.cpp | 23 ++++++++++++++++++++- src/cpp/SingletonManager/SessionManager.cpp | 6 +++--- src/cpp/model/Session.cpp | 18 ++++++++-------- src/cpp/model/User.cpp | 20 +++++++++--------- src/cpp/tasks/CPUSheduler.h | 2 +- src/cpp/tasks/CPUShedulerThread.cpp | 19 ++++++++++------- src/cpp/tasks/CPUShedulerThread.h | 6 ++++++ src/cpp/tasks/Task.h | 2 +- 8 files changed, 64 insertions(+), 32 deletions(-) diff --git a/src/cpp/Gradido_LoginServer.cpp b/src/cpp/Gradido_LoginServer.cpp index be4277880..b1fab6777 100644 --- a/src/cpp/Gradido_LoginServer.cpp +++ b/src/cpp/Gradido_LoginServer.cpp @@ -7,11 +7,16 @@ #include "SingletonManager/ConnectionManager.h" #include "SingletonManager/SessionManager.h" + #include "Poco/Util/HelpFormatter.h" #include "Poco/Net/ServerSocket.h" #include "Poco/Net/HTTPServer.h" #include "Poco/Net/SSLManager.h" #include "Poco/Environment.h" +#include "Poco/Logger.h" +#include "Poco/AsyncChannel.h" +#include "Poco/SimpleFileChannel.h" + #include "MySQL/Poco/Connector.h" @@ -90,7 +95,23 @@ int Gradido_LoginServer::main(const std::vector& args) // start cpu scheduler uint8_t worker_count = Poco::Environment::processorCount() * 2; - + + // init speed logger + Poco::AutoPtr speedLogFileChannel(new Poco::SimpleFileChannel("speedLog.txt")); + /* + The optional log file rotation mode: + never: no rotation (default) + : rotate if file size exceeds bytes + K: rotate if file size exceeds Kilobytes + M: rotate if file size exceeds Megabytes + */ + speedLogFileChannel->setProperty("rotation", "2 K"); + Poco::AutoPtr speedLogAsyncChannel(new Poco::AsyncChannel(speedLogFileChannel)); + + Poco::Logger& speedLogger = Poco::Logger::get("SpeedLog"); + speedLogger.setChannel(speedLogAsyncChannel); + speedLogger.setLevel("information"); + ServerConfig::g_CPUScheduler = new UniLib::controller::CPUSheduler(worker_count, "Default Worker"); ServerConfig::g_CryptoCPUScheduler = new UniLib::controller::CPUSheduler(2, "Crypto Worker"); diff --git a/src/cpp/SingletonManager/SessionManager.cpp b/src/cpp/SingletonManager/SessionManager.cpp index d596a01c4..c66b43aba 100644 --- a/src/cpp/SingletonManager/SessionManager.cpp +++ b/src/cpp/SingletonManager/SessionManager.cpp @@ -151,7 +151,7 @@ Session* SessionManager::getNewSession(int* handle) if (handle) { *handle = newHandle; } - printf("[SessionManager::getNewSession] handle: %ld, sum: %u\n", newHandle, mRequestSessionMap.size()); + //printf("[SessionManager::getNewSession] handle: %ld, sum: %u\n", newHandle, mRequestSessionMap.size()); return requestSession; @@ -168,7 +168,7 @@ bool SessionManager::releaseSession(int requestHandleSession) auto it = mRequestSessionMap.find(requestHandleSession); if (it == mRequestSessionMap.end()) { - printf("[SessionManager::releaseRequestSession] requestSession with handle: %d not found\n", requestHandleSession); + //printf("[SessionManager::releaseRequestSession] requestSession with handle: %d not found\n", requestHandleSession); mWorkingMutex.unlock(); return false; } @@ -253,7 +253,7 @@ Session* SessionManager::getSession(int handle) //result->setActive(true); result->updateTimeout(); } - printf("[SessionManager::getSession] handle: %ld\n", handle); + //printf("[SessionManager::getSession] handle: %ld\n", handle); mWorkingMutex.unlock(); return result; } diff --git a/src/cpp/model/Session.cpp b/src/cpp/model/Session.cpp index 58f448a16..7666a9ba4 100644 --- a/src/cpp/model/Session.cpp +++ b/src/cpp/model/Session.cpp @@ -38,7 +38,7 @@ int WriteEmailVerification::run() em->sendErrorsAsEmail(); return -2; } - printf("[WriteEmailVerification] timeUsed: %s\n", timeUsed.string().data()); + //printf("[WriteEmailVerification] timeUsed: %s\n", timeUsed.string().data()); return 0; } @@ -71,7 +71,7 @@ int WritePassphraseIntoDB::run() em->sendErrorsAsEmail(); } - printf("[WritePassphraseIntoDB] timeUsed: %s\n", timeUsed.string().data()); + //printf("[WritePassphraseIntoDB] timeUsed: %s\n", timeUsed.string().data()); return 0; } @@ -86,15 +86,15 @@ Session::Session(int handle) Session::~Session() { - printf("[Session::~Session] \n"); + //printf("[Session::~Session] \n"); reset(); - printf("[Session::~Session] finished \n"); + //printf("[Session::~Session] finished \n"); } void Session::reset() { - printf("[Session::reset]\n"); + //printf("[Session::reset]\n"); lock(); mSessionUser = nullptr; @@ -109,7 +109,7 @@ void Session::reset() mClientLoginIP = Poco::Net::IPAddress(); mEmailVerificationCode = 0; unlock(); - printf("[Session::reset] finished\n"); + //printf("[Session::reset] finished\n"); } void Session::updateTimeout() @@ -216,7 +216,7 @@ bool Session::createUser(const std::string& first_name, const std::string& last_ // generate and write email verification into db // send email - printf("[Session::createUser] time: %s\n", usedTime.string().data()); + //printf("[Session::createUser] time: %s\n", usedTime.string().data()); return true; } @@ -272,7 +272,7 @@ bool Session::updateEmailVerification(Poco::UInt64 emailVerificationCode) printf("[%s] time: %s\n", funcName, usedTime.string().data()); return false; } - printf("[%s] time: %s\n", funcName, usedTime.string().data()); + //printf("[%s] time: %s\n", funcName, usedTime.string().data()); return false; } @@ -459,7 +459,7 @@ void Session::updateState(SessionStates newState) lock(); if (!mActive) return; updateTimeout(); - printf("[%s] newState: %s\n", __FUNCTION__, translateSessionStateToString(newState)); + //printf("[%s] newState: %s\n", __FUNCTION__, translateSessionStateToString(newState)); if (newState > mState) { mState = newState; } diff --git a/src/cpp/model/User.cpp b/src/cpp/model/User.cpp index 023d14e50..708030f87 100644 --- a/src/cpp/model/User.cpp +++ b/src/cpp/model/User.cpp @@ -33,7 +33,7 @@ int UserCreateCryptoKey::run() crypto_shorthash((unsigned char*)&pwdHashed, *cryptoKey, crypto_box_SEEDBYTES, *ServerConfig::g_ServerCryptoKey); mUser->setPwdHashed(pwdHashed); - printf("crypto key created\n"); + //printf("crypto key created\n"); setTaskFinished(); // must poke cpu scheduler manually because another task is waiting for this task, but in the other scheduler ServerConfig::g_CPUScheduler->checkPendingTasks(); @@ -50,7 +50,7 @@ int UserGenerateKeys::run() mUser->setPublicKeyHex(mKeys.getPubkeyHex()); - printf("[UserGenerateKeys::run] time: %s\n", timeUsed.string().data()); + //printf("[UserGenerateKeys::run] time: %s\n", timeUsed.string().data()); return 0; } @@ -340,8 +340,8 @@ bool User::isEmptyPassword() { bool bRet = false; lock(); - printf("[User::isEmptyPassword] pwd hashed: %d, running: %d, this: %d\n", - mPasswordHashed, !mCreateCryptoKeyTask.isNull(), this); + //printf("[User::isEmptyPassword] pwd hashed: %d, running: %d, this: %d\n", +// mPasswordHashed, !mCreateCryptoKeyTask.isNull(), this); bRet = mPasswordHashed == 0 && (mCreateCryptoKeyTask.isNull() || mCreateCryptoKeyTask->isTaskFinished()); unlock(); return bRet; @@ -359,7 +359,7 @@ UserStates User::getUserState() // TODO: if a password and privkey already exist, load current private key and re encrypt with new crypto key bool User::setNewPassword(const std::string& newPassword) { - Profiler timeUsed; + //Profiler timeUsed; if (newPassword == "") { lock(); addError(new Error("Passwort", "Ist leer.")); @@ -374,7 +374,7 @@ bool User::setNewPassword(const std::string& newPassword) } duplicate(); lock(); - printf("[User::setNewPassword] start create crypto key task with this: %d\n", this); + //printf("[User::setNewPassword] start create crypto key task with this: %d\n", this); mCreateCryptoKeyTask = new UserCreateCryptoKey(this, newPassword, ServerConfig::g_CPUScheduler); mCreateCryptoKeyTask->scheduleTask(mCreateCryptoKeyTask); unlock(); @@ -386,7 +386,7 @@ bool User::setNewPassword(const std::string& newPassword) savePassword->scheduleTask(savePassword); - printf("[User::setNewPassword] timeUsed: %s\n", timeUsed.string().data()); + //printf("[User::setNewPassword] timeUsed: %s\n", timeUsed.string().data()); return true; } @@ -547,7 +547,7 @@ ObfusArray* User::createCryptoKey(const std::string& password) free(key); // mCryptoKey - printf("[User::createCryptoKey] time used: %s\n", timeUsed.string().data()); + //printf("[User::createCryptoKey] time used: %s\n", timeUsed.string().data()); return cryptoKey; } @@ -580,7 +580,7 @@ bool User::generateKeys(bool savePrivkey, const std::string& passphrase, Session saveKeysTask->scheduleTask(saveKeysTask); - printf("[User::generateKeys] call two tasks, time used: %s\n", timeUsed.string().data()); +// printf("[User::generateKeys] call two tasks, time used: %s\n", timeUsed.string().data()); return true; } @@ -608,7 +608,7 @@ Poco::Data::BLOB* User::encrypt(const ObfusArray* data) return nullptr; } - printf("[User::encrypt] encrypted: %s\n", KeyPair::getHex(ciphertext, ciphertext_len).data()); + //printf("[User::encrypt] encrypted: %s\n", KeyPair::getHex(ciphertext, ciphertext_len).data()); auto result_blob = new Poco::Data::BLOB(ciphertext, ciphertext_len); free(ciphertext); diff --git a/src/cpp/tasks/CPUSheduler.h b/src/cpp/tasks/CPUSheduler.h index 28941f699..788f5773f 100644 --- a/src/cpp/tasks/CPUSheduler.h +++ b/src/cpp/tasks/CPUSheduler.h @@ -60,7 +60,7 @@ namespace UniLib { int sheduleTask(TaskPtr task); void checkPendingTasks(); #ifdef _UNI_LIB_DEBUG - CPUShedulerThread** getThreads(u8& count) {count = mThreadCount; return mThreads;}; + CPUShedulerThread** getThreads(uint8_t& count) {count = mThreadCount; return mThreads;}; #endif // called from scheduler thread if he wants a new task to do // return null if no task pending, putting thread in wait queue, diff --git a/src/cpp/tasks/CPUShedulerThread.cpp b/src/cpp/tasks/CPUShedulerThread.cpp index 44ebeed42..9b9d00e43 100644 --- a/src/cpp/tasks/CPUShedulerThread.cpp +++ b/src/cpp/tasks/CPUShedulerThread.cpp @@ -4,7 +4,9 @@ //#include "debug/CPUSchedulerTasksLog.h" #ifdef _UNI_LIB_DEBUG -#include "lib/TimeCounter.h" +//#include "lib/TimeCounter.h" +#include "../model/Profiler.h" +#include "Poco/Message.h" #endif //_UNI_LIB_DEBUG @@ -12,6 +14,9 @@ namespace UniLib { namespace controller { CPUShedulerThread::CPUShedulerThread(CPUSheduler* parent, const char* name) : Thread(name), mParent(parent) +#ifdef _UNI_LIB_DEBUG + , mSpeedLog(Poco::Logger::get("SpeedLog")) +#endif { #ifdef _UNI_LIB_DEBUG mName = name; @@ -30,18 +35,18 @@ namespace UniLib { { #ifdef _UNI_LIB_DEBUG - lib::TimeCounter counter; - debug::CPUShedulerTasksLog* l = debug::CPUShedulerTasksLog::getInstance(); + Profiler counter; + //debug::CPUShedulerTasksLog* l = debug::CPUShedulerTasksLog::getInstance(); const char* name = mWaitingTask->getName(); - l->addTaskLogEntry((HASH)mWaitingTask.getResourcePtrHolder(), mWaitingTask->getResourceType(), mName.data(), name); + //l->addTaskLogEntry((HASH)mWaitingTask.getResourcePtrHolder(), mWaitingTask->getResourceType(), mName.data(), name); #endif if (!mWaitingTask->run()) { mWaitingTask->setTaskFinished(); } #ifdef _UNI_LIB_DEBUG - l->removeTaskLogEntry((HASH)mWaitingTask.getResourcePtrHolder()); - SpeedLog.writeToLog("%s used on thread: %s by Task: %s of: %s", - counter.string().data(), mName.data(), mWaitingTask->getResourceType(), name); + //l->removeTaskLogEntry((HASH)mWaitingTask.getResourcePtrHolder()); + mSpeedLog.information("%s used on thread: %s by Task: %s of: %s", + counter.string(), mName, mWaitingTask->getResourceType(), name); #endif mWaitingTask = mParent->getNextUndoneTask(this); } diff --git a/src/cpp/tasks/CPUShedulerThread.h b/src/cpp/tasks/CPUShedulerThread.h index f0a198447..5c2d59780 100644 --- a/src/cpp/tasks/CPUShedulerThread.h +++ b/src/cpp/tasks/CPUShedulerThread.h @@ -32,8 +32,13 @@ #ifndef __DR_UNIVERSUM_LIB_CONTROLLER_CPU_SHEDULER_THREAD_H__ #define __DR_UNIVERSUM_LIB_CONTROLLER_CPU_SHEDULER_THREAD_H__ +#define _UNI_LIB_DEBUG + #include "Thread.h" #include "Poco/AutoPtr.h" +#ifdef _UNI_LIB_DEBUG +#include "Poco/Logger.h" +#endif namespace UniLib { namespace controller { @@ -64,6 +69,7 @@ namespace UniLib { protected: #ifdef _UNI_LIB_DEBUG std::string mName; + Poco::Logger& mSpeedLog; #endif private: diff --git a/src/cpp/tasks/Task.h b/src/cpp/tasks/Task.h index aa2b1f14d..b4e05ef80 100644 --- a/src/cpp/tasks/Task.h +++ b/src/cpp/tasks/Task.h @@ -91,7 +91,7 @@ namespace UniLib { virtual const char* getResourceType() const {return "Task";}; #ifdef _UNI_LIB_DEBUG virtual const char* getName() const { return mName.data(); } - __inline__ void setName(const char* name) { mName = name; } + inline void setName(const char* name) { mName = name; } #else virtual const char* getName() const { return ""; } #endif