Send logging output through a BBQueue

This makes logging quite a bit faster, so we have a chance of hitting
the T_IFS timing properly now. Note that logging still is really slow
(125µs for a short message), so this might not help that much.

Author: jonas-schievink

Cargo.toml

@@ -23,6 +23,7 @@ panic-semihosting = "0.5.1"
 bitflags = "1.0.4"
 uuid = { version = "0.7.2", default-features = false }
 ux = { version = "0.1.3", default-features = false }
+bbqueue = "0.3.2"
 
 [profile.dev]
 opt-level = "s"

src/logger.rs

@@ -1,4 +1,4 @@
-use {crate::ble::time::Timer, core::fmt};
+use {crate::ble::time::Timer, bbqueue::Producer, core::fmt};
 
 /// A `fmt::Write` adapter that prints a timestamp before each line.
 pub struct StampedLogger<T: Timer, L: fmt::Write> {
@@ -27,3 +27,33 @@ impl<T: Timer, L: fmt::Write> fmt::Write for StampedLogger<T, L> {
         Ok(())
     }
 }
+
+/// A `fmt::Write` sink that writes to a `BBQueue`.
+///
+/// The sink will panic when the `BBQueue` doesn't have enough space to the data. This is to ensure
+/// that we never block or drop data.
+pub struct BbqLogger {
+    p: Producer,
+}
+
+impl BbqLogger {
+    pub fn new(p: Producer) -> Self {
+        Self { p }
+    }
+}
+
+impl fmt::Write for BbqLogger {
+    fn write_str(&mut self, s: &str) -> fmt::Result {
+        let mut bytes = s.as_bytes();
+
+        while !bytes.is_empty() {
+            let mut grant = self.p.grant_max(bytes.len()).expect("log buffer overflow");
+            let size = grant.buf().len();
+            grant.buf().copy_from_slice(&bytes[..size]);
+            bytes = &bytes[size..];
+            self.p.commit(size, grant);
+        }
+
+        Ok(())
+    }
+}

src/main.rs

@@ -18,10 +18,11 @@ use {
             },
             time::{Duration, Timer},
         },
-        logger::StampedLogger,
+        logger::{BbqLogger, StampedLogger},
         radio::{BleRadio, PacketBuffer},
         timer::BleTimer,
     },
+    bbqueue::{bbq, BBQueue, Consumer},
     byteorder::{ByteOrder, LittleEndian},
     core::fmt::Write,
     cortex_m_semihosting::hprintln,
@@ -35,7 +36,7 @@ use {
     rtfm::app,
 };
 
-type Logger = StampedLogger<timer::StampSource<pac::TIMER0>, Uarte<UARTE0>>;
+type Logger = StampedLogger<timer::StampSource<pac::TIMER0>, BbqLogger>;
 
 /// Whether to broadcast a beacon or to establish a proper connection.
 ///
@@ -51,6 +52,8 @@ const APP: () = {
     static mut RADIO: BleRadio = ();
     static mut BEACON: Beacon = ();
     static mut BEACON_TIMER: pac::TIMER1 = ();
+    static mut SERIAL: Uarte<UARTE0> = ();
+    static mut LOG_SINK: Consumer = ();
 
     #[init(resources = [BLE_TX_BUF, BLE_RX_BUF])]
     fn init() {
@@ -133,11 +136,11 @@ const APP: () = {
         .unwrap();
 
         let log_stamper = ble_timer.create_stamp_source();
-        let mut ll = LinkLayer::with_logger(
-            device_address,
-            ble_timer,
-            StampedLogger::new(serial, log_stamper),
-        );
+        let logq = bbq!(2048).unwrap();
+        let (tx, rx) = logq.split();
+        let logger = StampedLogger::new(BbqLogger::new(tx), log_stamper);
+
+        let mut ll = LinkLayer::with_logger(device_address, ble_timer, logger);
 
         if !TEST_BEACON {
             // Send advertisement and set up regular interrupt
@@ -155,6 +158,8 @@ const APP: () = {
         BLE = ll;
         BEACON = beacon;
         BEACON_TIMER = device.TIMER1;
+        SERIAL = serial;
+        LOG_SINK = rx;
     }
 
     #[interrupt(resources = [RADIO, BLE])]
@@ -187,4 +192,18 @@ const APP: () = {
 
         resources.BEACON.broadcast(&mut *resources.RADIO);
     }
+
+    #[idle(resources = [LOG_SINK, SERIAL])]
+    fn idle() -> ! {
+        // Drain the logging buffer through the serial connection
+        loop {
+            if let Ok(grant) = resources.LOG_SINK.read() {
+                for chunk in grant.buf().chunks(255) {
+                    resources.SERIAL.write(chunk).unwrap();
+                }
+
+                resources.LOG_SINK.release(grant.buf().len(), grant);
+            }
+        }
+    }
 };