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

[Telemetry] track and warn event loop delays thresholds #103615

Merged
merged 9 commits into from
Jun 29, 2021
Original file line number Diff line number Diff line change
Expand Up @@ -35,3 +35,23 @@ export const MONITOR_EVENT_LOOP_DELAYS_START = 1 * 60 * 1000;
* Event loop monitoring sampling rate in milliseconds.
*/
export const MONITOR_EVENT_LOOP_DELAYS_RESOLUTION = 10;

/**
* Mean event loop delay threshold for logging a warning.
*/
export const MONITOR_EVENT_LOOP_WARN_THRESHOLD = 350;

/**
* Start monitoring the event loop threshold after 1 minute
*/
export const MONITOR_EVENT_LOOP_THRESHOLD_START = 1 * 60 * 1000;

/**
* Check the event loop utilization every 30 seconds
*/
export const MONITOR_EVENT_LOOP_THRESHOLD_INTERVAL = 30 * 1000;

/**
* Nanosecond to milisecond conversion unit
*/
export const ONE_MILLISECOND_AS_NANOSECONDS = 1000000;
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@ export const monitorEventLoopDelay = jest.fn().mockReturnValue({
percentile: mockMonitorPercentile,
disable: mockMonitorDisable,
reset: mockMonitorReset,
...createMockHistogram(),
});

