Skip to content

Commit 4f38789

Browse files
author
Bart Koelman
committed
Instrumented code to measure execution time of the various layers
Example output: ``` JsonApiDotNetCoreExample.Startups.Startup: Warning: Measurement results for application startup: Configure other (startup): 0:00:00:00.0020100 - 0.14 % Configure JSON:API (startup): 0:00:00:01.4332855 - 99.86 % Initialize other (startup): 0:00:00:01.3046733 - 99.44 % (active) Initialize JSON:API (startup): 0:00:00:00.0073500 - 0.56 % JsonApiDotNetCore.Middleware.JsonApiMiddleware: Warning: Measurement results for http://localhost:14140/api/v1/todoItems?include=owner,assignee,tags: JSON:API middleware: 0:00:00:00.0001358 - 0.83 % Other middleware: 0:00:00:00.0011143 - 6.77 % Parse query string: 0:00:00:00.0001583 - 0.96 % Service - Get resources: 0:00:00:00.0004503 - 2.74 % Repository - Count resources: 0:00:00:00.0000099 - 0.06 % Build EF Core query: 0:00:00:00.0004315 - 2.62 % Execute SQL (count): 0:00:00:00.0053052 - 32.23 % Top-level query composition: 0:00:00:00.0002587 - 1.57 % Nested query composition: 0:00:00:00.0000574 - 0.35 % Repository - Get resource(s): 0:00:00:00.0000040 - 0.02 % Build EF Core query: 0:00:00:00.0006049 - 3.67 % Execute SQL (data): 0:00:00:00.0046698 - 28.37 % Serialize response body: 0:00:00:00.0013063 - 7.94 % Serializer.Build (list): 0:00:00:00.0012979 - 7.89 % Newtonsoft.Serialize: 0:00:00:00.0006558 - 3.98 % ```
1 parent 54775fb commit 4f38789

File tree

25 files changed

+1276
-477
lines changed

25 files changed

+1276
-477
lines changed

src/Examples/JsonApiDotNetCoreExample/Startups/EmptyStartup.cs

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
using Microsoft.AspNetCore.Builder;
22
using Microsoft.AspNetCore.Hosting;
33
using Microsoft.Extensions.DependencyInjection;
4+
using Microsoft.Extensions.Logging;
45

56
namespace JsonApiDotNetCoreExample.Startups
67
{
@@ -14,7 +15,7 @@ public virtual void ConfigureServices(IServiceCollection services)
1415
{
1516
}
1617

17-
public virtual void Configure(IApplicationBuilder app, IWebHostEnvironment environment)
18+
public virtual void Configure(IApplicationBuilder app, IWebHostEnvironment environment, ILoggerFactory loggerFactory)
1819
{
1920
}
2021
}
Lines changed: 114 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -1,12 +1,16 @@
11
using System;
2+
using System.Collections.Generic;
23
using JsonApiDotNetCore.Configuration;
4+
using JsonApiDotNetCore.Diagnostics;
35
using JsonApiDotNetCoreExample.Data;
6+
using JsonApiDotNetCoreExample.Models;
47
using Microsoft.AspNetCore.Authentication;
58
using Microsoft.AspNetCore.Builder;
69
using Microsoft.AspNetCore.Hosting;
710
using Microsoft.EntityFrameworkCore;
811
using Microsoft.Extensions.Configuration;
912
using Microsoft.Extensions.DependencyInjection;
13+
using Microsoft.Extensions.Logging;
1014
using Newtonsoft.Json;
1115
using Newtonsoft.Json.Converters;
1216

