Performance logging for calls to external services (#307)

* added Microsoft.Extensions.Logging.Abstractions dependency * added ILoggerExtensions class used for time tracking * added System.Linq.Async needed in ILogger.TraceTimeAsyncEnumeration * added custom method to log the time needed to complete the FindAllAsync * _logger used to trace time for all awaited calls * removed leftover comment * all awaited calls in EventBus methods wrapped in time tracing _logger statements * tracing the time needed to complete the datawallet modification * Console.WriteLine() statement removed * removed an unnecessary TraceTime() statement * removed TraceTimeAsyncEnumeration() method and its calls * time logged for the whole UploadChangedBlobs() method * saving changes async time elapsed logging (hopefully with latency) * fixing formatting issues * removed redundant logging for blob storage operations * extracted DEBUG_PERFORMANCE into a separate static class * adding interceptors only if DEBUG_PERFORMANCE var is set * Upgrade Helm chart for Consumer API and Admin UI (#316) * feat: set consumer api version to 3.0.0 * feat: set admin ui version to 2.0.0 * EVENT_ID_EXECUTION_TIME extracted into static LogEventIds class * fixing the "Run Admin UI Checks" ci/cd test fail * SaveChangesInterceptor moved to BuildingBlocks.Infrastructure.Persistence.Database * removed the unused _logger reference * unused directives in file removed * performance logging interceptor as DbContextOptionsBuilder extension * unused directives removed from file * performance tracking interceptors added to all db context options * fixed the missing parameter in CreateModification() method * more errors fixed by restoring the class to its original state * fixing the formatting pipeline * refactor: renamed the class to differentiate from built-in SaveChangesInterceptor * refactor: method renamed for consistency fix: AddTransient() changed to TryAddScoped() * fix: added refactored SaveChangesTime Interceptor to all db contexts * fix: fixing the formatting issues that caused the ci/cd test to fail * fix: DeleteRemovedBlobs calls wrapped in _logger.TraceTime() * chore: pin all versions and add comments for them * Revert "chore: pin all versions and add comments for them" This reverts commit 60ee17a. * refactor: add interceptor in Program.cs instead of in each module * refactor: move AddInterceptors call to OnConfiguring method of AbstractDbContextBase * refactor: simplify AddDbContext calls * chore: remove unused references * chore: some minor PR fixes * chore: reformat TraceTime calls * chore: unset DEBUG_PERFORMANCE flag in docker-compsoe.yml * chore: fix formatting * chore: add missing constructors to AdminUiDbContext * fix: use correct migrations assembly for Quotas module * ci: rename containers in docker-compsoe.test.*.yml files * ci: trigger pipelines * fix: readd call to UseNpgsql for Synchronization module * chore: remove duplicated code * test: remove unnecessary constructor parameters * chore: change log message phrasing * test: remove unnecessary parameter * ci: trigger pipelines --------- Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: Daniel Almeida <[email protected]> Co-authored-by: Timo Notheisen <[email protected]>
nmshd · Oct 9, 2023 · 40a7fa4 · 40a7fa4
1 parent 048624f
commit 40a7fa4
Show file tree

Hide file tree

Showing 54 changed files with 513 additions and 407 deletions.
diff --git a/.ci/docker-compose.test.postgres.yml b/.ci/docker-compose.test.postgres.yml
@@ -3,7 +3,7 @@ services:
   ### infrastructure ###
 
   database:
-    container_name: bkb-postgres
+    container_name: bkb-postgres-test
     hostname: postgres
     image: postgres
     environment:

diff --git a/.ci/docker-compose.test.sqlserver.yml b/.ci/docker-compose.test.sqlserver.yml
@@ -3,7 +3,7 @@ services:
   ### infrastructure ###
 
   database:
-    container_name: bkb-sql_server
+    container_name: bkb-sql_server-test
     hostname: sqlserver
     image: mcr.microsoft.com/mssql/server:2019-latest
     environment:

diff --git a/.ci/docker-compose.test.yml b/.ci/docker-compose.test.yml
@@ -1,7 +1,7 @@
 version: "3.3"
 services:
   consumer-api:
-    container_name: consumer-api
+    container_name: consumer-api-test
     hostname: consumer-api
     build:
       context: ..
@@ -30,7 +30,7 @@ services:
         target: app/appsettings.override.json
 
   admin-ui:
-    container_name: admin-ui
+    container_name: admin-ui-test
     hostname: admin-ui
     build:
       context: ..
@@ -51,15 +51,15 @@ services:
   ### infrastructure ###
 
   azure-storage-emulator:
-    container_name: azure-storage-emulator
+    container_name: azure-storage-emulator-test
     hostname: azurite
     image: mcr.microsoft.com/azure-storage/azurite
     command: azurite -d /data/debug.log -l /data --blobHost "0.0.0.0" --queueHost "0.0.0.0"
     ports:
       - "10000:10000"
 
   rabbitmq:
-    container_name: bkb-rabbitmq
+    container_name: bkb-rabbitmq-test
     hostname: rabbitmq
     image: rabbitmq:3.7-management-alpine
     ports:
@@ -68,7 +68,7 @@ services:
   ### seeds ###
 
   seed-client:
-    container_name: seed-client
+    container_name: seed-client-test
     image: ghcr.io/nmshd/backbone-admin-cli:v2.2.0
     depends_on:
       consumer-api:

diff --git a/AdminUi/src/AdminUi.Infrastructure/Persistence/Database/AdminUiDbContext.cs b/AdminUi/src/AdminUi.Infrastructure/Persistence/Database/AdminUiDbContext.cs
@@ -6,7 +6,17 @@ namespace AdminUi.Infrastructure.Persistence.Database;
 
 public class AdminUiDbContext : AbstractDbContextBase
 {
-    public AdminUiDbContext(DbContextOptions<AdminUiDbContext> options) : base(options) { }
+    public AdminUiDbContext()
+    {
+    }
+
+    public AdminUiDbContext(DbContextOptions<AdminUiDbContext> options) : base(options)
+    {
+    }
+
+    public AdminUiDbContext(DbContextOptions<AdminUiDbContext> options, IServiceProvider serviceProvider) : base(options, serviceProvider)
+    {
+    }
 
     public DbSet<IdentityOverview> IdentityOverviews { get; set; }
 

diff --git a/AdminUi/src/AdminUi.Infrastructure/Persistence/IServiceCollectionExtension.cs b/AdminUi/src/AdminUi.Infrastructure/Persistence/IServiceCollectionExtension.cs
@@ -27,45 +27,45 @@ public static IServiceCollection AddDatabase(this IServiceCollection services, A
         var options = new DbOptions();
         setupOptions?.Invoke(options);
 
-        switch (options.Provider)
-        {
-            case SQLSERVER:
-                services.AddDbContext<AdminUiDbContext>(dbContextOptions =>
-                    dbContextOptions.UseSqlServer(options.ConnectionString, sqlOptions =>
-                    {
-                        sqlOptions.CommandTimeout(20);
-                        sqlOptions.MigrationsAssembly(SQLSERVER_MIGRATIONS_ASSEMBLY);
-                        sqlOptions.EnableRetryOnFailure(options.RetryOptions.MaxRetryCount, TimeSpan.FromSeconds(options.RetryOptions.MaxRetryDelayInSeconds), null);
-                    })
-                );
-                break;
-            case POSTGRES:
-                services.AddDbContext<AdminUiDbContext>(dbContextOptions =>
-                    dbContextOptions.UseNpgsql(options.ConnectionString, sqlOptions =>
-                    {
-                        sqlOptions.CommandTimeout(20);
-                        sqlOptions.MigrationsAssembly(POSTGRES_MIGRATIONS_ASSEMBLY);
-                        sqlOptions.EnableRetryOnFailure(options.RetryOptions.MaxRetryCount, TimeSpan.FromSeconds(options.RetryOptions.MaxRetryDelayInSeconds), null);
-                    })
-                );
-                break;
-            default:
-                throw new Exception($"Unsupported database provider: {options.Provider}");
-        }
+        services
+            .AddDbContext<AdminUiDbContext>(dbContextOptions =>
+            {
+                switch (options.Provider)
+                {
+                    case SQLSERVER:
+                        dbContextOptions.UseSqlServer(options.ConnectionString, sqlOptions =>
+                        {
+                            sqlOptions.CommandTimeout(20);
+                            sqlOptions.MigrationsAssembly(SQLSERVER_MIGRATIONS_ASSEMBLY);
+                            sqlOptions.EnableRetryOnFailure(options.RetryOptions.MaxRetryCount, TimeSpan.FromSeconds(options.RetryOptions.MaxRetryDelayInSeconds), null);
+                        });
+                        break;
+                    case POSTGRES:
+                        dbContextOptions.UseNpgsql(options.ConnectionString, sqlOptions =>
+                        {
+                            sqlOptions.CommandTimeout(20);
+                            sqlOptions.MigrationsAssembly(POSTGRES_MIGRATIONS_ASSEMBLY);
+                            sqlOptions.EnableRetryOnFailure(options.RetryOptions.MaxRetryCount, TimeSpan.FromSeconds(options.RetryOptions.MaxRetryDelayInSeconds), null);
+                        });
+                        break;
+                    default:
+                        throw new Exception($"Unsupported database provider: {options.Provider}");
+                }
+            });
 
         return services;
     }
-}
 
-public class DbOptions
-{
-    public string Provider { get; set; }
-    public string ConnectionString { get; set; }
-    public RetryOptions RetryOptions { get; set; } = new();
-}
+    public class DbOptions
+    {
+        public string Provider { get; set; }
+        public string ConnectionString { get; set; }
+        public RetryOptions RetryOptions { get; set; } = new();
+    }
 
-public class RetryOptions
-{
-    public byte MaxRetryCount { get; set; } = 15;
-    public int MaxRetryDelayInSeconds { get; set; } = 30;
+    public class RetryOptions
+    {
+        public byte MaxRetryCount { get; set; } = 15;
+        public int MaxRetryDelayInSeconds { get; set; } = 30;
+    }
 }
diff --git a/AdminUi/src/AdminUi/Controllers/IdentitiesController.cs b/AdminUi/src/AdminUi/Controllers/IdentitiesController.cs
@@ -22,7 +22,6 @@
 using GetIdentityQueryQuotas = Backbone.Modules.Quotas.Application.Identities.Queries.GetIdentity.GetIdentityQuery;
 using GetIdentityResponseDevices = Backbone.Modules.Devices.Application.Identities.Queries.GetIdentity.GetIdentityResponse;
 using GetIdentityResponseQuotas = Backbone.Modules.Quotas.Application.Identities.Queries.GetIdentity.GetIdentityResponse;
-using Identity = Backbone.Modules.Devices.Domain.Entities.Identity;
 
 namespace AdminUi.Controllers;
 

diff --git a/AdminUi/src/AdminUi/Extensions/QuotasServiceCollectionExtensions.cs b/AdminUi/src/AdminUi/Extensions/QuotasServiceCollectionExtensions.cs
@@ -1,6 +1,6 @@
 using AdminUi.Configuration;
 using Backbone.Modules.Quotas.Application.Extensions;
-using Backbone.Modules.Quotas.Infrastructure.Persistence;
+using Backbone.Modules.Quotas.Infrastructure.Persistence.Database;
 
 namespace AdminUi.Extensions;
 

diff --git a/AdminUi/src/AdminUi/Program.cs b/AdminUi/src/AdminUi/Program.cs
@@ -9,9 +9,9 @@
 using Backbone.Modules.Devices.Application;
 using Backbone.Modules.Devices.Infrastructure.OpenIddict;
 using Backbone.Modules.Devices.Infrastructure.Persistence.Database;
-using Backbone.Modules.Quotas.Infrastructure.Persistence.Database;
 using Enmeshed.BuildingBlocks.API.Extensions;
 using Enmeshed.BuildingBlocks.Application.QuotaCheck;
+using Enmeshed.BuildingBlocks.Infrastructure.Persistence.Database;
 using Enmeshed.Tooling.Extensions;
 using Microsoft.AspNetCore.Diagnostics.HealthChecks;
 using Microsoft.Extensions.Options;
@@ -58,6 +58,8 @@
 
 static void ConfigureServices(IServiceCollection services, IConfiguration configuration, IHostEnvironment environment)
 {
+    services.AddSaveChangesTimeInterceptor();
+
     services.AddSingleton<ApiKeyValidator>();
 
     services

diff --git a/AdminUi/test/AdminUi.Tests.Integration/StepDefinitions/LogsStepDefinitions.cs b/AdminUi/test/AdminUi.Tests.Integration/StepDefinitions/LogsStepDefinitions.cs
@@ -1,6 +1,5 @@
 using AdminUi.Tests.Integration.API;
 using AdminUi.Tests.Integration.Models;
-using Enmeshed.UnitTestTools.Data;
 
 namespace AdminUi.Tests.Integration.StepDefinitions;
 

diff --git a/BuildingBlocks/src/BuildingBlocks.Infrastructure/BuildingBlocks.Infrastructure.csproj b/BuildingBlocks/src/BuildingBlocks.Infrastructure/BuildingBlocks.Infrastructure.csproj
@@ -19,7 +19,8 @@
 		<PackageReference Include="Microsoft.Extensions.Identity.Core" Version="7.0.11" />
 		<PackageReference Include="Newtonsoft.Json" Version="13.0.3" />
 		<PackageReference Include="Microsoft.Extensions.Logging" Version="7.0.0" />
-		<PackageReference Include="Npgsql.EntityFrameworkCore.PostgreSQL" Version="7.0.4" />
+		<!-- CAUTION: Do not upgrade 'Npgsql.EntityFrameworkCore.PostgreSQL' to 7.0.11, because there is an error regarding __EFMigrationHistory tables introduces with the fix of the following GitHub issue: https://github.com/npgsql/efcore.pg/issues/2787 -->
+		<PackageReference Include="Npgsql.EntityFrameworkCore.PostgreSQL" Version="[7.0.4]" />
 		<PackageReference Include="Polly" Version="8.0.0" />
 		<PackageReference Include="RabbitMQ.Client" Version="6.5.0" />
 		<PackageReference Include="System.Interactive.Async" Version="6.0.1" />

diff --git a/...cks/src/BuildingBlocks.Infrastructure/EventBus/AzureServiceBus/EventBusAzureServiceBus.cs b/...cks/src/BuildingBlocks.Infrastructure/EventBus/AzureServiceBus/EventBusAzureServiceBus.cs
@@ -7,7 +7,6 @@
 using Enmeshed.BuildingBlocks.Infrastructure.EventBus.Json;
 using Microsoft.Extensions.Logging;
 using Newtonsoft.Json;
-using Polly;
 
 namespace Enmeshed.BuildingBlocks.Infrastructure.EventBus.AzureServiceBus;
 
@@ -70,7 +69,8 @@ public async void Publish(IntegrationEvent @event)
 
         _logger.LogTrace("Sending integration event with id '{MessageId}'...", message.MessageId);
 
-        await _sender.SendMessageAsync(message);
+        await _logger.TraceTime(async () =>
+            await _sender.SendMessageAsync(message), nameof(_sender.SendMessageAsync));
 
         _logger.LogTrace("Successfully sent integration event with id '{MessageId}'.", message.MessageId);
     }

diff --git a/....Infrastructure/EventBus/GoogleCloudPubSub/DefaultGoogleCloudPubSubPersisterConnection.cs b/....Infrastructure/EventBus/GoogleCloudPubSub/DefaultGoogleCloudPubSubPersisterConnection.cs
@@ -2,7 +2,6 @@
 using Google.Api.Gax;
 using Google.Apis.Auth.OAuth2;
 using Google.Cloud.PubSub.V1;
-using Grpc.Core;
 
 namespace Enmeshed.BuildingBlocks.Infrastructure.EventBus.GoogleCloudPubSub;
 

diff --git a/...src/BuildingBlocks.Infrastructure/EventBus/GoogleCloudPubSub/EventBusGoogleCloudPubSub.cs b/...src/BuildingBlocks.Infrastructure/EventBus/GoogleCloudPubSub/EventBusGoogleCloudPubSub.cs
@@ -7,7 +7,6 @@
 using Google.Protobuf;
 using Microsoft.Extensions.Logging;
 using Newtonsoft.Json;
-using Polly;
 
 namespace Enmeshed.BuildingBlocks.Infrastructure.EventBus.GoogleCloudPubSub;
 
@@ -64,7 +63,8 @@ public async void Publish(IntegrationEvent @event)
             }
         };
 
