Skip to content

Commit 000607b

Browse files
pmachapmanpmachapman
authored
SF-3612 Capture execution time in event metrics (#3518)
1 parent bbe18df commit 000607b

File tree

10 files changed

+55
-38
lines changed

10 files changed

+55
-38
lines changed

‎src/SIL.XForge.Scripture/ClientApp/src/app/event-metrics/event-metric.ts‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@ export interface EventMetric {
88
scope: EventScope;
99
timeStamp: string;
1010
userId?: string;
11+
executionTime?: string;
1112
}
1213

1314
export enum EventScope {

‎src/SIL.XForge.Scripture/Services/MachineApiService.cs‎

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -779,8 +779,7 @@ await eventMetricService.SaveEventMetricAsync(
779779
nameof(ExecuteWebhookAsync),
780780
EventScope.Drafting,
781781
arguments,
782-
result: buildId,
783-
exception: null
782+
result: buildId
784783
);
785784

786785
// Run the background job

‎src/SIL.XForge.Scripture/Services/SFProjectService.cs‎

Lines changed: 1 addition & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -297,9 +297,7 @@ await _eventMetricService.SaveEventMetricAsync(
297297
curUserId,
298298
nameof(DeleteProjectAsync),
299299
EventScope.Settings,
300-
arguments,
301-
result: null,
302-
exception: null
300+
arguments
303301
);
304302

305303
// Log this to the system log

‎src/SIL.XForge/EventMetrics/EventMetric.cs‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,12 @@ public class EventMetric : IIdentifiable
2424
/// </summary>
2525
public string? Exception { get; set; }
2626

27+
/// <summary>
28+
/// Gets or sets the time it took to execute the method that recorded this metric.
29+
/// </summary>
30+
/// <remarks>This value will not be set if the metric was recorded manually.</remarks>
31+
public TimeSpan? ExecutionTime { get; set; }
32+
2733
/// <summary>
2834
/// Gets or sets the identifier.
2935
/// </summary>

‎src/SIL.XForge/EventMetrics/EventMetricLogger.cs‎

Lines changed: 13 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
using System;
22
using System.Collections.Generic;
3+
using System.Diagnostics;
34
using System.Linq;
45
using System.Reflection;
56
using System.Threading.Tasks;
@@ -57,24 +58,31 @@ is LogEventMetricAttribute logEventMetricAttribute
5758
{
5859
// Invoke the method, then record its event metrics
5960
Task task;
61+
Stopwatch stopwatch = Stopwatch.StartNew();
6062
try
6163
{
6264
invocation.Proceed();
6365
if (invocation.ReturnValue is Task methodTask)
6466
{
6567
// Save the event metric after the task has run
66-
task = methodTask.ContinueWith(t => SaveEventMetricAsync(t.Exception));
68+
task = methodTask.ContinueWith(t =>
69+
{
70+
stopwatch.Stop();
71+
return SaveEventMetricAsync(stopwatch.Elapsed, t.Exception);
72+
});
6773
}
6874
else
6975
{
7076
// Save the event metric in another thread after the method has executed
71-
task = Task.Run(() => SaveEventMetricAsync());
77+
stopwatch.Stop();
78+
task = Task.Run(() => SaveEventMetricAsync(stopwatch.Elapsed));
7279
}
7380
}
7481
catch (Exception e)
7582
{
7683
// Save the error in the event metric, as the Proceed() will have faulted
77-
task = Task.Run(() => SaveEventMetricAsync(e));
84+
stopwatch.Stop();
85+
task = Task.Run(() => SaveEventMetricAsync(stopwatch.Elapsed, e));
7886

7987
// Notify observers of the task of immediate completion
8088
TaskStarted?.Invoke(task);
@@ -89,7 +97,7 @@ is LogEventMetricAttribute logEventMetricAttribute
8997

9098
// Run as a separate task so we do not slow down the method execution
9199
// Unless we want the return value, in which case we will not write the metric until the method returns
92-
async Task SaveEventMetricAsync(Exception? exception = null)
100+
async Task SaveEventMetricAsync(TimeSpan executionTime, Exception? exception = null)
93101
{
94102
string methodName = invocation.Method.Name;
95103
try
@@ -177,6 +185,7 @@ await eventMetricService.SaveEventMetricAsync(
177185
logEventMetricAttribute.Scope,
178186
argumentsWithNames,
179187
result,
188+
executionTime,
180189
exception
181190
);
182191
}

‎src/SIL.XForge/Services/EventMetricService.cs‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -80,8 +80,9 @@ public async Task SaveEventMetricAsync(
8080
string eventType,
8181
EventScope scope,
8282
Dictionary<string, object> argumentsWithNames,
83-
object? result,
84-
Exception? exception
83+
object? result = null,
84+
TimeSpan? executionTime = null,
85+
Exception? exception = null
8586
)
8687
{
8788
// Process the arguments into a MongoDB format for the payload
@@ -97,6 +98,7 @@ public async Task SaveEventMetricAsync(
9798
{
9899
Id = ObjectId.GenerateNewId().ToString(),
99100
EventType = eventType,
101+
ExecutionTime = executionTime,
100102
Payload = payload,
101103
ProjectId = projectId,
102104
Scope = scope,

‎src/SIL.XForge/Services/IEventMetricService.cs‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -22,7 +22,8 @@ Task SaveEventMetricAsync(
2222
string eventType,
2323
EventScope scope,
2424
Dictionary<string, object> argumentsWithNames,
25-
object? result,
26-
Exception? exception
25+
object? result = null,
26+
TimeSpan? executionTime = null,
27+
Exception? exception = null
2728
);
2829
}

‎test/SIL.XForge.Scripture.Tests/Services/SFProjectServiceTests.cs‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2985,6 +2985,7 @@ await env
29852985
EventScope.Settings,
29862986
Arg.Any<Dictionary<string, object>>(),
29872987
Arg.Any<object?>(),
2988+
Arg.Any<TimeSpan?>(),
29882989
Arg.Any<Exception?>()
29892990
);
29902991
Assert.That(env.ContainsProject(Project01), Is.False);
@@ -3016,6 +3017,7 @@ await env
30163017
EventScope.Settings,
30173018
Arg.Any<Dictionary<string, object>>(),
30183019
Arg.Any<object?>(),
3020+
Arg.Any<TimeSpan?>(),
30193021
Arg.Any<Exception?>()
30203022
);
30213023
await env

‎test/SIL.XForge.Tests/Services/EventMetricLoggerTests.cs‎

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -33,6 +33,7 @@ public async Task EventMetrics_ErrorsAreLogged()
3333
EventScope.None,
3434
Arg.Any<Dictionary<string, object>>(),
3535
result: Arg.Any<object>(),
36+
executionTime: Arg.Any<TimeSpan?>(),
3637
exception: Arg.Any<Exception>()
3738
)
3839
.ThrowsAsync(ex);
@@ -83,6 +84,7 @@ await env
8384
scope: EventScope.None,
8485
argumentsWithNames: Arg.Is<Dictionary<string, object>>(a => a.Count == 0),
8586
result: Arg.Any<object>(),
87+
executionTime: Arg.Any<TimeSpan?>(),
8688
exception: Arg.Any<Exception>()
8789
);
8890
Assert.Zero(env.MockLogger.LogEvents.Count);
@@ -108,6 +110,7 @@ await env
108110
scope: EventScope.None,
109111
argumentsWithNames: Arg.Any<Dictionary<string, object>>(),
110112
result: Arg.Any<object>(),
113+
executionTime: Arg.Any<TimeSpan?>(),
111114
exception: Arg.Any<Exception>()
112115
);
113116
Assert.Zero(env.MockLogger.LogEvents.Count);
@@ -140,6 +143,7 @@ await env
140143
env.PayloadEqualityComparer.Equals(a, argumentsWithNames)
141144
),
142145
result: Arg.Any<object>(),
146+
executionTime: Arg.Any<TimeSpan?>(),
143147
exception: Arg.Any<Exception>()
144148
);
145149
Assert.Zero(env.MockLogger.LogEvents.Count);
@@ -172,6 +176,7 @@ await env
172176
env.PayloadEqualityComparer.Equals(a, argumentsWithNames)
173177
),
174178
result: Arg.Any<object>(),
179+
executionTime: Arg.Any<TimeSpan?>(),
175180
exception: Arg.Any<Exception>()
176181
);
177182
Assert.Zero(env.MockLogger.LogEvents.Count);
@@ -204,6 +209,7 @@ await env
204209
env.PayloadEqualityComparer.Equals(a, argumentsWithNames)
205210
),
206211
result: Arg.Any<object>(),
212+
executionTime: Arg.Any<TimeSpan?>(),
207213
exception: Arg.Any<Exception>()
208214
);
209215
Assert.Zero(env.MockLogger.LogEvents.Count);
@@ -236,6 +242,7 @@ await env
236242
env.PayloadEqualityComparer.Equals(a, argumentsWithNames)
237243
),
238244
result: Arg.Any<object>(),
245+
executionTime: Arg.Any<TimeSpan?>(),
239246
exception: Arg.Any<Exception>()
240247
);
241248
Assert.Zero(env.MockLogger.LogEvents.Count);
@@ -279,6 +286,7 @@ await env
279286
env.PayloadEqualityComparer.Equals(a, argumentsWithNames)
280287
),
281288
result: Arg.Any<object>(),
289+
executionTime: Arg.Any<TimeSpan?>(),
282290
exception: Arg.Any<Exception>()
283291
);
284292
Assert.Zero(env.MockLogger.LogEvents.Count);
@@ -340,6 +348,7 @@ await env
340348
env.PayloadEqualityComparer.Equals(a, argumentsWithNames)
341349
),
342350
result: Arg.Any<object>(),
351+
executionTime: Arg.Any<TimeSpan?>(),
343352
exception: Arg.Any<Exception>()
344353
);
345354
Assert.Zero(env.MockLogger.LogEvents.Count);
@@ -372,6 +381,7 @@ await env
372381
env.PayloadEqualityComparer.Equals(a, argumentsWithNames)
373382
),
374383
result: Arg.Any<object>(),
384+
executionTime: Arg.Any<TimeSpan?>(),
375385
exception: Arg.Any<Exception>()
376386
);
377387
Assert.Zero(env.MockLogger.LogEvents.Count);
@@ -405,6 +415,7 @@ await env
405415
env.PayloadEqualityComparer.Equals(a, argumentsWithNames)
406416
),
407417
result: expected,
418+
executionTime: Arg.Any<TimeSpan?>(),
408419
exception: Arg.Any<Exception>()
409420
);
410421
Assert.Zero(env.MockLogger.LogEvents.Count);
@@ -436,6 +447,7 @@ await env
436447
env.PayloadEqualityComparer.Equals(a, argumentsWithNames)
437448
),
438449
result: Arg.Any<object>(),
450+
executionTime: Arg.Any<TimeSpan?>(),
439451
exception: Arg.Any<Exception>()
440452
);
441453
Assert.Zero(env.MockLogger.LogEvents.Count);
@@ -469,6 +481,7 @@ await env
469481
env.PayloadEqualityComparer.Equals(a, argumentsWithNames)
470482
),
471483
result: expected,
484+
executionTime: Arg.Any<TimeSpan?>(),
472485
exception: Arg.Any<Exception>()
473486
);
474487
Assert.Zero(env.MockLogger.LogEvents.Count);
@@ -509,6 +522,7 @@ await env
509522
env.PayloadEqualityComparer.Equals(a, argumentsWithNames)
510523
),
511524
result: Arg.Any<object>(),
525+
executionTime: Arg.Any<TimeSpan?>(),
512526
exception: Arg.Is<ArgumentException>(e => e.ParamName == exceptionParamName)
513527
);
514528
Assert.Zero(env.MockLogger.LogEvents.Count);
@@ -549,6 +563,7 @@ await env
549563
env.PayloadEqualityComparer.Equals(a, argumentsWithNames)
550564
),
551565
result: Arg.Any<object>(),
566+
executionTime: Arg.Any<TimeSpan?>(),
552567
exception: Arg.Any<Exception>()
553568
);
554569
Assert.Zero(env.MockLogger.LogEvents.Count);
@@ -589,6 +604,7 @@ await env
589604
env.PayloadEqualityComparer.Equals(a, argumentsWithNames)
590605
),
591606
result: Arg.Any<object>(),
607+
executionTime: Arg.Any<TimeSpan?>(),
592608
exception: Arg.Any<Exception>()
593609
);
594610
Assert.Zero(env.MockLogger.LogEvents.Count);

