[kernel] Switch logger from bip to ring buffer

A bip-buffer is good for producer/consumer systems, but ideally logs
will stay in the buffer until they're ousted because they need to be
overwritten. Now they're a regular ring buffer and every entry has an
incremental id. Consumers pass in the last id they've seen, and will get
the next log in the sequence.

definitions/objects/system.def

@@ -10,8 +10,9 @@ object system : object {
         change_iopl
     ]
 
-    # Get a log line from the kernel log
+    # Get the next log line from the kernel log
     method get_log [cap:get_log] {
+        param seen uint64                 # Last seen log id
         param buffer buffer [out zero_ok] # Buffer for the log message data structure
     }
 

src/kernel/logger.cpp

@@ -18,18 +18,31 @@ log::logger &g_logger = __g_logger_storage.value;
 
 namespace log {
 
+namespace {
+
+} // anon namespace
+
 logger *logger::s_log = nullptr;
 
 logger::logger() :
-    m_buffer {nullptr, 0}
+    m_buffer {nullptr, 0},
+    m_start {0},
+    m_end {0},
+    m_count {0}
 {
     memset(&m_levels, 0, sizeof(m_levels));
     s_log = this;
 }
 
 logger::logger(util::buffer data) :
-    m_buffer {data.pointer, data.count}
+    m_buffer {data},
+    m_start {0},
+    m_end {0},
+    m_count {0}
 {
+    kassert((data.count & (data.count - 1)) == 0,
+        "log buffer size must be a power of two");
+
     memset(&m_levels, 0, sizeof(m_levels));
     s_log = this;
 
@@ -42,59 +55,56 @@ logger::logger(util::buffer data) :
 void
 logger::output(level severity, logs area, const char *fmt, va_list args)
 {
-    char buffer[256];
+    static constexpr size_t buffer_len = 256;
+    static constexpr size_t message_len = buffer_len - sizeof(entry);
 
+    char buffer[buffer_len];
     entry *header = reinterpret_cast<entry *>(buffer);
-    header->bytes = sizeof(entry);
-    header->area = area;
-    header->severity = severity;
 
-    size_t mlen = util::vformat({header->message, sizeof(buffer) - sizeof(entry) - 1}, fmt, args);
-    header->message[mlen] = 0;
-    header->bytes += mlen + 1;
+    size_t size = sizeof(buffer);
+    size += util::vformat({header->message, message_len}, fmt, args);
 
     util::scoped_lock lock {m_lock};
 
-    uint8_t *out;
-    size_t n = m_buffer.reserve(header->bytes, reinterpret_cast<void**>(&out));
-    if (n < header->bytes) {
-        m_buffer.commit(0); // Cannot write the message, give up
-        return;
+    while (free() < size) {
+        // Remove old entries until there's enough space
+        const entry *first = util::at<const entry>(m_buffer, start());
+        m_start += first->bytes;
     }
 
-    memcpy(out, buffer, n);
-    m_buffer.commit(n);
+    header->id = ++m_count;
+    header->bytes = size;
+    header->severity = severity;
+    header->area = area;
+
+    memcpy(util::at<void>(m_buffer, end()), buffer, size);
+    m_end += size;
 
     m_waiting.clear();
 }
 
 size_t
-logger::get_entry(void *buffer, size_t size)
+logger::get_entry(uint64_t seen, void *buffer, size_t size)
 {
     util::scoped_lock lock {m_lock};
 
-    void *out;
-    size_t out_size = m_buffer.get_block(&out);
-    if (out_size == 0 || out == 0) {
+    while (seen == m_count) {
         lock.release();
         m_waiting.wait();
         lock.reacquire();
-        out_size = m_buffer.get_block(&out);
-
-        if (out_size == 0 || out == 0)
-            return 0;
     }
 
-    kassert(out_size >= sizeof(entry), "Couldn't read a full entry");
-    if (out_size < sizeof(entry))
-        return 0;
-
-    entry *ent = reinterpret_cast<entry *>(out);
-    if (size >= ent->bytes) {
-        memcpy(buffer, out, ent->bytes);
-        m_buffer.consume(ent->bytes);
+    size_t off = m_start;
+    entry *ent = util::at<entry>(m_buffer, off);
+    while (seen >= ent->id) {
+        off += ent->bytes;
+        kassert(off < m_end, "Got to the end while looking for new log entry");
+        ent = util::at<entry>(m_buffer, off);
     }
 
+    if (size >= ent->bytes)
+        memcpy(buffer, ent, ent->bytes);
+
     return ent->bytes;
 }
 

src/kernel/logger.h

@@ -5,7 +5,6 @@
 #include <stdarg.h>
 #include <stdint.h>
 
-#include <util/bip_buffer.h>
 #include <util/counted.h>
 #include <util/spinlock.h>
 
@@ -20,7 +19,7 @@ enum class logs : uint8_t {
 
 namespace log {
 
-/// Size of the log ring buffer
+/// Size of the log ring buffer. Must be a power of two.
 inline constexpr unsigned log_pages = 16;
 
 enum class level : uint8_t {
@@ -60,21 +59,25 @@ public:
 
     struct entry
     {
-        uint8_t bytes;
-        logs area;
-        level severity;
+        uint64_t id    : 42;
+        uint16_t bytes : 11;
+        level severity :  4;
+        logs area      :  7;
         char message[0];
     };
 
-    /// Get the next log entry from the buffer
+    /// Get the next log entry from the buffer. Blocks the current thread until
+    /// a log arrives if there are no entries newer than `seen`.
+    /// \arg seen    The id of the last-seen log entry, or 0 for none
     /// \arg buffer  The buffer to copy the log message into
     /// \arg size    Size of the passed-in buffer, in bytes
     /// \returns     The size of the log entry (if larger than the
     ///              buffer, then no data was copied)
-    size_t get_entry(void *buffer, size_t size);
+    size_t get_entry(uint64_t seen, void *buffer, size_t size);
 
-    /// Get whether there is currently data in the log buffer
-    inline bool has_log() const { return m_buffer.size(); }
+    /// Check whether or not there's a new log entry to get
+    /// \arg seen  The id of the last-seen log entry, or 0 for none
+    inline bool has_entry(uint64_t seen) { return seen < m_count; }
 
 private:
     friend void spam   (logs area, const char *fmt, ...);
@@ -94,11 +97,19 @@ private:
         return m_levels[static_cast<unsigned>(area)];
     }
 
-    wait_queue m_waiting;
+    inline size_t offset(size_t i) const { return i & (m_buffer.count - 1); }
+
+    inline size_t start() const { return offset(m_start); }
+    inline size_t   end() const { return offset(m_end); }
+    inline size_t  free() const { return m_buffer.count - (m_end - m_start); }
 
     level m_levels[areas_count];
 
-    util::bip_buffer m_buffer;
+    util::buffer m_buffer;
+    size_t m_start, m_end;
+    uint64_t m_count;
+
+    wait_queue m_waiting;
     util::spinlock m_lock;
 
     static logger *s_log;

src/kernel/syscalls/system.cpp

@@ -45,10 +45,10 @@ test_finish(uint32_t exit_code)
 }
 
 j6_status_t
-system_get_log(system *self, void *buffer, size_t *buffer_len)
+system_get_log(system *self, uint64_t seen, void *buffer, size_t *buffer_len)
 {
     size_t orig_size = *buffer_len;
-    *buffer_len = g_logger.get_entry(buffer, *buffer_len);
+    *buffer_len = g_logger.get_entry(seen, buffer, *buffer_len);
     return (*buffer_len > orig_size) ? j6_err_insufficient : j6_status_ok;
 }
 

src/user/srv.logger/main.cpp

@@ -22,9 +22,10 @@ j6_handle_t g_handle_sys = j6_handle_invalid;
 
 struct entry
 {
-    uint8_t bytes;
-    uint8_t area;
-    uint8_t severity;
+    uint64_t id      : 42;
+    uint16_t bytes   : 11;
+    uint8_t severity :  4;
+    uint8_t area     :  7;
     char message[0];
 };
 
@@ -79,9 +80,11 @@ log_pump_proc(j6_handle_t cout)
     if (result != j6_status_ok)
         return;
 
+    uint64_t seen = 0;
+
     while (true) {
         size_t size = buffer_size;
-        j6_status_t s = j6_system_get_log(g_handle_sys, message_buffer, &size);
+        j6_status_t s = j6_system_get_log(g_handle_sys, seen, message_buffer, &size);
 
         if (s == j6_err_insufficient) {
             free(message_buffer);
@@ -95,6 +98,7 @@ log_pump_proc(j6_handle_t cout)
 
         const entry *e = reinterpret_cast<entry*>(message_buffer);
 
+        seen = e->id;
         const char *area_name = area_names[e->area];
         const char *level_name = level_names[e->severity];
         uint8_t level_color = level_colors[e->severity];