Skip to content

Commit eb7f6d1

Browse files
nimble-zakcatherallCATHERALL
nimble-zakcatherall
and
CATHERALL
authored
feat: add project summary stage timings for slow-request attribution (#1146)
* feat: add project summary stage timings for slow-request attribution * chore: gate logger expression on conditional --------- Co-authored-by: CATHERALL <Zak.CATHERALL@EDUCATION.GOV.UK>
1 parent 4301932 commit eb7f6d1

6 files changed

Lines changed: 127 additions & 2 deletions

File tree

‎Dfe.ManageFreeSchoolProjects/Dfe.ManageFreeSchoolProjects.API/Diagnostics/ProcessWarmupState.cs‎

Lines changed: 19 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,19 @@
1+
namespace Dfe.ManageFreeSchoolProjects.API.Diagnostics
2+
{
3+
public interface IProcessWarmupState
4+
{
5+
/// <summary>
6+
/// Records a business request. Returns true only for the first call in this process.
7+
/// </summary>
8+
bool MarkBusinessRequest();
9+
}
10+
11+
public sealed class ProcessWarmupState : IProcessWarmupState
12+
{
13+
public const string HttpContextItemKey = "IsFirstBusinessRequestInProcess";
14+
15+
private int _businessRequestCount;
16+
17+
public bool MarkBusinessRequest() => Interlocked.Increment(ref _businessRequestCount) == 1;
18+
}
19+
}

‎Dfe.ManageFreeSchoolProjects/Dfe.ManageFreeSchoolProjects.API/Middleware/ProcessWarmupMiddleware.cs‎

Lines changed: 17 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,17 @@
1+
using Dfe.ManageFreeSchoolProjects.API.Diagnostics;
2+
3+
namespace Dfe.ManageFreeSchoolProjects.API.Middleware
4+
{
5+
public class ProcessWarmupMiddleware(RequestDelegate next)
6+
{
7+
public async Task InvokeAsync(HttpContext context, IProcessWarmupState warmupState)
8+
{
9+
if (!context.Request.Path.StartsWithSegments("/health"))
10+
{
11+
context.Items[ProcessWarmupState.HttpContextItemKey] = warmupState.MarkBusinessRequest();
12+
}
13+
14+
await next(context);
15+
}
16+
}
17+
}

‎Dfe.ManageFreeSchoolProjects/Dfe.ManageFreeSchoolProjects.API/Startup.cs‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -73,6 +73,7 @@ public void Configure(IApplicationBuilder app, IWebHostEnvironment env, IApiVers
7373
}
7474

7575
app.UseMiddleware<ExceptionHandlerMiddleware>();
76+
app.UseMiddleware<ProcessWarmupMiddleware>();
7677
app.UseMiddleware<ApiKeyMiddleware>();
7778
app.UseMiddleware<UrlDecoderMiddleware>();
7879
app.UseMiddleware<CorrelationIdMiddleware>();

‎Dfe.ManageFreeSchoolProjects/Dfe.ManageFreeSchoolProjects.API/StartupConfiguration/DependencyConfigurationExtensions.cs‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -60,13 +60,17 @@
6060
using Dfe.ManageFreeSchoolProjects.API.UseCases.LocalAuthority;
6161
using Dfe.ManageFreeSchoolProjects.API.UseCases.Project.Sites;
6262
using Dfe.ManageFreeSchoolProjects.API.UseCases.Summary;
63+
using Dfe.ManageFreeSchoolProjects.API.Diagnostics;
6364

6465
namespace Dfe.ManageFreeSchoolProjects.API.StartupConfiguration
6566
{
6667
public static class DependencyConfigurationExtensions
6768
{
6869
public static IServiceCollection AddApiDependencies(this IServiceCollection services)
6970
{
71+
services.AddHttpContextAccessor();
72+
services.AddSingleton<IProcessWarmupState, ProcessWarmupState>();
73+
7074
services.AddScoped<IServerUserInfoService, ServerUserInfoService>();
7175

7276
services.AddScoped<ICorrelationContext, CorrelationContext>();

‎Dfe.ManageFreeSchoolProjects/Dfe.ManageFreeSchoolProjects.API/UseCases/Summary/GetProjectSummaryByUserService.cs‎

Lines changed: 84 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,6 @@
1-
using Dfe.ManageFreeSchoolProjects.API.Contracts.Project.Summary;
1+
using System.Diagnostics;
2+
using Dfe.ManageFreeSchoolProjects.API.Contracts.Project.Summary;
3+
using Dfe.ManageFreeSchoolProjects.API.Diagnostics;
24
using Dfe.ManageFreeSchoolProjects.API.Extensions;
35
using Dfe.ManageFreeSchoolProjects.API.UseCases.Project;
46
using Dfe.ManageFreeSchoolProjects.Data;
@@ -17,16 +19,31 @@ public record GetProjectSummaryByUserParameters
1719
public string ProjectManagedByEmail { get; set; }
1820
}
1921

20-
public class GetProjectSummaryByUserService(MfspContext context) : IGetProjectSummaryByUserService
22+
public class GetProjectSummaryByUserService(
23+
MfspContext context,
24+
IProcessWarmupState processWarmupState,
25+
IHttpContextAccessor httpContextAccessor,
26+
ILogger<GetProjectSummaryByUserService> logger) : IGetProjectSummaryByUserService
2127
{
28+
private const string StageTimingsEventName = "ProjectSummaryByUser.StageTimings";
29+
2230
public async Task<(List<GetProjectSummaryResponse>, int)> Execute(GetProjectSummaryByUserParameters parameters)
2331
{
32+
var isFirstBusinessRequestInProcess = ResolveIsFirstBusinessRequest();
33+
var totalStopwatch = Stopwatch.StartNew();
34+
2435
var query = context.Kpi.AsQueryable();
2536

2637
query = ApplyFilters(query, parameters);
2738

39+
var countStopwatch = Stopwatch.StartNew();
2840
var count = await query.CountAsync();
41+
countStopwatch.Stop();
42+
43+
// Wall-clock through the first EF round-trip (includes model-build/JIT when cold).
44+
var timeToFirstEfQueryMs = totalStopwatch.Elapsed.TotalMilliseconds;
2945

46+
var toListStopwatch = Stopwatch.StartNew();
3047
var projectRecords = await
3148
query
3249
.Select(
@@ -39,7 +56,9 @@ public class GetProjectSummaryByUserService(MfspContext context) : IGetProjectSu
3956
.OrderByDescending(record => record.Kpi.ProjectStatusProvisionalOpeningDateAgreedWithTrust)
4057
.ThenBy(record => record.Kpi.ProjectStatusCurrentFreeSchoolName)
4158
.ToListAsync();
59+
toListStopwatch.Stop();
4260

61+
var mappingStopwatch = Stopwatch.StartNew();
4362
var result = projectRecords.Select(record => new GetProjectSummaryResponse()
4463
{
4564
ProjectId = record.Kpi.ProjectStatusProjectId,
@@ -57,10 +76,73 @@ public class GetProjectSummaryByUserService(MfspContext context) : IGetProjectSu
5776
SchoolType = ProjectMapper.ToSchoolType(record.Kpi.SchoolDetailsSchoolTypeMainstreamApEtc).ToDescription(),
5877
UpdatedAt = record.PeriodStart
5978
}).ToList();
79+
mappingStopwatch.Stop();
80+
81+
totalStopwatch.Stop();
82+
83+
EmitStageTimings(
84+
isFirstBusinessRequestInProcess,
85+
timeToFirstEfQueryMs,
86+
countStopwatch.Elapsed.TotalMilliseconds,
87+
toListStopwatch.Elapsed.TotalMilliseconds,
88+
mappingStopwatch.Elapsed.TotalMilliseconds,
89+
result.Count,
90+
totalStopwatch.Elapsed.TotalMilliseconds);
6091

6192
return (result, count);
6293
}
6394

95+
private bool ResolveIsFirstBusinessRequest()
96+
{
97+
var httpContext = httpContextAccessor.HttpContext;
98+
if (httpContext?.Items.TryGetValue(ProcessWarmupState.HttpContextItemKey, out var value) == true
99+
&& value is bool markedByMiddleware)
100+
{
101+
return markedByMiddleware;
102+
}
103+
104+
return processWarmupState.MarkBusinessRequest();
105+
}
106+
107+
private void EmitStageTimings(
108+
bool isFirstBusinessRequestInProcess,
109+
double timeToFirstEfQueryMs,
110+
double countAsyncDurationMs,
111+
double toListAsyncDurationMs,
112+
double mappingDurationMs,
113+
int rowCount,
114+
double totalDurationMs)
115+
{
116+
if (!logger.IsEnabled(LogLevel.Information))
117+
{
118+
return;
119+
}
120+
121+
using (logger.BeginScope(new Dictionary<string, object>
122+
{
123+
["EventName"] = StageTimingsEventName,
124+
["IsFirstBusinessRequestInProcess"] = isFirstBusinessRequestInProcess,
125+
["TimeToFirstEfQueryMs"] = timeToFirstEfQueryMs,
126+
["CountAsyncDurationMs"] = countAsyncDurationMs,
127+
["ToListAsyncDurationMs"] = toListAsyncDurationMs,
128+
["MappingDurationMs"] = mappingDurationMs,
129+
["RowCount"] = rowCount,
130+
["TotalDurationMs"] = totalDurationMs
131+
}))
132+
{
133+
logger.LogInformation(
134+
"{EventName}: TimeToFirstEfQuery={TimeToFirstEfQueryMs}ms, CountAsync={CountAsyncDurationMs}ms, ToListAsync={ToListAsyncDurationMs}ms, Mapping={MappingDurationMs}ms, RowCount={RowCount}, IsFirstBusinessRequestInProcess={IsFirstBusinessRequestInProcess}, Total={TotalDurationMs}ms",
135+
StageTimingsEventName,
136+
timeToFirstEfQueryMs,
137+
countAsyncDurationMs,
138+
toListAsyncDurationMs,
139+
mappingDurationMs,
140+
rowCount,
141+
isFirstBusinessRequestInProcess,
142+
totalDurationMs);
143+
}
144+
}
145+
64146
private static IQueryable<Kpi> ApplyFilters(IQueryable<Kpi> query, GetProjectSummaryByUserParameters parameters)
65147
{
66148
query = query.Where(kpi => parameters.ProjectManagedByEmail == kpi.KeyContactsFsgLeadContactEmail);

‎terraform/terraform.tfvars.example‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,8 @@ enable_mssql_database = true
77
mssql_server_admin_password = "S3crEt"
88
mssql_database_name = "mydatabase"
99
container_command = ["/bin/bash", "-c", "echo hello && sleep 86400"]
10+
container_health_probe_path = "/health"
11+
monitor_endpoint_healthcheck = "/health"
1012
container_environment_variables = {
1113
"ASPNETCORE_ENVIRONMENT" = "production"
1214
}

0 commit comments

Comments
 (0)