Какво причини бавните връзки на сокета след Full GC?

Имаме приложение за клиентски сървър, 1 сървър, около 10 клиента. Те комуникират чрез tcp сокети, използвайки персонализирани заявки.

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

Докато проучвахме проблема, открихме:

  1. Няма проблеми със събирането на отпадъци както на клиентите, така и на сървъра
  2. Времето за обработка на заявката на сървъра беше малко.
  3. Натоварването на сървъра беше високо.
  4. Честотната лента на мрежата не беше наситена.
  5. Връзките не бяха нулирани по време на FULL GC (ежедневният FULL GC беше нормално събитие дотогава)
  6. Машината и операционната система наскоро се промениха от 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? Защо проследяването на стека завършва на 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)

АКТУАЛИЗАЦИЯ:

Относно отговора на EJP:

  1. Нямаше включен EOS, връзките бяха активирани, но бяха много бавни

  2. Дори и да имаше EOS, не виждам как кодът може да се върти в EOS, for е ограничен от стойността constructLength. Но все пак предложеното подобрение е валидно.

  3. Проследяването на стека с проблема завършва с четене, извършено на DataInputStream ((_socketDIS.read()), което е наследено от FilterInputStream.read(), вижте кода по-горе. DataInputStream, а не BufferedInputStream липсва read(). Тук в FilterInputStream.read() има in.read(), извикан на BufferedInputStream, този има собствен дефиниран метод read(). Но проследяването на стека спира по средата, не достига BufferedInputStream.read(). Защо?


person dcernahoschi    schedule 20.05.2015    source източник


Отговори (4)


Четенето на един байт наведнъж е разточително за процесора. Изхвърлете това:

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, а DataInputStream,, което не е буферирано.

РЕДАКТИРАНЕ

Защо stacktrace завършва във FilterInputStream.read()?

Гледай внимателно. BufferedInputStream не прилага и трите претоварвания read(). Един от тях, забравих кой, е имплементиран надолу във FilterInputStream, основния клас, а другите две претоварвания го наричат.

Не трябва ли да свършва някъде в BufferedInputStream

Не, виж по-горе.

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

Да, ако блокираше, но не е, вероятно защото се въртите в края на потока, поради лошия ви код.

Може ли това четене да доведе до голямо натоварване на сървъра?

да

person user207421    schedule 20.05.2015
comment
Добре, но през повечето време този код работи добре. И със сигурност _socketDIS е буфериран. Скоро ще кача друг stacktrace от връзки, който работи добре и използва същия код. - person dcernahoschi; 20.05.2015
comment
Както и да е, но това все пак е по-добър код. Той се грижи правилно за ъгловите случаи, например преждевременна EOS, където вашата просто се върти. - person user207421; 20.05.2015
comment
Благодаря, съгласен съм, че е по-добре, но не е проблемът тук, връзката остава жива през цялото време и в даден момент се възстановява, скоростта се връща към нормалното. - person dcernahoschi; 20.05.2015
comment
Разбира се, това е проблемът. Вашето собствено проследяване на стека го доказва. Вие сте заети в FilterInputStream.read(). Вие копирате байт в момент, когато бихте могли да направите всичко с едно четене. - person user207421; 21.05.2015
comment
Не е. Добавени са още обяснения във въпроса. Описано по-добре при какви условия се е появил проблемът. - person dcernahoschi; 21.05.2015
comment
Не е ако и само ако проблемът продължава да се случва с този код. Дали? - person user207421; 22.05.2015
comment
Случвало се е само веднъж в годината за 3 часа, в останалите времена за трансфер е няколко милиса с малко натоварване на сървъра, дори и в пикове. И този отговор не е издържан поради другите причини, посочени във въпроса. Въпреки че симптомите изглеждаха така, сякаш буферирането не е там. - person dcernahoschi; 22.05.2015
comment
Краят на потока може да настъпи по всяко време. Не е „ограничено от constructLength“, освен в един перфектен свят. Този не е идеален. - person user207421; 11.01.2018

Проследяването на стека показва, че използвате ScheduledThreadPoolExecutor. Предлагам ви да проучите графика. Вероятно закъсненията са просто защото четенето е по някакъв график - което ми се струва глупаво.

person OldCurmudgeon    schedule 20.05.2015
comment
А, наистина има ScheduledThreadPoolExecutor неправилно използван, но задачата е непрекъснато изпълнявана, тя просто чете заявки от сокет и ги поставя на опашка. - person dcernahoschi; 20.05.2015

Това е по-скоро разширен коментар, но е твърде дълъг за коментар, така че ще го предоставя в отговор.

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

Като се има предвид, че това се е случило след пълно събиране на боклука, струва ми се по-вероятно да отнеме повече време за разрешаване на извикването на FilterInputStream, тъй като класът BufferedInputStream е бил преместен или разтоварен по време на пълното събиране на боклук. Например, ако случайно не е имало използвани обекти BufferedInputStream, когато се е случило пълното събиране на отпадъци, класът BufferedInputStream може да е бил разтоварен, изисквайки зареждане на класа, когато е бил необходим неговият метод read(). Това може да обясни забавянето, което сте видели, поне веднъж.

Възможно е в някои ситуации класовете да бъдат разтоварени, когато последният им екземпляр е събран за боклук, дори при липса на пълно събиране за боклук. Ако класът BufferedInputStream по някакъв начин се разтоварва след всяко използване и презарежда следващия път, когато се използва, това може да обясни симптомите, които казвате, но обикновено не бих очаквал това да се случи.

Възможно е също да е имало разбиване на страницата с памет, която съдържа класа BufferedInputStream, може би защото класът е бил преместен по време на пълното събиране на боклука, ако сте използвали виртуална памет. Ако имате някакви записи относно използването на паметта през това време, може да си струва да ги разгледате.

person Warren Dew    schedule 23.05.2015
comment
Благодаря. BufferedInputStream екземплярите не трябваше да бъдат събирани за боклук, тъй като връзките на сокетите останаха живи. Не, паметта остана ниска, без кошче също. - person dcernahoschi; 23.05.2015

Предполагам, че трябва да опитате да го флъшнете, за да четете и пишете в потока без грешки или забавяне на връзките.

person Mrfrog    schedule 28.05.2015