Merge pull request #758 from yuriks/sync-logging

Common: Remove async logging

src/citra/citra.cpp

@@ -20,14 +20,8 @@
 
 /// Application entry point
 int main(int argc, char **argv) {
-    std::shared_ptr<Log::Logger> logger = Log::InitGlobalLogger();
     Log::Filter log_filter(Log::Level::Debug);
     Log::SetFilter(&log_filter);
-    std::thread logging_thread(Log::TextLoggingLoop, logger);
-    SCOPE_EXIT({
-        logger->Close();
-        logging_thread.join();
-    });
 
     if (argc < 2) {
         LOG_CRITICAL(Frontend, "Failed to load ROM: No ROM specified");

src/citra_qt/main.cpp

@@ -352,14 +352,8 @@ void GMainWindow::closeEvent(QCloseEvent* event)
 
 int main(int argc, char* argv[])
 {
-    std::shared_ptr<Log::Logger> logger = Log::InitGlobalLogger();
     Log::Filter log_filter(Log::Level::Info);
     Log::SetFilter(&log_filter);
-    std::thread logging_thread(Log::TextLoggingLoop, logger);
-    SCOPE_EXIT({
-        logger->Close();
-        logging_thread.join();
-    });
 
     QApplication::setAttribute(Qt::AA_X11InitThreads);
     QApplication app(argc, argv);

src/common/CMakeLists.txt

@@ -27,7 +27,6 @@ set(HEADERS
             common_funcs.h
             common_paths.h
             common_types.h
-            concurrent_ring_buffer.h
             cpu_detect.h
             debug_interface.h
             emu_window.h

src/common/assert.h

@@ -8,6 +8,7 @@
 #include <cstdlib>
 
 #include "common/common_funcs.h"
+#include "common/logging/log.h"
 
 // For asserts we'd like to keep all the junk executed when an assert happens away from the
 // important code in the function. One way of doing this is to put all the relevant code inside a
@@ -28,19 +29,14 @@ static void assert_noinline_call(const Fn& fn) {
     exit(1); // Keeps GCC's mouth shut about this actually returning
 }
 
-// TODO (yuriks) allow synchronous logging so we don't need printf
 #define ASSERT(_a_) \
     do if (!(_a_)) { assert_noinline_call([] { \
-        fprintf(stderr, "Assertion Failed!\n\n  Line: %d\n  File: %s\n  Time: %s\n", \
+        LOG_CRITICAL(Debug, "Assertion Failed!"); \
-                     __LINE__, __FILE__, __TIME__); \
     }); } while (0)
 
 #define ASSERT_MSG(_a_, ...) \
     do if (!(_a_)) { assert_noinline_call([&] { \
-        fprintf(stderr, "Assertion Failed!\n\n  Line: %d\n  File: %s\n  Time: %s\n", \
+        LOG_CRITICAL(Debug, "Assertion Failed!\n" __VA_ARGS__); \
-                     __LINE__, __FILE__, __TIME__); \
-        fprintf(stderr, __VA_ARGS__); \
-        fprintf(stderr, "\n"); \
     }); } while (0)
 
 #define UNREACHABLE() ASSERT_MSG(false, "Unreachable code!")

src/common/concurrent_ring_buffer.h

@@ -1,163 +0,0 @@
-// Copyright 2014 Citra Emulator Project
-// Licensed under GPLv2 or any later version
-// Refer to the license.txt file included.
-
-#pragma once
-
-#include <array>
-#include <condition_variable>
-#include <cstdint>
-#include <mutex>
-#include <thread>
-
-#include "common/common_types.h" // for NonCopyable
-
-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 <typename T, size_t ArraySize>
-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<std::mutex> 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<std::mutex> 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<std::mutex> lock(mutex);
-        if (closed && !CanRead()) {
-            return QUEUE_CLOSED;
-        }
-
-        while (!CanRead()) {
-            reader.wait(lock);
-            if (closed && !CanRead()) {
-                return QUEUE_CLOSED;
-            }
-        }
-        DEBUG_ASSERT(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<std::mutex> 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()) {
-            DEBUG_ASSERT(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<T*>(static_cast<void*>(&storage));
-    }
-
-    /// Storage for entries
-    typename std::aligned_storage<ArraySize * sizeof(T),
-                                  std::alignment_of<T>::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

src/common/logging/backend.cpp

@@ -3,17 +3,17 @@
 // Refer to the license.txt file included.
 
 #include <algorithm>
+#include <array>
+#include <cstdio>
 
-#include "common/assert.h"
+#include "common/common_funcs.h" // snprintf compatibility define
-
 #include "common/logging/backend.h"
+#include "common/logging/filter.h"
 #include "common/logging/log.h"
 #include "common/logging/text_formatter.h"
 
 namespace Log {
 
-static std::shared_ptr<Logger> global_logger;
-
 /// Macro listing all log classes. Code should define CLS and SUB as desired before invoking this.
 #define ALL_LOG_CLASSES() \
         CLS(Log) \
@@ -55,28 +55,8 @@ static std::shared_ptr<Logger> global_logger;
         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.
-    DEBUG_ASSERT(all_classes.size() == (size_t)Class::Count);
-}
-
 // GetClassName is a macro defined by Windows.h, grrr...
-const char* Logger::GetLogClassName(Class log_class) {
+const char* 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;
@@ -87,7 +67,7 @@ const char* Logger::GetLogClassName(Class log_class) {
     return "Unknown";
 }
 
-const char* Logger::GetLevelName(Level log_level) {
+const char* GetLevelName(Level log_level) {
 #define LVL(x) case Level::x: return #x
     switch (log_level) {
         LVL(Trace);
@@ -101,19 +81,6 @@ const char* Logger::GetLevelName(Level log_level) {
 #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<Logger> InitGlobalLogger() {
-    global_logger = std::make_shared<Logger>();
-    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) {
@@ -138,7 +105,7 @@ Entry CreateEntry(Class log_class, Level log_level,
     return std::move(entry);
 }
 
-static Filter* filter;
+static Filter* filter = nullptr;
 
 void SetFilter(Filter* new_filter) {
     filter = new_filter;
@@ -147,7 +114,7 @@ void SetFilter(Filter* new_filter) {
 void LogMessage(Class log_class, Level log_level,
                 const char* filename, unsigned int line_nr, const char* function,
                 const char* format, ...) {
-    if (!filter->CheckMessage(log_class, log_level))
+    if (filter != nullptr && !filter->CheckMessage(log_class, log_level))
         return;
 
     va_list args;
@@ -156,12 +123,7 @@ void LogMessage(Class log_class, Level log_level,
             filename, line_nr, function, format, args);
     va_end(args);
 
-    if (global_logger != nullptr && !global_logger->IsClosed()) {
+    PrintColoredMessage(entry);
-        global_logger->LogMessage(std::move(entry));
-    } else {
-        // Fall back to directly printing to stderr
-        PrintMessage(entry);
-    }
 }
 
 }

src/common/logging/backend.h

@@ -4,17 +4,17 @@
 
 #pragma once
 
+#include <chrono>
 #include <cstdarg>
-#include <memory>
+#include <string>
-#include <vector>
+#include <utility>
 
-#include "common/concurrent_ring_buffer.h"
-
-#include "common/logging/filter.h"
 #include "common/logging/log.h"
 
 namespace Log {
 
+class Filter;
+
 /**
  * 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.
@@ -48,89 +48,21 @@ struct Entry {
     }
 };
 
-struct ClassInfo {
+/**
-    Class log_class;
+ * Returns the name of the passed log class as a C-string. Subclasses are separated by periods
-
+ * instead of underscores as in the enumeration.
-    /**
+ */
-        * Total number of (direct or indirect) sub classes this class has. If any, they follow in
+const char* GetLogClassName(Class log_class);
-        * 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
+ * Returns the name of the passed log level as a C-string.
- * the logging clients and the log outputter, as well as containing reflection info about available
- * log classes.
  */
-class Logger {
+const char* GetLevelName(Level log_level);
-private:
-    using Buffer = Common::ConcurrentRingBuffer<Entry, 16 * 1024 / sizeof(Entry)>;
-
-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<ClassInfo>& 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<ClassInfo> 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<Logger> InitGlobalLogger();
 
 void SetFilter(Filter* filter);
 

src/common/logging/filter.cpp

@@ -22,16 +22,6 @@ void Filter::SetClassLevel(Class log_class, Level level) {
     class_levels[static_cast<size_t>(log_class)] = level;
 }
 
-void Filter::SetSubclassesLevel(const ClassInfo& log_class, Level level) {
-    const size_t log_class_i = static_cast<size_t>(log_class.log_class);
-
-    const size_t begin = log_class_i + 1;
-    const size_t end = begin + log_class.num_children;
-    for (size_t i = begin; begin < end; ++i) {
-        class_levels[i] = level;
-    }
-}
-
 void Filter::ParseFilterString(const std::string& filter_str) {
     auto clause_begin = filter_str.cbegin();
     while (clause_begin != filter_str.cend()) {
@@ -53,7 +43,7 @@ void Filter::ParseFilterString(const std::string& filter_str) {
 template <typename It>
 static Level GetLevelByName(const It begin, const It end) {
     for (u8 i = 0; i < static_cast<u8>(Level::Count); ++i) {
-        const char* level_name = Logger::GetLevelName(static_cast<Level>(i));
+        const char* level_name = GetLevelName(static_cast<Level>(i));
         if (Common::ComparePartialString(begin, end, level_name)) {
             return static_cast<Level>(i);
         }
@@ -64,7 +54,7 @@ static Level GetLevelByName(const It begin, const It end) {
 template <typename It>
 static Class GetClassByName(const It begin, const It end) {
     for (ClassType i = 0; i < static_cast<ClassType>(Class::Count); ++i) {
-        const char* level_name = Logger::GetLogClassName(static_cast<Class>(i));
+        const char* level_name = GetLogClassName(static_cast<Class>(i));
         if (Common::ComparePartialString(begin, end, level_name)) {
             return static_cast<Class>(i);
         }
@@ -72,20 +62,6 @@ static Class GetClassByName(const It begin, const It end) {
     return Class::Count;
 }
 
-template <typename InputIt, typename T>
-static InputIt find_last(InputIt begin, const InputIt end, const T& value) {
-    auto match = end;
-    while (begin != end) {
-        auto new_match = std::find(begin, end, value);
-        if (new_match != end) {
-            match = new_match;
-            ++new_match;
-        }
-        begin = new_match;
-    }
-    return match;
-}
-
 bool Filter::ParseFilterRule(const std::string::const_iterator begin,
         const std::string::const_iterator end) {
     auto level_separator = std::find(begin, end, ':');
@@ -106,22 +82,13 @@ bool Filter::ParseFilterRule(const std::string::const_iterator begin,
         return true;
     }
 
-    auto class_name_end = find_last(begin, level_separator, '.');
+    const Class log_class = GetClassByName(begin, level_separator);
-    if (class_name_end != level_separator &&
-            !Common::ComparePartialString(class_name_end + 1, level_separator, "*")) {
-        class_name_end = level_separator;
-    }
-
-    const Class log_class = GetClassByName(begin, class_name_end);
     if (log_class == Class::Count) {
         LOG_ERROR(Log, "Unknown log class in filter: %s", std::string(begin, end).c_str());
         return false;
     }
 
-    if (class_name_end == level_separator) {
+    SetClassLevel(log_class, level);
-        SetClassLevel(log_class, level);
-    }
-    SetSubclassesLevel(log_class, level);
     return true;
 }
 

src/common/logging/filter.h

@@ -11,8 +11,6 @@
 
 namespace Log {
 
-struct ClassInfo;
-
 /**
  * Implements a log message filter which allows different log classes to have different minimum
  * severity levels. The filter can be changed at runtime and can be parsed from a string to allow
@@ -27,29 +25,19 @@ public:
     void ResetAll(Level level);
     /// Sets the minimum level of `log_class` (and not of its subclasses) to `level`.
     void SetClassLevel(Class log_class, Level level);
-    /**
-     * Sets the minimum level of all of `log_class` subclasses to `level`. The level of `log_class`
-     * itself is not changed.
-     */
-    void SetSubclassesLevel(const ClassInfo& log_class, Level level);
 
     /**
      * Parses a filter string and applies it to this filter.
      *
      * A filter string consists of a space-separated list of filter rules, each of the format
      * `<class>:<level>`. `<class>` is a log class name, with subclasses separated using periods.
-     * A rule for a given class also affects all of its subclasses. `*` wildcards are allowed and
+     * `*` is allowed as a class name and will reset all filters to the specified level. `<level>`
-     * can be used to apply a rule to all classes or to all subclasses of a class without affecting
+     * a severity level name which will be set as the minimum logging level of the matched classes.
-     * the parent class. `<level>` a severity level name which will be set as the minimum logging
+     * Rules are applied left to right, with each rule overriding previous ones in the sequence.
-     * level of the matched classes. Rules are applied left to right, with each rule overriding
-     * previous ones in the sequence.
      *
      * A few examples of filter rules:
      *  - `*:Info` -- Resets the level of all classes to Info.
-     *  - `Service:Info` -- Sets the level of Service and all subclasses (Service.FS, Service.APT,
+     *  - `Service:Info` -- Sets the level of Service to Info.
-     *                       etc.) to Info.
-     *  - `Service.*:Debug` -- Sets the level of all Service subclasses to Debug, while leaving the
-     *                         level of Service unchanged.
      *  - `Service.FS:Trace` -- Sets the level of the Service.FS class to Trace.
      */
     void ParseFilterString(const std::string& filter_str);

src/common/logging/log.h

@@ -78,11 +78,7 @@ enum class Class : ClassType {
     Count ///< Total number of logging classes
 };
 
-/**
+/// Logs a message to the global logger.
- * 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

src/common/logging/text_formatter.cpp

@@ -46,8 +46,8 @@ void FormatLogMessage(const Entry& entry, char* out_text, size_t text_len) {
     unsigned int time_seconds    = static_cast<unsigned int>(entry.timestamp.count() / 1000000);
     unsigned int time_fractional = static_cast<unsigned int>(entry.timestamp.count() % 1000000);
 
-    const char* class_name = Logger::GetLogClassName(entry.log_class);
+    const char* class_name = GetLogClassName(entry.log_class);
-    const char* level_name = Logger::GetLevelName(entry.log_level);
+    const char* level_name = GetLevelName(entry.log_level);
 
     snprintf(out_text, text_len, "[%4u.%06u] %s <%s> %s: %s",
         time_seconds, time_fractional, class_name, level_name,
@@ -116,19 +116,4 @@ void PrintColoredMessage(const Entry& entry) {
 #endif
 }
 
-void TextLoggingLoop(std::shared_ptr<Logger> logger) {
-    std::array<Entry, 256> 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) {
-            const Entry& entry = entry_buffer[i];
-            PrintColoredMessage(entry);
-        }
-    }
-}
-
 }

src/common/logging/text_formatter.h

@@ -5,11 +5,9 @@
 #pragma once
 
 #include <cstddef>
-#include <memory>
 
 namespace Log {
 
-class Logger;
 struct Entry;
 
 /**
@@ -31,10 +29,4 @@ void PrintMessage(const Entry& entry);
 /// Prints the same message as `PrintMessage`, but colored acoording to the severity level.
 void PrintColoredMessage(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> logger);
-
 }