Merge pull request #361 from DFE-Digital/job-time-in-queue

Track how long UpsertCandidateJobs spend in the queue
DFE-Digital · Nov 10, 2020 · 64588d3 · 64588d3
2 parents 8d839d2 + ed150ad
commit 64588d3
Show file tree

Hide file tree

Showing 7 changed files with 43 additions and 3 deletions.
diff --git a/GetIntoTeachingApi/Adapters/IPerformContextAdapter.cs b/GetIntoTeachingApi/Adapters/IPerformContextAdapter.cs
@@ -1,9 +1,11 @@
-using Hangfire.Server;
+using System;
+using Hangfire.Server;
 
 namespace GetIntoTeachingApi.Adapters
 {
     public interface IPerformContextAdapter
     {
         int GetRetryCount(PerformContext context);
+        DateTime GetJobCreatedAt(PerformContext context);
     }
 }
diff --git a/GetIntoTeachingApi/Adapters/PerformContextAdapter.cs b/GetIntoTeachingApi/Adapters/PerformContextAdapter.cs
@@ -1,4 +1,5 @@
-using Hangfire.Server;
+using System;
+using Hangfire.Server;
 
 namespace GetIntoTeachingApi.Adapters
 {
@@ -8,5 +9,10 @@ public int GetRetryCount(PerformContext context)
         {
             return context.GetJobParameter<int>("RetryCount");
         }
+
+        public DateTime GetJobCreatedAt(PerformContext context)
+        {
+            return context.BackgroundJob.CreatedAt;
+        }
     }
 }
diff --git a/GetIntoTeachingApi/Jobs/UpsertCandidateJob.cs b/GetIntoTeachingApi/Jobs/UpsertCandidateJob.cs
@@ -6,6 +6,7 @@
 using GetIntoTeachingApi.Utils;
 using Hangfire.Server;
 using Microsoft.Extensions.Logging;
+using Prometheus;
 
 namespace GetIntoTeachingApi.Jobs
 {
@@ -14,19 +15,22 @@ public class UpsertCandidateJob : BaseJob
         private readonly ICrmService _crm;
         private readonly INotifyService _notifyService;
         private readonly IPerformContextAdapter _contextAdapter;
+        private readonly IMetricService _metrics;
         private readonly ILogger<UpsertCandidateJob> _logger;
 
         public UpsertCandidateJob(
             IEnv env,
             ICrmService crm,
             INotifyService notifyService,
             IPerformContextAdapter contextAdapter,
+            IMetricService metrics,
             ILogger<UpsertCandidateJob> logger)
             : base(env)
         {
             _crm = crm;
             _notifyService = notifyService;
             _contextAdapter = contextAdapter;
+            _metrics = metrics;
             _logger = logger;
         }
 
@@ -56,6 +60,9 @@ public void Run(Candidate candidate, PerformContext context)
 
                 _logger.LogInformation($"UpsertCandidateJob - Succeeded - {candidate.Id}");
             }
+
+            var duration = (DateTime.UtcNow - _contextAdapter.GetJobCreatedAt(context)).TotalSeconds;
+            _metrics.HangfireJobQueueDuration.WithLabels(new[] { "UpsertCandidateJob" }).Observe(duration);
         }
 
         private void SaveCandidate(Candidate candidate)

diff --git a/GetIntoTeachingApi/Services/IMetricService.cs b/GetIntoTeachingApi/Services/IMetricService.cs
@@ -7,6 +7,7 @@ public interface IMetricService
         Histogram CrmSyncDuration { get; }
         Histogram LocationSyncDuration { get; }
         Histogram LocationBatchDuration { get; }
+        Histogram HangfireJobQueueDuration { get; }
         Gauge HangfireJobs { get; }
         Counter GoogleApiCalls { get; }
         Counter CacheLookups { get; }

diff --git a/GetIntoTeachingApi/Services/MetricService.cs b/GetIntoTeachingApi/Services/MetricService.cs
@@ -10,6 +10,11 @@ public class MetricService : IMetricService
             .CreateHistogram("api_location_sync_duration_seconds", "Histogram of location sync durations.");
         private static readonly Histogram _locationBatchDuration = Metrics
             .CreateHistogram("api_location_batch_duration_seconds", "Histogram of location batch processing durations.");
+        private static readonly Histogram _hangfireJobQueueDuration = Metrics
+            .CreateHistogram("api_hangfire_job_queue_duration_seconds", "Histogram of the time jobs spend in the queue.", new HistogramConfiguration
+            {
+                LabelNames = new[] { "job" },
+            });
         private static readonly Gauge _hangfireJobs = Metrics
             .CreateGauge("api_hangfire_jobs", "Gauge number of Hangifre jobs.", "state");
         private static readonly Counter _googleApiCalls = Metrics
@@ -26,6 +31,7 @@ public class MetricService : IMetricService
         public Histogram CrmSyncDuration => _crmSyncDuration;
         public Histogram LocationSyncDuration => _locationSyncDuration;
         public Histogram LocationBatchDuration => _locationBatchDuration;
+        public Histogram HangfireJobQueueDuration => _hangfireJobQueueDuration;
         public Gauge HangfireJobs => _hangfireJobs;
         public Counter GoogleApiCalls => _googleApiCalls;
         public Counter CacheLookups => _cacheLookups;

