From 616d87444313db865c60fbeee36ebe5250ef301e Mon Sep 17 00:00:00 2001 From: Yuri Kunde Schlesner Date: Tue, 28 Oct 2014 05:36:00 -0200 Subject: [PATCH] New logging system --- src/citra/citra.cpp | 16 ++- src/citra_qt/main.cpp | 18 ++- src/common/CMakeLists.txt | 6 + src/common/common_types.h | 2 - src/common/concurrent_ring_buffer.h | 164 ++++++++++++++++++++++++++ src/common/log.h | 78 ++++++------ src/common/log_manager.cpp | 58 ++++----- src/common/logging/backend.cpp | 151 ++++++++++++++++++++++++ src/common/logging/backend.h | 134 +++++++++++++++++++++ src/common/logging/log.h | 115 ++++++++++++++++++ src/common/logging/text_formatter.cpp | 47 ++++++++ src/common/logging/text_formatter.h | 26 ++++ src/common/thread.h | 1 + src/core/hle/config_mem.cpp | 1 + 14 files changed, 743 insertions(+), 74 deletions(-) create mode 100644 src/common/concurrent_ring_buffer.h create mode 100644 src/common/logging/backend.cpp create mode 100644 src/common/logging/backend.h create mode 100644 src/common/logging/log.h create mode 100644 src/common/logging/text_formatter.cpp create mode 100644 src/common/logging/text_formatter.h diff --git a/src/citra/citra.cpp b/src/citra/citra.cpp index f2aeb510e..7c031ce8d 100644 --- a/src/citra/citra.cpp +++ b/src/citra/citra.cpp @@ -2,8 +2,12 @@ // Licensed under GPLv2 // Refer to the license.txt file included. +#include + #include "common/common.h" -#include "common/log_manager.h" +#include "common/logging/text_formatter.h" +#include "common/logging/backend.h" +#include "common/scope_exit.h" #include "core/settings.h" #include "core/system.h" @@ -15,7 +19,12 @@ /// Application entry point int __cdecl main(int argc, char **argv) { - LogManager::Init(); + std::shared_ptr logger = Log::InitGlobalLogger(); + std::thread logging_thread(Log::TextLoggingLoop, logger); + SCOPE_EXIT({ + logger->Close(); + logging_thread.join(); + }); if (argc < 2) { ERROR_LOG(BOOT, "Failed to load ROM: No ROM specified"); @@ -24,9 +33,6 @@ int __cdecl main(int argc, char **argv) { Config config; - if (!Settings::values.enable_log) - LogManager::Shutdown(); - std::string boot_filename = argv[1]; EmuWindow_GLFW* emu_window = new EmuWindow_GLFW; diff --git a/src/citra_qt/main.cpp b/src/citra_qt/main.cpp index b4e3ad964..2e3025295 100644 --- a/src/citra_qt/main.cpp +++ b/src/citra_qt/main.cpp @@ -1,3 +1,5 @@ +#include + #include #include #include @@ -5,8 +7,13 @@ #include "main.hxx" #include "common/common.h" -#include "common/platform.h" #include "common/log_manager.h" +#include "common/logging/text_formatter.h" +#include "common/logging/log.h" +#include "common/logging/backend.h" +#include "common/platform.h" +#include "common/scope_exit.h" + #if EMU_PLATFORM == PLATFORM_LINUX #include #endif @@ -33,10 +40,8 @@ #include "version.h" - GMainWindow::GMainWindow() { - LogManager::Init(); Pica::g_debug_context = Pica::DebugContext::Construct(); @@ -271,6 +276,13 @@ void GMainWindow::closeEvent(QCloseEvent* event) int __cdecl main(int argc, char* argv[]) { + std::shared_ptr logger = Log::InitGlobalLogger(); + std::thread logging_thread(Log::TextLoggingLoop, logger); + SCOPE_EXIT({ + logger->Close(); + logging_thread.join(); + }); + QApplication::setAttribute(Qt::AA_X11InitThreads); QApplication app(argc, argv); GMainWindow main_window; diff --git a/src/common/CMakeLists.txt b/src/common/CMakeLists.txt index 1dbc5db21..7c1d3d1dc 100644 --- a/src/common/CMakeLists.txt +++ b/src/common/CMakeLists.txt @@ -11,6 +11,8 @@ set(SRCS hash.cpp key_map.cpp log_manager.cpp + logging/text_formatter.cpp + logging/backend.cpp math_util.cpp mem_arena.cpp memory_util.cpp @@ -32,6 +34,7 @@ set(HEADERS common_funcs.h common_paths.h common_types.h + concurrent_ring_buffer.h console_listener.h cpu_detect.h debug_interface.h @@ -45,6 +48,9 @@ set(HEADERS linear_disk_cache.h log.h log_manager.h + logging/text_formatter.h + logging/log.h + logging/backend.h math_util.h mem_arena.h memory_util.h diff --git a/src/common/common_types.h b/src/common/common_types.h index fcc8b9a4e..c74c74f0f 100644 --- a/src/common/common_types.h +++ b/src/common/common_types.h @@ -41,8 +41,6 @@ typedef std::int64_t s64; ///< 64-bit signed int typedef float f32; ///< 32-bit floating point typedef double f64; ///< 64-bit floating point -#include "common/common.h" - /// Union for fast 16-bit type casting union t16 { u8 _u8[2]; ///< 8-bit unsigned char(s) diff --git a/src/common/concurrent_ring_buffer.h b/src/common/concurrent_ring_buffer.h new file mode 100644 index 000000000..2951d93db --- /dev/null +++ b/src/common/concurrent_ring_buffer.h @@ -0,0 +1,164 @@ +// Copyright 2014 Citra Emulator Project +// Licensed under GPLv2+ +// Refer to the license.txt file included. + +#pragma once + +#include +#include +#include +#include +#include + +#include "common/common.h" // for NonCopyable +#include "common/log.h" // for _dbg_assert_ + +namespace Common { + +/** + * A MPMC (Multiple-Producer Multiple-Consumer) concurrent ring buffer. This data structure permits + * multiple threads to push and pop from a queue of bounded size. + */ +template +class ConcurrentRingBuffer : private NonCopyable { +public: + /// Value returned by the popping functions when the queue has been closed. + static const size_t QUEUE_CLOSED = -1; + + ConcurrentRingBuffer() {} + + ~ConcurrentRingBuffer() { + // If for whatever reason the queue wasn't completely drained, destroy the left over items. + for (size_t i = reader_index, end = writer_index; i != end; i = (i + 1) % ArraySize) { + Data()[i].~T(); + } + } + + /** + * Pushes a value to the queue. If the queue is full, this method will block. Does nothing if + * the queue is closed. + */ + void Push(T val) { + std::unique_lock lock(mutex); + if (closed) { + return; + } + + // If the buffer is full, wait + writer.wait(lock, [&]{ + return (writer_index + 1) % ArraySize != reader_index; + }); + + T* item = &Data()[writer_index]; + new (item) T(std::move(val)); + + writer_index = (writer_index + 1) % ArraySize; + + // Wake up waiting readers + lock.unlock(); + reader.notify_one(); + } + + /** + * Pops up to `dest_len` items from the queue, storing them in `dest`. This function will not + * block, and might return 0 values if there are no elements in the queue when it is called. + * + * @return The number of elements stored in `dest`. If the queue has been closed, returns + * `QUEUE_CLOSED`. + */ + size_t Pop(T* dest, size_t dest_len) { + std::unique_lock lock(mutex); + if (closed && !CanRead()) { + return QUEUE_CLOSED; + } + return PopInternal(dest, dest_len); + } + + /** + * Pops up to `dest_len` items from the queue, storing them in `dest`. This function will block + * if there are no elements in the queue when it is called. + * + * @return The number of elements stored in `dest`. If the queue has been closed, returns + * `QUEUE_CLOSED`. + */ + size_t BlockingPop(T* dest, size_t dest_len) { + std::unique_lock lock(mutex); + if (closed && !CanRead()) { + return QUEUE_CLOSED; + } + + while (!CanRead()) { + reader.wait(lock); + if (closed && !CanRead()) { + return QUEUE_CLOSED; + } + } + _dbg_assert_(Common, CanRead()); + return PopInternal(dest, dest_len); + } + + /** + * Closes the queue. After calling this method, `Push` operations won't have any effect, and + * `PopMany` and `PopManyBlock` will start returning `QUEUE_CLOSED`. This is intended to allow + * a graceful shutdown of all consumers. + */ + void Close() { + std::unique_lock lock(mutex); + closed = true; + // We need to wake up any reader that are waiting for an item that will never come. + lock.unlock(); + reader.notify_all(); + } + + /// Returns true if `Close()` has been called. + bool IsClosed() const { + return closed; + } + +private: + size_t PopInternal(T* dest, size_t dest_len) { + size_t output_count = 0; + while (output_count < dest_len && CanRead()) { + _dbg_assert_(Common, CanRead()); + + T* item = &Data()[reader_index]; + T out_val = std::move(*item); + item->~T(); + + size_t prev_index = (reader_index + ArraySize - 1) % ArraySize; + reader_index = (reader_index + 1) % ArraySize; + if (writer_index == prev_index) { + writer.notify_one(); + } + dest[output_count++] = std::move(out_val); + } + return output_count; + } + + bool CanRead() const { + return reader_index != writer_index; + } + + T* Data() { + return static_cast(static_cast(&storage)); + } + + /// Storage for entries + typename std::aligned_storage::value>::type storage; + + /// Data is valid in the half-open interval [reader, writer). If they are `QUEUE_CLOSED` then the + /// queue has been closed. + size_t writer_index = 0, reader_index = 0; + // True if the queue has been closed. + bool closed = false; + + /// Mutex that protects the entire data structure. + std::mutex mutex; + /// Signaling wakes up reader which is waiting for storage to be non-empty. + std::condition_variable reader; + /// Signaling wakes up writer which is waiting for storage to be non-full. + std::condition_variable writer; +}; + +} // namespace diff --git a/src/common/log.h b/src/common/log.h index 78f0dae4d..105db9802 100644 --- a/src/common/log.h +++ b/src/common/log.h @@ -6,6 +6,7 @@ #include "common/common_funcs.h" #include "common/msg_handler.h" +#include "common/logging/log.h" #ifndef LOGGING #define LOGGING @@ -24,45 +25,45 @@ namespace LogTypes { enum LOG_TYPE { - ACTIONREPLAY, - AUDIO, - AUDIO_INTERFACE, + //ACTIONREPLAY, + //AUDIO, + //AUDIO_INTERFACE, BOOT, - COMMANDPROCESSOR, + //COMMANDPROCESSOR, COMMON, - CONSOLE, + //CONSOLE, CONFIG, - DISCIO, - FILEMON, - DSPHLE, - DSPLLE, - DSP_MAIL, - DSPINTERFACE, - DVDINTERFACE, - DYNA_REC, - EXPANSIONINTERFACE, - GDB_STUB, + //DISCIO, + //FILEMON, + //DSPHLE, + //DSPLLE, + //DSP_MAIL, + //DSPINTERFACE, + //DVDINTERFACE, + //DYNA_REC, + //EXPANSIONINTERFACE, + //GDB_STUB, ARM11, GSP, OSHLE, MASTER_LOG, MEMMAP, - MEMCARD_MANAGER, - OSREPORT, - PAD, - PROCESSORINTERFACE, - PIXELENGINE, - SERIALINTERFACE, - SP1, - STREAMINGINTERFACE, + //MEMCARD_MANAGER, + //OSREPORT, + //PAD, + //PROCESSORINTERFACE, + //PIXELENGINE, + //SERIALINTERFACE, + //SP1, + //STREAMINGINTERFACE, VIDEO, - VIDEOINTERFACE, + //VIDEOINTERFACE, LOADER, FILESYS, - WII_IPC_DVD, - WII_IPC_ES, - WII_IPC_FILEIO, - WII_IPC_HID, + //WII_IPC_DVD, + //WII_IPC_ES, + //WII_IPC_FILEIO, + //WII_IPC_HID, KERNEL, SVC, HLE, @@ -70,7 +71,7 @@ enum LOG_TYPE { GPU, HW, TIME, - NETPLAY, + //NETPLAY, GUI, NUMBER_OF_LOGS // Must be last @@ -118,12 +119,19 @@ void GenericLog(LOGTYPES_LEVELS level, LOGTYPES_TYPE type, const char*file, int GenericLog(v, t, __FILE__, __LINE__, __func__, __VA_ARGS__); \ } -#define OS_LOG(t,...) do { GENERIC_LOG(LogTypes::t, LogTypes::LOS, __VA_ARGS__) } while (0) -#define ERROR_LOG(t,...) do { GENERIC_LOG(LogTypes::t, LogTypes::LERROR, __VA_ARGS__) } while (0) -#define WARN_LOG(t,...) do { GENERIC_LOG(LogTypes::t, LogTypes::LWARNING, __VA_ARGS__) } while (0) -#define NOTICE_LOG(t,...) do { GENERIC_LOG(LogTypes::t, LogTypes::LNOTICE, __VA_ARGS__) } while (0) -#define INFO_LOG(t,...) do { GENERIC_LOG(LogTypes::t, LogTypes::LINFO, __VA_ARGS__) } while (0) -#define DEBUG_LOG(t,...) do { GENERIC_LOG(LogTypes::t, LogTypes::LDEBUG, __VA_ARGS__) } while (0) +//#define OS_LOG(t,...) do { GENERIC_LOG(LogTypes::t, LogTypes::LOS, __VA_ARGS__) } while (0) +//#define ERROR_LOG(t,...) do { GENERIC_LOG(LogTypes::t, LogTypes::LERROR, __VA_ARGS__) } while (0) +//#define WARN_LOG(t,...) do { GENERIC_LOG(LogTypes::t, LogTypes::LWARNING, __VA_ARGS__) } while (0) +//#define NOTICE_LOG(t,...) do { GENERIC_LOG(LogTypes::t, LogTypes::LNOTICE, __VA_ARGS__) } while (0) +//#define INFO_LOG(t,...) do { GENERIC_LOG(LogTypes::t, LogTypes::LINFO, __VA_ARGS__) } while (0) +//#define DEBUG_LOG(t,...) do { GENERIC_LOG(LogTypes::t, LogTypes::LDEBUG, __VA_ARGS__) } while (0) + +#define OS_LOG(t,...) LOG_INFO(Common, __VA_ARGS__) +#define ERROR_LOG(t,...) LOG_ERROR(Common_Filesystem, __VA_ARGS__) +#define WARN_LOG(t,...) LOG_WARNING(Kernel_SVC, __VA_ARGS__) +#define NOTICE_LOG(t,...) LOG_INFO(Service, __VA_ARGS__) +#define INFO_LOG(t,...) LOG_INFO(Service_FS, __VA_ARGS__) +#define DEBUG_LOG(t,...) LOG_DEBUG(Common, __VA_ARGS__) #if MAX_LOGLEVEL >= DEBUG_LEVEL #define _dbg_assert_(_t_, _a_) \ diff --git a/src/common/log_manager.cpp b/src/common/log_manager.cpp index 128c15388..adc17444c 100644 --- a/src/common/log_manager.cpp +++ b/src/common/log_manager.cpp @@ -30,49 +30,49 @@ LogManager::LogManager() m_Log[LogTypes::BOOT] = new LogContainer("BOOT", "Boot"); m_Log[LogTypes::COMMON] = new LogContainer("COMMON", "Common"); m_Log[LogTypes::CONFIG] = new LogContainer("CONFIG", "Configuration"); - m_Log[LogTypes::DISCIO] = new LogContainer("DIO", "Disc IO"); - m_Log[LogTypes::FILEMON] = new LogContainer("FileMon", "File Monitor"); - m_Log[LogTypes::PAD] = new LogContainer("PAD", "Pad"); - m_Log[LogTypes::PIXELENGINE] = new LogContainer("PE", "PixelEngine"); - m_Log[LogTypes::COMMANDPROCESSOR] = new LogContainer("CP", "CommandProc"); - m_Log[LogTypes::VIDEOINTERFACE] = new LogContainer("VI", "VideoInt"); - m_Log[LogTypes::SERIALINTERFACE] = new LogContainer("SI", "SerialInt"); - m_Log[LogTypes::PROCESSORINTERFACE] = new LogContainer("PI", "ProcessorInt"); + //m_Log[LogTypes::DISCIO] = new LogContainer("DIO", "Disc IO"); + //m_Log[LogTypes::FILEMON] = new LogContainer("FileMon", "File Monitor"); + //m_Log[LogTypes::PAD] = new LogContainer("PAD", "Pad"); + //m_Log[LogTypes::PIXELENGINE] = new LogContainer("PE", "PixelEngine"); + //m_Log[LogTypes::COMMANDPROCESSOR] = new LogContainer("CP", "CommandProc"); + //m_Log[LogTypes::VIDEOINTERFACE] = new LogContainer("VI", "VideoInt"); + //m_Log[LogTypes::SERIALINTERFACE] = new LogContainer("SI", "SerialInt"); + //m_Log[LogTypes::PROCESSORINTERFACE] = new LogContainer("PI", "ProcessorInt"); m_Log[LogTypes::MEMMAP] = new LogContainer("MI", "MI & memmap"); - m_Log[LogTypes::SP1] = new LogContainer("SP1", "Serial Port 1"); - m_Log[LogTypes::STREAMINGINTERFACE] = new LogContainer("Stream", "StreamingInt"); - m_Log[LogTypes::DSPINTERFACE] = new LogContainer("DSP", "DSPInterface"); - m_Log[LogTypes::DVDINTERFACE] = new LogContainer("DVD", "DVDInterface"); + //m_Log[LogTypes::SP1] = new LogContainer("SP1", "Serial Port 1"); + //m_Log[LogTypes::STREAMINGINTERFACE] = new LogContainer("Stream", "StreamingInt"); + //m_Log[LogTypes::DSPINTERFACE] = new LogContainer("DSP", "DSPInterface"); + //m_Log[LogTypes::DVDINTERFACE] = new LogContainer("DVD", "DVDInterface"); m_Log[LogTypes::GSP] = new LogContainer("GSP", "GSP"); - m_Log[LogTypes::EXPANSIONINTERFACE] = new LogContainer("EXI", "ExpansionInt"); - m_Log[LogTypes::GDB_STUB] = new LogContainer("GDB_STUB", "GDB Stub"); - m_Log[LogTypes::AUDIO_INTERFACE] = new LogContainer("AI", "AudioInt"); + //m_Log[LogTypes::EXPANSIONINTERFACE] = new LogContainer("EXI", "ExpansionInt"); + //m_Log[LogTypes::GDB_STUB] = new LogContainer("GDB_STUB", "GDB Stub"); + //m_Log[LogTypes::AUDIO_INTERFACE] = new LogContainer("AI", "AudioInt"); m_Log[LogTypes::ARM11] = new LogContainer("ARM11", "ARM11"); m_Log[LogTypes::OSHLE] = new LogContainer("HLE", "HLE"); - m_Log[LogTypes::DSPHLE] = new LogContainer("DSPHLE", "DSP HLE"); - m_Log[LogTypes::DSPLLE] = new LogContainer("DSPLLE", "DSP LLE"); - m_Log[LogTypes::DSP_MAIL] = new LogContainer("DSPMails", "DSP Mails"); + //m_Log[LogTypes::DSPHLE] = new LogContainer("DSPHLE", "DSP HLE"); + //m_Log[LogTypes::DSPLLE] = new LogContainer("DSPLLE", "DSP LLE"); + //m_Log[LogTypes::DSP_MAIL] = new LogContainer("DSPMails", "DSP Mails"); m_Log[LogTypes::VIDEO] = new LogContainer("Video", "Video Backend"); - m_Log[LogTypes::AUDIO] = new LogContainer("Audio", "Audio Emulator"); - m_Log[LogTypes::DYNA_REC] = new LogContainer("JIT", "JIT"); - m_Log[LogTypes::CONSOLE] = new LogContainer("CONSOLE", "Dolphin Console"); - m_Log[LogTypes::OSREPORT] = new LogContainer("OSREPORT", "OSReport"); + //m_Log[LogTypes::AUDIO] = new LogContainer("Audio", "Audio Emulator"); + //m_Log[LogTypes::DYNA_REC] = new LogContainer("JIT", "JIT"); + //m_Log[LogTypes::CONSOLE] = new LogContainer("CONSOLE", "Dolphin Console"); + //m_Log[LogTypes::OSREPORT] = new LogContainer("OSREPORT", "OSReport"); m_Log[LogTypes::TIME] = new LogContainer("Time", "Core Timing"); m_Log[LogTypes::LOADER] = new LogContainer("Loader", "Loader"); m_Log[LogTypes::FILESYS] = new LogContainer("FileSys", "File System"); - m_Log[LogTypes::WII_IPC_HID] = new LogContainer("WII_IPC_HID", "WII IPC HID"); + //m_Log[LogTypes::WII_IPC_HID] = new LogContainer("WII_IPC_HID", "WII IPC HID"); m_Log[LogTypes::KERNEL] = new LogContainer("KERNEL", "KERNEL HLE"); - m_Log[LogTypes::WII_IPC_DVD] = new LogContainer("WII_IPC_DVD", "WII IPC DVD"); - m_Log[LogTypes::WII_IPC_ES] = new LogContainer("WII_IPC_ES", "WII IPC ES"); - m_Log[LogTypes::WII_IPC_FILEIO] = new LogContainer("WII_IPC_FILEIO", "WII IPC FILEIO"); + //m_Log[LogTypes::WII_IPC_DVD] = new LogContainer("WII_IPC_DVD", "WII IPC DVD"); + //m_Log[LogTypes::WII_IPC_ES] = new LogContainer("WII_IPC_ES", "WII IPC ES"); + //m_Log[LogTypes::WII_IPC_FILEIO] = new LogContainer("WII_IPC_FILEIO", "WII IPC FILEIO"); m_Log[LogTypes::RENDER] = new LogContainer("RENDER", "RENDER"); m_Log[LogTypes::GPU] = new LogContainer("GPU", "GPU"); m_Log[LogTypes::SVC] = new LogContainer("SVC", "Supervisor Call HLE"); m_Log[LogTypes::HLE] = new LogContainer("HLE", "High Level Emulation"); m_Log[LogTypes::HW] = new LogContainer("HW", "Hardware"); - m_Log[LogTypes::ACTIONREPLAY] = new LogContainer("ActionReplay", "ActionReplay"); - m_Log[LogTypes::MEMCARD_MANAGER] = new LogContainer("MemCard Manager", "MemCard Manager"); - m_Log[LogTypes::NETPLAY] = new LogContainer("NETPLAY", "Netplay"); + //m_Log[LogTypes::ACTIONREPLAY] = new LogContainer("ActionReplay", "ActionReplay"); + //m_Log[LogTypes::MEMCARD_MANAGER] = new LogContainer("MemCard Manager", "MemCard Manager"); + //m_Log[LogTypes::NETPLAY] = new LogContainer("NETPLAY", "Netplay"); m_Log[LogTypes::GUI] = new LogContainer("GUI", "GUI"); m_fileLog = new FileLogListener(FileUtil::GetUserPath(F_MAINLOG_IDX).c_str()); diff --git a/src/common/logging/backend.cpp b/src/common/logging/backend.cpp new file mode 100644 index 000000000..e79b84604 --- /dev/null +++ b/src/common/logging/backend.cpp @@ -0,0 +1,151 @@ +// Copyright 2014 Citra Emulator Project +// Licensed under GPLv2+ +// Refer to the license.txt file included. + +#include + +#include "common/log.h" // For _dbg_assert_ + +#include "common/logging/backend.h" +#include "common/logging/log.h" +#include "common/logging/text_formatter.h" + +namespace Log { + +static std::shared_ptr global_logger; + +/// Macro listing all log classes. Code should define CLS and SUB as desired before invoking this. +#define ALL_LOG_CLASSES() \ + CLS(Log) \ + CLS(Common) \ + SUB(Common, Filesystem) \ + SUB(Common, Memory) \ + CLS(Core) \ + SUB(Core, ARM11) \ + CLS(Config) \ + CLS(Debug) \ + SUB(Debug, Emulated) \ + SUB(Debug, GPU) \ + SUB(Debug, Breakpoint) \ + CLS(Kernel) \ + SUB(Kernel, SVC) \ + CLS(Service) \ + SUB(Service, SRV) \ + SUB(Service, FS) \ + SUB(Service, APT) \ + SUB(Service, GSP) \ + SUB(Service, AC) \ + SUB(Service, PTM) \ + SUB(Service, CFG) \ + SUB(Service, DSP) \ + SUB(Service, HID) \ + CLS(HW) \ + SUB(HW, Memory) \ + SUB(HW, GPU) \ + CLS(Frontend) \ + CLS(Render) \ + SUB(Render, Software) \ + SUB(Render, OpenGL) \ + CLS(Loader) + +Logger::Logger() { + // Register logging classes so that they can be queried at runtime + size_t parent_class; + all_classes.reserve((size_t)Class::Count); + +#define CLS(x) \ + all_classes.push_back(Class::x); \ + parent_class = all_classes.size() - 1; +#define SUB(x, y) \ + all_classes.push_back(Class::x##_##y); \ + all_classes[parent_class].num_children += 1; + + ALL_LOG_CLASSES() +#undef CLS +#undef SUB + + // Ensures that ALL_LOG_CLASSES isn't missing any entries. + _dbg_assert_(Log, all_classes.size() == (size_t)Class::Count); +} + +// GetClassName is a macro defined by Windows.h, grrr... +const char* Logger::GetLogClassName(Class log_class) { + switch (log_class) { +#define CLS(x) case Class::x: return #x; +#define SUB(x, y) case Class::x##_##y: return #x "." #y; + ALL_LOG_CLASSES() +#undef CLS +#undef SUB + } + return "Unknown"; +} + +const char* Logger::GetLevelName(Level log_level) { +#define LVL(x) case Level::x: return #x + switch (log_level) { + LVL(Trace); + LVL(Debug); + LVL(Info); + LVL(Warning); + LVL(Error); + LVL(Critical); + } + return "Unknown"; +#undef LVL +} + +void Logger::LogMessage(Entry entry) { + ring_buffer.Push(std::move(entry)); +} + +size_t Logger::GetEntries(Entry* out_buffer, size_t buffer_len) { + return ring_buffer.BlockingPop(out_buffer, buffer_len); +} + +std::shared_ptr InitGlobalLogger() { + global_logger = std::make_shared(); + return global_logger; +} + +Entry CreateEntry(Class log_class, Level log_level, + const char* filename, unsigned int line_nr, const char* function, + const char* format, va_list args) { + using std::chrono::steady_clock; + using std::chrono::duration_cast; + + static steady_clock::time_point time_origin = steady_clock::now(); + + std::array formatting_buffer; + + Entry entry; + entry.timestamp = duration_cast(steady_clock::now() - time_origin); + entry.log_class = log_class; + entry.log_level = log_level; + + snprintf(formatting_buffer.data(), formatting_buffer.size(), "%s:%s:%u", filename, function, line_nr); + entry.location = std::string(formatting_buffer.data()); + + vsnprintf(formatting_buffer.data(), formatting_buffer.size(), format, args); + entry.message = std::string(formatting_buffer.data()); + + return std::move(entry); +} + +void LogMessage(Class log_class, Level log_level, + const char* filename, unsigned int line_nr, const char* function, + const char* format, ...) { + va_list args; + va_start(args, format); + Entry entry = CreateEntry(log_class, log_level, + filename, line_nr, function, format, args); + va_end(args); + + if (global_logger != nullptr && !global_logger->IsClosed()) { + global_logger->LogMessage(std::move(entry)); + } else { + // Fall back to directly printing to stderr + PrintMessage(entry); + } +} + +} diff --git a/src/common/logging/backend.h b/src/common/logging/backend.h new file mode 100644 index 000000000..ae270efe8 --- /dev/null +++ b/src/common/logging/backend.h @@ -0,0 +1,134 @@ +// Copyright 2014 Citra Emulator Project +// Licensed under GPLv2+ +// Refer to the license.txt file included. + +#pragma once + +#include +#include +#include + +#include "common/concurrent_ring_buffer.h" + +#include "common/logging/log.h" + +namespace Log { + +/** + * A log entry. Log entries are store in a structured format to permit more varied output + * formatting on different frontends, as well as facilitating filtering and aggregation. + */ +struct Entry { + std::chrono::microseconds timestamp; + Class log_class; + Level log_level; + std::string location; + std::string message; + + Entry() = default; + + // TODO(yuriks) Use defaulted move constructors once MSVC supports them +#define MOVE(member) member(std::move(o.member)) + Entry(Entry&& o) + : MOVE(timestamp), MOVE(log_class), MOVE(log_level), + MOVE(location), MOVE(message) + {} +#undef MOVE + + Entry& operator=(const Entry&& o) { +#define MOVE(member) member = std::move(o.member) + MOVE(timestamp); + MOVE(log_class); + MOVE(log_level); + MOVE(location); + MOVE(message); +#undef MOVE + return *this; + } +}; + +struct ClassInfo { + Class log_class; + + /** + * Total number of (direct or indirect) sub classes this class has. If any, they follow in + * sequence after this class in the class list. + */ + unsigned int num_children = 0; + + ClassInfo(Class log_class) : log_class(log_class) {} +}; + +/** + * Logging management class. This class has the dual purpose of acting as an exchange point between + * the logging clients and the log outputter, as well as containing reflection info about available + * log classes. + */ +class Logger { +private: + using Buffer = Common::ConcurrentRingBuffer; + +public: + static const size_t QUEUE_CLOSED = Buffer::QUEUE_CLOSED; + + Logger(); + + /** + * Returns a list of all vector classes and subclasses. The sequence returned is a pre-order of + * classes and subclasses, which together with the `num_children` field in ClassInfo, allows + * you to recover the hierarchy. + */ + const std::vector& GetClasses() const { return all_classes; } + + /** + * Returns the name of the passed log class as a C-string. Subclasses are separated by periods + * instead of underscores as in the enumeration. + */ + static const char* GetLogClassName(Class log_class); + + /** + * Returns the name of the passed log level as a C-string. + */ + static const char* GetLevelName(Level log_level); + + /** + * Appends a messages to the log buffer. + * @note This function is thread safe. + */ + void LogMessage(Entry entry); + + /** + * Retrieves a batch of messages from the log buffer, blocking until they are available. + * @note This function is thread safe. + * + * @param out_buffer Destination buffer that will receive the log entries. + * @param buffer_len The maximum size of `out_buffer`. + * @return The number of entries stored. In case the logger is shutting down, `QUEUE_CLOSED` is + * returned, no entries are stored and the logger should shutdown. + */ + size_t GetEntries(Entry* out_buffer, size_t buffer_len); + + /** + * Initiates a shutdown of the logger. This will indicate to log output clients that they + * should shutdown. + */ + void Close() { ring_buffer.Close(); } + + /** + * Returns true if Close() has already been called on the Logger. + */ + bool IsClosed() const { return ring_buffer.IsClosed(); } + +private: + Buffer ring_buffer; + std::vector all_classes; +}; + +/// Creates a log entry by formatting the given source location, and message. +Entry CreateEntry(Class log_class, Level log_level, + const char* filename, unsigned int line_nr, const char* function, + const char* format, va_list args); +/// Initializes the default Logger. +std::shared_ptr InitGlobalLogger(); + +} diff --git a/src/common/logging/log.h b/src/common/logging/log.h new file mode 100644 index 000000000..1eec34fbb --- /dev/null +++ b/src/common/logging/log.h @@ -0,0 +1,115 @@ +// Copyright 2014 Citra Emulator Project +// Licensed under GPLv2+ +// Refer to the license.txt file included. + +#pragma once + +#include +#include +#include + +#include "common/common_types.h" + +namespace Log { + +/// Specifies the severity or level of detail of the log message. +enum class Level : u8 { + Trace, ///< Extremely detailed and repetitive debugging information that is likely to + /// pollute logs. + Debug, ///< Less detailed debugging information. + Info, ///< Status information from important points during execution. + Warning, ///< Minor or potential problems found during execution of a task. + Error, ///< Major problems found during execution of a task that prevent it from being + /// completed. + Critical, ///< Major problems during execution that threathen the stability of the entire + /// application. + + Count ///< Total number of logging levels +}; + +typedef u8 ClassType; + +/** + * Specifies the sub-system that generated the log message. + * + * @note If you add a new entry here, also add a corresponding one to `ALL_LOG_CLASSES` in log.cpp. + */ +enum class Class : ClassType { + Log, ///< Messages about the log system itself + Common, ///< Library routines + Common_Filesystem, ///< Filesystem interface library + Common_Memory, ///< Memory mapping and management functions + Core, ///< LLE emulation core + Core_ARM11, ///< ARM11 CPU core + Config, ///< Emulator configuration (including commandline) + Debug, ///< Debugging tools + Debug_Emulated, ///< Debug messages from the emulated programs + Debug_GPU, ///< GPU debugging tools + Debug_Breakpoint, ///< Logging breakpoints and watchpoints + Kernel, ///< The HLE implementation of the CTR kernel + Kernel_SVC, ///< Kernel system calls + Service, ///< HLE implementation of system services. Each major service + /// should have its own subclass. + Service_SRV, ///< The SRV (Service Directory) implementation + Service_FS, ///< The FS (Filesystem) service implementation + Service_APT, ///< The APT (Applets) service + Service_GSP, ///< The GSP (GPU control) service + Service_AC, ///< The AC (WiFi status) service + Service_PTM, ///< The PTM (Power status & misc.) service + Service_CFG, ///< The CFG (Configuration) service + Service_DSP, ///< The DSP (DSP control) service + Service_HID, ///< The HID (User input) service + HW, ///< Low-level hardware emulation + HW_Memory, ///< Memory-map and address translation + HW_GPU, ///< GPU control emulation + Frontend, ///< Emulator UI + Render, ///< Emulator video output and hardware acceleration + Render_Software, ///< Software renderer backend + Render_OpenGL, ///< OpenGL backend + Loader, ///< ROM loader + + Count ///< Total number of logging classes +}; + +/** + * Level below which messages are simply discarded without buffering regardless of the display + * settings. + */ +const Level MINIMUM_LEVEL = +#ifdef _DEBUG + Level::Trace; +#else + Level::Debug; +#endif + +/** + * Logs a message to the global logger. This proxy exists to avoid exposing the details of the + * Logger class, including the ConcurrentRingBuffer template, to all files that desire to log + * messages, reducing unecessary recompilations. + */ +void LogMessage(Class log_class, Level log_level, + const char* filename, unsigned int line_nr, const char* function, +#ifdef _MSC_VER + _Printf_format_string_ +#endif + const char* format, ...) +#ifdef __GNUC__ + __attribute__((format(printf, 6, 7))) +#endif + ; + +} // namespace Log + +#define LOG_GENERIC(log_class, log_level, ...) \ + do { \ + if (::Log::Level::log_level >= ::Log::MINIMUM_LEVEL) \ + ::Log::LogMessage(::Log::Class::log_class, ::Log::Level::log_level, \ + __FILE__, __LINE__, __func__, __VA_ARGS__); \ + } while (0) + +#define LOG_TRACE( log_class, ...) LOG_GENERIC(log_class, Trace, __VA_ARGS__) +#define LOG_DEBUG( log_class, ...) LOG_GENERIC(log_class, Debug, __VA_ARGS__) +#define LOG_INFO( log_class, ...) LOG_GENERIC(log_class, Info, __VA_ARGS__) +#define LOG_WARNING( log_class, ...) LOG_GENERIC(log_class, Warning, __VA_ARGS__) +#define LOG_ERROR( log_class, ...) LOG_GENERIC(log_class, Error, __VA_ARGS__) +#define LOG_CRITICAL(log_class, ...) LOG_GENERIC(log_class, Critical, __VA_ARGS__) diff --git a/src/common/logging/text_formatter.cpp b/src/common/logging/text_formatter.cpp new file mode 100644 index 000000000..01c355bb6 --- /dev/null +++ b/src/common/logging/text_formatter.cpp @@ -0,0 +1,47 @@ +// Copyright 2014 Citra Emulator Project +// Licensed under GPLv2+ +// Refer to the license.txt file included. + +#include +#include + +#include "common/logging/backend.h" +#include "common/logging/log.h" +#include "common/logging/text_formatter.h" + +namespace Log { + +void FormatLogMessage(const Entry& entry, char* out_text, size_t text_len) { + unsigned int time_seconds = static_cast(entry.timestamp.count() / 1000000); + unsigned int time_fractional = static_cast(entry.timestamp.count() % 1000000); + + const char* class_name = Logger::GetLogClassName(entry.log_class); + const char* level_name = Logger::GetLevelName(entry.log_level); + + snprintf(out_text, text_len, "[%4u.%06u] %s <%s> %s: %s", + time_seconds, time_fractional, class_name, level_name, + entry.location.c_str(), entry.message.c_str()); +} + +void PrintMessage(const Entry& entry) { + std::array format_buffer; + FormatLogMessage(entry, format_buffer.data(), format_buffer.size()); + fputs(format_buffer.data(), stderr); + fputc('\n', stderr); +} + +void TextLoggingLoop(std::shared_ptr logger) { + std::array entry_buffer; + + while (true) { + size_t num_entries = logger->GetEntries(entry_buffer.data(), entry_buffer.size()); + if (num_entries == Logger::QUEUE_CLOSED) { + break; + } + for (size_t i = 0; i < num_entries; ++i) { + PrintMessage(entry_buffer[i]); + } + } +} + +} diff --git a/src/common/logging/text_formatter.h b/src/common/logging/text_formatter.h new file mode 100644 index 000000000..6c2a6f1ea --- /dev/null +++ b/src/common/logging/text_formatter.h @@ -0,0 +1,26 @@ +// Copyright 2014 Citra Emulator Project +// Licensed under GPLv2+ +// Refer to the license.txt file included. + +#pragma once + +#include +#include + +namespace Log { + +class Logger; +struct Entry; + +/// Formats a log entry into the provided text buffer. +void FormatLogMessage(const Entry& entry, char* out_text, size_t text_len); +/// Formats and prints a log entry to stderr. +void PrintMessage(const Entry& entry); + +/** + * Logging loop that repeatedly reads messages from the provided logger and prints them to the + * console. It is the baseline barebones log outputter. + */ +void TextLoggingLoop(std::shared_ptr logger); + +} diff --git a/src/common/thread.h b/src/common/thread.h index be9b5cbe2..8c36d3f07 100644 --- a/src/common/thread.h +++ b/src/common/thread.h @@ -21,6 +21,7 @@ //for gettimeofday and struct time(spec|val) #include #include +#include #endif namespace Common diff --git a/src/core/hle/config_mem.cpp b/src/core/hle/config_mem.cpp index c7cf5b1d3..1c9b89227 100644 --- a/src/core/hle/config_mem.cpp +++ b/src/core/hle/config_mem.cpp @@ -3,6 +3,7 @@ // Refer to the license.txt file included. #include "common/common_types.h" +#include "common/log.h" #include "core/hle/config_mem.h"