2015-05-20 19 views
18

Abbiamo un'app server client, 1 server, circa 10 client. Comunicano tramite socket TCP usando le query personalizzate.Che cosa ha causato il rallentamento delle connessioni socket dopo Full GC?

Il sistema era stato buon funzionamento per molti mesi, ma ad un certo punto, dopo che il server programmata GC PIENA quotidiano che ha richiesto circa 50, abbiamo capito che il tempo tra le query inviate dal client e le risposte ricevute da il server era grande,> 10-20 secondi. Dopo circa 3 ore il sistema è stato ripristinato, tutto stava funzionando di nuovo bene.

Mentre indaga la questione, abbiamo trovato:

  1. Nessun problema di raccolta dei rifiuti su entrambi i client e il server
  2. tempo di elaborazione delle query sul server era piccola.
  3. Il carico sul server era alto.
  4. La larghezza di banda della rete non è stata saturata.
  5. I collegamenti non sono stati azzerati durante l'PIENO GC (GC completo giornaliero è stato un evento normale fino a quel momento)
  6. La macchina e il sistema operativo cambiato recentemente da CentOS 6 (kernel 2.6.32) a CentOS 7 (kernel 3.10.0) , ma la nuova configurazione è stata testata estensivamente. Anche la versione Oracle JDK è passata da 1.7.65 a 1.7.75.

Abbiamo preso una discarica filo sul server:

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) 

Il FilterInputStream.read() è la seguente:

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

Il in nel nostro codice è un BufferedInputStream.

Le domande sono: Perché la maggior parte delle connessioni è rallentata dopo la pausa GC completa? Perché lo stacktrace termina con FilterInputStream.read()? Non dovrebbe finire da qualche parte nello BufferedInputStream o nel flusso di input del socket? Questa lettura può comportare un carico elevato sul server?

Il codice che utilizziamo per la lettura:

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

dove:

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

Ecco la stacktrace dalle connessioni client e di lavoro:

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:

Per quanto riguarda la risposta EJP:

  1. Non c'era EOS coinvolti, i collegamenti erano su, ma erano molto lento

  2. Anche se ci fosse un EOS non riesco a vedere come il codice potrebbe filare a EOS, il valore for è limitato dal valore constructLength. Ma ancora, il miglioramento suggerito è valido.

  3. La stacktrace il problema termina in una lettura fatta su un DataInputStream ((_socketDIS.read()) che viene ereditato da FilterInputStream.read(), vedere codice precedente. DataInputStream, non BufferedInputStream manca il read(). Qui nel FilterInputStream.read() è presente un in.read() chiamato su BufferedInputStream, questo ha il proprio metodo read() definito. Ma lo stacktrace si ferma nel mezzo, non raggiunge lo BufferedInputStream.read(). Perché?

risposta

3

La traccia di stack indica che si sta utilizzando un ScheduledThreadPoolExecutor. Ti suggerirei di studiare il programma. È probabile che i ritardi siano semplicemente dovuti al fatto che la lettura è in qualche modo programmata, il che mi sembra pazzesco.

+0

Ah, infatti esiste un 'ScheduledThreadPoolExecutor' utilizzato in modo errato, ma l'attività è in esecuzione continua, legge solo le query dal socket e le inserisce in una coda. – dcernahoschi

7

Leggere un byte alla volta è uno spreco di CPU. Buttare via questo:

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

Utilizzando questo:

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

NB _socketDIS è chiaramente non un BufferedInputStream ma un DataInputStream, che è bufferizzato.

EDIT

Perché lo stacktrace finisce in FilterInputStream.read()?

Osservare attentamente. BufferedInputStream non implementa tutti e tre i sovraccarichi di read(). Uno di questi, ho dimenticato quale, è implementato in FilterInputStream, la classe base e gli altri due overload lo chiamano.

non dovrebbe finire da qualche parte nel BufferedInputStream

No, vedi sopra.

o nel flusso di input socket?

Sì, se si bloccava, ma non lo è, probabilmente perché stai girando alla fine del flusso, a causa del tuo codice scadente.

Questa lettura può comportare un carico elevato sul server?

Sì.

+0

Ok, ma la maggior parte delle volte questo codice funziona correttamente. E sicuramente '_socketDIS' è memorizzato nel buffer. Caricherò a breve un altro stacktrace dalle connessioni che funziona correttamente e che utilizza lo stesso codice. – dcernahoschi

+0

In ogni caso, ma questo è il codice migliore comunque. Si prende cura delle casse d'angolo in modo appropriato, ad esempio, EOS precoce, in cui i tuoi si limitano a spin-loop. – EJP

+0

Grazie, sono d'accordo che è meglio, ma non è il problema qui, la connessione rimane sempre viva e ad un certo punto recupera, la velocità ritorna normale. – dcernahoschi

1

Questo è più di un commento esteso, ma è troppo lungo per un commento, quindi fornirò una risposta.

Come si nota, il dump del thread che mostra un thread nel mezzo di FilterInputStream.read() è inusuale. Mentre potrebbe accadere per caso, mentre il FilterInputStream.read() sottoposto a override viene risolto in BufferedInputStream.read(), accade per caso sembra piuttosto improbabile.

Dato che questo è accaduto dopo una raccolta completa dei dati inutili, mi sembra più probabile che ci sia voluto più tempo per risolvere la chiamata FilterInputStream perché la classe BufferedInputStream è stata spostata o scaricata durante la garbage collection completa. Ad esempio, se per caso non ci fossero oggetti BufferedInputStream in uso al momento del completo Garbage Collection, la classe BufferedInputStream avrebbe potuto essere scaricata, richiedendo il caricamento della classe quando era necessario il suo metodo read(). Questo potrebbe spiegare il ritardo che hai visto, almeno una volta.

In alcune situazioni è possibile che le classi vengano scaricate quando l'ultima delle loro istanze viene raccolta spazzatura, anche in assenza di una garbage collection completa. Se la classe BufferedInputStream venisse in qualche modo scaricata dopo ogni utilizzo e ricaricata la volta successiva in cui è stata utilizzata, ciò potrebbe spiegare i sintomi che si dicono, ma normalmente non mi aspetto che ciò accada.

È anche possibile che ci sia stato il thrashing della pagina di memoria che conteneva la classe BufferedInputStream, forse perché la classe è stata spostata durante la garbage collection completa, se si stesse utilizzando la memoria virtuale. Se si dispone di registrazioni relative all'utilizzo della memoria durante questo periodo, potrebbero valere la pena dare un'occhiata.

+0

Grazie. Le istanze di 'BufferedInputStream' non dovrebbero essere state raccolte come garbage collection in quanto le connessioni socket sono rimaste attive. No, la memoria è rimasta bassa, non c'è stata nessuna cimatura. – dcernahoschi

-1

Immagino che devi provare a svuotare per leggere e scrivere nello stream senza errori o rallentare le connessioni.

Problemi correlati