-        var messageId = await _connection.PublisherClient.PublishAsync(message);
+        var messageId = await _logger.TraceTime(
+            () => _connection.PublisherClient.PublishAsync(message), nameof(_connection.PublisherClient.PublishAsync));
 
         _logger.LogTrace("Successfully sent integration event with id '{messageId}'.", messageId);
     }

diff --git a/BuildingBlocks/src/BuildingBlocks.Infrastructure/EventBus/RabbitMQ/EventBusRabbitMQ.cs b/BuildingBlocks/src/BuildingBlocks.Infrastructure/EventBus/RabbitMQ/EventBusRabbitMQ.cs
@@ -184,6 +184,7 @@ private async Task ProcessEvent(string eventName, string message)
         if (_subsManager.HasSubscriptionsForEvent(eventName))
         {
             await using var scope = _autofac.BeginLifetimeScope(AUTOFAC_SCOPE_NAME);
+
             var subscriptions = _subsManager.GetHandlersForEvent(eventName);
             foreach (var subscription in subscriptions)
             {

diff --git a/...gBlocks.Infrastructure/Persistence/BlobStorage/AzureStorageAccount/AzureStorageAccount.cs b/...gBlocks.Infrastructure/Persistence/BlobStorage/AzureStorageAccount/AzureStorageAccount.cs
@@ -44,7 +44,10 @@ public async Task<byte[]> FindAsync(string folder, string blobId)
         {
             var blob = container.GetBlobClient(blobId);
             var stream = new MemoryStream();
-            await blob.DownloadToAsync(stream);
+
+            await _logger.TraceTime(async () =>
+                await blob.DownloadToAsync(stream), nameof(blob.DownloadToAsync));
+
             stream.Position = 0;
 
             _logger.LogTrace("Found blob with id '{blobId}'.", blobId);
@@ -78,8 +81,8 @@ public Task<IAsyncEnumerable<string>> FindAllAsync(string folder, string? prefix
 
     public async Task SaveAsync()
     {
-        await UploadChangedBlobs();
-        await DeleteRemovedBlobs();
+        await _logger.TraceTime(UploadChangedBlobs, nameof(UploadChangedBlobs));
+        await _logger.TraceTime(DeleteRemovedBlobs, nameof(DeleteRemovedBlobs));
     }
 
     public void Dispose()

diff --git a/...ingBlocks.Infrastructure/Persistence/BlobStorage/GoogleCloudStorage/GoogleCloudStorage.cs b/...ingBlocks.Infrastructure/Persistence/BlobStorage/GoogleCloudStorage/GoogleCloudStorage.cs
@@ -45,7 +45,10 @@ public async Task<byte[]> FindAsync(string folder, string blobId)
         try
         {
             var stream = new MemoryStream();
-            await _storageClient.DownloadObjectAsync(folder, blobId, stream);
+
+            await _logger.TraceTime(async () =>
+                await _storageClient.DownloadObjectAsync(folder, blobId, stream), nameof(FindAsync));
+
             stream.Position = 0;
             _logger.LogTrace("Found blob with key '{blobId}'.", blobId);
 
@@ -88,8 +91,8 @@ private void EliminateNotFound(Exception ex, string blobId)
 
     public async Task SaveAsync()
     {
-        await UploadChangedBlobs();
-        await DeleteRemovedBlobs();
+        await _logger.TraceTime(UploadChangedBlobs, nameof(UploadChangedBlobs));
+        await _logger.TraceTime(DeleteRemovedBlobs, nameof(DeleteRemovedBlobs));
     }
 
     private async Task UploadChangedBlobs()
@@ -127,7 +130,9 @@ private async Task EnsureKeyDoesNotExist(string folder, string key)
     {
         try
         {
-            await _storageClient.GetObjectAsync(folder, key);
+            await _logger.TraceTime(async () =>
+                await _storageClient.GetObjectAsync(folder, key), nameof(_storageClient.GetObjectAsync));
+
             _logger.LogError("The blob with the given key already exists.");
             throw new BlobAlreadyExistsException(key);
         }
@@ -163,5 +168,6 @@ private async Task DeleteRemovedBlobs()
     }
 
     private record ChangedBlob(string Folder, string Name, byte[] Content);
+
     private record RemovedBlob(string Folder, string Name);
 }
diff --git a/...ingBlocks/src/BuildingBlocks.Infrastructure/Persistence/Database/AbstractDbContextBase.cs b/...ingBlocks/src/BuildingBlocks.Infrastructure/Persistence/Database/AbstractDbContextBase.cs
@@ -2,14 +2,17 @@
 using Enmeshed.BuildingBlocks.Application.Abstractions.Infrastructure.Persistence.Database;
 using Enmeshed.BuildingBlocks.Infrastructure.Persistence.Database.ValueConverters;
 using Enmeshed.DevelopmentKit.Identity.ValueObjects;
+using Enmeshed.Tooling.Extensions;
 using Microsoft.EntityFrameworkCore;
 using Microsoft.EntityFrameworkCore.Storage;
+using Microsoft.Extensions.DependencyInjection;
 using Npgsql.EntityFrameworkCore.PostgreSQL;
 
 namespace Enmeshed.BuildingBlocks.Infrastructure.Persistence.Database;
 
 public class AbstractDbContextBase : DbContext, IDbContext
 {
+    private readonly IServiceProvider? _serviceProvider;
     private const int MAX_RETRY_COUNT = 50000;
     private static readonly TimeSpan MAX_RETRY_DELAY = TimeSpan.FromSeconds(1);
     private const string SQLSERVER = "Microsoft.EntityFrameworkCore.SqlServer";
@@ -19,19 +22,27 @@ protected AbstractDbContextBase()
     {
     }
 
-    protected AbstractDbContextBase(DbContextOptions options) : base(options)
+    protected AbstractDbContextBase(DbContextOptions options, IServiceProvider? serviceProvider = null) : base(options)
     {
+        _serviceProvider = serviceProvider;
     }
 
     public IQueryable<T> SetReadOnly<T>() where T : class
     {
         return Set<T>().AsNoTracking();
     }
 
+    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
+    {
+        base.OnConfiguring(optionsBuilder);
+
+        if (EnvironmentVariables.DEBUG_PERFORMANCE && _serviceProvider != null)
+            optionsBuilder.AddInterceptors(_serviceProvider.GetRequiredService<SaveChangesTimeInterceptor>());
+    }
+
     public async Task RunInTransaction(Func<Task> action, List<int>? errorNumbersToRetry,
         IsolationLevel isolationLevel = IsolationLevel.ReadCommitted)
     {
-
         ExecutionStrategy executionStrategy;
         switch (Database.ProviderName)
         {

diff --git a/...c/BuildingBlocks.Infrastructure/Persistence/Database/DbContextOptionsBuilderExtensions.cs b/...c/BuildingBlocks.Infrastructure/Persistence/Database/DbContextOptionsBuilderExtensions.cs
@@ -0,0 +1,12 @@
+using Microsoft.EntityFrameworkCore;
+using Microsoft.Extensions.DependencyInjection;
+
+namespace Enmeshed.BuildingBlocks.Infrastructure.Persistence.Database;
+
+public static class DbContextOptionsBuilderExtensions
+{
+    public static void AddSaveChangesTimeInterceptor(this DbContextOptionsBuilder builder, IServiceProvider serviceProvider)
+    {
+        builder.AddInterceptors(serviceProvider.GetRequiredService<SaveChangesTimeInterceptor>());
+    }
+}