diff --git a/lib/temporal/activity/poller.rb b/lib/temporal/activity/poller.rb index 55271593..c006adff 100644 --- a/lib/temporal/activity/poller.rb +++ b/lib/temporal/activity/poller.rb @@ -73,7 +73,11 @@ def poll_loop Temporal.metrics.timing(Temporal::MetricKeys::ACTIVITY_POLLER_TIME_SINCE_LAST_POLL, time_diff_ms, metrics_tags) Temporal.logger.debug("Polling activity task queue", { namespace: namespace, task_queue: task_queue }) + poll_time = Time.now task = poll_for_task + poll_time_diff_ms = ((Time.now - poll_time) * 1000).round + Temporal.metrics.timing(Temporal::MetricKeys::ACTIVITY_POLLER_POLL_LATENCY, poll_time_diff_ms, metrics_tags) + last_poll_time = Time.now Temporal.metrics.increment( diff --git a/lib/temporal/metric_keys.rb b/lib/temporal/metric_keys.rb index e945f0b6..cc185bd7 100644 --- a/lib/temporal/metric_keys.rb +++ b/lib/temporal/metric_keys.rb @@ -2,11 +2,13 @@ module Temporal module MetricKeys ACTIVITY_POLLER_TIME_SINCE_LAST_POLL = 'activity_poller.time_since_last_poll'.freeze ACTIVITY_POLLER_POLL_COMPLETED = 'activity_poller.poll_completed'.freeze + ACTIVITY_POLLER_POLL_LATENCY = 'activity_poller.poll_latency'.freeze ACTIVITY_TASK_QUEUE_TIME = 'activity_task.queue_time'.freeze ACTIVITY_TASK_LATENCY = 'activity_task.latency'.freeze WORKFLOW_POLLER_TIME_SINCE_LAST_POLL = 'workflow_poller.time_since_last_poll'.freeze WORKFLOW_POLLER_POLL_COMPLETED = 'workflow_poller.poll_completed'.freeze + WORKFLOW_POLLER_POLL_LATENCY = 'workflow_poller.poll_latency'.freeze WORKFLOW_TASK_QUEUE_TIME = 'workflow_task.queue_time'.freeze WORKFLOW_TASK_LATENCY = 'workflow_task.latency'.freeze WORKFLOW_TASK_EXECUTION_FAILED = 'workflow_task.execution_failed'.freeze diff --git a/lib/temporal/workflow/poller.rb b/lib/temporal/workflow/poller.rb index 07162ce1..fb36861b 100644 --- a/lib/temporal/workflow/poller.rb +++ b/lib/temporal/workflow/poller.rb @@ -74,7 +74,11 @@ def poll_loop Temporal.metrics.timing(Temporal::MetricKeys::WORKFLOW_POLLER_TIME_SINCE_LAST_POLL, time_diff_ms, metrics_tags) Temporal.logger.debug("Polling workflow task queue", { namespace: namespace, task_queue: task_queue }) + poll_time = Time.now task = poll_for_task + poll_time_diff_ms = ((Time.now - poll_time) * 1000).round + Temporal.metrics.timing(Temporal::MetricKeys::WORKFLOW_POLLER_POLL_LATENCY, poll_time_diff_ms, metrics_tags) + last_poll_time = Time.now Temporal.metrics.increment( diff --git a/spec/unit/lib/temporal/activity/poller_spec.rb b/spec/unit/lib/temporal/activity/poller_spec.rb index 0476e950..8b2d9496 100644 --- a/spec/unit/lib/temporal/activity/poller_spec.rb +++ b/spec/unit/lib/temporal/activity/poller_spec.rb @@ -74,6 +74,20 @@ def poll(task, times: 1) .at_least(:twice) end + it 'reports poll latency' do + poll(nil, times: 2) + + expect(Temporal.metrics) + .to have_received(:timing) + .with( + Temporal::MetricKeys::ACTIVITY_POLLER_POLL_LATENCY, + an_instance_of(Integer), + namespace: namespace, + task_queue: task_queue + ) + .at_least(:twice) + end + it 'reports polling completed with received_task false' do poll(nil, times: 2) diff --git a/spec/unit/lib/temporal/workflow/poller_spec.rb b/spec/unit/lib/temporal/workflow/poller_spec.rb index e8d5692b..639badde 100644 --- a/spec/unit/lib/temporal/workflow/poller_spec.rb +++ b/spec/unit/lib/temporal/workflow/poller_spec.rb @@ -84,6 +84,20 @@ def poll(task, times: 1) .at_least(2).times end + it 'reports poll latency' do + poll(nil) + + expect(Temporal.metrics) + .to have_received(:timing) + .with( + Temporal::MetricKeys::WORKFLOW_POLLER_POLL_LATENCY, + an_instance_of(Integer), + namespace: namespace, + task_queue: task_queue + ) + .at_least(2).times + end + it 'reports polling completed with received_task false' do poll(nil)