Feature/set up a performance logging service (#3703)

* Setup performance logging service

* Update changelog

CHANGELOG.md

@@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## 2.106.0-beta.2 - 2024-08-26
 
+### Added
+
+- Set up a performance logging service
+
 ### Changed
 
 - Reworked the portfolio calculator

apps/api/src/app/account-balance/account-balance.service.ts

@@ -1,4 +1,5 @@
 import { PortfolioChangedEvent } from '@ghostfolio/api/events/portfolio-changed.event';
+import { LogPerformance } from '@ghostfolio/api/interceptors/performance-logging/performance-logging.interceptor';
 import { ExchangeRateDataService } from '@ghostfolio/api/services/exchange-rate-data/exchange-rate-data.service';
 import { PrismaService } from '@ghostfolio/api/services/prisma/prisma.service';
 import { resetHours } from '@ghostfolio/common/helper';
@@ -90,6 +91,7 @@ export class AccountBalanceService {
     return accountBalance;
   }
 
+  @LogPerformance
   public async getAccountBalances({
     filters,
     user,

apps/api/src/app/order/order.service.ts

@@ -1,5 +1,6 @@
 import { AccountService } from '@ghostfolio/api/app/account/account.service';
 import { PortfolioChangedEvent } from '@ghostfolio/api/events/portfolio-changed.event';
+import { LogPerformance } from '@ghostfolio/api/interceptors/performance-logging/performance-logging.interceptor';
 import { DataGatheringService } from '@ghostfolio/api/services/data-gathering/data-gathering.service';
 import { ExchangeRateDataService } from '@ghostfolio/api/services/exchange-rate-data/exchange-rate-data.service';
 import { PrismaService } from '@ghostfolio/api/services/prisma/prisma.service';
@@ -519,6 +520,7 @@ export class OrderService {
     return { activities, count };
   }
 
+  @LogPerformance
   public async getOrdersForPortfolioCalculator({
     filters,
     userCurrency,

apps/api/src/app/portfolio/calculator/portfolio-calculator.ts

@@ -5,6 +5,7 @@ import { TransactionPointSymbol } from '@ghostfolio/api/app/portfolio/interfaces
 import { TransactionPoint } from '@ghostfolio/api/app/portfolio/interfaces/transaction-point.interface';
 import { RedisCacheService } from '@ghostfolio/api/app/redis-cache/redis-cache.service';
 import { getFactor } from '@ghostfolio/api/helper/portfolio.helper';
+import { LogPerformance } from '@ghostfolio/api/interceptors/performance-logging/performance-logging.interceptor';
 import { ConfigurationService } from '@ghostfolio/api/services/configuration/configuration.service';
 import { ExchangeRateDataService } from '@ghostfolio/api/services/exchange-rate-data/exchange-rate-data.service';
 import { IDataGatheringItem } from '@ghostfolio/api/services/interfaces/interfaces';
@@ -148,6 +149,7 @@ export abstract class PortfolioCalculator {
     positions: TimelinePosition[]
   ): PortfolioSnapshot;
 
+  @LogPerformance
   private async computeSnapshot(): Promise<PortfolioSnapshot> {
     const lastTransactionPoint = last(this.transactionPoints);
 
@@ -861,6 +863,7 @@ export abstract class PortfolioCalculator {
     return chartDateMap;
   }
 
+  @LogPerformance
   private computeTransactionPoints() {
     this.transactionPoints = [];
     const symbols: { [symbol: string]: TransactionPointSymbol } = {};
@@ -999,6 +1002,7 @@ export abstract class PortfolioCalculator {
     }
   }
 
+  @LogPerformance
   private async initialize() {
     const startTimeTotal = performance.now();
 
@@ -1033,14 +1037,6 @@ export abstract class PortfolioCalculator {
         JSON.stringify(this.snapshot),
         this.configurationService.get('CACHE_QUOTES_TTL')
       );
-
-      Logger.debug(
-        `Computed portfolio snapshot in ${(
-          (performance.now() - startTimeTotal) /
-          1000
-        ).toFixed(3)} seconds`,
-        'PortfolioCalculator'
-      );
     }
   }
 }

apps/api/src/app/portfolio/current-rate.service.ts

@@ -1,4 +1,5 @@
 import { OrderService } from '@ghostfolio/api/app/order/order.service';
+import { LogPerformance } from '@ghostfolio/api/interceptors/performance-logging/performance-logging.interceptor';
 import { DataProviderService } from '@ghostfolio/api/services/data-provider/data-provider.service';
 import { MarketDataService } from '@ghostfolio/api/services/market-data/market-data.service';
 import { resetHours } from '@ghostfolio/common/helper';
@@ -27,6 +28,7 @@ export class CurrentRateService {
     @Inject(REQUEST) private readonly request: RequestWithUser
   ) {}
 
+  @LogPerformance
   // TODO: Pass user instead of using this.request.user
   public async getValues({
     dataGatheringItems,

apps/api/src/app/portfolio/portfolio.controller.ts

@@ -7,6 +7,7 @@ import {
   hasNotDefinedValuesInObject,
   nullifyValuesInObject
 } from '@ghostfolio/api/helper/object.helper';
+import { PerformanceLoggingInterceptor } from '@ghostfolio/api/interceptors/performance-logging/performance-logging.interceptor';
 import { RedactValuesInResponseInterceptor } from '@ghostfolio/api/interceptors/redact-values-in-response/redact-values-in-response.interceptor';
 import { TransformDataSourceInRequestInterceptor } from '@ghostfolio/api/interceptors/transform-data-source-in-request/transform-data-source-in-request.interceptor';
 import { TransformDataSourceInResponseInterceptor } from '@ghostfolio/api/interceptors/transform-data-source-in-response/transform-data-source-in-response.interceptor';
@@ -390,6 +391,7 @@ export class PortfolioController {
 
   @Get('performance')
   @UseGuards(AuthGuard('jwt'), HasPermissionGuard)
+  @UseInterceptors(PerformanceLoggingInterceptor)
   @UseInterceptors(TransformDataSourceInResponseInterceptor)
   @Version('2')
   public async getPerformanceV2(

apps/api/src/app/portfolio/portfolio.module.ts

@@ -4,6 +4,7 @@ import { AccountService } from '@ghostfolio/api/app/account/account.service';
 import { OrderModule } from '@ghostfolio/api/app/order/order.module';
 import { RedisCacheModule } from '@ghostfolio/api/app/redis-cache/redis-cache.module';
 import { UserModule } from '@ghostfolio/api/app/user/user.module';
+import { PerformanceLoggingModule } from '@ghostfolio/api/interceptors/performance-logging/performance-logging.module';
 import { RedactValuesInResponseModule } from '@ghostfolio/api/interceptors/redact-values-in-response/redact-values-in-response.module';
 import { TransformDataSourceInRequestModule } from '@ghostfolio/api/interceptors/transform-data-source-in-request/transform-data-source-in-request.module';
 import { TransformDataSourceInResponseModule } from '@ghostfolio/api/interceptors/transform-data-source-in-response/transform-data-source-in-response.module';
@@ -38,6 +39,7 @@ import { RulesService } from './rules.service';
     ImpersonationModule,
     MarketDataModule,
     OrderModule,
+    PerformanceLoggingModule,
     PrismaModule,
     RedactValuesInResponseModule,
     RedisCacheModule,

apps/api/src/interceptors/performance-logging/performance-logging.interceptor.ts

@@ -0,0 +1,80 @@
+import {
+  Injectable,
+  NestInterceptor,
+  ExecutionContext,
+  CallHandler
+} from '@nestjs/common';
+import { Observable } from 'rxjs';
+import { tap } from 'rxjs/operators';
+
+import { PerformanceLoggingService } from './performance-logging.service';
+
+@Injectable()
+export class PerformanceLoggingInterceptor implements NestInterceptor {
+  public constructor(
+    private readonly performanceLoggingService: PerformanceLoggingService
+  ) {}
+
+  public intercept(
+    context: ExecutionContext,
+    next: CallHandler
+  ): Observable<any> {
+    const startTime = performance.now();
+
+    const className = context.getClass().name;
+    const methodName = context.getHandler().name;
+
+    return next.handle().pipe(
+      tap(() => {
+        return this.performanceLoggingService.logPerformance({
+          className,
+          methodName,
+          startTime
+        });
+      })
+    );
+  }
+}
+
+export function LogPerformance(
+  target: any,
+  propertyKey: string,
+  descriptor: PropertyDescriptor
+) {
+  const originalMethod = descriptor.value;
+
+  descriptor.value = async function (...args: any[]) {
+    const startTime = performance.now();
+    const performanceLoggingService = new PerformanceLoggingService();
+
+    const result = originalMethod.apply(this, args);
+
+    if (result instanceof Promise) {
+      // Handle async method
+      return result
+        .then((res: any) => {
+          performanceLoggingService.logPerformance({
+            startTime,
+            className: target.constructor.name,
+            methodName: propertyKey
+          });
+
+          return res;
+        })
+        .catch((error: any) => {
+          throw error;
+        });
+    } else {
+      // Handle sync method
+      performanceLoggingService.logPerformance({
+        startTime,
+        className: target.constructor.name,
+        methodName: propertyKey
+      });
+
+      return result;
+    }
+  };
+
+  return descriptor;
+}

apps/api/src/interceptors/performance-logging/performance-logging.module.ts

@@ -0,0 +1,10 @@
+import { Module } from '@nestjs/common';
+
+import { PerformanceLoggingInterceptor } from './performance-logging.interceptor';
+import { PerformanceLoggingService } from './performance-logging.service';
+
+@Module({
+  exports: [PerformanceLoggingInterceptor, PerformanceLoggingService],
+  providers: [PerformanceLoggingInterceptor, PerformanceLoggingService]
+})
+export class PerformanceLoggingModule {}

apps/api/src/interceptors/performance-logging/performance-logging.service.ts

@@ -0,0 +1,21 @@
+import { Injectable, Logger } from '@nestjs/common';
+
+@Injectable()
+export class PerformanceLoggingService {
+  public logPerformance({
+    className,
+    methodName,
+    startTime
+  }: {
+    className: string;
+    methodName: string;
+    startTime: number;
+  }) {
+    const endTime = performance.now();
+
+    Logger.debug(
+      `Completed execution of ${methodName}() in ${((endTime - startTime) / 1000).toFixed(3)} seconds`,
+      className
+    );
+  }
+}

apps/api/src/services/data-provider/coingecko/coingecko.service.ts

@@ -206,9 +206,9 @@ export class CoinGeckoService implements DataProviderInterface {
       let message = error;
 
       if (error?.code === 'ABORT_ERR') {
-        message = `RequestError: The operation to get the quotes was aborted because the request to the data provider took more than ${this.configurationService.get(
+        message = `RequestError: The operation to get the quotes was aborted because the request to the data provider took more than ${(
-          'REQUEST_TIMEOUT'
+          this.configurationService.get('REQUEST_TIMEOUT') / 1000
-        )}ms`;
+        ).toFixed(3)} seconds`;
       }
 
       Logger.error(message, 'CoinGeckoService');

apps/api/src/services/data-provider/eod-historical-data/eod-historical-data.service.ts

@@ -290,9 +290,9 @@ export class EodHistoricalDataService implements DataProviderInterface {
       let message = error;
 
       if (error?.code === 'ABORT_ERR') {
-        message = `RequestError: The operation to get the quotes was aborted because the request to the data provider took more than ${this.configurationService.get(
+        message = `RequestError: The operation to get the quotes was aborted because the request to the data provider took more than ${(
-          'REQUEST_TIMEOUT'
+          this.configurationService.get('REQUEST_TIMEOUT') / 1000
-        )}ms`;
+        ).toFixed(3)} seconds`;
       }
 
       Logger.error(message, 'EodHistoricalDataService');

apps/api/src/services/data-provider/financial-modeling-prep/financial-modeling-prep.service.ts

@@ -154,9 +154,9 @@ export class FinancialModelingPrepService implements DataProviderInterface {
       let message = error;
 
       if (error?.code === 'ABORT_ERR') {
-        message = `RequestError: The operation to get the quotes was aborted because the request to the data provider took more than ${this.configurationService.get(
+        message = `RequestError: The operation to get the quotes was aborted because the request to the data provider took more than ${(
-          'REQUEST_TIMEOUT'
+          this.configurationService.get('REQUEST_TIMEOUT') / 1000
-        )}ms`;
+        ).toFixed(3)} seconds`;
       }
 
       Logger.error(message, 'FinancialModelingPrepService');

apps/api/src/services/exchange-rate-data/exchange-rate-data.service.ts

@@ -1,3 +1,4 @@
+import { LogPerformance } from '@ghostfolio/api/interceptors/performance-logging/performance-logging.interceptor';
 import { DataProviderService } from '@ghostfolio/api/services/data-provider/data-provider.service';
 import { IDataGatheringItem } from '@ghostfolio/api/services/interfaces/interfaces';
 import { MarketDataService } from '@ghostfolio/api/services/market-data/market-data.service';
@@ -46,6 +47,7 @@ export class ExchangeRateDataService {
     return this.currencyPairs;
   }
 
+  @LogPerformance
   public async getExchangeRatesByCurrency({
     currencies,
     endDate = new Date(),