jest.doMock('perf_hooks', () => ({
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -6,17 +6,14 @@
* Side Public License, v 1.
*/

import { Subject } from 'rxjs';

import {
mockMonitorEnable,
mockMonitorPercentile,
monitorEventLoopDelay,
mockMonitorReset,
mockMonitorDisable,
} from './event_loop_delays.mocks';
import { savedObjectsRepositoryMock } from '../../../../../core/server/mocks';
import { startTrackingEventLoopDelaysUsage, EventLoopDelaysCollector } from './event_loop_delays';
import { EventLoopDelaysCollector } from './event_loop_delays';

describe('EventLoopDelaysCollector', () => {
jest.useFakeTimers('modern');
Expand Down Expand Up @@ -64,72 +61,3 @@ describe('EventLoopDelaysCollector', () => {
expect(mockMonitorDisable).toBeCalledTimes(1);
});
});

describe('startTrackingEventLoopDelaysUsage', () => {
const mockInternalRepository = savedObjectsRepositoryMock.create();
const stopMonitoringEventLoop$ = new Subject<void>();

beforeAll(() => jest.useFakeTimers('modern'));
beforeEach(() => jest.clearAllMocks());
afterEach(() => stopMonitoringEventLoop$.next());

it('initializes EventLoopDelaysCollector and starts timer', () => {
const collectionStartDelay = 1000;
startTrackingEventLoopDelaysUsage(
mockInternalRepository,
stopMonitoringEventLoop$,
collectionStartDelay
);

expect(monitorEventLoopDelay).toBeCalledTimes(1);
expect(mockMonitorPercentile).toBeCalledTimes(0);
jest.advanceTimersByTime(collectionStartDelay);
expect(mockMonitorPercentile).toBeCalled();
});

it('stores event loop delays every collectionInterval duration', () => {
const collectionStartDelay = 100;
const collectionInterval = 1000;
startTrackingEventLoopDelaysUsage(
mockInternalRepository,
stopMonitoringEventLoop$,
collectionStartDelay,
collectionInterval
);

expect(mockInternalRepository.create).toBeCalledTimes(0);
jest.advanceTimersByTime(collectionStartDelay);
expect(mockInternalRepository.create).toBeCalledTimes(1);
jest.advanceTimersByTime(collectionInterval);
expect(mockInternalRepository.create).toBeCalledTimes(2);
jest.advanceTimersByTime(collectionInterval);
expect(mockInternalRepository.create).toBeCalledTimes(3);
});

it('resets histogram every histogramReset duration', () => {
const collectionStartDelay = 0;
const collectionInterval = 1000;
const histogramReset = 5000;
startTrackingEventLoopDelaysUsage(
mockInternalRepository,
stopMonitoringEventLoop$,
collectionStartDelay,
collectionInterval,
histogramReset
);

expect(mockMonitorReset).toBeCalledTimes(0);
jest.advanceTimersByTime(collectionInterval * 5);
expect(mockMonitorReset).toBeCalledTimes(1);
jest.advanceTimersByTime(collectionInterval * 5);
expect(mockMonitorReset).toBeCalledTimes(2);
});

it('stops monitoring event loop delays once stopMonitoringEventLoop$.next is called', () => {
startTrackingEventLoopDelaysUsage(mockInternalRepository, stopMonitoringEventLoop$);

expect(mockMonitorDisable).toBeCalledTimes(0);
stopMonitoringEventLoop$.next();
expect(mockMonitorDisable).toBeCalledTimes(1);
});
});
Original file line number Diff line number Diff line change
Expand Up @@ -8,16 +8,7 @@

import type { EventLoopDelayMonitor } from 'perf_hooks';
import { monitorEventLoopDelay } from 'perf_hooks';
import { takeUntil, finalize, map } from 'rxjs/operators';
import { Observable, timer } from 'rxjs';
import type { ISavedObjectsRepository } from 'kibana/server';
import {
MONITOR_EVENT_LOOP_DELAYS_START,
MONITOR_EVENT_LOOP_DELAYS_INTERVAL,
MONITOR_EVENT_LOOP_DELAYS_RESET,
MONITOR_EVENT_LOOP_DELAYS_RESOLUTION,
} from './constants';
import { storeHistogram } from './saved_objects';
import { MONITOR_EVENT_LOOP_DELAYS_RESOLUTION } from './constants';

export interface IntervalHistogram {
fromTimestamp: string;
Expand Down Expand Up @@ -77,33 +68,3 @@ export class EventLoopDelaysCollector {
this.loopMonitor.disable();
}
}

/**
* The monitoring of the event loop starts immediately.
* The first collection of the histogram happens after 1 minute.
* The daily histogram data is updated every 1 hour.
*/
export function startTrackingEventLoopDelaysUsage(
internalRepository: ISavedObjectsRepository,
stopMonitoringEventLoop$: Observable<void>,
collectionStartDelay = MONITOR_EVENT_LOOP_DELAYS_START,
collectionInterval = MONITOR_EVENT_LOOP_DELAYS_INTERVAL,
histogramReset = MONITOR_EVENT_LOOP_DELAYS_RESET
) {
const eventLoopDelaysCollector = new EventLoopDelaysCollector();

const resetOnCount = Math.ceil(histogramReset / collectionInterval);
timer(collectionStartDelay, collectionInterval)
.pipe(
map((i) => (i + 1) % resetOnCount === 0),
takeUntil(stopMonitoringEventLoop$),
finalize(() => eventLoopDelaysCollector.stop())
)
.subscribe(async (shouldReset) => {
const histogram = eventLoopDelaysCollector.collect();
if (shouldReset) {
eventLoopDelaysCollector.reset();
}
await storeHistogram(histogram, internalRepository);
});
}
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@
* Side Public License, v 1.
*/

export { startTrackingEventLoopDelaysUsage } from './event_loop_delays';
export { registerEventLoopDelaysCollector } from './event_loop_delays_usage_collector';
export { startTrackingEventLoopDelaysThreshold } from './track_threshold';
export { startTrackingEventLoopDelaysUsage } from './track_delays';
export { SAVED_OBJECTS_DAILY_TYPE } from './saved_objects';
Original file line number Diff line number Diff line change
@@ -0,0 +1,81 @@
/*
* Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
* or more contributor license agreements. Licensed under the Elastic License
* 2.0 and the Server Side Public License, v 1; you may not use this file except
* in compliance with, at your election, the Elastic License 2.0 or the Server
* Side Public License, v 1.
*/

import { Subject } from 'rxjs';

import {
mockMonitorPercentile,
monitorEventLoopDelay,
mockMonitorReset,
mockMonitorDisable,
} from './event_loop_delays.mocks';
import { savedObjectsRepositoryMock } from '../../../../../core/server/mocks';
import { startTrackingEventLoopDelaysUsage } from './track_delays';

describe('startTrackingEventLoopDelaysUsage', () => {
const mockInternalRepository = savedObjectsRepositoryMock.create();
const stopMonitoringEventLoop$ = new Subject<void>();

beforeAll(() => jest.useFakeTimers('modern'));
beforeEach(() => jest.clearAllMocks());
afterEach(() => stopMonitoringEventLoop$.next());

it('initializes EventLoopDelaysCollector and starts timer', () => {
const collectionStartDelay = 1000;
startTrackingEventLoopDelaysUsage(mockInternalRepository, stopMonitoringEventLoop$, {
collectionStartDelay,
});

expect(monitorEventLoopDelay).toBeCalledTimes(1);
expect(mockMonitorPercentile).toBeCalledTimes(0);
jest.advanceTimersByTime(collectionStartDelay);
expect(mockMonitorPercentile).toBeCalled();
});

it('stores event loop delays every collectionInterval duration', () => {
const collectionStartDelay = 100;
const collectionInterval = 1000;
startTrackingEventLoopDelaysUsage(mockInternalRepository, stopMonitoringEventLoop$, {
collectionStartDelay,
collectionInterval,
});

expect(mockInternalRepository.create).toBeCalledTimes(0);
jest.advanceTimersByTime(collectionStartDelay);
expect(mockInternalRepository.create).toBeCalledTimes(1);
jest.advanceTimersByTime(collectionInterval);
expect(mockInternalRepository.create).toBeCalledTimes(2);
jest.advanceTimersByTime(collectionInterval);
expect(mockInternalRepository.create).toBeCalledTimes(3);
});

it('resets histogram every histogramReset duration', () => {
const collectionStartDelay = 0;
const collectionInterval = 1000;
const histogramReset = 5000;
startTrackingEventLoopDelaysUsage(mockInternalRepository, stopMonitoringEventLoop$, {
collectionStartDelay,
collectionInterval,
histogramReset,
});

expect(mockMonitorReset).toBeCalledTimes(0);
jest.advanceTimersByTime(collectionInterval * 5);
expect(mockMonitorReset).toBeCalledTimes(1);
jest.advanceTimersByTime(collectionInterval * 5);
expect(mockMonitorReset).toBeCalledTimes(2);
});

it('stops monitoring event loop delays once stopMonitoringEventLoop$.next is called', () => {
startTrackingEventLoopDelaysUsage(mockInternalRepository, stopMonitoringEventLoop$);

expect(mockMonitorDisable).toBeCalledTimes(0);
stopMonitoringEventLoop$.next();
expect(mockMonitorDisable).toBeCalledTimes(1);
});
});
Original file line number Diff line number Diff line change
@@ -0,0 +1,56 @@
/*
* Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
* or more contributor license agreements. Licensed under the Elastic License
* 2.0 and the Server Side Public License, v 1; you may not use this file except
* in compliance with, at your election, the Elastic License 2.0 or the Server
* Side Public License, v 1.
*/

import { takeUntil, finalize, map } from 'rxjs/operators';
import { Observable, timer } from 'rxjs';
import type { ISavedObjectsRepository } from 'kibana/server';
import {
MONITOR_EVENT_LOOP_DELAYS_START,
MONITOR_EVENT_LOOP_DELAYS_INTERVAL,
MONITOR_EVENT_LOOP_DELAYS_RESET,
} from './constants';
import { storeHistogram } from './saved_objects';
import { EventLoopDelaysCollector } from './event_loop_delays';

/**
* The monitoring of the event loop starts immediately.
* The first collection of the histogram happens after 1 minute.
* The daily histogram data is updated every 1 hour.
*/
export function startTrackingEventLoopDelaysUsage(
internalRepository: ISavedObjectsRepository,
stopMonitoringEventLoop$: Observable<void>,
configs: {
collectionStartDelay?: number;
collectionInterval?: number;
histogramReset?: number;
} = {}
) {
const {
collectionStartDelay = MONITOR_EVENT_LOOP_DELAYS_START,
collectionInterval = MONITOR_EVENT_LOOP_DELAYS_INTERVAL,
histogramReset = MONITOR_EVENT_LOOP_DELAYS_RESET,
} = configs;

const eventLoopDelaysCollector = new EventLoopDelaysCollector();
const resetOnCount = Math.ceil(histogramReset / collectionInterval);

timer(collectionStartDelay, collectionInterval)
.pipe(
map((i) => (i + 1) % resetOnCount === 0),
takeUntil(stopMonitoringEventLoop$),
finalize(() => eventLoopDelaysCollector.stop())
)
.subscribe(async (shouldReset) => {
const histogram = eventLoopDelaysCollector.collect();
if (shouldReset) {
eventLoopDelaysCollector.reset();
}
await storeHistogram(histogram, internalRepository);
});
}
Loading