Improved logger locking.

The logger is a low-level mechanism that should not depend on sophisticated
Rubinius code, but still needs synchronization to produce intelligible results
when any thread at any time may log some activity.

We switch to a custom spinlock mutex implemented with C++11 features
(unfortunate that C++11 didn't think it was essential to provide such a mutex
but it's trivial to create).

Since the process may log something at any time from any thread, running
managed or unmanaged, even while fork'ing, we always reset the state of the
lock after fork().

machine/environment.cpp

@@ -186,18 +186,15 @@ namespace rubinius {
     }
 
     if(!config.system_log.value.compare("syslog")) {
-      logger::open(fork_exec_lock_,
-          logger::eSyslog, RBX_PROGRAM_NAME, level);
+      logger::open(logger::eSyslog, RBX_PROGRAM_NAME, level);
     } else if(!config.system_log.value.compare("console")) {
-      logger::open(fork_exec_lock_,
-          logger::eConsoleLogger, RBX_PROGRAM_NAME, level);
+      logger::open(logger::eConsoleLogger, RBX_PROGRAM_NAME, level);
     } else {
       expand_config_value(config.system_log.value, "$TMPDIR", config.system_tmp);
       expand_config_value(config.system_log.value, "$PROGRAM_NAME", RBX_PROGRAM_NAME);
       expand_config_value(config.system_log.value, "$USER", shared->username.c_str());
 
-      logger::open(fork_exec_lock_,
-          logger::eFileLogger,
+      logger::open(logger::eFileLogger,
           config.system_log.value.c_str(), level,
           config.system_log_limit.value,
           config.system_log_archives.value,

machine/logger.cpp

@@ -1,8 +1,8 @@
 #include "util/file.hpp"
-#include "util/thread.hpp"
 
 #include "logger.hpp"
 #include "vm.hpp"
+#include "spinlock.hpp"
 #include "state.hpp"
 #include "thread_phase.hpp"
 
@@ -25,22 +25,21 @@ namespace rubinius {
   namespace logger {
     static Logger* logger_ = 0;
     static logger_level loglevel_ = eWarn;
+    static locks::spinlock_mutex logger_lock_;
 
-    void open(utilities::thread::SpinLock& lock, logger_type type,
-        const char* identifier, logger_level level, ...)
-    {
+    void open(logger_type type, const char* identifier, logger_level level, ...) {
       va_list varargs;
 
       switch(type) {
       case eSyslog:
-        logger_ = new Syslog(lock, identifier);
+        logger_ = new Syslog(identifier);
         break;
       case eConsoleLogger:
-        logger_ = new ConsoleLogger(lock, identifier);
+        logger_ = new ConsoleLogger(identifier);
         break;
       case eFileLogger:
         va_start(varargs, level);
-        logger_ = new FileLogger(lock, identifier, varargs);
+        logger_ = new FileLogger(identifier, varargs);
         va_end(varargs);
         break;
       }
@@ -180,7 +179,7 @@ namespace rubinius {
 
     void write(STATE, const char* message, va_list args) {
       if(logger_) {
-        SpinLockWaiting guard(state, logger_->lock());
+        std::lock_guard<locks::spinlock_mutex> guard(logger_lock_);
 
         char buf[LOGGER_MSG_SIZE];
 
@@ -192,7 +191,7 @@ namespace rubinius {
 
     void fatal(STATE, const char* message, va_list args) {
       if(logger_) {
-        SpinLockWaiting guard(state, logger_->lock());
+        std::lock_guard<locks::spinlock_mutex> guard(logger_lock_);
 
         if(loglevel_ < eFatal) return;
 
@@ -206,7 +205,7 @@ namespace rubinius {
 
     void error(STATE, const char* message, va_list args) {
       if(logger_) {
-        SpinLockWaiting guard(state, logger_->lock());
+        std::lock_guard<locks::spinlock_mutex> guard(logger_lock_);
 
         if(loglevel_ < eError) return;
 
@@ -220,7 +219,7 @@ namespace rubinius {
 
     void warn(STATE, const char* message, va_list args) {
       if(logger_) {
-        SpinLockWaiting guard(state, logger_->lock());
+        std::lock_guard<locks::spinlock_mutex> guard(logger_lock_);
 
         if(loglevel_ < eWarn) return;
 
@@ -234,7 +233,7 @@ namespace rubinius {
 
     void info(STATE, const char* message, va_list args) {
       if(logger_) {
-        SpinLockWaiting guard(state, logger_->lock());
+        std::lock_guard<locks::spinlock_mutex> guard(logger_lock_);
 
         if(loglevel_ < eInfo) return;
 
@@ -248,7 +247,7 @@ namespace rubinius {
 
     void debug(STATE, const char* message, va_list args) {
       if(logger_) {
-        SpinLockWaiting guard(state, logger_->lock());
+        std::lock_guard<locks::spinlock_mutex> guard(logger_lock_);
 
         if(loglevel_ < eDebug) return;
 
@@ -261,7 +260,7 @@ namespace rubinius {
     }
 
     void Logger::reset_lock() {
-      lock_.init();
+      logger_lock_.unlock();
     }
 
     char* Logger::timestamp() {
@@ -273,8 +272,8 @@ namespace rubinius {
       return formatted_time_;
     }
 
-    Syslog::Syslog(utilities::thread::SpinLock& lock, const char* identifier)
-      : Logger(lock)
+    Syslog::Syslog(const char* identifier)
+      : Logger()
     {
       openlog(identifier, LOG_CONS | LOG_PID, LOG_LOCAL7);
 
@@ -336,8 +335,8 @@ namespace rubinius {
       syslog(LOG_DEBUG, "%s", message);
     }
 
-    ConsoleLogger::ConsoleLogger(utilities::thread::SpinLock& lock, const char* identifier)
-      : Logger(lock)
+    ConsoleLogger::ConsoleLogger(const char* identifier)
+      : Logger()
       , identifier_(identifier)
     {
       set_label();
@@ -390,9 +389,8 @@ namespace rubinius {
 #define LOGGER_FROM_FLAGS   (O_RDONLY | O_CLOEXEC)
 #define LOGGER_TO_FLAGS     (O_CREAT | O_TRUNC | O_APPEND | O_WRONLY | O_CLOEXEC)
 
-    FileLogger::FileLogger(utilities::thread::SpinLock& lock,
-        const char* path, va_list varargs)
-      : Logger(lock)
+    FileLogger::FileLogger(const char* path, va_list varargs)
+      : Logger()
       , path_(path)
     {
       set_label();

machine/logger.hpp

@@ -7,12 +7,6 @@
 #include <stdarg.h>
 
 namespace rubinius {
-  namespace utilities {
-    namespace thread {
-      class SpinLock;
-    }
-  }
-
   namespace logger {
     enum logger_type {
       eSyslog,
@@ -29,8 +23,7 @@ namespace rubinius {
     };
 
 
-    void open(utilities::thread::SpinLock& lock, logger_type type,
-        const char* identifier, logger_level level=eWarn, ...);
+    void open(logger_type type, const char* identifier, logger_level level=eWarn, ...);
     void close();
 
     /* The API without passing STATE as the first argument must retrieve the
@@ -63,18 +56,12 @@ namespace rubinius {
     void reset_lock();
 
     class Logger {
-      utilities::thread::SpinLock& lock_;
-
 #define LOGGER_TIME_SIZE    16
 
       char formatted_time_[LOGGER_TIME_SIZE];
 
     public:
 
-      Logger(utilities::thread::SpinLock& lock)
-        : lock_(lock)
-      { }
-
       virtual ~Logger() { }
 
       virtual void write(const char* message, int size) = 0;
@@ -88,16 +75,12 @@ namespace rubinius {
 
       void reset_lock();
       char* timestamp();
-
-      utilities::thread::SpinLock& lock() {
-        return lock_;
-      }
     };
 
     class Syslog : public Logger {
     public:
 
-      Syslog(utilities::thread::SpinLock& lock, const char* identifier);
+      Syslog(const char* identifier);
       ~Syslog();
 
       void write(const char* message, int size);
@@ -118,7 +101,7 @@ namespace rubinius {
 
     public:
 
-      ConsoleLogger(utilities::thread::SpinLock& lock, const char* identifier);
+      ConsoleLogger(const char* identifier);
 
       void write(const char* message, int size);
       void fatal(const char* message, int size);
@@ -145,7 +128,7 @@ namespace rubinius {
 
     public:
 
-      FileLogger(utilities::thread::SpinLock& lock, const char* path, va_list varargs);
+      FileLogger(const char* path, va_list varargs);
       ~FileLogger();
 
       void write(const char* message, int size);

machine/spinlock.hpp

@@ -0,0 +1,27 @@
+#include <atomic>
+
+namespace rubinius {
+  namespace locks {
+    // Adapted from: Anthony Williams. “C++ Concurrency In Action.”
+
+    class spinlock_mutex {
+      std::atomic_flag flag;
+    public:
+      spinlock_mutex()
+        : flag()
+      {
+        flag.clear();
+      }
+
+      void lock() {
+        while(flag.test_and_set(std::memory_order_acquire)) {
+          ; // spin
+        }
+      }
+
+      void unlock() {
+        flag.clear(std::memory_order_release);
+      }
+    };
+  }
+}