Logging system rework

* use one central unified log with channels/priorities ad-hoc listener registration and de-registration
* disable buffering by default
* add multi-threaded ringbuffer implementation
* use buffered listener for the gui (using the ringbuffer)

Utilities/Log.cpp

@@ -0,0 +1,225 @@
+#include "stdafx.h"
+#include "Log.h"
+#include <iostream>
+#include <string>
+#include <cinttypes>
+#include <memory>
+#include <vector>
+#include <mutex>
+#include <condition_variable>
+#include <thread>
+#include <set>
+#include <array>
+
+using namespace Log;
+
+LogManager *gLogManager = nullptr;
+
+u32 LogMessage::size()
+{
+	//1 byte for NULL terminator
+	return sizeof(LogMessage::size_type) + sizeof(LogType) + sizeof(LogSeverity) + sizeof(std::string::value_type)*mText.size() + 1;
+}
+
+void LogMessage::serialize(char *output)
+{
+	LogMessage::size_type size = this->size();
+	memcpy(output, &size, sizeof(LogMessage::size_type));
+	output += sizeof(LogMessage::size_type);
+	memcpy(output, &mType, sizeof(LogType));
+	output += sizeof(LogType);
+	memcpy(output, &mServerity, sizeof(LogSeverity));
+	output += sizeof(LogSeverity);
+	memcpy(output, mText.c_str(), mText.size() );
+	output += sizeof(std::string::value_type)*mText.size();
+	*output = '\0';
+
+}
+LogMessage LogMessage::deserialize(char *input, u32* size_out)
+{
+	LogMessage msg;
+	LogMessage::size_type msgSize = *(reinterpret_cast<LogMessage::size_type*>(input));
+	input += sizeof(LogMessage::size_type);
+	msg.mType = *(reinterpret_cast<LogType*>(input));
+	input += sizeof(LogType);
+	msg.mServerity = *(reinterpret_cast<LogSeverity*>(input));
+	input += sizeof(LogSeverity);
+	if (msgSize > 9000)
+	{
+		int wtf = 6;
+	}
+	msg.mText.append(input, msgSize - 1 - sizeof(LogSeverity) - sizeof(LogType));
+	if (size_out){(*size_out) = msgSize;}
+	return msg;
+}
+
+
+
+LogChannel::LogChannel() : LogChannel("unknown")
+{}
+
+LogChannel::LogChannel(const std::string& name) :
+	  name(name)
+	, mEnabled(true)
+	, mLogLevel(Warning)
+{}
+
+void LogChannel::log(LogMessage msg)
+{
+	std::lock_guard<std::mutex> lock(mListenerLock);
+	for (auto &listener : mListeners)
+	{
+		listener->log(msg);
+	}
+}
+
+void LogChannel::addListener(std::shared_ptr<LogListener> listener)
+{
+	std::lock_guard<std::mutex> lock(mListenerLock);
+	mListeners.insert(listener);
+}
+void LogChannel::removeListener(std::shared_ptr<LogListener> listener)
+{
+	std::lock_guard<std::mutex> lock(mListenerLock);
+	mListeners.erase(listener);
+}
+
+struct CoutListener : LogListener
+{
+	void log(LogMessage msg)
+	{
+		std::cerr << msg.mText << std::endl;
+	}
+};
+
+struct FileListener : LogListener
+{
+	rFile mFile;
+	bool mPrependChannelName;
+
+	FileListener(const std::string& name = _PRGNAME_, bool prependChannel = true)
+		: mFile(name + ".log", rFile::write),
+		mPrependChannelName(prependChannel)
+	{
+		if (!mFile.IsOpened())
+		{
+			rMessageBox("Can't create log file! (" + name + ".log)", rMessageBoxCaptionStr, rICON_ERROR);
+		}
+	}
+
+	void log(LogMessage msg)
+	{
+		if (mPrependChannelName)
+		{
+			msg.mText.insert(0, gTypeNameTable[static_cast<u32>(msg.mType)].mName);
+		}
+		mFile.Write(msg.mText);
+	}
+};
+
+LogManager::LogManager() 
+#ifdef BUFFERED_LOGGING
+	: mExiting(false), mLogConsumer()
+#endif
+{
+	auto it = mChannels.begin();
+	std::shared_ptr<LogListener> listener(new FileListener());
+	for (const LogTypeName& name : gTypeNameTable)
+	{
+		it->name = name.mName;
+		it->addListener(listener);
+		it++;
+	}
+	std::shared_ptr<LogListener> TTYListener(new FileListener("TTY",false));
+	getChannel(TTY).addListener(TTYListener);
+#ifdef BUFFERED_LOGGING
+	mLogConsumer = std::thread(&LogManager::consumeLog, this);
+#endif
+}
+
+LogManager::~LogManager()
+{
+#ifdef BUFFERED_LOGGING
+	mExiting = true;
+	mBufferReady.notify_all();
+	mLogConsumer.join();
+}
+
+void LogManager::consumeLog()
+{
+	std::unique_lock<std::mutex> lock(mStatusMut);
+	while (!mExiting)
+	{
+		mBufferReady.wait(lock);
+		mBuffer.lockGet();
+		size_t size = mBuffer.size();
+		std::vector<char> local_messages(size);
+		mBuffer.popN(&local_messages.front(), size);
+		mBuffer.unlockGet();
+
+		u32 cursor = 0;
+		u32 removed = 0;
+		while (cursor < size)
+		{
+			Log::LogMessage msg = Log::LogMessage::deserialize(local_messages.data() + cursor, &removed);
+			cursor += removed;
+			getChannel(msg.mType).log(msg);
+		}
+	}
+#endif
+}
+
+void LogManager::log(LogMessage msg)
+{
+	//don't do any formatting changes or filtering to the TTY output since we
+	//use the raw output to do diffs with the output of a real PS3 and some
+	//programs write text in single bytes to the console
+	if (msg.mType != TTY)
+	{
+		std::string prefix;
+		switch (msg.mServerity)
+		{
+		case Success:
+			prefix = "S ";
+			break;
+		case Notice:
+			prefix = "! ";
+			break;
+		case Warning:
+			prefix = "W ";
+			break;
+		case Error:
+			prefix = "E ";
+			break;
+		}
+		if (NamedThreadBase* thr = GetCurrentNamedThread())
+		{
+			prefix += thr->GetThreadName();
+		}
+		msg.mText.insert(0, prefix);
+		msg.mText.append(1,'\n');
+	}
+#ifdef BUFFERED_LOGGING
+	size_t size = msg.size();
+	std::vector<char> temp_buffer(size);
+	msg.serialize(temp_buffer.data());
+	mBuffer.pushRange(temp_buffer.begin(), temp_buffer.end());
+	mBufferReady.notify_one();
+#else
+	mChannels[static_cast<u32>(msg.mType)].log(msg);
+#endif
+}
+
+
+LogManager& LogManager::getInstance()
+{
+	if (!gLogManager)
+	{
+		gLogManager = new LogManager();
+	}
+	return *gLogManager;
+}
+LogChannel &LogManager::getChannel(LogType type)
+{
+	return mChannels[static_cast<u32>(type)];
+}