‎test/SIL.XForge.Tests/Services/EventMetricServiceTests.cs‎

Lines changed: 8 additions & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -166,9 +166,7 @@ await env.Service.SaveEventMetricAsync(
166166
userId: null,
167167
EventType01,
168168
EventScope01,
169-
argumentsWithNames: [],
170-
result: null,
171-
exception: null
169+
argumentsWithNames: []
172170
);
173171

174172
// Verify the saved event metric
@@ -205,8 +203,7 @@ await env.Service.SaveEventMetricAsync(
205203
EventType01,
206204
EventScope01,
207205
argumentsWithNames,
208-
result,
209-
exception: null
206+
result
210207
);
211208

212209
// Verify the saved event metric
@@ -246,6 +243,7 @@ public async Task SaveEventMetricAsync_ComplexObjectAndThrowsException()
246243
{
247244
{ "complexObject", complexObjectBson },
248245
};
246+
TimeSpan expectedExecutionTime = new TimeSpan(0, 0, 0, 1, 2, 3);
249247
var exception = new InvalidOperationException("A test error occurred");
250248
string expectedException = exception.ToString();
251249

@@ -257,6 +255,7 @@ await env.Service.SaveEventMetricAsync(
257255
EventScope01,
258256
argumentsWithNames,
259257
complexObject,
258+
expectedExecutionTime,
260259
exception
261260
);
262261

