From f52e2195cf79d3bf82c77ed321de573d5b6ac231 Mon Sep 17 00:00:00 2001 From: Mads Magnus Due Date: Tue, 10 Dec 2024 12:38:57 +0100 Subject: [PATCH 1/2] chore: log incoming message execution time (#1414) --- .../IncomingMessageReceiver.cs | 5 +++++ .../UseCases/ReceiveIncomingMarketMessage.cs | 19 +++++++++++++++++++ 2 files changed, 24 insertions(+) diff --git a/source/B2BApi/IncomingMessages/IncomingMessageReceiver.cs b/source/B2BApi/IncomingMessages/IncomingMessageReceiver.cs index 87ffc8477..77361ee5e 100644 --- a/source/B2BApi/IncomingMessages/IncomingMessageReceiver.cs +++ b/source/B2BApi/IncomingMessages/IncomingMessageReceiver.cs @@ -12,6 +12,7 @@ // See the License for the specific language governing permissions and // limitations under the License. +using System.Diagnostics; using System.Net; using System.Text; using Energinet.DataHub.EDI.AuditLog.AuditLogger; @@ -55,6 +56,7 @@ public async Task RunAsync( CancellationToken hostCancellationToken) { ArgumentNullException.ThrowIfNull(request); + var stopwatch = Stopwatch.StartNew(); var cancellationToken = request.GetCancellationToken(hostCancellationToken); if (!await _featureFlagManager.ReceiveMeteredDataForMeasurementPointsAsync().ConfigureAwait(false)) @@ -113,6 +115,9 @@ public async Task RunAsync( var httpResponseData = await CreateResponseAsync(request, httpStatusCode, documentFormat, responseMessage) .ConfigureAwait(false); + stopwatch.Stop(); + _logger.LogInformation($"IncomingMessage Execution time: {stopwatch.ElapsedMilliseconds} ms"); + return httpResponseData; } diff --git a/source/IncomingMessages.Application/UseCases/ReceiveIncomingMarketMessage.cs b/source/IncomingMessages.Application/UseCases/ReceiveIncomingMarketMessage.cs index bcfe9b900..ca5070ed6 100644 --- a/source/IncomingMessages.Application/UseCases/ReceiveIncomingMarketMessage.cs +++ b/source/IncomingMessages.Application/UseCases/ReceiveIncomingMarketMessage.cs @@ -12,6 +12,7 @@ // See the License for the specific language governing permissions and // limitations under the License. +using System.Diagnostics; using Energinet.DataHub.EDI.ArchivedMessages.Interfaces; using Energinet.DataHub.EDI.ArchivedMessages.Interfaces.Models; using Energinet.DataHub.EDI.BuildingBlocks.Domain.Authentication; @@ -78,12 +79,18 @@ public async Task ReceiveIncomingMarketMessageAsync( { ArgumentNullException.ThrowIfNull(documentType); ArgumentNullException.ThrowIfNull(incomingMarketMessageStream); + var stopwatch = Stopwatch.StartNew(); + var incomingMarketMessageParserResult = await ParseIncomingMessageAsync( incomingMarketMessageStream, incomingDocumentFormat, documentType, cancellationToken) .ConfigureAwait(false); + + stopwatch.Stop(); + _logger.LogInformation($"IncomingMessage Parsing execution time: {stopwatch.ElapsedMilliseconds} ms"); + if (incomingMarketMessageParserResult.Errors.Count != 0 || incomingMarketMessageParserResult.IncomingMessage == null) { @@ -99,21 +106,30 @@ public async Task ReceiveIncomingMarketMessageAsync( if (ShouldArchive(documentType)) { + stopwatch.Restart(); await ArchiveIncomingMessageAsync( incomingMarketMessageStream, incomingMarketMessageParserResult.IncomingMessage, documentType, cancellationToken) .ConfigureAwait(false); + stopwatch.Stop(); + _logger.LogInformation($"IncomingMessage Archiving execution time: {stopwatch.ElapsedMilliseconds} ms"); } + stopwatch.Restart(); await _delegateIncomingMessage .DelegateAsync(incomingMarketMessageParserResult.IncomingMessage, documentType, cancellationToken) .ConfigureAwait(false); + stopwatch.Stop(); + _logger.LogInformation($"IncomingMessage Delegation execution time: {stopwatch.ElapsedMilliseconds} ms"); + stopwatch.Restart(); var validationResult = await _validateIncomingMessage .ValidateAsync(incomingMarketMessageParserResult.IncomingMessage, incomingDocumentFormat, cancellationToken) .ConfigureAwait(false); + stopwatch.Stop(); + _logger.LogInformation($"IncomingMessage Validation execution time: {stopwatch.ElapsedMilliseconds} ms"); if (!validationResult.Success) { @@ -124,11 +140,14 @@ await _delegateIncomingMessage return _responseFactory.From(validationResult, responseDocumentFormat); } + stopwatch.Restart(); var result = await _incomingMessageReceiver .ReceiveAsync( incomingMarketMessageParserResult.IncomingMessage, cancellationToken) .ConfigureAwait(false); + stopwatch.Stop(); + _logger.LogInformation($"IncomingMessage Receiving execution time: {stopwatch.ElapsedMilliseconds} ms"); if (result.Success) { From acb21cb4bdcff611ae9f7a6e94ba888ba28c0f9f Mon Sep 17 00:00:00 2001 From: Mads Magnus Due Date: Tue, 10 Dec 2024 14:32:20 +0100 Subject: [PATCH 2/2] feat: added execution time logging when validating incoming messages (#1417) --- .../UseCases/ValidateIncomingMessage.cs | 27 ++++++++++++++++++- 1 file changed, 26 insertions(+), 1 deletion(-) diff --git a/source/IncomingMessages.Application/UseCases/ValidateIncomingMessage.cs b/source/IncomingMessages.Application/UseCases/ValidateIncomingMessage.cs index 78abacd3f..f54feb791 100644 --- a/source/IncomingMessages.Application/UseCases/ValidateIncomingMessage.cs +++ b/source/IncomingMessages.Application/UseCases/ValidateIncomingMessage.cs @@ -12,12 +12,14 @@ // See the License for the specific language governing permissions and // limitations under the License. +using System.Diagnostics; using Energinet.DataHub.EDI.BuildingBlocks.Domain.Models; using Energinet.DataHub.EDI.IncomingMessages.Domain.Abstractions; using Energinet.DataHub.EDI.IncomingMessages.Domain.Validation; using Energinet.DataHub.EDI.IncomingMessages.Domain.Validation.ValidationErrors; using Energinet.DataHub.EDI.IncomingMessages.Infrastructure.Repositories.MessageId; using Energinet.DataHub.EDI.IncomingMessages.Infrastructure.Repositories.TransactionId; +using Microsoft.Extensions.Logging; namespace Energinet.DataHub.EDI.IncomingMessages.Application.UseCases; @@ -28,7 +30,8 @@ public class ValidateIncomingMessage( IMessageTypeValidator messageTypeValidator, IProcessTypeValidator processTypeValidator, IBusinessTypeValidator businessTypeValidator, - ITransactionIdRepository transactionIdRepository) + ITransactionIdRepository transactionIdRepository, + ILogger logger) { private const int MaxMessageIdLength = 36; private const int MaxTransactionIdLength = 36; @@ -54,8 +57,11 @@ public async Task ValidateAsync( // It is slightly annoying since all we do is FirstOrDefaultAsync which we await. // And read access shouldn't be that much of a problem wrt concurrency. // It is also a bit silly to have this as a separate call, but it works. + var stopwatch = Stopwatch.StartNew(); var transactionIdErrors = await CheckTransactionIdsAsync(incomingMessage, cancellationToken).ConfigureAwait(false); + stopwatch.Stop(); + logger.LogInformation($"ValidateIncomingMessage CheckTransactionIdsAsync execution time: {stopwatch.ElapsedMilliseconds} ms"); var allErrors = errors.Concat(transactionIdErrors).ToArray(); @@ -64,20 +70,26 @@ public async Task ValidateAsync( private async Task> AuthorizeSenderAsync(IIncomingMessage message) { + var stopwatch = Stopwatch.StartNew(); var allSeriesAreDelegated = message.Series.Count > 0 && message.Series.All(s => s.IsDelegated); var result = await senderAuthorizer .AuthorizeAsync(message, allSeriesAreDelegated) .ConfigureAwait(false); + stopwatch.Stop(); + logger.LogInformation($"ValidateIncomingMessage AuthorizeSenderAsync execution time: {stopwatch.ElapsedMilliseconds} ms"); return result.Errors; } private async Task> VerifyReceiverAsync(IIncomingMessage message) { + var stopwatch = Stopwatch.StartNew(); var receiverVerification = await receiverValidator .VerifyAsync(message.ReceiverNumber, message.ReceiverRoleCode) .ConfigureAwait(false); + stopwatch.Stop(); + logger.LogInformation($"ValidateIncomingMessage VerifyReceiverAsync execution time: {stopwatch.ElapsedMilliseconds} ms"); return receiverVerification.Errors; } @@ -86,6 +98,7 @@ private async Task> CheckMessageIdAsync( IIncomingMessage message, CancellationToken cancellationToken) { + var stopwatch = Stopwatch.StartNew(); var errors = new List(); if (string.IsNullOrEmpty(message.MessageId)) @@ -104,6 +117,9 @@ private async Task> CheckMessageIdAsync( errors.Add(new DuplicateMessageIdDetected(message.MessageId)); } + stopwatch.Stop(); + logger.LogInformation($"ValidateIncomingMessage CheckMessageIdAsync execution time: {stopwatch.ElapsedMilliseconds} ms"); + return errors; } @@ -111,8 +127,11 @@ private async Task> CheckMessageTypeAsync( IIncomingMessage message, CancellationToken cancellationToken) { + var stopwatch = Stopwatch.StartNew(); var result = await messageTypeValidator.ValidateAsync(message, cancellationToken) .ConfigureAwait(false); + stopwatch.Stop(); + logger.LogInformation($"ValidateIncomingMessage CheckMessageTypeAsync execution time: {stopwatch.ElapsedMilliseconds} ms"); return result.Errors; } @@ -121,8 +140,11 @@ private async Task> CheckBusinessReasonAsyn DocumentFormat documentFormat, CancellationToken cancellationToken) { + var stopwatch = Stopwatch.StartNew(); var result = await processTypeValidator.ValidateAsync(message, documentFormat, cancellationToken) .ConfigureAwait(false); + stopwatch.Stop(); + logger.LogInformation($"ValidateIncomingMessage CheckBusinessReasonAsync execution time: {stopwatch.ElapsedMilliseconds} ms"); return result.Errors; } @@ -130,8 +152,11 @@ private async Task> CheckBusinessTypeAsync( IIncomingMessage message, CancellationToken cancellationToken) { + var stopwatch = Stopwatch.StartNew(); var result = await businessTypeValidator.ValidateAsync(message.BusinessType, cancellationToken) .ConfigureAwait(false); + stopwatch.Stop(); + logger.LogInformation($"ValidateIncomingMessage CheckBusinessTypeAsync execution time: {stopwatch.ElapsedMilliseconds} ms"); return result.Errors; }