Что привело к тому, что соединения сокетов были медленными после Full GC?

У нас есть клиентское серверное приложение, 1 сервер, около 10 клиентов. Они взаимодействуют через сокеты tcp, используя пользовательские запросы.

Система работала бесперебойно в течение многих месяцев, но в какой-то момент после ежедневного запланированного сервера FULL GC, который занял около 50 секунд, мы выяснили, что время между запросами, отправленными клиентом и ответы, полученные от сервера, были большими, > 10-20 с. Спустя примерно 3 часа система восстановилась, все снова стало нормально.

При исследовании проблемы мы обнаружили:

Нет проблем с сборкой мусора на обоих клиентах и сервере.
Время обработки запроса на сервере было небольшим.
Загрузка на сервер была высокой.
Полоса пропускания сети не была насыщенной.
Соединения не были reset во время FULL GC (ежедневный FULL GC был обычным событием до тех пор)
Аппарат и ОС недавно изменились с Centos 6 (ядро 2.6.32) до Centos 7 (ядро 3.10.0), но новая конфигурация была протестирована полностью. Также версия Oracle JDK изменилась с 1.7.65 до 1.7.75.

Мы взяли дамп потока на сервере:

java.lang.Thread.State: RUNNABLE
    at java.io.FilterInputStream.read(FilterInputStream.java:83)
    at util.network.BytesBasedSocketConnection$ReadConnectionRunnable.run(BytesBasedSocketConnection.java:293)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:745)

FilterInputStream.read():

    public int read() throws IOException {
    return in.read();
}

in в нашем коде есть BufferedInputStream.

Вопросы: почему большинство соединений замедлилось после полной паузы GC? Почему stacktrace заканчивается на FilterInputStream.read()? Разве он не должен заканчиваться где-то в BufferedInputStream или во входном потоке сокета? Может ли это прочитать привести к высокой нагрузке на сервер?

Код, который мы используем для чтения:

int constructLength = _socketDIS.readInt();
ByteArrayOutputStream constructBOAS = new ByteArrayOutputStream(constructLength);
for (int i = 0; i != constructLength; i++)
      constructBOAS.write(_socketDIS.read());
constructBOAS.close();
byte[] bytes = constructBOAS.toByteArray();

где:

_socketDIS = new DataInputStream(new BufferedInputStream(_socket.getInputStream()));

Вот стек из хорошо работающих клиентских подключений:

java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.read(SocketInputStream.java:152)
    at java.net.SocketInputStream.read(SocketInputStream.java:122)
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:254)
    - locked <0x00007f522cbebca8> (a java.io.BufferedInputStream)
    at java.io.DataInputStream.readInt(DataInputStream.java:387)
    at util.network.BytesBasedSocketConnection$ReadConnectionRunnable.run(BytesBasedSocketConnection.java:287)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:745)

UPDATE:

Относительно ответа EJP:

Не было задействовано EOS, соединения были вверх, но они были очень медленными
Даже если бы EOS я не мог видеть, как код мог бы вращаться в EOS, for ограничивается значением constructLength. Тем не менее, предлагаемое улучшение действительно.
Столбец с проблемой заканчивается прочитанным в DataInputStream ((_socketDIS.read()), который наследуется от FilterInputStream.read(), см. выше код. DataInputStream, а не BufferedInputStream отсутствует read(). Здесь в FilterInputStream.read() существует in.read(), вызываемый в BufferedInputStream, этот имеет свой собственный метод read(). Но stacktrace останавливается посередине, не достигает BufferedInputStream.read(). Почему?

Ответ 1

Чтение одного байта за раз в расточительство CPU. Бросьте это:

int constructLength = _socketDIS.readInt();
ByteArrayOutputStream constructBOAS = new ByteArrayOutputStream(constructLength);
for (int i = 0; i != constructLength; i++)
      constructBOAS.write(_socketDIS.read());
constructBOAS.close();
byte[] bytes = constructBOAS.toByteArray();

и используйте это:

int constructLength = _socketDIS.readInt();
byte[] bytes = new byte[constructLength];
_socketDIS.readFully(bytes);

NB _socketDIS, очевидно, не является BufferedInputStream, но a DataInputStream,, который не загружен.

ИЗМЕНИТЬ

Почему stacktrace заканчивается в FilterInputStream.read()?

Посмотрите внимательно. BufferedInputStream не реализует все три чтения() перегрузки. Один из них, я забыл, что, реализовано в FilterInputStream, базовый класс, а остальные две перегрузки называют это.

Не должен ли он заканчиваться где-то в BufferedInputStream

Нет, см. выше.

или во входном потоке сокета?

Да, если он блокирует, но это не так, возможно, потому, что вы вращаетесь в конце потока из-за вашего плохого кода.

Может ли это прочитать привести к высокой нагрузке на сервер?

Да.

Ответ 2

Трассировка стека показывает, что вы используете ScheduledThreadPoolExecutor. Я бы посоветовал вам изучить расписание. Вполне вероятно, что задержки - это просто потому, что чтение относится к какому-то графику, что кажется мне глупым.

Ответ 3

Это скорее расширенный комментарий, но он слишком длинный для комментария, поэтому я предоставлю его в ответ.

Как вы заметили, дамп потока, показывающий поток в середине FilterInputStream.read(), необычен. Хотя это может произойти случайно, в то время как переопределенный FilterInputStream.read() решается в BufferedInputStream.read(), случайный случай кажется маловероятным.

Учитывая, что это произошло после полной сборки мусора, мне кажется более вероятным, что потребовалось больше времени, чтобы разрешить вызов FilterInputStream, потому что класс BufferedInputStream был перемещен или выгружен во время полной сборки мусора. Например, если случайно не были задействованы объекты BufferedInputStream, когда была собрана полная сборка мусора, класс BufferedInputStream мог быть выгружен, требуя загрузки классов, когда был необходим метод read(). Это может объяснить задержку, которую вы видели, по крайней мере один раз.

В некоторых ситуациях для классов можно разгрузить, когда последний из их экземпляров собирает мусор даже при отсутствии полной сборки мусора. Если класс BufferedInputStream каким-то образом выгружался после каждого использования и перезагружался в следующий раз, когда он использовался, это могло бы объяснить симптомы, которые вы говорите, но я обычно не ожидал, что это произойдет.

Также возможно, что на странице памяти, содержащей класс BufferedInputStream, произошла ошибка, возможно, потому, что класс был перемещен во время полной сборки мусора, если вы использовали виртуальную память. Если у вас есть записи об использовании памяти в течение этого времени, они могут быть полезны.

Ответ 4

Я думаю, вы должны попытаться очистить его, чтобы читать и писать в потоке без ошибок или замедлять соединения.