@@ -269,6 +268,7 @@ await env.Service.SaveEventMetricAsync(
269268
Assert.IsTrue(env.PayloadEqualityComparer.Equals(expectedPayload, eventMetric.Payload));
270269
Assert.AreEqual(complexObjectBson, eventMetric.Result);
271270
Assert.AreEqual(expectedException, eventMetric.Exception);
271+
Assert.AreEqual(expectedExecutionTime, eventMetric.ExecutionTime);
272272
}
273273

274274
[Test]
@@ -324,8 +324,7 @@ await env.Service.SaveEventMetricAsync(
324324
EventType01,
325325
EventScope01,
326326
argumentsWithNames,
327-
result,
328-
exception: null
327+
result
329328
);
330329

331330
// Verify the saved event metric
@@ -355,15 +354,7 @@ public async Task SaveEventMetricAsync_DoNotSaveCancellationToken()
355354
};
356355

357356
// SUT
358-
await env.Service.SaveEventMetricAsync(
359-
Project01,
360-
User01,
361-
EventType01,
362-
EventScope01,
363-
argumentsWithNames,
364-
result: null,
365-
exception: null
366-
);
357+
await env.Service.SaveEventMetricAsync(Project01, User01, EventType01, EventScope01, argumentsWithNames);
367358

368359
// Verify the saved event metric
369360
EventMetric eventMetric = env.EventMetrics.Query().OrderByDescending(e => e.TimeStamp).First();
@@ -388,15 +379,7 @@ public async Task SaveEventMetricAsync_ArraysOfObjects()
388379
};
389380

390381
// SUT
391-
await env.Service.SaveEventMetricAsync(
392-
Project01,
393-
User01,
394-
EventType01,
395-
EventScope01,
396-
argumentsWithNames,
397-
result: null,
398-
exception: null
399-
);
382+
await env.Service.SaveEventMetricAsync(Project01, User01, EventType01, EventScope01, argumentsWithNames);
400383

401384
// Verify the saved event metric
402385
EventMetric eventMetric = env.EventMetrics.Query().OrderByDescending(e => e.TimeStamp).First();

0 commit comments

Comments
 (0)