diff --git a/src/interceptors/response-time.cpu.interceptor.ts b/src/interceptors/response-time.cpu.interceptor.ts new file mode 100644 index 000000000..8aa4173f0 --- /dev/null +++ b/src/interceptors/response-time.cpu.interceptor.ts @@ -0,0 +1,47 @@ +import { CallHandler, ExecutionContext, Injectable, NestInterceptor, Logger } from '@nestjs/common'; +import { Observable } from 'rxjs'; +import { tap } from 'rxjs/operators'; +import { MetricsService, PerformanceProfiler } from '@multiversx/sdk-nestjs-monitoring'; + +@Injectable() +export class ResponseTimeCpuInterceptor implements NestInterceptor { + private readonly logger = new Logger(ResponseTimeCpuInterceptor.name); + private readonly shouldLog: boolean; + + constructor( + private readonly metricsService: MetricsService, + options: { shouldLog?: boolean } = {}, + ) { + this.shouldLog = options.shouldLog ?? true; + } + + intercept(context: ExecutionContext, next: CallHandler): Observable { + const profiler = new PerformanceProfiler(); + const startCpuUsage = process.cpuUsage(); + + return next.handle().pipe( + tap(() => { + const duration = profiler.stop(); + const endCpuUsage = process.cpuUsage(startCpuUsage); + const cpuUsage = (endCpuUsage.user + endCpuUsage.system) / 1000; + + const request = context.switchToHttp().getRequest(); + const endpoint = request.url; + + console.log(`${endpoint} - ${duration}ms - ${cpuUsage}ms`); + this.metricsService.setExternalCall('response_time', duration); + this.metricsService.setExternalCall('cpu_usage', cpuUsage); + + if (this.shouldLog) { + if (duration > 1000) { + this.logger.warn(`Warning: Response time for ${endpoint} is ${duration}ms`); + } + + if (cpuUsage > 500) { + this.logger.warn(`Warning: CPU usage for ${endpoint} is ${cpuUsage}ms`); + } + } + }), + ); + } +} diff --git a/src/main.ts b/src/main.ts index 0ffab0cd9..514d5efb2 100644 --- a/src/main.ts +++ b/src/main.ts @@ -35,6 +35,7 @@ import { JwtOrNativeAuthGuard } from '@multiversx/sdk-nestjs-auth'; import { WebSocketPublisherModule } from './common/websockets/web-socket-publisher-module'; import { IndexerService } from './common/indexer/indexer.service'; import { NotWritableError } from './common/indexer/entities/not.writable.error'; +import { ResponseTimeCpuInterceptor } from './interceptors/response-time.cpu.interceptor'; async function bootstrap() { const logger = new Logger('Bootstrapper'); @@ -220,6 +221,8 @@ async function configurePublicApp(publicApp: NestExpressApplication, apiConfigSe globalInterceptors.push(new RequestCpuTimeInterceptor(metricsService)); // @ts-ignore globalInterceptors.push(new LoggingInterceptor(metricsService)); + //@ts-ignore + globalInterceptors.push(new ResponseTimeCpuInterceptor(metricsService, { shouldLog: true })); const getUseRequestCachingFlag = await settingsService.getUseRequestCachingFlag(); const cacheDuration = apiConfigService.getCacheDuration(); diff --git a/src/test/integration/response-time.cpu.interceptor.e2e-spec.ts b/src/test/integration/response-time.cpu.interceptor.e2e-spec.ts new file mode 100644 index 000000000..5a785f966 --- /dev/null +++ b/src/test/integration/response-time.cpu.interceptor.e2e-spec.ts @@ -0,0 +1,72 @@ +import { Test, TestingModule } from '@nestjs/testing'; +import { INestApplication, HttpServer, Logger, Controller, Get } from '@nestjs/common'; +import request from 'supertest'; +import { MetricsService } from '@multiversx/sdk-nestjs-monitoring'; +import { ResponseTimeCpuInterceptor } from 'src/interceptors/response-time.cpu.interceptor'; +import { PublicAppModule } from 'src/public.app.module'; + +@Controller('test') +class TestController { + @Get('endpoint') + getFastEndpoint() { + return { message: 'Test Endpoint' }; + } +} + +describe('ResponseTimeCpuInterceptor (e2e)', () => { + let app: INestApplication; + let httpServer: HttpServer; + let metricsService: MetricsService; + + beforeAll(async () => { + const moduleFixture: TestingModule = await Test.createTestingModule({ + imports: [PublicAppModule], + controllers: [TestController], + }).compile(); + + app = moduleFixture.createNestApplication(); + metricsService = app.get(MetricsService); + await app.init(); + httpServer = app.getHttpServer(); + }); + + afterEach(async () => { + await app.close(); + }); + + afterAll(async () => { + await app.close(); + }); + + it('should log response time and CPU usage for test endpoint', async () => { + app.useGlobalInterceptors(new ResponseTimeCpuInterceptor(metricsService, { shouldLog: true })); + await app.init(); + + const logSpy = jest.spyOn(Logger.prototype, 'warn').mockImplementation(); + + await request(httpServer) + .get('/test/endpoint') + .expect(200); + + expect(logSpy).not.toHaveBeenCalledWith(expect.stringContaining('Warning: Response time for')); + expect(logSpy).not.toHaveBeenCalledWith(expect.stringContaining('Warning: CPU usage for')); + + logSpy.mockRestore(); + }); + + it('should not log response time and CPU usage when logging is disabled', async () => { + app.useGlobalInterceptors(new ResponseTimeCpuInterceptor(metricsService, { shouldLog: false })); + await app.init(); + + const logSpy = jest.spyOn(Logger.prototype, 'warn').mockImplementation(); + + await request(httpServer) + .get('/test/endpoint') + .expect(200); + + expect(logSpy).not.toHaveBeenCalledWith(expect.stringContaining('Warning: Response time for')); + expect(logSpy).not.toHaveBeenCalledWith(expect.stringContaining('Warning: CPU usage for')); + + logSpy.mockRestore(); + }); +});