Utilities/Log.h

@@ -0,0 +1,139 @@
+#pragma once
+#include <iostream>
+#include <string>
+#include <cinttypes>
+#include <memory>
+#include <vector>
+#include <mutex>
+#include <set>
+#include <array>
+#include "Utilities/MTRingbuffer.h"
+
+//#define BUFFERED_LOGGING 1
+
+//another msvc bug makes these not work, uncomment these and replace it with the one at the bottom when it's fixed
+//#define LOG_MESSAGE(logType, severity, text) Log::LogManager::getInstance().log({logType, severity, text})
+
+//first parameter is of type Log::LogType and text is of type std::string
+#define LOG_MESSAGE(logType, severity, text) do{Log::LogMessage msg{logType, severity, text}; Log::LogManager::getInstance().log(msg);}while(0)
+
+#define LOG_SUCCESS(logType, text)           LOG_MESSAGE(logType, Log::Success, text)
+#define LOG_NOTICE(logType, text)            LOG_MESSAGE(logType, Log::Notice,  text) 
+#define LOG_WARNING(logType, text)           LOG_MESSAGE(logType, Log::Warning, text) 
+#define LOG_ERROR(logType, text)             LOG_MESSAGE(logType, Log::Error,   text)
+
+#define LOGF_SUCCESS(logType, fmtstring, ...)  LOG_SUCCESS(logType, fmt::Format(fmtstring, ##__VA_ARGS__ ))
+#define LOGF_NOTICE(logType, fmtstring, ...)   LOG_NOTICE(logType, fmt::Format(fmtstring, ##__VA_ARGS__ ))
+#define LOGF_WARNING(logType, fmtstring, ...)  LOG_WARNING(logType, fmt::Format(fmtstring, ##__VA_ARGS__ ))
+#define LOGF_ERROR(logType, fmtstring, ...)    LOG_ERROR(logType, fmt::Format(fmtstring, ##__VA_ARGS__ ))
+
+namespace Log
+{
+	const unsigned int MAX_LOG_BUFFER_LENGTH = 1024*1024;
+	const unsigned int gBuffSize = 1000;
+
+	enum LogType : u32
+	{
+		GENERAL = 0,
+		LOADER,
+		MEMORY,
+		RSX,
+		HLE,
+		PPU,
+		SPU,
+		TTY,
+	};
+
+
+	struct LogTypeName
+	{
+		LogType mType;
+		std::string mName;
+	};
+
+	//well I'd love make_array() but alas manually counting is not the end of the world
+	static const std::array<LogTypeName, 8> gTypeNameTable = { {
+			{ GENERAL, "G: " },
+			{ LOADER, "LDR: " },
+			{ MEMORY, "MEM: " },
+			{ RSX, "RSX: " },
+			{ HLE, "HLE: " },
+			{ PPU, "PPU: " },
+			{ SPU, "SPU: " },
+			{ TTY, "TTY: " }
+			} };
+
+	enum LogSeverity : u32
+	{
+		Success = 0,
+		Notice,
+		Warning,
+		Error,
+	};
+
+	struct LogMessage
+	{
+		using size_type = u32;
+		LogType mType;
+		LogSeverity mServerity;
+		std::string mText;
+
+		u32 size();
+		void serialize(char *output);
+		static LogMessage deserialize(char *input, u32* size_out=nullptr);
+	};
+
+	struct LogListener
+	{
+		virtual ~LogListener() {};
+		virtual void log(LogMessage msg) = 0;
+	};
+
+	struct LogChannel
+	{
+		LogChannel();
+		LogChannel(const std::string& name);
+		LogChannel(LogChannel& other) = delete;
+		LogChannel& operator = (LogChannel& other) = delete;
+		void log(LogMessage msg);
+		void addListener(std::shared_ptr<LogListener> listener);
+		void removeListener(std::shared_ptr<LogListener> listener);
+		std::string name;
+	private:
+		bool mEnabled;
+		LogSeverity mLogLevel;
+		std::mutex mListenerLock;
+		std::set<std::shared_ptr<LogListener>> mListeners;
+	};
+
+	struct LogManager
+	{
+		LogManager();
+		~LogManager();
+		static LogManager& getInstance();
+		LogChannel& getChannel(LogType type);
+		void log(LogMessage msg);
+#ifdef BUFFERED_LOGGING
+		void consumeLog();
+#endif
+	private:
+#ifdef BUFFERED_LOGGING
+		MTRingbuffer<char, MAX_LOG_BUFFER_LENGTH> mBuffer;
+		std::condition_variable mBufferReady;
+		std::mutex mStatusMut;
+		std::atomic<bool> mExiting;
+		std::thread mLogConsumer;
+#endif
+		std::array<LogChannel, std::tuple_size<decltype(gTypeNameTable)>::value> mChannels;
+		//std::array<LogChannel,gTypeNameTable.size()> mChannels; //TODO: use this once Microsoft sorts their shit out
+	};
+}
+
+static struct { inline operator Log::LogType() { return Log::LogType::GENERAL; } } GENERAL;
+static struct { inline operator Log::LogType() { return Log::LogType::LOADER; } } LOADER;
+static struct { inline operator Log::LogType() { return Log::LogType::MEMORY; } } MEMORY;
+static struct { inline operator Log::LogType() { return Log::LogType::RSX; } } RSX;
+static struct { inline operator Log::LogType() { return Log::LogType::HLE; } } HLE;
+static struct { inline operator Log::LogType() { return Log::LogType::PPU; } } PPU;
+static struct { inline operator Log::LogType() { return Log::LogType::SPU; } } SPU;
+static struct { inline operator Log::LogType() { return Log::LogType::TTY; } } TTY;

