add kumo.time lua module, with new timer object

The timer object can track latencies in lua code and is helpful for
ad-hoc, explicit "profiling" in your policy script: the latencies are
exported via a prometheus histogram.

Cargo.toml

@@ -9,6 +9,7 @@ members = [
   "crates/kumo-prometheus",
   "crates/kumod",
   "crates/mailparsing",
+  "crates/mod-time",
   "crates/mod-uuid",
   "crates/mta-sts",
   "crates/proxy-server",

crates/kumo-server-common/Cargo.toml

@@ -42,6 +42,7 @@ mod-redis = {path="../mod-redis"}
 mod-serde = {path="../mod-serde"}
 mod-sqlite = {path="../mod-sqlite"}
 mod-string = {path="../mod-string"}
+mod-time = {path="../mod-time"}
 mod-uuid = {path="../mod-uuid"}
 nix = {workspace=true, features=["fs", "signal"]}
 num-format = {workspace=true}

crates/kumo-server-common/src/lib.rs

@@ -31,6 +31,7 @@ pub fn register(lua: &Lua) -> anyhow::Result<()> {
         mod_serde::register,
         mod_sqlite::register,
         mod_string::register,
+        mod_time::register,
         mod_dns_resolver::register,
         mod_kafka::register,
         mod_memoize::register,
@@ -239,14 +240,6 @@ pub fn register(lua: &Lua) -> anyhow::Result<()> {
         })?,
     )?;
 