@@ -15,53 +19,139 @@ namespace JsonApiDotNetCoreExample.Startups
1519
public sealed class Startup : EmptyStartup
1620
{
1721
private readonly string _connectionString;
22+
private readonly ICodeTimerSession _codeTimingSession;
1823

1924
public Startup(IConfiguration configuration)
2025
{
26+
_codeTimingSession = new DefaultCodeTimerSession();
27+
CodeTimingSessionManager.Capture(_codeTimingSession);
28+
2129
string postgresPassword = Environment.GetEnvironmentVariable("PGPASSWORD") ?? "postgres";
2230
_connectionString = configuration["Data:DefaultConnection"].Replace("###", postgresPassword);
2331
}
2432

2533
// This method gets called by the runtime. Use this method to add services to the container.
2634
public override void ConfigureServices(IServiceCollection services)
2735
{
28-
services.AddSingleton<ISystemClock, SystemClock>();
29-
30-
services.AddDbContext<AppDbContext>(options =>
36+
using (CodeTimingSessionManager.Current.Measure("Configure other (startup)"))
3137
{
32-
options.UseNpgsql(_connectionString);
38+
services.AddSingleton<ISystemClock, SystemClock>();
39+
40+
services.AddDbContext<AppDbContext>(options =>
41+
{
42+
options.UseNpgsql(_connectionString);
3343
#if DEBUG
34-
options.EnableSensitiveDataLogging();
35-
options.EnableDetailedErrors();
44+
options.EnableSensitiveDataLogging();
45+
options.EnableDetailedErrors();
3646
#endif
37-
});
47+
});
3848

39-
services.AddJsonApi<AppDbContext>(options =>
40-
{
41-
options.Namespace = "api/v1";
42-
options.UseRelativeLinks = true;
43-
options.ValidateModelState = true;
44-
options.IncludeTotalResourceCount = true;
45-
options.SerializerSettings.Formatting = Formatting.Indented;
46-
options.SerializerSettings.Converters.Add(new StringEnumConverter());
49+
using (CodeTimingSessionManager.Current.Measure("Configure JSON:API (startup)"))
50+
{
51+
services.AddJsonApi<AppDbContext>(options =>
52+
{
53+
options.Namespace = "api/v1";
54+
options.UseRelativeLinks = true;
55+
options.ValidateModelState = true;
56+
options.IncludeTotalResourceCount = true;
57+
options.SerializerSettings.Formatting = Formatting.Indented;
58+
options.SerializerSettings.Converters.Add(new StringEnumConverter());
4759
#if DEBUG
48-
options.IncludeExceptionStackTraceInErrors = true;
60+
options.IncludeExceptionStackTraceInErrors = true;
4961
#endif
50-
}, discovery => discovery.AddCurrentAssembly());
62+
}, discovery => discovery.AddCurrentAssembly());
63+
}
64+
}
5165
}
5266

