Logging system rewritten

GUI doesn't freeze anymore
Some things simplified
This commit is contained in:
Nekotekina 2016-01-13 00:57:16 +03:00
parent b3e3c68f15
commit 38531459df
130 changed files with 2026 additions and 2479 deletions

View file

@ -1,6 +1,4 @@
#include "stdafx.h"
#include <iostream>
#include <cinttypes>
#include "stdafx.h"
#include "Thread.h"
#include "File.h"
#include "Log.h"
@ -9,257 +7,144 @@
#include <Windows.h>
#endif
using namespace Log;
std::unique_ptr<LogManager> g_log_manager;
u32 LogMessage::size() const
namespace _log
{
//1 byte for NULL terminator
return (u32)(sizeof(LogMessage::size_type) + sizeof(LogType) + sizeof(Severity) + sizeof(std::string::value_type) * mText.size() + 1);
}
void LogMessage::serialize(char *output) const
{
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(Severity));
output += sizeof(Severity);
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<Severity*>(input));
input += sizeof(Severity);
if (msgSize > 9000)
logger& get_logger()
{
int wtf = 6;
// Use magic static for global logger instance
static logger instance;
return instance;
}
msg.mText.append(input, msgSize - 1 - sizeof(Severity) - sizeof(LogType));
if (size_out){(*size_out) = msgSize;}
return msg;
file_listener g_log_file(_PRGNAME_ ".log");
file_writer g_tty_file("TTY.log");
channel GENERAL("", level::notice);
channel LOADER("LDR", level::notice);
channel MEMORY("MEM", level::notice);
channel RSX("RSX", level::notice);
channel HLE("HLE", level::notice);
channel PPU("PPU", level::notice);
channel SPU("SPU", level::notice);
channel ARMv7("ARMv7");
}
LogChannel::LogChannel() : LogChannel("unknown")
{}
LogChannel::LogChannel(const std::string& name) :
name(name)
, mEnabled(true)
, mLogLevel(Severity::Warning)
{}
void LogChannel::log(const LogMessage &msg)
_log::listener::listener()
{
std::lock_guard<std::mutex> lock(mListenerLock);
for (auto &listener : mListeners)
// Register self
get_logger().add_listener(this);
}
_log::listener::~listener()
{
// Unregister self
get_logger().remove_listener(this);
}
_log::channel::channel(const std::string& name, _log::level init_level)
: name{ name }
, enabled{ init_level }
{
// TODO: register config property "name" associated with "enabled" member
}
void _log::logger::add_listener(_log::listener* listener)
{
std::lock_guard<shared_mutex> lock(m_mutex);
m_listeners.emplace(listener);
}
void _log::logger::remove_listener(_log::listener* listener)
{
std::lock_guard<shared_mutex> lock(m_mutex);
m_listeners.erase(listener);
}
void _log::logger::broadcast(const _log::channel& ch, _log::level sev, const std::string& text) const
{
reader_lock lock(m_mutex);
for (auto listener : m_listeners)
{
listener->log(msg);
listener->log(ch, sev, text);
}
}
void LogChannel::addListener(std::shared_ptr<LogListener> listener)
void _log::broadcast(const _log::channel& ch, _log::level sev, const std::string& text)
{
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);
get_logger().broadcast(ch, sev, text);
}
struct CoutListener : LogListener
_log::file_writer::file_writer(const std::string& name)
{
void log(const LogMessage &msg) override
try
{
std::cerr << msg.mText << std::endl;
}
};
struct FileListener : LogListener
{
fs::file mFile;
bool mPrependChannelName;
FileListener(const std::string& name = _PRGNAME_ ".log", bool prependChannel = true)
: mFile(fs::get_config_dir() + name, fom::rewrite)
, mPrependChannelName(prependChannel)
{
if (!mFile)
if (!m_file.open(fs::get_config_dir() + name, fom::rewrite | fom::append))
{
throw EXCEPTION("Can't create log file %s (error %d)", name, errno);
}
}
catch (const fmt::exception& e)
{
#ifdef _WIN32
MessageBoxA(0, ("Can't create log file: " + name).c_str(), "Error", MB_ICONERROR);
MessageBoxA(0, e.what(), "_log::file_writer() failed", MB_ICONERROR);
#else
std::printf("Can't create log file: %s\n", name.c_str());
std::printf("_log::file_writer() failed: %s\n", e.what());
#endif
}
}
}
void log(const LogMessage &msg) override
void _log::file_writer::log(const std::string& text)
{
m_file.write(text);
}
std::size_t _log::file_writer::size() const
{
return m_file.seek(0, fs::seek_cur);
}
void _log::file_listener::log(const _log::channel& ch, _log::level sev, const std::string& text)
{
std::string msg; msg.reserve(text.size() + 200);
// Used character: U+00B7 (Middle Dot)
switch (sev)
{
std::string text = msg.mText;
if (mPrependChannelName)
{
text.insert(0, gTypeNameTable[static_cast<u32>(msg.mType)].mName);
if (msg.mType == Log::TTY)
{
text = fmt::escape(text);
if (text[text.length() - 1] != '\n')
{
text += '\n';
}
}
}
mFile.write(text);
case level::always: msg = u8"·A "; break;
case level::fatal: msg = u8"·F "; break;
case level::error: msg = u8"·E "; break;
case level::todo: msg = u8"·U "; break;
case level::success: msg = u8"·S "; break;
case level::warning: msg = u8"·W "; break;
case level::notice: msg = u8"·! "; break;
case level::trace: msg = u8"·T "; break;
}
};
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)
// TODO: print time?
if (auto t = thread_ctrl::get_current())
{
it->name = name.mName;
it->addListener(listener);
it++;
msg += '{';
msg += t->get_name();
msg += "} ";
}
std::shared_ptr<LogListener> TTYListener(new FileListener("TTY.log", 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)
if (ch.name.size())
{
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);
}
msg += ch.name;
msg += sev == level::todo ? " TODO: " : ": ";
}
#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)
else if (sev == level::todo)
{
std::string prefix;
switch (msg.mServerity)
{
case Severity::Success:
prefix = "S ";
break;
case Severity::Notice:
prefix = "! ";
break;
case Severity::Warning:
prefix = "W ";
break;
case Severity::Error:
prefix = "E ";
break;
}
if (auto thr = thread_ctrl::get_current())
{
prefix += "{" + thr->get_name() + "} ";
}
msg.mText.insert(0, prefix);
msg.mText.append(1,'\n');
msg += "TODO: ";
}
#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
}
msg += text;
msg += '\n';
void LogManager::addListener(std::shared_ptr<LogListener> listener)
{
for (auto& channel : mChannels)
{
channel.addListener(listener);
}
}
void LogManager::removeListener(std::shared_ptr<LogListener> listener)
{
for (auto& channel : mChannels)
{
channel.removeListener(listener);
}
}
LogManager& LogManager::getInstance()
{
if (!g_log_manager)
{
g_log_manager.reset(new LogManager());
}
return *g_log_manager;
}
LogChannel &LogManager::getChannel(LogType type)
{
return mChannels[static_cast<u32>(type)];
}
void log_message(Log::LogType type, Log::Severity sev, const char* text)
{
log_message(type, sev, std::string(text));
}
void log_message(Log::LogType type, Log::Severity sev, std::string text)
{
g_log_manager->log({ type, sev, std::move(text) });
file_writer::log(msg);
}

