Stopwatch and reducer rng (#1681)

Signed-off-by: Ingvar Stepanyan <me@rreverser.com>
Co-authored-by: Steve Boytsun <steve@clockwokrlabs.io>
Co-authored-by: Ingvar Stepanyan <me@rreverser.com>

.gitignore

@@ -202,6 +202,7 @@ __pycache__/
 cs-src/
 crates/bench/spacetime.svg
 crates/bench/sqlite.svg
+.vs/
 
 # benchmark files
 out.json

crates/bindings-csharp/Runtime/Exceptions.cs

@@ -42,6 +42,11 @@ public class NoSuchIterException : StdbException
     public override string Message => "The provided row iterator does not exist";
 }
 
+public class NoSuchLogStopwatch : StdbException
+{
+    public override string Message => "The provided stopwatch does not exist";
+}
+
 public class NoSuchBytesException : StdbException
 {
     public override string Message => "The provided bytes source or sink does not exist";

crates/bindings-csharp/Runtime/Internal/FFI.cs

@@ -27,6 +27,7 @@ public enum Errno : short
     BSATN_DECODE_ERROR = 3,
     NO_SUCH_TABLE = 4,
     NO_SUCH_ITER = 6,
+    NO_SUCH_CONSOLE_TIMER = 7,
     NO_SUCH_BYTES = 8,
     NO_SPACE = 9,
     BUFFER_TOO_SMALL = 11,
@@ -75,6 +76,7 @@ public static CheckedStatus ConvertToManaged(Errno status)
                     Errno.BSATN_DECODE_ERROR => new BsatnDecodeException(),
                     Errno.NO_SUCH_TABLE => new NoSuchTableException(),
                     Errno.NO_SUCH_ITER => new NoSuchIterException(),
+                    Errno.NO_SUCH_CONSOLE_TIMER => new NoSuchLogStopwatch(),
                     Errno.NO_SUCH_BYTES => new NoSuchBytesException(),
                     Errno.NO_SPACE => new NoSpaceException(),
                     Errno.BUFFER_TOO_SMALL => new BufferTooSmallException(),
@@ -221,4 +223,35 @@ public static partial CheckedStatus _bytes_sink_write(
         ReadOnlySpan<byte> buffer,
         ref uint buffer_len
     );
+
+    [NativeMarshalling(typeof(ConsoleTimerIdMarshaller))]
+    [StructLayout(LayoutKind.Sequential)]
+    public readonly struct ConsoleTimerId
+    {
+        private readonly uint timer_id;
+
+        private ConsoleTimerId(uint id)
+        {
+            timer_id = id;
+        }
+
+        //LayoutKind.Sequential is apparently not enough for this struct to be returnable in PInvoke, so we need a custom marshaller unfortunately
+        [CustomMarshaller(
+            typeof(ConsoleTimerId),
+            MarshalMode.Default,
+            typeof(ConsoleTimerIdMarshaller)
+        )]
+        internal static class ConsoleTimerIdMarshaller
+        {
+            public static ConsoleTimerId ConvertToManaged(uint id) => new ConsoleTimerId(id);
+
+            public static uint ConvertToUnmanaged(ConsoleTimerId id) => id.timer_id;
+        }
+    }
+
+    [LibraryImport(StdbNamespace)]
+    public static partial ConsoleTimerId _console_timer_start([In] byte[] name, uint name_len);
+
+    [LibraryImport(StdbNamespace)]
+    public static partial CheckedStatus _console_timer_end(ConsoleTimerId stopwatch_id);
 }

crates/bindings-csharp/Runtime/Internal/Module.cs