5367
// This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
54-
public override void Configure(IApplicationBuilder app, IWebHostEnvironment environment)
68+
public override void Configure(IApplicationBuilder app, IWebHostEnvironment environment, ILoggerFactory loggerFactory)
5569
{
56-
using (IServiceScope scope = app.ApplicationServices.CreateScope())
70+
using (CodeTimingSessionManager.Current.Measure("Initialize other (startup)"))
71+
{
72+
ILogger<Startup> logger = loggerFactory.CreateLogger<Startup>();
73+
74+
CreateTestData(app);
75+
76+
app.UseRouting();
77+
78+
using (CodeTimingSessionManager.Current.Measure("Initialize JSON:API (startup)"))
79+
{
80+
app.UseJsonApi();
81+
}
82+
83+
app.UseEndpoints(endpoints => endpoints.MapControllers());
84+
85+
string result = CodeTimingSessionManager.Current.GetResult();
86+
logger.LogWarning($"Measurement results for application startup:{Environment.NewLine}{result}");
87+
}
88+
89+
_codeTimingSession.Dispose();
90+
}
91+
92+
private static void CreateTestData(IApplicationBuilder app)
93+
{
94+
using IServiceScope scope = app.ApplicationServices.CreateScope();
95+
96+
var appDbContext = scope.ServiceProvider.GetRequiredService<AppDbContext>();
97+
98+
appDbContext.Database.EnsureDeleted();
99+
appDbContext.Database.EnsureCreated();
100+
101+
var tags = new List<Tag>
102+
{
103+
new Tag
104+
{
105+
Name = "Personal"
106+
},
107+
new Tag
108+
{
109+
Name = "Family"
110+
},
111+
new Tag
112+
{
113+
Name = "Work"
114+
}
115+
};
116+
117+
var owner = new Person
118+
{
119+
FirstName = "John",
120+
LastName = "Doe"
121+
};
122+
123+
var assignee = new Person
124+
{
125+
FirstName = "Jane",
126+
LastName = "Doe"
127+
};
128+
129+
for (int index = 0; index < 20; index++)
57130
{
58-
var appDbContext = scope.ServiceProvider.GetRequiredService<AppDbContext>();
59-
appDbContext.Database.EnsureCreated();
131+
appDbContext.TodoItems.Add(new TodoItem
132+
{
133+
Description = $"Task {index + 1}",
134+
Owner = owner,
135+
Assignee = assignee,
136+
TodoItemTags = new HashSet<TodoItemTag>
137+
{
138+
new TodoItemTag
139+
{
140+
Tag = tags[0]
141+
},
142+
new TodoItemTag
143+
{
144+
Tag = tags[1]
145+
},
146+
new TodoItemTag
147+
{
148+
Tag = tags[2]
149+
}
150+
}
151+
});
60152
}
61153

62-
app.UseRouting();
63-
app.UseJsonApi();
64-
app.UseEndpoints(endpoints => endpoints.MapControllers());
154+
appDbContext.SaveChanges();
65155
}
66156
}
67157
}
Lines changed: 83 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,83 @@
1+
using System;
2+
using JetBrains.Annotations;
3+
using Microsoft.AspNetCore.Http;
4+
5+
namespace JsonApiDotNetCore.Diagnostics
6+
{
7+
/// <summary>
8+
/// Code timing session management intended for use in ASP.NET Web Applications. Uses <see cref="HttpContext.Items" /> to isolate concurrent requests.
9+
/// Can be used with async/wait, but it cannot distinguish between concurrently running threads within a single HTTP request, so you'll need to pass an
10+
/// <see cref="CascadingCodeTimer" /> instance through the entire call chain in that case.
11+
/// </summary>
12+
[PublicAPI]
13+
public sealed class AspNetCodeTimerSession : ICodeTimerSession
14+
{
15+
private const string HttpContextItemKey = "CascadingCodeTimer:Session";
16+
17+
private readonly HttpContext _httpContext;
18+
private readonly IHttpContextAccessor _httpContextAccessor;
19+
20+
public ICodeTimer CodeTimer
21+
{
22+
get
23+
{
24+
HttpContext httpContext = GetHttpContext();
25+
var codeTimer = (ICodeTimer)httpContext.Items[HttpContextItemKey];
26+
27+
if (codeTimer == null)
28+
{
29+
codeTimer = new CascadingCodeTimer();
30+
httpContext.Items[HttpContextItemKey] = codeTimer;
31+
}
32+
33+
return codeTimer;
34+
}
35+
}
36+
37+
public event EventHandler Disposed;
38+
39+
public AspNetCodeTimerSession(IHttpContextAccessor httpContextAccessor)
40+
{
41+
ArgumentGuard.NotNull(httpContextAccessor, nameof(httpContextAccessor));
42+
43+
_httpContextAccessor = httpContextAccessor;
44+
}
45+
46+
public AspNetCodeTimerSession(HttpContext httpContext)
47+
{
48+
ArgumentGuard.NotNull(httpContext, nameof(httpContext));
49+
50+
_httpContext = httpContext;
51+
}
52+
53+
public void Dispose()
54+
{
55+
HttpContext httpContext = TryGetHttpContext();
56+
var codeTimer = (ICodeTimer)httpContext?.Items[HttpContextItemKey];
57+
58+
if (codeTimer != null)
59+
{
60+
codeTimer.Dispose();
61+
httpContext.Items[HttpContextItemKey] = null;
62+
}
63+
64+
OnDisposed();
65+
}
66+
67+
private void OnDisposed()
68+
{
69+
Disposed?.Invoke(this, EventArgs.Empty);
70+
}
71+
72+
private HttpContext GetHttpContext()
73+
{
74+
HttpContext httpContext = TryGetHttpContext();
75+
return httpContext ?? throw new InvalidOperationException("An active HTTP request is required.");
76+
}
77+
78+
private HttpContext TryGetHttpContext()
79+
{
80+
return _httpContext ?? _httpContextAccessor?.HttpContext;
81+
}
82+
}
83+
}

0 commit comments

Comments
 (0)