From 9e823dc352a1071659ee33abc882a11aa2134a36 Mon Sep 17 00:00:00 2001 From: Wez Furlong Date: Thu, 9 Jan 2025 15:36:30 -0700 Subject: [PATCH] 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.lock | 12 ++++ Cargo.toml | 1 + crates/kumo-server-common/Cargo.toml | 1 + crates/kumo-server-common/src/lib.rs | 9 +-- crates/mod-time/Cargo.toml | 11 ++++ crates/mod-time/src/lib.rs | 76 +++++++++++++++++++++++++ docs/generate-toc.py | 4 ++ docs/reference/kumo.time/_index.md | 7 +++ docs/reference/kumo.time/sleep.md | 8 +++ docs/reference/kumo.time/start_timer.md | 66 +++++++++++++++++++++ docs/reference/kumo/sleep.md | 6 +- 11 files changed, 192 insertions(+), 9 deletions(-) create mode 100644 crates/mod-time/Cargo.toml create mode 100644 crates/mod-time/src/lib.rs create mode 100644 docs/reference/kumo.time/_index.md create mode 100644 docs/reference/kumo.time/sleep.md create mode 100644 docs/reference/kumo.time/start_timer.md diff --git a/Cargo.lock b/Cargo.lock index a3b86d495..66457334f 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3140,6 +3140,7 @@ dependencies = [ "mod-serde", "mod-sqlite", "mod-string", + "mod-time", "mod-uuid", "nix 0.28.0", "num-format", @@ -4065,6 +4066,17 @@ dependencies = [ "psl", ] +[[package]] +name = "mod-time" +version = "0.1.0" +dependencies = [ + "anyhow", + "config", + "mlua", + "prometheus", + "tokio", +] + [[package]] name = "mod-uuid" version = "0.1.0" diff --git a/Cargo.toml b/Cargo.toml index 973e7a66a..32827d083 100644 --- a/Cargo.toml +++ b/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", diff --git a/crates/kumo-server-common/Cargo.toml b/crates/kumo-server-common/Cargo.toml index 867994702..4af8d3d78 100644 --- a/crates/kumo-server-common/Cargo.toml +++ b/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} diff --git a/crates/kumo-server-common/src/lib.rs b/crates/kumo-server-common/src/lib.rs index 2ac727fc9..9a572b8c0 100644 --- a/crates/kumo-server-common/src/lib.rs +++ b/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| { diff --git a/crates/mod-time/Cargo.toml b/crates/mod-time/Cargo.toml new file mode 100644 index 000000000..1bb382519 --- /dev/null +++ b/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 diff --git a/crates/mod-time/src/lib.rs b/crates/mod-time/src/lib.rs new file mode 100644 index 000000000..e6c4a3490 --- /dev/null +++ b/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 = 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, +} + +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 { + 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>(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(()) +} diff --git a/docs/generate-toc.py b/docs/generate-toc.py index e5abd6db4..5e13ac3b4 100755 --- a/docs/generate-toc.py +++ b/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", diff --git a/docs/reference/kumo.time/_index.md b/docs/reference/kumo.time/_index.md new file mode 100644 index 000000000..efab850b9 --- /dev/null +++ b/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 + diff --git a/docs/reference/kumo.time/sleep.md b/docs/reference/kumo.time/sleep.md new file mode 100644 index 000000000..7c37521d3 --- /dev/null +++ b/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. + diff --git a/docs/reference/kumo.time/start_timer.md b/docs/reference/kumo.time/start_timer.md new file mode 100644 index 000000000..3dd67343f --- /dev/null +++ b/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 `` 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 = kumo.time.start_timer("mything") + + if something then + return + end + + if something_else then + return + end + +end +``` + diff --git a/docs/reference/kumo/sleep.md b/docs/reference/kumo/sleep.md index 3c01d9af6..f0b9f803a 100644 --- a/docs/reference/kumo/sleep.md +++ b/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. -