diff --git a/GetIntoTeachingApiTests/Jobs/UpsertCandidateJobTests.cs b/GetIntoTeachingApiTests/Jobs/UpsertCandidateJobTests.cs
@@ -19,6 +19,7 @@ public class UpsertCandidateJobTests
         private readonly Mock<ICrmService> _mockCrm;
         private readonly Mock<INotifyService> _mockNotifyService;
         private readonly Candidate _candidate;
+        private readonly IMetricService _metrics;
         private readonly UpsertCandidateJob _job;
         private readonly Mock<ILogger<UpsertCandidateJob>> _mockLogger;
 
@@ -28,9 +29,13 @@ public UpsertCandidateJobTests()
             _mockCrm = new Mock<ICrmService>();
             _mockNotifyService = new Mock<INotifyService>();
             _mockLogger = new Mock<ILogger<UpsertCandidateJob>>();
+            _metrics = new MetricService();
             _candidate = new Candidate() { Id = Guid.NewGuid(), Email = "test@test.com" };
             _job = new UpsertCandidateJob(new Env(), _mockCrm.Object, _mockNotifyService.Object,
-                _mockContext.Object, _mockLogger.Object);
+                _mockContext.Object, _metrics, _mockLogger.Object);
+
+            _metrics.HangfireJobQueueDuration.RemoveLabelled(new[] { "UpsertCandidateJob" });
+            _mockContext.Setup(m => m.GetJobCreatedAt(null)).Returns(DateTime.UtcNow.AddDays(-1));
         }
 
         [Fact]
@@ -43,6 +48,7 @@ public void Run_OnSuccess_SavesCandidate()
             _mockCrm.Verify(mock => mock.Save(_candidate), Times.Once);
             _mockLogger.VerifyInformationWasCalled("UpsertCandidateJob - Started (1/24)");
             _mockLogger.VerifyInformationWasCalled($"UpsertCandidateJob - Succeeded - {_candidate.Id}");
+            _metrics.HangfireJobQueueDuration.WithLabels(new[] { "UpsertCandidateJob" }).Count.Should().Be(1);
         }
 
         [Fact]
@@ -58,6 +64,7 @@ public void Run_WithTeachingEventRegistrationsOnSuccess_SavesTeachingEventRegist
 
             _mockCrm.Verify(mock => mock.Save(registration), Times.Once);
             registration.CandidateId.Should().Be(candidateId);
+            _metrics.HangfireJobQueueDuration.WithLabels(new[] { "UpsertCandidateJob" }).Count.Should().Be(1);
         }
 
         [Fact]
@@ -73,6 +80,7 @@ public void Run_WithPhoneCallOnSuccess_SavesPhoneCall()
 
             _mockCrm.Verify(mock => mock.Save(phoneCall), Times.Once);
             phoneCall.CandidateId.Should().Be(candidateId.ToString());
+            _metrics.HangfireJobQueueDuration.WithLabels(new[] { "UpsertCandidateJob" }).Count.Should().Be(1);
         }
 
         [Fact]
@@ -91,6 +99,7 @@ public void Run_WithPhoneCallOnSuccess_IncrementsCallbackBookingQuotaNumberOfBoo
 
             _mockCrm.Verify(mock => mock.Save(quota), Times.Once);
             quota.NumberOfBookings.Should().Be(6);
+            _metrics.HangfireJobQueueDuration.WithLabels(new[] { "UpsertCandidateJob" }).Count.Should().Be(1);
         }
 
         [Fact]
@@ -109,6 +118,7 @@ public void Run_WithPhoneCallOnSuccessButMatchingQuotaIsAlreadyFull_DoesNotIncre
 
             _mockCrm.Verify(mock => mock.Save(quota), Times.Never);
             quota.NumberOfBookings.Should().Be(5);
+            _metrics.HangfireJobQueueDuration.WithLabels(new[] { "UpsertCandidateJob" }).Count.Should().Be(1);
         }
 
         [Fact]
@@ -123,6 +133,7 @@ public void Run_OnFailure_EmailsCandidate()
                 NotifyService.CandidateRegistrationFailedEmailTemplateId, It.IsAny<Dictionary<string, dynamic>>()));
             _mockLogger.VerifyInformationWasCalled("UpsertCandidateJob - Started (24/24)");
             _mockLogger.VerifyInformationWasCalled("UpsertCandidateJob - Deleted");
+            _metrics.HangfireJobQueueDuration.WithLabels(new[] { "UpsertCandidateJob" }).Count.Should().Be(1);
         }
     }
 }
diff --git a/GetIntoTeachingApiTests/Services/MetricServiceTests.cs b/GetIntoTeachingApiTests/Services/MetricServiceTests.cs
@@ -32,6 +32,13 @@ public void LocationBatchDuration_ReturnsMetric()
             _metrics.LocationBatchDuration.Name.Should().Be("api_location_batch_duration_seconds");
         }
 
+        [Fact]
+        public void HangfireJobQueueDuration_ReturnsMetric()
+        {
+            _metrics.HangfireJobQueueDuration.Name.Should().Be("api_hangfire_job_queue_duration_seconds");
+            _metrics.HangfireJobQueueDuration.LabelNames.Should().BeEquivalentTo(new[] { "job" });
+        }
+
         [Fact]
         public void HangfireJobs_ReturnsMetric()
         {