View file

@ -1,134 +1,155 @@
#pragma once
#include "Utilities/MTRingbuffer.h"
//#define BUFFERED_LOGGING 1
#include "SharedMutex.h"
//first parameter is of type Log::LogType and text is of type std::string
#define LOG_SUCCESS(logType, text, ...) log_message(logType, Log::Severity::Success, text, ##__VA_ARGS__)
#define LOG_NOTICE(logType, text, ...) log_message(logType, Log::Severity::Notice, text, ##__VA_ARGS__)
#define LOG_WARNING(logType, text, ...) log_message(logType, Log::Severity::Warning, text, ##__VA_ARGS__)
#define LOG_ERROR(logType, text, ...) log_message(logType, Log::Severity::Error, text, ##__VA_ARGS__)
namespace Log
namespace _log
{
const unsigned int MAX_LOG_BUFFER_LENGTH = 1024*1024;
const unsigned int gBuffSize = 1000;
enum LogType : u32
enum class level : uint
{
GENERAL = 0,
LOADER,
MEMORY,
RSX,
HLE,
PPU,
SPU,
ARMv7,
TTY,
always, // highest level (unused, cannot be disabled)
fatal,
error,
todo,
success,
warning,
notice,
trace, // lowest level (usually disabled)
};
struct channel;
struct listener;
struct LogTypeName
// Log manager
class logger final
{
LogType mType;
std::string mName;
mutable shared_mutex m_mutex;
std::set<listener*> m_listeners;
public:
// Register listener
void add_listener(listener* listener);
// Unregister listener
void remove_listener(listener* listener);
// Send log message to all listeners
void broadcast(const channel& ch, level sev, const std::string& text) const;
};
//well I'd love make_array() but alas manually counting is not the end of the world
static const std::array<LogTypeName, 9> gTypeNameTable = { {
{ GENERAL, "G: " },
{ LOADER, "LDR: " },
{ MEMORY, "MEM: " },
{ RSX, "RSX: " },
{ HLE, "HLE: " },
{ PPU, "PPU: " },
{ SPU, "SPU: " },
{ ARMv7, "ARM: " },
{ TTY, "TTY: " }
} };
// Send log message to global logger instance
void broadcast(const channel& ch, level sev, const std::string& text);
enum class Severity : u32
// Log channel (source)
struct channel
{
Notice = 0,
Warning,
Success,
Error,
// Channel prefix (also used for identification)
const std::string name;
// The lowest logging level enabled for this channel (used for early filtering)
std::atomic<level> enabled;
// Initialization (max level enabled by default)
channel(const std::string& name, level = level::trace);
virtual ~channel() = default;
// Log without formatting
force_inline void log(level sev, const std::string& text) const
{
if (sev <= enabled)
broadcast(*this, sev, text);
}
// Log with formatting
template<typename... Args>
force_inline safe_buffers void format(level sev, const char* fmt, const Args&... args) const
{
if (sev <= enabled)
broadcast(*this, sev, fmt::format(fmt, fmt::do_unveil(args)...));
}
#define GEN_LOG_METHOD(_sev)\
template<typename... Args>\
force_inline void _sev(const char* fmt, const Args&... args)\
{\
return format<Args...>(level::_sev, fmt, args...);\
}
GEN_LOG_METHOD(fatal)
GEN_LOG_METHOD(error)
GEN_LOG_METHOD(todo)
GEN_LOG_METHOD(success)
GEN_LOG_METHOD(warning)
GEN_LOG_METHOD(notice)
GEN_LOG_METHOD(trace)
#undef GEN_LOG_METHOD
};
struct LogMessage
// Log listener (destination)
struct listener
{
using size_type = u32;
LogType mType;
Severity mServerity;
std::string mText;
listener();
virtual ~listener();
u32 size() const;
void serialize(char *output) const;
static LogMessage deserialize(char *input, u32* size_out=nullptr);
virtual void log(const channel& ch, level sev, const std::string& text) = 0;
};
struct LogListener
class file_writer
{
virtual ~LogListener() {};
virtual void log(const LogMessage &msg) = 0;
// Could be memory-mapped file
fs::file m_file;
public:
file_writer(const std::string& name);
virtual ~file_writer() = default;
// Append raw data
void log(const std::string& text);
// Get current file size (may be used by secondary readers)
std::size_t size() const;
};
struct LogChannel
struct file_listener : public file_writer, public listener
{
LogChannel();
LogChannel(const std::string& name);
LogChannel(LogChannel& other) = delete;
void log(const LogMessage &msg);
void addListener(std::shared_ptr<LogListener> listener);
void removeListener(std::shared_ptr<LogListener> listener);
std::string name;
private:
bool mEnabled;
Severity mLogLevel;
std::mutex mListenerLock;
std::set<std::shared_ptr<LogListener>> mListeners;
file_listener(const std::string& name)
: file_writer(name)
, listener()
{
}
// Encode level, current thread name, channel name and write log message
virtual void log(const channel& ch, level sev, const std::string& text) override;
};
struct LogManager
{
LogManager();
~LogManager();
static LogManager& getInstance();
LogChannel& getChannel(LogType type);
void log(LogMessage msg);
void addListener(std::shared_ptr<LogListener> listener);
void removeListener(std::shared_ptr<LogListener> listener);
#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
};
// Global variable for RPCS3.log
extern file_listener g_log_file;
// Global variable for TTY.log
extern file_writer g_tty_file;
// Small set of predefined channels:
extern channel GENERAL;
extern channel LOADER;
extern channel MEMORY;
extern channel RSX;
extern channel HLE;
extern channel PPU;
extern channel SPU;
extern channel ARMv7;
}
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::ARMv7; } } ARMv7;
static struct { inline operator Log::LogType() { return Log::LogType::TTY; } } TTY;
// Legacy:
void log_message(Log::LogType type, Log::Severity sev, const char* text);
void log_message(Log::LogType type, Log::Severity sev, std::string text);
template<typename... Args> never_inline void log_message(Log::LogType type, Log::Severity sev, const char* fmt, Args... args)
{
log_message(type, sev, fmt::format(fmt, fmt::do_unveil(args)...));
}
#define LOG_SUCCESS(ch, fmt, ...) _log::ch.success(fmt, ##__VA_ARGS__)
#define LOG_NOTICE(ch, fmt, ...) _log::ch.notice (fmt, ##__VA_ARGS__)
#define LOG_WARNING(ch, fmt, ...) _log::ch.warning(fmt, ##__VA_ARGS__)
#define LOG_ERROR(ch, fmt, ...) _log::ch.error (fmt, ##__VA_ARGS__)
#define LOG_TODO(ch, fmt, ...) _log::ch.todo (fmt, ##__VA_ARGS__)
#define LOG_TRACE(ch, fmt, ...) _log::ch.trace (fmt, ##__VA_ARGS__)
#define LOG_FATAL(ch, fmt, ...) _log::ch.fatal (fmt, ##__VA_ARGS__)

