From 669ca19dfd3a3012c2e076645e1a7439011a4bd8 Mon Sep 17 00:00:00 2001 From: Fredrik Ekre Date: Sun, 12 Nov 2023 00:53:36 +0100 Subject: [PATCH] New macros `Prometheus.@time` and `Prometheus.@inprogress` - New macro `Prometheus.@time collector ` for timing `` and pass the elapsed time to the collector. - New macro `Prometheus.@inprogress collector ` to track number of in-progress concurrent evalutations of ``. In both cases, `` can be a single expression, a block, or a function *definition*. In the latter case, all calls to the function will be instrumented (no matter the call site). See documentation for more details. --- CHANGELOG.md | 13 +++- docs/src/index.md | 5 ++ src/Prometheus.jl | 155 +++++++++++++++++++++++++++++++++++++++++----- test/runtests.jl | 100 ++++++++++++++++++++++++++++++ 4 files changed, 258 insertions(+), 15 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index a551881..3bb4066 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,7 +5,16 @@ All notable changes to this project will be documented in this file. The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). - +## [Unreleased] +### Added + - New macro `Prometheus.@time collector ` for timing `` and pass the elapsed + time to the collector. `` can be a single expression, a block, or a function + *definition*. In the latter case, all calls to the function will be instrumented (no + matter the call site). See documentation for more details. ([#6][github-6]) + - New macro `Prometheus.@inprogress collector ` to track number of in-progress + concurrent evalutations of ``. Just like `Prometheus.@time`, valid ``s are + single expressions, blocks, and function definitions. See documentation for more details. + ([#6][github-6]) ## [1.0.1] - 2023-11-06 ### Fixed @@ -28,6 +37,8 @@ First stable release of Prometheus.jl: See [README.md](README.md) for details and documentation. +[github-6]: https://github.com/fredrikekre/Prometheus.jl/pull/6 + [Unreleased]: https://github.com/fredrikekre/Prometheus.jl/compare/v1.0.1...HEAD [1.0.1]: https://github.com/fredrikekre/Prometheus.jl/compare/v1.0.0...v1.0.1 [1.0.0]: https://github.com/fredrikekre/Prometheus.jl/tree/v1.0.0 diff --git a/docs/src/index.md b/docs/src/index.md index 8b39b6e..ad54f5f 100644 --- a/docs/src/index.md +++ b/docs/src/index.md @@ -107,6 +107,8 @@ Prometheus.inc(::Prometheus.Gauge, ::Any) Prometheus.dec(::Prometheus.Gauge, ::Any) Prometheus.set(::Prometheus.Gauge, ::Any) Prometheus.set_to_current_time(::Prometheus.Gauge) +Prometheus.@time +Prometheus.@inprogress ``` ### Summary @@ -124,6 +126,9 @@ documentation](https://prometheus.io/docs/concepts/metric_types/#summary): Prometheus.Summary(::String, ::String; kwargs...) Prometheus.observe(::Prometheus.Summary, ::Any) ``` +```@docs; canonical=false +Prometheus.@time +``` ### GCCollector diff --git a/src/Prometheus.jl b/src/Prometheus.jl index edeeb63..316081f 100644 --- a/src/Prometheus.jl +++ b/src/Prometheus.jl @@ -214,14 +214,6 @@ end ###################### # https://prometheus.io/docs/instrumenting/writing_clientlibs/#gauge -# TODO: A gauge is ENCOURAGED to have: -# - A way to track in-progress requests in some piece of code/function. This is -# track_inprogress in Python. -# - A way to time a piece of code and set the gauge to its duration in seconds. This is -# useful for batch jobs. This is startTimer/setDuration in Java and the time() -# decorator/context manager in Python. This SHOULD match the pattern in Summary/Histogram -# (though set() rather than observe()). - mutable struct Gauge <: Collector @const metric_name::String @const help::String @@ -261,6 +253,10 @@ Construct a Gauge collector. - [`Prometheus.set`](@ref): set the value of the gauge. - [`Prometheus.set_to_current_time`](@ref): set the value of the gauge to the current unixtime. + - [`Prometheus.@time`](@ref): time a section and set the value of the the gauge to the + elapsed time. + - [`Prometheus.@inprogress`](@ref): Track number of inprogress operations; increment the + gauge when entering the section, decrement it when leaving. """ Gauge(::String, ::String; kwargs...) @@ -326,12 +322,6 @@ end ######################## # https://prometheus.io/docs/instrumenting/writing_clientlibs/#summary -# TODO: A summary SHOULD have the following methods: -# - Some way to time code for users in seconds. In Python this is the time() -# decorator/context manager. In Java this is startTimer/observeDuration. Units other than -# seconds MUST NOT be offered (if a user wants something else, they can do it by hand). -# This should follow the same pattern as Gauge/Histogram. - mutable struct Summary <: Collector @const metric_name::String @const help::String @@ -368,6 +358,7 @@ Construct a Summary collector. **Methods** - [`Prometheus.observe`](@ref): add an observation to the summary. + - [`Prometheus.@time`](@ref): time a section and add the elapsed time as an observation. """ Summary(::String, ::String; kwargs...) @@ -401,6 +392,142 @@ function collect!(metrics::Vector, summary::Summary) end +################ +# "Decorators" # +################ + +""" + Prometheus.@time collector expr + +Time the evaluation of `expr` and send the elapsed time in seconds to `collector`. The +specific action depends on the type of collector: + + - `collector :: Gauge`: set the value of the gauge to the elapsed time + ([`Prometheus.set`](@ref)) + - `collector :: Summary`: add the elapsed time as an observation + ([`Prometheus.observe`](@ref)) + +The expression to time, `expr`, can be a single expression (for example a function call), or +a code block (`begin`, `let`, etc), e.g. +```julia +Prometheus.@time collector + +Prometheus.@time collector begin + +end +``` + +It is also possible to apply the macro to a function *definition*, i.e. +```julia +Prometheus.@time collector function time_this(args...) + # function body +end +``` +to time every call to this function (covering all call sites). +""" +macro time(collector, expr) + return expr_gen(:time, collector, expr) +end + +at_time(gauge::Gauge, v) = set(gauge, v) +at_time(summary::Summary, v) = observe(summary, v) +at_time(::Collector, v) = unreachable() + +""" + Prometheus.@inprogress collector expr + +Track the number of concurrent in-progress evaluations of `expr`. From the builtin +collectors this is only applicable to the [`Gauge`](@ref) -- the value of the gauge is +incremented with 1 when entering the section, and decremented with 1 when exiting the +section. + +The expression, `expr`, can be a single expression (for example a function call), or a code +block (`begin`, `let`, etc), e.g. +```julia +Prometheus.@inprogress collector + +Prometheus.@inprogress collector begin + +end +``` + +It is also possible to apply the macro to a function *definition*, i.e. +```julia +Prometheus.@inprogress collector function track_this(args...) + # function body +end +``` +to track number of concurrent in-progress calls (covering all call sites). +""" +macro inprogress(collector, expr) + return expr_gen(:inprogress, collector, expr) +end + +at_inprogress_enter(gauge::Gauge) = inc(gauge) +at_inprogress_exit(gauge::Gauge) = dec(gauge) +at_inprogress_enter(::Collector) = unreachable() +at_inprogress_exit(::Collector) = unreachable() + +function expr_gen(macroname, collector, code) + if macroname === :time + local cllctr, t0, val + @gensym cllctr t0 val + preamble = Expr[ + Expr(:(=), cllctr, esc(collector)), + Expr(:(=), t0, Expr(:call, time)), + ] + postamble = Expr[ + Expr(:(=), val, Expr(:call, max, Expr(:call, -, Expr(:call, time), t0), 0.0)), + Expr(:call, at_time, cllctr, val) + ] + elseif macroname === :inprogress + local cllctr + @gensym cllctr + preamble = Expr[ + Expr(:(=), cllctr, esc(collector)), + Expr(:call, at_inprogress_enter, cllctr), + ] + postamble = Expr[ + Expr(:call, at_inprogress_exit, cllctr) + ] + else + unreachable() + end + local ret + @gensym ret + if Meta.isexpr(code, :function) || Base.is_short_function_def(code) + @assert length(code.args) == 2 + fsig = esc(code.args[1]) + fbody = esc(code.args[2]) + return Expr( + code.head, # might as well preserve :function or :(=) + fsig, + Expr( + :block, + preamble..., + Expr( + :tryfinally, + Expr(:(=), ret, fbody), + Expr(:block, postamble...,), + ), + ret, + ), + ) + else + return Expr( + :block, + preamble..., + Expr( + :tryfinally, + Expr(:(=), ret, esc(code)), + Expr(:block, postamble...,), + ), + ret, + ) + end +end + + #################################### # Family{<:Collector} <: Collector # #################################### diff --git a/test/runtests.jl b/test/runtests.jl index 0fc6911..23aa4c1 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -253,6 +253,106 @@ end """ end +@testset "Prometheus.@time gauge::Gauge" begin + gauge = Prometheus.Gauge("call_time_last", "Time of last call"; registry=nothing) + Prometheus.@time gauge sleep(0.1) + @test 0.3 > gauge.value > 0.1 + Prometheus.@time gauge let + sleep(0.1) + end + @test 0.3 > gauge.value > 0.1 + Prometheus.@time gauge f() = sleep(0.1) + @sync begin + @async f() + @async f() + end + @test 0.3 > gauge.value > 0.1 + Prometheus.@time gauge function g() + sleep(0.1) + end + @sync begin + @async g() + @async g() + end + @test 0.3 > gauge.value > 0.1 +end + +@testset "Prometheus.@time summary::Summary" begin + summary = Prometheus.Summary("call_time", "Time of calls"; registry=nothing) + Prometheus.@time summary sleep(0.1) + @test 0.3 > summary._sum > 0.1 + @test summary._count == 1 + Prometheus.@time summary let + sleep(0.1) + end + @test 0.4 > summary._sum > 0.2 + @test summary._count == 2 + Prometheus.@time summary f() = sleep(0.1) + @sync begin + @async f() + @async f() + end + @test 0.7 > summary._sum > 0.4 + @test summary._count == 4 + Prometheus.@time summary function g() + sleep(0.1) + end + @sync begin + @async g() + @async g() + end + @test 0.9 > summary._sum > 0.6 + @test summary._count == 6 +end + +@testset "Prometheus.@inprogress gauge::Gauge" begin + gauge = Prometheus.Gauge("calls_inprogres", "Number of calls in progress"; registry=nothing) + Prometheus.@inprogress gauge sleep(0.01) + @test gauge.value == 0.0 + Prometheus.@inprogress gauge let + sleep(0.01) + end + @test gauge.value == 0.0 + Prometheus.@inprogress gauge f() = sleep(0.01) + @sync begin + @async f() + @async f() + end + @test gauge.value == 0.0 + Prometheus.@inprogress gauge function g() + sleep(0.01) + end + @sync begin + @async g() + @async g() + end + @test gauge.value == 0.0 + # Concurrency tests + @sync begin + tsks = Vector{Task}(undef, 100) + for i in 1:100 + tsk = @async begin + 0 <= gauge.value <= 100 || error() + Prometheus.@inprogress gauge sleep(1 + rand()) + end + tsks[i] = tsk + end + # Make sure all tasks have started before testing the value + while any(!istaskstarted, tsks) + sleep(0.1) + end + @test gauge.value == 100 + end + @test gauge.value == 0 +end + +@testset "Custom collector with @time/@inprogress" begin + struct Coll <: Prometheus.Collector end + @test_throws Prometheus.UnreachableError Prometheus.at_time(Coll(), 1.0) + @test_throws Prometheus.UnreachableError Prometheus.at_inprogress_enter(Coll()) + @test_throws Prometheus.UnreachableError Prometheus.at_inprogress_exit(Coll()) +end + @testset "Prometheus.Family{Summary}" begin r = Prometheus.CollectorRegistry() c = Prometheus.Family{Prometheus.Summary}(