@@ -192,11 +192,10 @@ BytesSink error
 
         try
         {
-            Runtime.Random = new((int)timestamp.MicrosecondsSinceEpoch);
-
             using var stream = new MemoryStream(args.Consume());
             using var reader = new BinaryReader(stream);
-            reducers[(int)id].Invoke(reader, new(sender, address, timestamp.ToStd()));
+            var context = new ReducerContext(sender, address, timestamp);
+            reducers[(int)id].Invoke(reader, context);
             if (stream.Position != stream.Length)
             {
                 throw new Exception("Unrecognised extra bytes in the reducer arguments");

crates/bindings-csharp/Runtime/LogStopwatch.cs

@@ -0,0 +1,30 @@
+using System.Text;
+using SpacetimeDB.Internal;
+
+namespace SpacetimeDB;
+
+public sealed class LogStopwatch : IDisposable
+{
+    private readonly FFI.ConsoleTimerId StopwatchId;
+    private bool WasStopped;
+
+    public LogStopwatch(string name)
+    {
+        var name_bytes = Encoding.UTF8.GetBytes(name);
+        StopwatchId = FFI._console_timer_start(name_bytes, (uint)name_bytes.Length);
+    }
+
+    void IDisposable.Dispose()
+    {
+        if (!WasStopped)
+        {
+            End();
+        }
+    }
+
+    public void End()
+    {
+        FFI._console_timer_end(StopwatchId);
+        WasStopped = true;
+    }
+}

crates/bindings-csharp/Runtime/Runtime.cs

@@ -11,15 +11,21 @@ public class ReducerContext
     public readonly DateTimeOffset Time;
     public readonly Address? Address;
 
+    /// <summary>
+    /// A reducer-specific instance of `System.Random` that is seeded by current reducer's timestamp. This object is unchanged throught the entire reducer call
+    /// </summary>
+    public readonly Random Rng;
+
     internal ReducerContext(
         Identity senderIdentity,
         Address? senderAddress,
-        DateTimeOffset timestamp
+        DateTimeOffsetRepr timestamp
     )
     {
         Sender = senderIdentity;
         Address = senderAddress;
-        Time = timestamp;
+        Time = timestamp.ToStd();
+        Rng = new Random((int)timestamp.MicrosecondsSinceEpoch);
     }
 }
 
@@ -112,7 +118,4 @@ public static void Log(
             (uint)text_bytes.Length
         );
     }
-
-    // An instance of `System.Random` that is reseeded by each reducer's timestamp.
-    public static Random Random { get; internal set; } = new();
 }

crates/bindings-csharp/Runtime/bindings.c

@@ -21,6 +21,7 @@ OPAQUE_TYPEDEF(LogLevel, uint8_t);
 OPAQUE_TYPEDEF(BytesSink, uint32_t);
 OPAQUE_TYPEDEF(BytesSource, uint32_t);
 OPAQUE_TYPEDEF(RowIter, uint32_t);
+OPAQUE_TYPEDEF(ConsoleTimerId, uint32_t);
 
 #define CSTR(s) (uint8_t*)s, sizeof(s) - 1
 