-    kumo_mod.set(
-        "sleep",
-        lua.create_async_function(|_, seconds: f64| async move {
-            tokio::time::sleep(tokio::time::Duration::from_secs_f64(seconds)).await;
-            Ok(())
-        })?,
-    )?;
-
     kumo_mod.set(
         "traceback",
         lua.create_function(move |lua: &Lua, level: usize| {

crates/mod-time/Cargo.toml

@@ -0,0 +1,11 @@
+[package]
+name = "mod-time"
+version = "0.1.0"
+edition = "2021"
+
+[dependencies]
+anyhow.workspace = true
+config = {path="../config"}
+mlua = {workspace=true, features=["vendored", "lua54", "async", "send", "serialize"]}
+prometheus.workspace = true
+tokio.workspace = true

crates/mod-time/src/lib.rs

@@ -0,0 +1,76 @@
+use config::{get_or_create_module, get_or_create_sub_module};
+use mlua::{Lua, MetaMethod, UserData, UserDataMethods};
+use prometheus::{HistogramTimer, HistogramVec};
+use std::sync::LazyLock;
+use tokio::time::Duration;
+
+static LATENCY_HIST: LazyLock<HistogramVec> = LazyLock::new(|| {
+    prometheus::register_histogram_vec!(
+        "user_lua_latency",
+        "how long something user-defined took to run in your lua policy",
+        &["label"]
+    )
+    .unwrap()
+});
+
+pub fn register(lua: &Lua) -> anyhow::Result<()> {
+    let kumo_mod = get_or_create_module(lua, "kumo")?;
+    let time_mod = get_or_create_sub_module(lua, "time")?;
+
+    let sleep_fn = lua.create_async_function(sleep)?;
+    kumo_mod.set("sleep", sleep_fn.clone())?;
+    time_mod.set("sleep", sleep_fn)?;
+
+    time_mod.set("start_timer", lua.create_function(Timer::start)?)?;
+
+    Ok(())
+}
+
+/// A Timer keeps track of the time since it was started,
+/// and will record the duration until its done method is
+/// called, or the __close metamethod is invoked.
+struct Timer {
+    timer: Option<HistogramTimer>,
+}
+
+impl Drop for Timer {
+    fn drop(&mut self) {
+        // We might be called some time after the code is done due
+        // to gc delays and pooling. We don't want the default
+        // Drop impl for HistogramTimer to record in that case:
+        // we will only report when our done method is explicitly
+        // called in lua
+        if let Some(timer) = self.timer.take() {
+            timer.stop_and_discard();
+        }
+    }
+}
+
+impl Timer {
+    fn start(_lua: &Lua, name: String) -> mlua::Result<Self> {
+        let timer = LATENCY_HIST
+            .get_metric_with_label_values(&[&name])
+            .expect("to get histo")
+            .start_timer();
+        Ok(Self { timer: Some(timer) })
+    }
+
+    fn done(_lua: &Lua, this: &mut Self, _: ()) -> mlua::Result<()> {
+        if let Some(timer) = this.timer.take() {
+            timer.observe_duration();
+        }
+        Ok(())
+    }
+}
+
+impl UserData for Timer {
+    fn add_methods<M: UserDataMethods<Self>>(methods: &mut M) {
+        methods.add_method_mut("done", Self::done);
+        methods.add_meta_method_mut(MetaMethod::Close, Self::done);
+    }
+}
+
+async fn sleep(_lua: Lua, seconds: f64) -> mlua::Result<()> {
+    tokio::time::sleep(Duration::from_secs_f64(seconds)).await;
+    Ok(())
+}

docs/generate-toc.py

@@ -441,6 +441,10 @@ def render(self, output, depth=0):
                 "module: string",
                 "reference/string",
             ),
+            Gen(
+                "module: kumo.time",
+                "reference/kumo.time",
+            ),
             Gen(
                 "module: tsa",
                 "reference/tsa",

docs/reference/kumo.time/_index.md

@@ -0,0 +1,7 @@
+# `require 'kumo.time'`
+
+The time  module provides access to a number of functions
+for working with time or timer functionality.
+
+## Available Functions
+

docs/reference/kumo.time/sleep.md

@@ -0,0 +1,8 @@
+# `kumo.time.sleep(SECONDS)`
+
+{{since('dev')}}
+
+Sleeps the current task for the specified number of seconds.
+The value can be either an integer or a floating point value,
+the latter can be used to specify fractional duration values.
+

docs/reference/kumo.time/start_timer.md

@@ -0,0 +1,66 @@
+# `kumo.time.start_timer(LABEL)`
+
+{{since('dev')}}
+
+Starts a timer with a specific label and returns a timer object.
+
+The timer object can be used to update a latency histogram that is reported in
+the prometheus metrics for the server to track how long it takes for a certain
+operation to complete.
+
+The most basic usage looks like this:
+
+```lua
+local timer = kumo.time.start_timer 'my-operation'
+
+-- do something here
+kumo.time.sleep(1.5)
+
+-- And record the latency
+timer:done()
+```
+
+After this runs, you will see the following metrics:
+
+```console
+$ curl -s 'http://127.0.0.1:8000/metrics' | grep user_lua
+# HELP user_lua_latency how long something user-defined took to run in your lua policy
+# TYPE user_lua_latency histogram
+user_lua_latency_bucket{label="my-operation",le="0.005"} 1
+user_lua_latency_bucket{label="my-operation",le="0.01"} 1
+user_lua_latency_bucket{label="my-operation",le="0.025"} 1
+user_lua_latency_bucket{label="my-operation",le="0.05"} 1
+user_lua_latency_bucket{label="my-operation",le="0.1"} 1
+user_lua_latency_bucket{label="my-operation",le="0.25"} 1
+user_lua_latency_bucket{label="my-operation",le="0.5"} 1
+user_lua_latency_bucket{label="my-operation",le="1"} 1
+user_lua_latency_bucket{label="my-operation",le="2.5"} 1
+user_lua_latency_bucket{label="my-operation",le="5"} 1
+user_lua_latency_bucket{label="my-operation",le="10"} 1
+user_lua_latency_bucket{label="my-operation",le="+Inf"} 1
+user_lua_latency_sum{label="my-operation"} 1.5
+user_lua_latency_count{label="my-operation"} 1
+```
+
+You can use the `<close>` feature of lua to automatically trigger the `:done()` call
+when the timer object falls out of scope.  This is useful for example to track how
+long it takes to run a function:
+
+```
+local function mything()
+  -- This `timer` will automatically report the duration of the `mything`
+  -- function when it returns, so you don't need to litter the function
+  -- with timer:done() calls for each return case below
+  local timer <close> = kumo.time.start_timer("mything")
+
+  if something then
+    return
+  end
+
+  if something_else then
+    return
+  end
+
+end
+```
+

docs/reference/kumo/sleep.md

@@ -1,8 +1,12 @@
 # `kumo.sleep(SECONDS)`
 
+!!! warning
+    This function has moved to the [kumo.time](../kumo.time/index.md) module and
+    will be removed in a future release.
+    {{since('dev', inline=True)}}
+
 {{since('2024.06.10-84e84b89')}}
 
 Sleeps the current task for the specified number of seconds.
 The value can be either an integer or a floating point value,
 the latter can be used to specify fractional duration values.
-