Add a way to log messages asynchronously.

CMakeLists.txt

@@ -38,6 +38,7 @@ add_library(cubeb
   src/cubeb_mixer.cpp
   src/cubeb_resampler.cpp
   src/cubeb_panner.cpp
+  src/cubeb_log.cpp
    $<TARGET_OBJECTS:speex>)
 target_include_directories(cubeb PUBLIC include)
 target_include_directories(cubeb PRIVATE src)

src/cubeb.c

@@ -14,9 +14,6 @@
 
 #define NELEMS(x) ((int) (sizeof(x) / sizeof(x[0])))
 
-cubeb_log_level g_log_level;
-cubeb_log_callback g_log_callback;
-
 struct cubeb {
   struct cubeb_ops * ops;
 };
@@ -620,6 +617,15 @@ int cubeb_set_log_callback(cubeb_log_level log_level,
   g_log_callback = log_callback;
   g_log_level = log_level;
 
+  // Logging a message here allows to initialize the asynchronous logger from a
+  // thread that is not the audio rendering thread, and especially to not
+  // initialize it the first time we find a verbose log, which is often in the
+  // audio rendering callback, that runs from the audio rendering thread, and
+  // that is high priority, and that we don't want to block.
+  if (log_level >= CUBEB_LOG_VERBOSE) {
+    ALOGV("Starting cubeb log");
+  }
+
   return CUBEB_OK;
 }
 

src/cubeb_log.cpp

@@ -0,0 +1,108 @@
+/*
+ * Copyright © 2016 Mozilla Foundation
+ *
+ * This program is made available under an ISC-style license.  See the
+ * accompanying file LICENSE for details.
+ */
+#define NOMINMAX
+
+#include "cubeb_log.h"
+#include "cubeb_ringbuffer.h"
+#include <cstdarg>
+
+cubeb_log_level g_log_level;
+cubeb_log_callback g_log_callback;
+
+/** The maximum size of a log message, after having been formatted. */
+const size_t CUBEB_LOG_MESSAGE_MAX_SIZE = 256;
+/** The maximum number of log messages that can be queued before dropping
+ * messages. */
+const size_t CUBEB_LOG_MESSAGE_QUEUE_DEPTH = 40;
+/** Number of milliseconds to wait before dequeuing log messages. */
+const std::chrono::milliseconds CUBEB_LOG_BATCH_PRINT_INTERVAL_MS =
+                                              std::chrono::milliseconds(10);
+
+/**
+  * This wraps an inline buffer, that represents a log message, that must be
+  * null-terminated.
+  * This class should not use system calls or other potentially blocking code.
+  */
+class cubeb_log_message
+{
+public:
+  cubeb_log_message()
+  {
+    *storage = '\0';
+  }
+  cubeb_log_message(char const str[CUBEB_LOG_MESSAGE_MAX_SIZE])
+  {
+    size_t length = strlen(str);
+    /* paranoia against malformed message */
+    assert(length < CUBEB_LOG_MESSAGE_MAX_SIZE);
+    if (length > CUBEB_LOG_MESSAGE_MAX_SIZE - 1) {
+      return;
+    }
+    PodCopy(storage, str, length);
+    storage[length + 1] = '\0';
+  }
+  char const * get() {
+    return storage;
+  }
+private:
+  char storage[CUBEB_LOG_MESSAGE_MAX_SIZE];
+};
+
+/** Lock-free asynchronous logger, made so that logging from a
+ *  real-time audio callback does not block the audio thread. */
+class cubeb_async_logger
+{
+public:
+  /* This is thread-safe since C++11 */
+  static cubeb_async_logger & get() {
+    static cubeb_async_logger instance;
+    return instance;
+  }
+  void push(char const str[CUBEB_LOG_MESSAGE_MAX_SIZE])
+  {
+    cubeb_log_message msg(str);
+    msg_queue.enqueue(msg);
+  }
+  void run()
+  {
+    std::thread([this]() {
+      while (true) {
+        cubeb_log_message msg;
+        while (msg_queue.dequeue(&msg, 1)) {
+          LOGV("%s", msg.get());
+        }
+        std::this_thread::sleep_for(CUBEB_LOG_BATCH_PRINT_INTERVAL_MS);
+      }
+    }).detach();
+  }
+private:
+  cubeb_async_logger()
+    : msg_queue(CUBEB_LOG_MESSAGE_QUEUE_DEPTH)
+  {
+    run();
+  }
+  /** This is quite a big data structure, but is only instantiated if the
+   * asynchronous logger is used.*/
+  lock_free_queue<cubeb_log_message> msg_queue;
+};
+
+
+void cubeb_async_log(char const * fmt, ...)
+{
+  if (!g_log_callback) {
+    return;
+  }
+  // This is going to copy a 256 bytes array around, which is fine.
+  // We don't want to allocate memory here, because this is made to
+  // be called from a real-time callback.
+  va_list args;
+  va_start(args, fmt);
+  char msg[CUBEB_LOG_MESSAGE_MAX_SIZE];
+  vsnprintf(msg, CUBEB_LOG_MESSAGE_MAX_SIZE, fmt, args);
+  cubeb_async_logger::get().push(msg);
+  va_end(args);
+}

src/cubeb_log.h

@@ -8,6 +8,8 @@
 #ifndef CUBEB_LOG
 #define CUBEB_LOG
 
+#include "cubeb/cubeb.h"
+
 #ifdef __cplusplus
 extern "C" {
 #endif
@@ -20,6 +22,7 @@ extern "C" {
 
 extern cubeb_log_level g_log_level;
 extern cubeb_log_callback g_log_callback PRINTF_FORMAT(1, 2);
+void cubeb_async_log(const char * fmt, ...);
 
 #ifdef __cplusplus
 }
@@ -34,4 +37,10 @@ extern cubeb_log_callback g_log_callback PRINTF_FORMAT(1, 2);
     }                                                                        \
   } while(0)
 
+/* Asynchronous verbose logging, to log in real-time callbacks. */
+#define ALOGV(fmt, ...)                   \
+do {                                      \
+  cubeb_async_log(fmt, ##__VA_ARGS__);    \
+} while(0)
+
 #endif // CUBEB_LOG

src/cubeb_wasapi.cpp

@@ -734,7 +734,8 @@ refill_callback_duplex(cubeb_stream * stm)
     return true;
   }
 
-  LOGV("Duplex callback: input frames: %Iu, output frames: %Iu",
+
+  ALOGV("Duplex callback: input frames: %Iu, output frames: %Iu",
         stm->linear_input_buffer.length(), output_frames);
 
   refill(stm,
@@ -770,7 +771,7 @@ refill_callback_input(cubeb_stream * stm)
     return true;
   }
 
-  LOGV("Input callback: input frames: %Iu", stm->linear_input_buffer.length());
+  ALOGV("Input callback: input frames: %Iu", stm->linear_input_buffer.length());
 
   long read = refill(stm,
                      stm->linear_input_buffer.data(),
@@ -811,7 +812,7 @@ refill_callback_output(cubeb_stream * stm)
                     output_buffer,
                     output_frames);
 
-  LOGV("Output callback: output frames requested: %Iu, got %ld",
+  ALOGV("Output callback: output frames requested: %Iu, got %ld",
         output_frames, got);
 
   XASSERT(got >= 0);