View file

@ -1,155 +0,0 @@
#pragma once
//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 "spaceLeft()" if you want to avoid blocking
//also lock the get mutex around the spaceLeft() 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)); // hack
}
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)); // hack
}
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 spaceLeft() //apparently free() is a macro definition in msvc in some conditions
{
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 spaceLeft() function
return mBuffer.size() - spaceLeft() - 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 (spaceLeft() < 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)); // hack
}
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();
}
};

View file

@ -155,19 +155,19 @@ namespace fmt
}
};
template<> struct unveil<char*, false>
template<> struct unveil<const char*, false>
{
using result_type = const char*;
using result_type = const char* const;
force_inline static result_type get_value(const char* arg)
force_inline static result_type get_value(const char* const& arg)
{
return arg;
}
};
template<std::size_t N> struct unveil<const char[N], false>
template<std::size_t N> struct unveil<char[N], false>
{
using result_type = const char*;
using result_type = const char* const;
force_inline static result_type get_value(const char(&arg)[N])
{
@ -220,7 +220,8 @@ namespace fmt
// vm::ptr, vm::bptr, ... (fmt::do_unveil) (vm_ptr.h) (with appropriate address type, using .addr() can be avoided)
// vm::ref, vm::bref, ... (fmt::do_unveil) (vm_ref.h)
//
template<typename... Args> safe_buffers std::string format(const char* fmt, Args... args)
template<typename... Args>
safe_buffers std::string format(const char* fmt, const Args&... args)
{
// fixed stack buffer for the first attempt
std::array<char, 4096> fixed_buf;

View file

@ -1351,21 +1351,15 @@ void named_thread_t::start()
{
try
{
if (rpcs3::config.misc.log.hle_logging.value())
{
LOG_NOTICE(GENERAL, "Thread started");
}
LOG_TRACE(GENERAL, "Thread started");
thread->on_task();
if (rpcs3::config.misc.log.hle_logging.value())
{
LOG_NOTICE(GENERAL, "Thread ended");
}
LOG_TRACE(GENERAL, "Thread ended");
}
catch (const std::exception& e)
{
LOG_ERROR(GENERAL, "Exception: %s\nPlease report this to the developers.", e.what());
LOG_FATAL(GENERAL, "Exception: %s\nPlease report this to the developers.", e.what());
Emu.Pause();
}
catch (EmulationStopped)