Обзор
Триггер: Член набора реплик перестает отвечать на запросы.
Проблема: Драйвер продолжит маршрутизировать запросы на подключение кнеотвечающий член набора реплик.Потоки, ожидающие ответа или соединения, накапливаются «перед» этим элементом, пока они в конечном итоге не исчерпают пул потоков приложения.Целое приложение останавливается на несколько минут, пока не истечет время ожидания или возврата потоков.
Мои вопросы: Эта проблема меня действительно удивляет - не должен ли драйвер принять распределение потоков между членами набора реплик вучетная запись при принятии решения, к какому участнику направлять запросы?Как другие пользователи справляются с этим поведением?
Я создал пример проекта (https://github.com/McKeeAtx/mongo-java-driver-degradation-example), который демонстрирует, как один не отвечающий элемент набора реплик делает клиентское приложение не отвечающим в течение нескольких минут.во время тестирования использовалась локальная настройка:
- OpenJDK 1.8.0_121
- macOS High Sierra 10.13.6
- версия mongod v3.4.20
- mongo-java-driver 3.10.2
Начальная настройка
Создание трех пустых каталогов rs0-0
, rs0-1
и rs0-2
.
Запуск трех экземпляров mongod:
mongod --replSet rs0 --port 27017 --bind_ip 127.0.0.1 --dbpath rs0-0 --smallfiles --oplogSize 128
mongod --replSet rs0 --port 27018 --bind_ip 127.0.0.1 --dbpath rs0-1 --smallfiles --oplogSize 128
mongod --replSet rs0 --port 27019 --bind_ip 127.0.0.1 --dbpath rs0-2 --smallfiles --oplogSize 128
Войдите в оболочку mongo и настройте набор реплик
mongo
> rsconf = { _id: "rs0", members: [ { _id: 0, host: "127.0.0.1:27017" }, { _id: 1, host: "127.0.0.1:27018" }, { _id: 2, host: "127.0.0.1:27019" } ] }
> rs.initiate(rsconf)
{ "ok" : 1 }
Создайте тестовую базу данных:
rs0:PRIMARY> use test
mongo
switched to db test
Запустите DataFixture
, чтобы вставить 10000документы в коллекцию test
в базе данных test
.
Запуск примера
Запуск трех экземпляров mongod:
mongod --replSet rs0 --port 27017 --bind_ip 127.0.0.1 --dbpath rs0-0 --smallfiles --oplogSize 128
mongod --replSet rs0 --port 27018 --bind_ip 127.0.0.1 --dbpath rs0-1 --smallfiles --oplogSize 128
mongod --replSet rs0 --port 27019 --bind_ip 127.0.0.1 --dbpath rs0-2 --smallfiles --oplogSize 128
Запустите приложение Consumer
.
ConnectionHistogramListener
регистрирует простую гистограмму каждый раз, когда ConnectionPoolWaitQueueEnteredEvent
событие iОпубликовано:
connected
: нет потоков, которые установили соединение с участником waiting
: нет потоков, ожидающих подключения к члену
Пример:
11:47:41 [pool-2-thread-2] - connect to 127.0.0.1:27019: {127.0.0.1:27019[connected: 2, waiting: 1],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 0]}
Вышеприведенная строка гласит:
- подключиться к 127.0.0.1:27019: драйвервыбирает 127.0.0.1: 27019 для следующего запроса на подключение
- 127.0.0.1: 27019 [подключено: 2, ожидание: 1] : 2 потока подключены к 127.0.0.1: 27019 , 1 поток ожидает подключения
- 127.0.0.1: 27018 [подключено: 0, ожидание: 0] : 0 потоков подключено к 127.0.0.1: 27018 , 0 потоков ожидают подключения
- 127.0.0.1: 27017 [подключено: 0, ожидание: 0] : 0 потоков подключенодо 127.0.0.1: 27017 , 0 потоков ожидают подключения
Удалите один элемент набора реплик
Определите PID
набора репликчлен:
ps -ef | grep mongo | grep "replSet"
501 24989 11889 0 7:42AM ttys001 0:30.81 mongod --replSet rs0 --port 27017 --bind_ip 127.0.0.1 --dbpath rs0-0 --smallfiles --oplogSize 128
501 24990 11905 0 7:42AM ttys002 0:30.02 mongod --replSet rs0 --port 27018 --bind_ip 127.0.0.1 --dbpath rs0-1 --smallfiles --oplogSize 128
501 24991 11922 0 7:42AM ttys005 0:30.03 mongod --replSet rs0 --port 27019 --bind_ip 127.0.0.1 --dbpath rs0-2 --smallfiles --oplogSize 128
В этом примере мы выбираем 24991
(член, который прослушивает порт 27019).
Используйте cpulimit
, чтобы уменьшить процент ЦП, который будет назначен этому процессу:
cpulimit -p 24991 -l 0
Process 24991 found
Алгоритм выбора сервера теперь продолжает циклически обрабатывать запросы на соединение между тремя членами набора реплик.Все участники считаются
- приемлемыми
- не устаревшими
- и в пределах окна задержки.
Пример журнала:
11:47:34 [pool-2-thread-1] - Roundtrip times (micro): {127.0.0.1:27019: 3257, 127.0.0.1:27018: 3286, 127.0.0.1:27017: 2081}
11:47:34 [pool-2-thread-1] - connect to 127.0.0.1:27019: {127.0.0.1:27019[connected: 0, waiting: 1],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 0]}
11:47:34 [pool-2-thread-1] - connect to 127.0.0.1:27019: {127.0.0.1:27019[connected: 0, waiting: 1],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 0]}
11:47:35 [pool-2-thread-2] - Roundtrip times (micro): {127.0.0.1:27019: 3257, 127.0.0.1:27018: 3286, 127.0.0.1:27017: 2081}
11:47:35 [pool-2-thread-2] - connect to 127.0.0.1:27017: {127.0.0.1:27019[connected: 0, waiting: 0],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 1]}
11:47:35 [pool-2-thread-2] - connect to 127.0.0.1:27017: {127.0.0.1:27019[connected: 0, waiting: 0],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 1]}
// now the node 127.0.0.1:27019 is 'frozen'
cpulimit -p 24991 -l 0
Process 24991 found
11:47:36 [pool-2-thread-3] - Roundtrip times (micro): {127.0.0.1:27019: 3257, 127.0.0.1:27018: 3286, 127.0.0.1:27017: 2081}
11:47:36 [pool-2-thread-3] - connect to 127.0.0.1:27017: {127.0.0.1:27019[connected: 0, waiting: 0],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 1]}
11:47:36 [pool-2-thread-3] - connect to 127.0.0.1:27017: {127.0.0.1:27019[connected: 0, waiting: 0],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 1]}
11:47:37 [pool-2-thread-4] - Roundtrip times (micro): {127.0.0.1:27019: 3257, 127.0.0.1:27018: 3286, 127.0.0.1:27017: 2081}
11:47:37 [pool-2-thread-4] - connect to 127.0.0.1:27019: {127.0.0.1:27019[connected: 0, waiting: 1],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 0]}
11:47:38 [pool-2-thread-5] - Roundtrip times (micro): {127.0.0.1:27019: 3257, 127.0.0.1:27018: 3286, 127.0.0.1:27017: 2081}
11:47:38 [pool-2-thread-5] - connect to 127.0.0.1:27019: {127.0.0.1:27019[connected: 1, waiting: 1],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 0]}
11:47:39 [pool-2-thread-6] - Roundtrip times (micro): {127.0.0.1:27019: 3257, 127.0.0.1:27018: 3286, 127.0.0.1:27017: 2081}
11:47:39 [pool-2-thread-6] - connect to 127.0.0.1:27017: {127.0.0.1:27019[connected: 2, waiting: 0],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 1]}
11:47:39 [pool-2-thread-6] - connect to 127.0.0.1:27017: {127.0.0.1:27019[connected: 2, waiting: 0],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 1]}
11:47:40 [pool-2-thread-1] - Roundtrip times (micro): {127.0.0.1:27019: 3257, 127.0.0.1:27018: 3286, 127.0.0.1:27017: 2081}
11:47:40 [pool-2-thread-1] - connect to 127.0.0.1:27018: {127.0.0.1:27019[connected: 2, waiting: 0],127.0.0.1:27018[connected: 0, waiting: 1],127.0.0.1:27017[connected: 0, waiting: 0]}
11:47:40 [pool-2-thread-1] - connect to 127.0.0.1:27018: {127.0.0.1:27019[connected: 2, waiting: 0],127.0.0.1:27018[connected: 0, waiting: 1],127.0.0.1:27017[connected: 0, waiting: 0]}
11:47:41 [pool-2-thread-2] - Roundtrip times (micro): {127.0.0.1:27019: 3257, 127.0.0.1:27018: 3286, 127.0.0.1:27017: 2081}
11:47:41 [pool-2-thread-2] - connect to 127.0.0.1:27019: {127.0.0.1:27019[connected: 2, waiting: 1],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 0]}
11:47:42 [pool-2-thread-3] - Roundtrip times (micro): {127.0.0.1:27019: 3257, 127.0.0.1:27018: 3286, 127.0.0.1:27017: 2081}
11:47:42 [pool-2-thread-3] - connect to 127.0.0.1:27019: {127.0.0.1:27019[connected: 2, waiting: 2],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 0]}
11:47:43 [pool-2-thread-6] - Roundtrip times (micro): {127.0.0.1:27019: 3257, 127.0.0.1:27018: 3286, 127.0.0.1:27017: 2081}
11:47:43 [pool-2-thread-6] - connect to 127.0.0.1:27018: {127.0.0.1:27019[connected: 2, waiting: 2],127.0.0.1:27018[connected: 0, waiting: 1],127.0.0.1:27017[connected: 0, waiting: 0]}
11:47:43 [pool-2-thread-6] - connect to 127.0.0.1:27018: {127.0.0.1:27019[connected: 2, waiting: 2],127.0.0.1:27018[connected: 0, waiting: 1],127.0.0.1:27017[connected: 0, waiting: 0]}
11:47:44 [pool-2-thread-1] - Roundtrip times (micro): {127.0.0.1:27019: 3257, 127.0.0.1:27018: 3286, 127.0.0.1:27017: 2081}
11:47:44 [pool-2-thread-1] - connect to 127.0.0.1:27019: {127.0.0.1:27019[connected: 2, waiting: 3],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 0]}
11:47:45 [pool-2-thread-6] - Roundtrip times (micro): {127.0.0.1:27019: 3257, 127.0.0.1:27018: 2885, 127.0.0.1:27017: 1917}
11:47:45 [pool-2-thread-6] - connect to 127.0.0.1:27019: {127.0.0.1:27019[connected: 2, waiting: 4],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 0]}
Узел 127.0.0.1:27019
не отвечает на запросы своевременно, но он по-прежнему выбирается алгоритмом выбора сервера, потому что он все еще попадает в допустимое окно задержки в соответствии с устаревшими (!) Данными туда-обратно.С каждым решением в пользу 127.0.0.1:27019
другой поток накапливается в ожидании ответа или соединения.
Сокращенная версия вышеприведенного журнала показывает, как потоки накапливаются в ожидании 127.0.0.1:27019
:
127.0.0.1:27019[connected: 0, waiting: 0],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 1]}
127.0.0.1:27019[connected: 0, waiting: 0],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 1]}
127.0.0.1:27019[connected: 0, waiting: 1],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 0]}
127.0.0.1:27019[connected: 1, waiting: 1],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 0]}
127.0.0.1:27019[connected: 2, waiting: 0],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 1]}
127.0.0.1:27019[connected: 2, waiting: 0],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 1]}
127.0.0.1:27019[connected: 2, waiting: 0],127.0.0.1:27018[connected: 0, waiting: 1],127.0.0.1:27017[connected: 0, waiting: 0]}
127.0.0.1:27019[connected: 2, waiting: 0],127.0.0.1:27018[connected: 0, waiting: 1],127.0.0.1:27017[connected: 0, waiting: 0]}
127.0.0.1:27019[connected: 2, waiting: 1],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 0]}
127.0.0.1:27019[connected: 2, waiting: 2],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 0]}
127.0.0.1:27019[connected: 2, waiting: 2],127.0.0.1:27018[connected: 0, waiting: 1],127.0.0.1:27017[connected: 0, waiting: 0]}
127.0.0.1:27019[connected: 2, waiting: 2],127.0.0.1:27018[connected: 0, waiting: 1],127.0.0.1:27017[connected: 0, waiting: 0]}
127.0.0.1:27019[connected: 2, waiting: 3],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 0]}
127.0.0.1:27019[connected: 2, waiting: 4],127.0.0.1:27018[connected: 0, waiting: 0],127.0.0.1:27017[connected: 0, waiting: 0]}
В конечном итоге все потоки в пуле потоков приложения (фиксированный пул с 6 потоками впример приложения) будет ожидать 127.0.0.1:27019
, в результате чего все приложение не отвечает, хотя члены набора реплик 127.0.0.1:27017
и 127.0.0.1:27018
могут по-прежнему обслуживать запросы.
Через пару минут потоки, ожидающие 127.0.0.1:27019
, либо возвращаются, либо истекают, и драйвер останавливает для направления дальнейших запросов на 127.0.0.1:27019
. Затем приложение восстанавливается, распределяя трафик между членами набора исправных реплик 127.0.0.1:27017
и 127.0.0.1:27018
.
С точки зрения пользователей, такое поведение вызывает полный сбой клиентского приложения, который длится несколько минут.
Consumer.java
public class Consumer {
public static void main( String[] args ) throws ExecutionException, InterruptedException, IOException {
MongoClient client = Configuration.createClient(true);
MongoDatabase db = client.getDatabase("test");
final MongoCollection<Document> customers = db.getCollection("test");
ExecutorService executorService = Executors.newFixedThreadPool(6);
for (;;) {
executorService.submit(() -> {
FindIterable<Document> documents = customers.find();
documents.into(new LinkedList<>());
});
Thread.sleep(1000);
}
}
}
Configuration.java
public class Configuration {
private static ClusterConnectionMode mode = ClusterConnectionMode.MULTIPLE;
private static int minConnections = 2;
private static int maxConnections = 2;
private static int maxWaitQueueSize = 6;
private static int connectionTimeoutInMs = 500;
private static int readTimeoutInSeconds = 45;
static List<ServerAddress> servers = asList(
new ServerAddress("127.0.0.1", 27017),
new ServerAddress("127.0.0.1", 27018),
new ServerAddress("127.0.0.1", 27019)
);
static MongoClient createClient(boolean withHistogramListener) {
return MongoClients.create(MongoClientSettings.builder()
.applyToConnectionPoolSettings(builder -> builder.applySettings(
ConnectionPoolSettings.builder()
.addConnectionPoolListener(withHistogramListener ? new ConnectionHistogramListener() : new NoOpListener())
.minSize(minConnections)
.maxSize(maxConnections)
.maxWaitQueueSize(maxWaitQueueSize)
.build()))
.readPreference(ReadPreference.nearest())
.applyToSocketSettings(builder -> builder.applySettings(
SocketSettings.builder()
.connectTimeout(connectionTimeoutInMs, TimeUnit.MILLISECONDS)
.readTimeout(readTimeoutInSeconds, TimeUnit.SECONDS)
.build()
))
.applyToClusterSettings(builder -> builder.applySettings(
ClusterSettings.builder()
.mode(mode)
.hosts(servers)
.maxWaitQueueSize(maxWaitQueueSize)
.serverSelector(new RoundtripTimeTracingSelector())
.build()))
.build());
}
}