@@ -79,6 +80,12 @@ IMPORT(int16_t, _bytes_source_read, (BytesSource source, uint8_t* buffer_ptr, si
        (source, buffer_ptr, buffer_len_ptr));
 IMPORT(uint16_t, _bytes_sink_write, (BytesSink sink, const uint8_t* buffer_ptr, size_t* buffer_len_ptr),
        (sink, buffer_ptr, buffer_len_ptr));
+IMPORT(ConsoleTimerId, _console_timer_start,
+       (const uint8_t* name, size_t name_len),
+       (name, name_len));
+IMPORT(Status, _console_timer_end,
+       (ConsoleTimerId stopwatch_id),
+       (stopwatch_id));
 
 #ifndef EXPERIMENTAL_WASM_AOT
 static MonoClass* ffi_class;

crates/bindings/src/lib.rs

@@ -4,12 +4,12 @@
 #[macro_use]
 mod io;
 mod impls;
+pub mod log_stopwatch;
 mod logger;
 #[cfg(feature = "rand")]
 mod rng;
 #[doc(hidden)]
 pub mod rt;
-pub mod time_span;
 mod timestamp;
 
 use spacetimedb_lib::buffer::{BufReader, BufWriter, Cursor, DecodeError};

crates/bindings/src/time_span.rs → crates/bindings/src/log_stopwatch.rs

@@ -1,23 +1,23 @@
-pub struct Span {
-    span_id: u32,
+pub struct LogStopwatch {
+    stopwatch_id: u32,
 }
 
-impl Span {
-    pub fn start(name: &str) -> Self {
+impl LogStopwatch {
+    pub fn new(name: &str) -> Self {
         let name = name.as_bytes();
         let id = unsafe { spacetimedb_bindings_sys::raw::_console_timer_start(name.as_ptr(), name.len()) };
-        Self { span_id: id }
+        Self { stopwatch_id: id }
     }
 
     pub fn end(self) {
         // just drop self
     }
 }
 
-impl std::ops::Drop for Span {
+impl std::ops::Drop for LogStopwatch {
     fn drop(&mut self) {
         unsafe {
-            spacetimedb_bindings_sys::raw::_console_timer_end(self.span_id);
+            spacetimedb_bindings_sys::raw::_console_timer_end(self.stopwatch_id);
         }
     }
 }

crates/primitives/src/errno.rs

@@ -14,7 +14,7 @@ macro_rules! errnos {
             NO_SUCH_TABLE(4, "No such table"),
             NO_SUCH_INDEX(5, "No such index"),
             NO_SUCH_ITER(6, "The provided row iterator is not valid"),
-            NO_SUCH_CONSOLE_TIMER(7, "The started console timer does not exist"),
+            NO_SUCH_CONSOLE_TIMER(7, "The provided console timer does not exist"),
             NO_SUCH_BYTES(8, "The provided bytes source or sink is not valid"),
             NO_SPACE(9, "The provided sink has no more space left"),
             BUFFER_TOO_SMALL(11, "The provided buffer is not large enough to store the data"),

modules/perf-test/src/lib.rs

@@ -1,4 +1,4 @@
-use spacetimedb::{query, time_span::Span};
+use spacetimedb::{log_stopwatch::LogStopwatch, query};
 
 #[spacetimedb::table(name = location, index(name = coordinates, btree(columns = [x, z, dimension])))]
 #[derive(Debug, PartialEq, Eq)]
@@ -42,7 +42,7 @@ const CHUNK: u64 = ID / ROWS_PER_CHUNK;
 #[spacetimedb::reducer]
 /// Probing a single column index for a single row should be fast!
 pub fn test_index_scan_on_id() {
-    let span = Span::start("Index scan on {id}");
+    let span = LogStopwatch::new("Index scan on {id}");
     let location = Location::filter_by_id(&ID).unwrap();
     span.end();
     assert_eq!(ID, location.id);
@@ -51,7 +51,7 @@ pub fn test_index_scan_on_id() {
 #[spacetimedb::reducer]
 /// Scanning a single column index for `ROWS_PER_CHUNK` rows should also be fast!
 pub fn test_index_scan_on_chunk() {
-    let span = Span::start("Index scan on {chunk}");
+    let span = LogStopwatch::new("Index scan on {chunk}");
     let n = Location::filter_by_chunk(&CHUNK).count();
     span.end();
     assert_eq!(n as u64, ROWS_PER_CHUNK);
@@ -62,7 +62,7 @@ pub fn test_index_scan_on_chunk() {
 pub fn test_index_scan_on_x_z_dimension() {
     let z = CHUNK as i32;
     let dimension = ID as u32;
-    let span = Span::start("Index scan on {x, z, dimension}");
+    let span = LogStopwatch::new("Index scan on {x, z, dimension}");
     let n = query!(|r: Location| r.x == 0 && r.z == z && r.dimension == dimension).count();
     span.end();
     assert_eq!(n, 1);
@@ -72,7 +72,7 @@ pub fn test_index_scan_on_x_z_dimension() {
 /// Probing a multi-column index for `ROWS_PER_CHUNK` rows should also be fast!
 pub fn test_index_scan_on_x_z() {
     let z = CHUNK as i32;
-    let span = Span::start("Index scan on {x, z}");
+    let span = LogStopwatch::new("Index scan on {x, z}");
     let n = query!(|r: Location| r.x == 0 && r.z == z).count();
     span.end();
     assert_eq!(n as u64, ROWS_PER_CHUNK);