diff --git a/CHANGELOG.md b/CHANGELOG.md index 33a2710..23bf6e2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -23,6 +23,7 @@ Some actions that application developers should consider taking when upgrading f * In your own `perform.hot_cell` subscribers, test for success with `payload[:code] == "ok"` instead of `payload[:code].nil?`, and expect `interrupted`. The event now sets `code` on every call; see [Per-call notification](docs/observability.md#per-call-notification). * Where a test instruments `perform.hot_cell` by hand to stand in for a successful call, pass `code: "ok"`. `HotCell::LogSubscriber` and `yabeda-hotcell` now record `code` as the event gives it, so an event without one records no code. * Count `code="interrupted"` as a failed call wherever a dashboard or alert computes an error rate from `hotcell_requests`. `yabeda-hotcell` counted these calls as `ok` before. +* `hotcell_uptime_seconds` is now deprecated. In dashboards and alerts, replace it with `time() - hotcell_start_time_seconds`. `hotcell_start_time_seconds` has a value only for cells running this release. ### HotCell::Client @@ -39,6 +40,12 @@ Some actions that application developers should consider taking when upgrading f * On macOS, a call to a full cell reports `capacity` instead of occasionally reporting `unavailable`. A full cell answers and closes the connection without reading the request, so the client's send fails. The client already ignored that failure as `EPIPE` or `ECONNRESET` and read the answer, but macOS sometimes raises `ENOTCONN` instead. (#110) +### HotCell::Server + +#### Added + +* `metrics` reports `start_time_s`, the time the supervisor booted, in seconds since the Unix epoch. (#112) + ### HotCell::Client::Legacy #### Breaking @@ -47,6 +54,14 @@ Some actions that application developers should consider taking when upgrading f ### Yabeda::HotCell +#### Added + +* The `start_time_seconds` gauge records when each cell booted, in seconds since the Unix epoch. (#112) + +#### Deprecated + +* `uptime_seconds` is now deprecated. Use `time() - hotcell_start_time_seconds` instead. It will be removed in a future version. (#112) + #### Fixed * A call that an exception interrupted, such as the application's own request timeout, is counted in `requests` under `code="interrupted"` and records no `perform` observation. Previously, it was counted as `code="ok"` with a `perform` of 0 seconds. (#93) diff --git a/docs/observability.md b/docs/observability.md index 8f5f4a5..46ede25 100644 --- a/docs/observability.md +++ b/docs/observability.md @@ -141,7 +141,8 @@ The metrics are in the `hotcell` group: | `queue_high_water` | gauge | `cell` | The deepest that the queue has been since boot. | | `cancelled` | gauge | `cell` | Callers that gave up before the cell answered. This is a floor. | | `killed` | gauge | `cell`, `cause` | Workers killed since boot, by cause. | -| `uptime_seconds` | gauge | `cell` | Seconds since the supervisor booted. | +| `start_time_seconds` | gauge | `cell` | When the supervisor booted, in seconds since the Unix epoch. `time() - hotcell_start_time_seconds` is the uptime. | +| `uptime_seconds` | gauge | `cell` | ⚠️ Deprecated: use `start_time_seconds`. Seconds since the supervisor booted. This field will be removed in a future version. | On each scrape, the gem reads `metrics` from each registered cell and sets the gauges from it. A scrape never fails because a cell misbehaves: the gem reports the error to the Active Support error reporter. diff --git a/hotcell-server/lib/hot_cell/counters.rb b/hotcell-server/lib/hot_cell/counters.rb index 9bad2a0..2d99ec6 100644 --- a/hotcell-server/lib/hot_cell/counters.rb +++ b/hotcell-server/lib/hot_cell/counters.rb @@ -18,6 +18,7 @@ module HotCell class Counters def initialize @started_at = Clock.now + @start_time = Time.now.to_f @requests = Hash.new(0) @killed_by = Hash.new(0) @cancelled = 0 @@ -42,8 +43,8 @@ def observe_queue(depth) end def to_h(running: 0, queued: 0) - { uptime_s: (Clock.now - @started_at).round, running: running, queued: queued, - queue_high_water: @queue_high_water, requests: @requests, killed_by: @killed_by, + { start_time_s: @start_time, uptime_s: (Clock.now - @started_at).round, running: running, + queued: queued, queue_high_water: @queue_high_water, requests: @requests, killed_by: @killed_by, cancelled: @cancelled } end end diff --git a/hotcell-server/test/control_test.rb b/hotcell-server/test/control_test.rb index 55a482e..82d7ed2 100644 --- a/hotcell-server/test/control_test.rb +++ b/hotcell-server/test/control_test.rb @@ -83,6 +83,18 @@ def test_metrics_count_a_caller_that_gave_up_before_the_cell_answered end end + def test_metrics_report_when_the_cell_started + before_boot = Time.now.to_f + + TestCell.boot do |cell| + started = assert_ok(cell.control("hotcell.metrics")).result[:start_time_s] + + assert_operator started, :>=, before_boot + assert_operator started, :<=, Time.now.to_f + assert_equal started, assert_ok(cell.control("hotcell.metrics")).result[:start_time_s] + end + end + def test_metrics_report_what_no_single_caller_can_see TestCell.boot(concurrency: 1, queue_size: 4, deadline: 30) do |cell| blocker = cell.connect diff --git a/yabeda-hotcell/lib/yabeda/hot_cell.rb b/yabeda-hotcell/lib/yabeda/hot_cell.rb index 33c3029..b119988 100644 --- a/yabeda-hotcell/lib/yabeda/hot_cell.rb +++ b/yabeda-hotcell/lib/yabeda/hot_cell.rb @@ -33,7 +33,9 @@ def self.install! tags: %i[ cell ], aggregation: :most_recent gauge :killed, comment: "Workers killed since boot, by cause", tags: %i[ cell cause ], aggregation: :most_recent - gauge :uptime_seconds, comment: "Seconds since the supervisor booted", + gauge :uptime_seconds, comment: "Seconds since the supervisor booted. Deprecated: use start_time_seconds", + tags: %i[ cell ], aggregation: :most_recent + gauge :start_time_seconds, comment: "When the supervisor booted, in seconds since the Unix epoch", tags: %i[ cell ], aggregation: :most_recent collect { Yabeda::HotCell.collect_stats } @@ -91,6 +93,7 @@ def self.record_perform(event) Yabeda.hotcell.queue_high_water.set(tags, counters[:queue_high_water]) Yabeda.hotcell.cancelled.set(tags, counters[:cancelled]) Yabeda.hotcell.uptime_seconds.set(tags, counters[:uptime_s]) + Yabeda.hotcell.start_time_seconds.set(tags, counters[:start_time_s]) if counters[:start_time_s] ::HotCell::Codes::PERMANENT_BY_CAUSE.each_key do |cause| Yabeda.hotcell.killed.set(tags.merge(cause: cause), counters[:killed_by].fetch(cause.to_sym, 0)) end diff --git a/yabeda-hotcell/test/collect_test.rb b/yabeda-hotcell/test/collect_test.rb index f440d8c..c9c0c28 100644 --- a/yabeda-hotcell/test/collect_test.rb +++ b/yabeda-hotcell/test/collect_test.rb @@ -19,6 +19,28 @@ def test_publishes_a_running_cells_counters assert_equal 0, gauge(:queue_high_water) assert_equal 0, gauge(:cancelled) assert_kind_of Integer, gauge(:uptime_seconds) + assert_kind_of Float, gauge(:start_time_seconds) + end + + def test_publishes_when_the_cell_started + HotCell.root = "/nowhere" + register transport: CannedTransport.new(metrics(start_time_s: 1_760_000_000.25)) + + Yabeda.collect! + + assert_equal 1_760_000_000.25, gauge(:start_time_seconds) + end + + def test_a_cell_that_does_not_report_its_start_time_publishes_none + HotCell.root = "/nowhere" + register transport: CannedTransport.new(metrics) + + Yabeda.collect! + + refute_includes Yabeda::TestAdapter.instance.gauges[Yabeda.hotcell.start_time_seconds], { cell: "test" } + assert_equal 41, gauge(:uptime_seconds) + assert_equal 0, gauge(:killed, cause: "memory") + assert_empty @reported end def test_publishes_kills_by_cause