adding speed log

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<std::string>& args)
 
 		// start cpu scheduler
 		uint8_t worker_count = Poco::Environment::processorCount() * 2;
-		
+
+		// init speed logger
+		Poco::AutoPtr<Poco::SimpleFileChannel> speedLogFileChannel(new Poco::SimpleFileChannel("speedLog.txt"));
+		/*
+			The optional log file rotation mode:
+			never:      no rotation (default)
+			<n>:  rotate if file size exceeds <n> bytes
+			<n> K:     rotate if file size exceeds <n> Kilobytes
+			<n> M:    rotate if file size exceeds <n> Megabytes
+		*/
+		speedLogFileChannel->setProperty("rotation", "2 K");
+		Poco::AutoPtr<Poco::AsyncChannel> 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");
 

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

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

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",
+	//printf("[User::isEmptyPassword] pwd hashed: %d, running: %d, this: %d\n",
-		mPasswordHashed, !mCreateCryptoKeyTask.isNull(), this);
+//		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);
 	

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,

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;
+				Profiler counter;
-				debug::CPUShedulerTasksLog* l = debug::CPUShedulerTasksLog::getInstance();
+				//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());
+				//l->removeTaskLogEntry((HASH)mWaitingTask.getResourcePtrHolder());
-				SpeedLog.writeToLog("%s used on thread: %s by Task: %s of: %s",
+				mSpeedLog.information("%s used on thread: %s by Task: %s of: %s",
-					counter.string().data(), mName.data(), mWaitingTask->getResourceType(), name);
+					counter.string(), mName, mWaitingTask->getResourceType(), name);
 #endif
 				mWaitingTask = mParent->getNextUndoneTask(this);
 			}

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: 

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