java - online - ¿Qué causó que las conexiones de zócalo fueran lentas después de Full GC?

gc analyzer online (4)

Tenemos una aplicación de servidor de cliente, 1 servidor, unos 10 clientes. Se comunican a través de sockets tcp mediante consultas personalizadas.

El sistema había funcionado sin problemas durante muchos meses, pero en algún momento, después del servidor FULL GC programado a diario que demoraba unos 50 s , descubrimos que el tiempo entre las consultas enviadas por el cliente y las respuestas recibidas del servidor era grande,> 10-20s. Después de unas 3 horas, el sistema se recuperó y todo volvió a funcionar bien.

Al investigar el tema, encontramos:

No hay problemas de recolección de basura en los clientes y el servidor
El tiempo de procesamiento de consultas en el servidor era pequeño.
La carga en el servidor era alta.
El ancho de banda de la red no estaba saturado.
Las conexiones no se restablecieron durante el FULL GC (el FULL GC diario era un evento normal hasta ese momento)
La máquina y el sistema operativo cambiaron recientemente de Centos 6 (kernel 2.6.32) a Centos 7 (kernel 3.10.0), pero la nueva configuración se probó ampliamente. También la versión de Oracle JDK cambió de 1.7.65 a 1.7.75.

Tomamos un volcado de hilo en el servidor:

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)

El FilterInputStream.read() es el siguiente:

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

El in en nuestro código es un BufferedInputStream .

Las preguntas son: ¿Por qué la mayoría de las conexiones se desaceleraron después de la pausa de GC total? ¿Por qué el stacktrace termina en FilterInputStream.read() ? ¿No debería terminar en algún lugar del flujo de entrada BufferedInputStream o en el flujo de entrada de socket? ¿Puede esta lectura llevar a una alta carga en el servidor?

El código que usamos para leer:

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();

dónde:

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

Aquí está el seguimiento de pila de las conexiones de cliente que funcionan bien:

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)

ACTUALIZAR:

Respecto a la respuesta EJP:

No hubo EOS involucrado, las conexiones estaban arriba, pero eran muy lentas
Incluso si hubiera una EOS, no puedo ver cómo el código podría girar en la EOS, el for está delimitado por el valor constructLength . Pero aún así, la mejora sugerida es válida.
El stacktrace con el problema termina en una lectura realizada en un DataInputStream ( (_socketDIS.read() ) que se hereda de FilterInputStream.read() , consulte el código anterior. DataInputStream , no BufferedInputStream no se encuentra en la read() . Aquí, en FilterInputStream.read() hay un in.read() llamado en un BufferedInputStream , este tiene su propio método de read() definido. Pero el stacktrace se detiene en el medio, no llega a BufferedInputStream.read() . ¿Por qué?

El seguimiento de la pila muestra que está utilizando un ScheduledThreadPoolExecutor . Te sugiero que estudies el horario. Es probable que los retrasos sean meramente porque la lectura está en algún tipo de horario, lo que me parece una tontería.

Esto es más un comentario extendido, pero es demasiado largo para un comentario, así que lo proporcionaré en una respuesta.

Como ha notado, el volcado de hilos que muestra un hilo en medio de FilterInputStream.read () es inusual. Aunque podría suceder por casualidad, mientras que el FilterInputStream.read () anulado se está resolviendo en BufferedInputStream.read (), el suceso por casualidad parece bastante improbable.

Dado que esto sucedió después de una recolección de basura completa, me parece más probable que tardara más en resolver la llamada FilterInputStream porque la clase BufferedInputStream se movió o descargó durante la recolección de basura completa. Por ejemplo, si por casualidad no hubiera objetos BufferedInputStream en uso cuando se produjo la recolección de basura completa, la clase BufferedInputStream podría haberse descargado, lo que requeriría la carga de la clase cuando se necesitaba su método read (). Esto podría explicar el retraso que vio, al menos una vez.

En algunas situaciones es posible que las clases se descarguen cuando la última de sus instancias es la recolección de basura, incluso en ausencia de una recolección de basura completa. Si la clase BufferedInputStream se descargase de alguna manera después de cada uso y se volviera a cargar la próxima vez que se usara, eso podría explicar los síntomas que dice, pero normalmente no espero que eso suceda.

También es posible que haya una paliza en la página de memoria que contenía la clase BufferedInputStream, tal vez porque la clase se reubicó durante la recolección de elementos no utilizados completa, si estaba usando memoria virtual. Si tiene algún registro sobre el uso de la memoria durante este tiempo, puede que valga la pena verlo.

La lectura de un byte a la vez es un desperdicio de CPU. Deseche esto:

y usa esto:

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

NB _socketDIS claramente no es un BufferedInputStream sino un DataInputStream, que no tiene buffers.

EDITAR

¿Por qué el stacktrace termina en FilterInputStream.read ()?

Mira cuidadosamente. BufferedInputStream no implementa las tres sobrecargas de lectura (). Uno de ellos, olvido cuál, se implementa en FilterInputStream, la clase base, y las otras dos sobrecargas lo llaman.

¿No debería terminar en algún lugar del BufferedInputStream?

No, ver más arriba.

o en el flujo de entrada de socket?

Sí, si estaba bloqueando, pero no lo está, probablemente porque estás girando al final de la transmisión, debido a tu pobre código.

¿Puede esta lectura llevar a una alta carga en el servidor?

Sí.

Supongo que debe intentar limpiarlo para leer y escribir en el flujo sin errores o ralentizar las conexiones.