Utilities/MTRingbuffer.h

@@ -0,0 +1,159 @@
+#pragma once
+#include <thread>
+#include <array>
+#include <mutex>
+#include <algorithm>
+
+//Simple non-resizable FIFO Ringbuffer that can be simultaneously be read from and written to
+//if we ever get to use boost please replace this with boost::circular_buffer, there's no reason
+//why we would have to keep this amateur attempt at such a fundamental data-structure around
+template< typename T, unsigned int MAX_MTRINGBUFFER_BUFFER_SIZE>
+class MTRingbuffer{
+	std::array<T, MAX_MTRINGBUFFER_BUFFER_SIZE> mBuffer;
+	//this is a recursive mutex because the get methods lock it but the only
+	//way to be sure that they do not block is to check the size and the only
+	//way to check the size and use get atomically is to lock this mutex,
+	//so it goes:
+	//lock get mutex-->check size-->call get-->lock get mutex-->unlock get mutex-->return from get-->unlock get mutex
+	std::recursive_mutex mMutGet;
+	std::mutex mMutPut;
+
+	size_t mGet;
+	size_t mPut;
+	size_t moveGet(size_t by = 1){ return (mGet + by) % MAX_MTRINGBUFFER_BUFFER_SIZE; }
+	size_t movePut(size_t by = 1){ return (mPut + by) % MAX_MTRINGBUFFER_BUFFER_SIZE; }
+public:
+	MTRingbuffer() : mGet(0), mPut(0){}
+
+	//blocks until there's something to get, so check "free()" if you want to avoid blocking
+	//also lock the get mutex around the free() check and the pop if you want to avoid racing
+	T pop()
+	{
+		std::lock_guard<std::recursive_mutex> lock(mMutGet);
+		while (mGet == mPut)
+		{
+			//wait until there's actually something to get
+			//throwing an exception might be better, blocking here is a little awkward
+			std::this_thread::sleep_for(std::chrono::milliseconds(1));
+		}
+		size_t ret = mGet;
+		mGet = moveGet();
+		return mBuffer[ret];
+	}
+
+	//blocks if the buffer is full until there's enough room
+	void push(T &putEle)
+	{
+		std::lock_guard<std::mutex> lock(mMutPut);
+		while (movePut() == mGet)
+		{
+			//if this is reached a lot it's time to increase the buffer size
+			//or implement dynamic re-sizing
+			std::this_thread::sleep_for(std::chrono::milliseconds(1));
+		}
+		mBuffer[mPut] = std::forward(putEle);
+		mPut = movePut();
+	}
+
+	bool empty()
+	{
+		return mGet == mPut;
+	}
+
+	//returns the amount of free places, this is the amount of actual free spaces-1
+	//since mGet==mPut signals an empty buffer we can't actually use the last free
+	//space, so we shouldn't report it as free.
+	size_t free()
+	{
+		if (mGet < mPut)
+		{
+			return mBuffer.size() - (mPut - mGet) - 1;
+		}
+		else if (mGet > mPut)
+		{
+			return mGet - mPut - 1;
+		}
+		else
+		{
+			return mBuffer.size() - 1;
+		}
+	}
+
+	size_t size()
+	{
+		//the magic -1 is the same magic 1 that is explained in the free() function
+		return mBuffer.size() - free() - 1;
+	}
+
+	//takes random access iterator to T
+	template<typename IteratorType>
+	void pushRange(IteratorType from, IteratorType until)
+	{
+		std::lock_guard<std::mutex> lock(mMutPut);
+		size_t length = until - from;
+
+		//if whatever we're trying to store is greater than the entire buffer the following loop will be infinite
+		assert(mBuffer.size() > length);
+		while (free() < length)
+		{
+			//if this is reached a lot it's time to increase the buffer size
+			//or implement dynamic re-sizing
+			std::this_thread::sleep_for(std::chrono::milliseconds(1));
+		}
+		if (mPut + length <= mBuffer.size())
+		{
+			std::copy(from, until, mBuffer.begin() + mPut);
+		}
+		else
+		{
+			size_t tillEnd = mBuffer.size() - mPut;
+			std::copy(from, from + tillEnd, mBuffer.begin() + mPut);
+			std::copy(from + tillEnd, until, mBuffer.begin());
+		}
+		mPut = movePut(length);
+
+	}
+
+	//takes output iterator to T
+	template<typename IteratorType>
+	void popN(IteratorType output, size_t n)
+	{
+		std::lock_guard<std::recursive_mutex> lock(mMutGet);
+		//make sure we're not trying to retrieve more than is in
+		assert(n <= size());
+		peekN<IteratorType>(output, n);
+		mGet = moveGet(n);
+	}
+
+	//takes output iterator to T
+	template<typename IteratorType>
+	void peekN(IteratorType output, size_t n)
+	{
+		size_t lGet = mGet;
+		if (lGet + n <= mBuffer.size())
+		{
+			std::copy_n(mBuffer.begin() + lGet, n, output);
+		}
+		else
+		{
+			auto next = std::copy(mBuffer.begin() + lGet, mBuffer.end(), output);
+			std::copy_n(mBuffer.begin(), n - (mBuffer.size() - lGet), next);
+		}
+	}
+
+	//well this is just asking for trouble
+	//but the comment above the declaration of mMutGet explains why it's there
+	//if there's a better way please remove this
+	void lockGet()
+	{
+		mMutGet.lock();
+	}
+
+	//well this is just asking for trouble
+	//but the comment above the declaration of mMutGet explains why it's there
+	//if there's a better way please remove this
+	void unlockGet()
+	{
+		mMutGet.unlock();
+	}
+};

