New macros `Prometheus.@time` and `Prometheus.@inprogress` (#6)

- New macro `Prometheus.@time collector <expr>` for timing `<expr>` and
  pass the elapsed time to the collector.
- New macro `Prometheus.@inprogress collector <expr>` to track number of
  in-progress concurrent evalutations of `<expr>`.

In both cases, `<expr>` 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

@@ -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] -->
+## [Unreleased]
+### Added
+ - New macro `Prometheus.@time collector <expr>` for timing `<expr>` and pass the elapsed
+   time to the collector. `<expr>` 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 <expr>` to track number of in-progress
+   concurrent evalutations of `<expr>`. Just like `Prometheus.@time`, valid `<expr>`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

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
 

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 <expr>
+
+Prometheus.@time collector begin
+    <expr>
+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 <expr>
+
+Prometheus.@inprogress collector begin
+    <expr>
+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 #
 ####################################

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}(