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

Add ResponseTimeCpuInterceptor to monitor response time and CPU usage per endpoint #1379

Open
wants to merge 4 commits into
base: development
Choose a base branch
from
Open
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
46 changes: 46 additions & 0 deletions src/interceptors/response-time.cpu.interceptor.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,46 @@
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;
bogdan-rosianu marked this conversation as resolved.
Show resolved Hide resolved

constructor(
private readonly metricsService: MetricsService,
options: { shouldLog?: boolean } = {},
) {
this.shouldLog = options.shouldLog ?? true;
}

intercept(context: ExecutionContext, next: CallHandler): Observable<any> {
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;

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`);
}
}
}),
);
}
}
3 changes: 3 additions & 0 deletions src/main.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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');
Expand Down Expand Up @@ -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();
Expand Down
72 changes: 72 additions & 0 deletions src/test/integration/response-time.cpu.interceptor.e2e-spec.ts
Original file line number Diff line number Diff line change
@@ -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>(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();
});
});
Loading