Utilities/SMutex.cpp

@@ -1,5 +1,5 @@
 #include <stdafx.h>
-#include "Emu/ConLog.h"
+#include "Utilities/Log.h"
 #include "Emu/Memory/Memory.h"
 #include "Emu/System.h"
 #include "Emu/CPU/CPUThread.h"

Utilities/SMutex.h

@@ -148,7 +148,7 @@ public:
 		{
 			if (!Emu.IsStopped())
 			{
-				ConLog.Error("SMutexLockerBase: thread id == 0");
+				LOG_ERROR(HLE, "SMutexLockerBase: thread id == 0");
 				Emu.Pause();
 			}
 			return;

Utilities/StrFmt.h

@@ -4,6 +4,7 @@
 #include <ostream>
 #include <sstream>
 #include <cstdio>
+#include <functional>
 
 #if defined(_MSC_VER)
 #define snprintf _snprintf

Utilities/Thread.cpp

@@ -1,5 +1,5 @@
 #include "stdafx.h"
-#include "Emu/ConLog.h"
+#include "Utilities/Log.h"
 
 #include "Thread.h"
 
@@ -134,7 +134,7 @@ void thread::start(std::function<void()> func)
 		}
 		catch(...)
 		{
-			ConLog.Error("Crash :(");
+			LOG_ERROR(HLE, "Crash :(");
 			//std::terminate();
 		}
 

Utilities/rFile.cpp

@@ -120,7 +120,7 @@ size_t rFile::Write(const void *buffer, size_t count)
 
 bool rFile::Write(const std::string &text)
 {
-	return reinterpret_cast<wxFile*>(handle)->Write(fmt::FromUTF8(text));
+	return reinterpret_cast<wxFile*>(handle)->Write(reinterpret_cast<const void*>(text.c_str()),text.size());
 }
 
 bool rFile::Close()