Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: add duration measurement io dependency measurement #285

Merged
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 4 additions & 4 deletions docs/preview/02-Features/writing-different-telemetry-types.md
Original file line number Diff line number Diff line change
Expand Up @@ -354,14 +354,14 @@ logger.LogDependency("SendGrid", dependencyData, isSuccessful: true, startTime:

#### Making it easier to measure dependencies

By using `DependencyMeasurement.Start()` we take care of the measuring aspect:
By using `DurationMeasurement.Start()` we take care of the measuring aspect:

```csharp
using Arcus.Observability.Telemetry.Core;
using Microsoft.Extensions.Logging;

// Start measuring
using (var measurement = DependencyMeasurement.Start(dependencyData: "Call_SendGrid"))
using (var measurement = DurationMeasurement.Start())
{
// Do Action

Expand Down Expand Up @@ -397,7 +397,7 @@ catch (Exception exception)

#### Making it easier to measure requests

By using `RequestMeasurement.Start()` we take care of the measuring aspect:
By using `DurationMeasurement.Start()` we take care of the measuring aspect:

```csharp
using Arcus.Observability.Telemetry.Core;
Expand All @@ -408,7 +408,7 @@ HttpRequest request = ...
HttpResponse response = ...

// Start measuring
using (var measurement = RequestMeasurement.Start())
using (var measurement = DurationMeasurement.Start())
{
// Process message

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@
<GenerateDocumentationFile>true</GenerateDocumentationFile>
<AssemblyName>Arcus.Observability.Telemetry.AspNetCore</AssemblyName>
<RootNamespace>Arcus.Observability.Telemetry.AspNetCore</RootNamespace>
<NoWarn>NU5048;NU5125</NoWarn>
</PropertyGroup>

<ItemGroup Condition="'$(TargetFramework)' == 'netstandard2.1'">
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@
<GenerateDocumentationFile>true</GenerateDocumentationFile>
<AssemblyName>Arcus.Observability.Telemetry.Core</AssemblyName>
<RootNamespace>Arcus.Observability.Telemetry.Core</RootNamespace>
<NoWarn>NU5048;NU5125</NoWarn>
</PropertyGroup>

<ItemGroup>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@ namespace Arcus.Observability.Telemetry.Core
/// <summary>
/// Represents an instance to measure easily dependencies in an application.
/// </summary>
[Obsolete("Use " + nameof(DurationMeasurement) + " instead to track the duration of the telemetry")]
public class DependencyMeasurement : IDisposable
{
private readonly Stopwatch _stopwatch;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -4,13 +4,13 @@
namespace Arcus.Observability.Telemetry.Core
{
/// <summary>
/// Represents an instance to measure easily requests in an application.
/// Represents an instance to measure easily telemetry in an application.
/// </summary>
public class RequestMeasurement : IDisposable
public class DurationMeasurement : IDisposable
{
private readonly Stopwatch _stopwatch;

private RequestMeasurement()
private DurationMeasurement()
{
_stopwatch = Stopwatch.StartNew();
StartTime = DateTimeOffset.UtcNow;
Expand All @@ -19,18 +19,18 @@ private RequestMeasurement()
/// <summary>
/// Starts measuring a request until the measurement is disposed.
/// </summary>
public static RequestMeasurement Start()
public static DurationMeasurement Start()
{
return new RequestMeasurement();
return new DurationMeasurement();
}

/// <summary>
/// Gets the time when the request measurement was started.
/// Gets the time when the measurement was started.
/// </summary>
public DateTimeOffset StartTime { get; }

/// <summary>
/// Gets the total elapsed time measured for the request.
/// Gets the total elapsed time measured for the telemetry.
/// </summary>
public TimeSpan Elapsed => _stopwatch.Elapsed;

Expand Down
662 changes: 587 additions & 75 deletions src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerExtensions.cs

Large diffs are not rendered by default.

Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,7 @@ public static class ILoggerExtensions
/// <param name="isSuccessful">Indication whether or not the operation was successful</param>
/// <param name="measurement">Measuring the latency to call the dependency</param>
/// <param name="context">Context that provides more insights on the dependency that was measured</param>
[Obsolete("Use the overload with " + nameof(DurationMeasurement) + " instead to track IoT Hub dependencies")]
public static void LogIotHubDependency(this ILogger logger, string iotHubConnectionString, bool isSuccessful, DependencyMeasurement measurement, Dictionary<string, object> context = null)
{
Guard.NotNull(logger, nameof(logger));
Expand All @@ -30,18 +31,54 @@ public static void LogIotHubDependency(this ILogger logger, string iotHubConnect
}

/// <summary>
/// Logs an Azure Iot Hub Dependency.
/// Logs an Azure Iot Hub Dependency.
/// </summary>
/// <param name="logger">Logger to use</param>
/// <param name="iotHubConnectionString">Name of the Event Hub resource</param>
/// <param name="isSuccessful">Indication whether or not the operation was successful</param>
/// <param name="startTime">Point in time when the interaction with the dependency was started</param>
/// <param name="duration">Duration of the operation</param>
/// <param name="context">Context that provides more insights on the dependency that was measured</param>
public static void LogIotHubDependency(this ILogger logger, string iotHubConnectionString, bool isSuccessful, DateTimeOffset startTime, TimeSpan duration, Dictionary<string, object> context = null)
/// <param name="logger">The logger instance to track the IoT Hub dependency.</param>
/// <param name="iotHubConnectionString">The connection string to interact with an IoT Hub resource.</param>
/// <param name="isSuccessful">The indication whether or not the operation was successful.</param>
/// <param name="measurement">The measuring the latency to call the dependency.</param>
/// <param name="context">The context that provides more insights on the dependency that was measured.</param>
/// <exception cref="ArgumentNullException">Thrown when the <paramref name="logger"/> is <c>null</c>.</exception>
/// <exception cref="ArgumentException">Thrown when the <paramref name="iotHubConnectionString"/> is blank or is invalid.</exception>
/// <exception cref="FormatException">Thrown when the <paramref name="iotHubConnectionString"/> is invalid.</exception>
public static void LogIotHubDependency(
this ILogger logger,
string iotHubConnectionString,
bool isSuccessful,
DurationMeasurement measurement,
Dictionary<string, object> context = null)
{
Guard.NotNull(logger, nameof(logger));
Guard.NotNullOrWhitespace(iotHubConnectionString, nameof(iotHubConnectionString));
Guard.NotNull(logger, nameof(logger), "Requires an logger instance to track the IoT Hub dependency");
Guard.NotNullOrWhitespace(iotHubConnectionString, nameof(iotHubConnectionString), "Requires an IoT Hub connection string to retrieve the IoT host name to track the IoT Hub dependency");
Guard.NotNull(measurement, nameof(measurement), "Requires an measurement instance to measure the duration of interaction with the IoT Hub dependency");

context = context ?? new Dictionary<string, object>();

LogIotHubDependency(logger, iotHubConnectionString, isSuccessful, measurement.StartTime, measurement.Elapsed, context);
}

/// <summary>
/// Logs an Azure Iot Hub Dependency.
/// </summary>
/// <param name="logger">The logger instance to track the IoT Hub dependency.</param>
/// <param name="iotHubConnectionString">The connection string to interact with an IoT Hub resource.</param>
/// <param name="isSuccessful">The indication whether or not the operation was successful.</param>
/// <param name="startTime">The point in time when the interaction with the dependency was started.</param>
/// <param name="duration">The duration of the operation.</param>
/// <param name="context">The context that provides more insights on the dependency that was measured.</param>
/// <exception cref="ArgumentNullException">Thrown when the <paramref name="logger"/> is <c>null</c>.</exception>
/// <exception cref="ArgumentException">Thrown when the <paramref name="iotHubConnectionString"/> is blank or is invalid.</exception>
/// <exception cref="FormatException">Thrown when the <paramref name="iotHubConnectionString"/> is invalid.</exception>
public static void LogIotHubDependency(
this ILogger logger,
string iotHubConnectionString,
bool isSuccessful,
DateTimeOffset startTime,
TimeSpan duration,
Dictionary<string, object> context = null)
{
Guard.NotNull(logger, nameof(logger), "Requires an logger instance to track the IoT Hub dependency");
Guard.NotNullOrWhitespace(iotHubConnectionString, nameof(iotHubConnectionString), "Requires an IoT Hub connection string to retrieve the IoT host name to track the IoT Hub dependency");

context = context ?? new Dictionary<string, object>();

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@
<GenerateDocumentationFile>true</GenerateDocumentationFile>
<AssemblyName>Arcus.Observability.Telemetry.Sql</AssemblyName>
<RootNamespace>Arcus.Observability.Telemetry.Sql</RootNamespace>
<NoWarn>NU5048;NU5125</NoWarn>
</PropertyGroup>

<ItemGroup>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -23,7 +23,15 @@ public static class ILoggerExtensions
/// <param name="isSuccessful">Indication whether or not the operation was successful</param>
/// <param name="measurement">Measuring the latency to call the SQL dependency</param>
/// <param name="context">Context that provides more insights on the dependency that was measured</param>
public static void LogSqlDependency(this ILogger logger, string connectionString, string tableName, string operationName, DependencyMeasurement measurement, bool isSuccessful, Dictionary<string, object> context = null)
[Obsolete("Use the overload with " + nameof(DurationMeasurement) + " instead to track a SQL dependency")]
public static void LogSqlDependency(
this ILogger logger,
string connectionString,
string tableName,
string operationName,
DependencyMeasurement measurement,
bool isSuccessful,
Dictionary<string, object> context = null)
{
Guard.NotNull(logger, nameof(logger));
Guard.NotNull(measurement, nameof(measurement));
Expand All @@ -32,21 +40,62 @@ public static void LogSqlDependency(this ILogger logger, string connectionString
}

/// <summary>
/// Logs a SQL dependency
/// Logs a SQL dependency.
/// </summary>
/// <param name="logger">The logger instance to track the SQL dependency.</param>
/// <param name="connectionString">The SQL connection string.</param>
/// <param name="tableName">The name of tracked table in the SQL database.</param>
/// <param name="operationName">The name of the operation that was performed on the SQL database.</param>
/// <param name="isSuccessful">The indication whether or not the operation was successful.</param>
/// <param name="measurement">The measuring the latency to call the SQL dependency.</param>
/// <param name="context">The context that provides more insights on the dependency that was measured.</param>
/// <exception cref="ArgumentNullException">Thrown when the <paramref name="logger"/> or the <paramref name="measurement"/> is <c>null</c>.</exception>
/// <exception cref="ArgumentException">Thrown when the <paramref name="tableName"/> or <paramref name="operationName"/> is blank.</exception>
public static void LogSqlDependency(
this ILogger logger,
string connectionString,
string tableName,
string operationName,
bool isSuccessful,
DurationMeasurement measurement,
Dictionary<string, object> context = null)
{
Guard.NotNull(logger, nameof(logger), "Requires a logger instance to track telemetry");
Guard.NotNullOrWhitespace(tableName, nameof(tableName), "Requires a non-blank SQL table name to track a SQL dependency");
Guard.NotNullOrWhitespace(operationName, nameof(operationName), "Requires a non-blank name of the SQL operation to track a SQL dependency");
Guard.NotNull(measurement, nameof(measurement));

LogSqlDependency(logger, connectionString, tableName, operationName, measurement.StartTime, measurement.Elapsed, isSuccessful, context);
}

/// <summary>
/// Logs a SQL dependency
/// </summary>
/// <param name="logger">Logger to use</param>
/// <param name="connectionString">SQL connection string</param>
/// <param name="tableName">Name of table</param>
/// <param name="operationName">Name of the operation that was performed</param>
/// <param name="startTime">Point in time when the interaction with the HTTP dependency was started</param>
/// <param name="duration">Duration of the operation</param>
/// <param name="isSuccessful">Indication whether or not the operation was successful</param>
/// <param name="context">Context that provides more insights on the dependency that was measured</param>
public static void LogSqlDependency(this ILogger logger, string connectionString, string tableName, string operationName, DateTimeOffset startTime, TimeSpan duration, bool isSuccessful, Dictionary<string, object> context = null)
/// <param name="logger">The logger to track the SQL dependency.</param>
/// <param name="connectionString">The SQL connection string.</param>
/// <param name="tableName">The name of tracked table in the SQL database.</param>
/// <param name="operationName">The name of the operation that was performed on the SQL database.</param>
/// <param name="startTime">The point in time when the interaction with the HTTP dependency was started</param>
/// <param name="duration">The duration of the operation</param>
/// <param name="isSuccessful">The indication whether or not the operation was successful.</param>
/// <param name="context">The context that provides more insights on the dependency that was measured.</param>
/// <exception cref="ArgumentNullException">Thrown when the <paramref name="logger"/> is <c>null</c>.</exception>
/// <exception cref="ArgumentException">Thrown when the <paramref name="tableName"/> or <paramref name="operationName"/> is blank.</exception>
public static void LogSqlDependency(
this ILogger logger,
string connectionString,
string tableName,
string operationName,
DateTimeOffset startTime,
TimeSpan duration,
bool isSuccessful,
Dictionary<string, object> context = null)
{
Guard.NotNull(logger, nameof(logger), "Requires a logger instance to track telemetry");
Guard.NotNullOrEmpty(connectionString, nameof(connectionString));
var connection = new SqlConnectionStringBuilder(connectionString);
Guard.NotNullOrWhitespace(operationName, nameof(operationName), "Requires a non-blank name of the SQL operation to track a SQL dependency");
fgheysels marked this conversation as resolved.
Show resolved Hide resolved

var connection = new SqlConnectionStringBuilder(connectionString);
logger.LogSqlDependency(connection.DataSource, connection.InitialCatalog, tableName, operationName, isSuccessful, startTime, duration, context);
}
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -35,7 +35,7 @@ public static DependencyLogEntry GetMessageAsDependency(this TestLogger logger)
"Cannot parse the written message as a telemetry dependency because no log message was written to this test logger");
}

const string pattern = @"^(?<dependencytype>[\w\s]+) (?<dependencyname>[\w\.\/\/:]+) (?<dependencydata>[\w\s\-]+) named (?<targetname>[\w\s\.\/\/:]+) with ID (?<dependencyid>[\w\s\-]*) in (?<duration>(\d{1}\.)?\d{2}:\d{2}:\d{2}\.\d{7}) at (?<starttime>\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.\d{7} \+\d{2}:\d{2}) \(IsSuccessful: (?<issuccessful>(True|False)) - ResultCode: (?<resultcode>\d*) - Context: \{(?<context>((\[\w+, \w+\])(; \[[\w\-]+, \w+\])*))\}\)$";
const string pattern = @"^(?<dependencytype>[\w\s]+) (?<dependencyname>[\w\.\/\/:\-]+)? (?<dependencydata>[\w\s\-\,\/]+)? named (?<targetname>[\w\s\.\/\/:\-]+)? with ID (?<dependencyid>[\w\s\-]*)? in (?<duration>(\d{1}\.)?\d{2}:\d{2}:\d{2}\.\d{7}) at (?<starttime>\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.\d{7} \+\d{2}:\d{2}) \(IsSuccessful: (?<issuccessful>(True|False)) - ResultCode: (?<resultcode>\d*) - Context: \{(?<context>((\[\w+, \w+\])(; \[[\w\-]+, \w+\])*))\}\)$";
Match match = Regex.Match(logger.WrittenMessage, pattern);

string dependencyType = match.GetGroupValue("dependencytype");
Expand Down Expand Up @@ -128,8 +128,7 @@ private static string GetGroupValue(this Match match, string name)
match.Groups.TryGetValue(name, out Group group),
$"Cannot find {name} in logged message");

string value = Assert.Single(@group.Captures).Value;
return value;
return group.Captures.FirstOrDefault()?.Value;
}

private static double GetGroupValueAsDouble(this Match match, string name)
Expand Down
Loading