[Java] Profiling applicazione per trovare memory leak

[tylerdurden83]

Ragazzi ho bisogno di aiuto per trovare un probabile leak nell'applicazione Java in questione. Ho attivato il remote profiling sul server e mi ci sono connesso con il profiler di netbeans. Questi i risultati attuali:

Oggetti:
http://img704.imageshack.us/f/oggetti.jpg/

Surviving Generations:
http://img807.imageshack.us/i/generations.jpg/

Heap Size:
http://img175.imageshack.us/i/heap.jpg/

Il problema è che navigando ad es l'array di char, non riesco a risalire a nulla di utile

Qualcuno può darmi una mano?

Grazie,
TD

[sottovento]

Originariamente inviato da tylerdurden83

Ragazzi ho bisogno di aiuto per trovare un probabile leak nell'applicazione Java in questione. Ho attivato il remote profiling sul server e mi ci sono connesso con il profiler di netbeans. Questi i risultati attuali:

Oggetti:
http://img704.imageshack.us/f/oggetti.jpg/

Surviving Generations:
http://img807.imageshack.us/i/generations.jpg/

Heap Size:
http://img175.imageshack.us/i/heap.jpg/

Il problema è che navigando ad es l'array di char, non riesco a risalire a nulla di utile

Qualcuno può darmi una mano?

Grazie,
TD

Immagino pero' che utilizzi gli array di char in qualche punto della tua applicazione, giusto? Quanti punti? char[] non e' poi cosi' comune in Java, direi che non avrai tanti punti da analizzare. Hai gia' dato un'occhiata?

[tylerdurden83]

Originariamente inviato da sottovento

Immagino pero' che utilizzi gli array di char in qualche punto della tua applicazione, giusto? Quanti punti? char[] non e' poi cosi' comune in Java, direi che non avrai tanti punti da analizzare. Hai gia' dato un'occhiata?

No non li uso mai, sicuramente sono utilizzati internamente da oggetti più avanzati, se riesco a riconnettermi alla vm con il profiler remoto (senza dover restartare l'applicazione) ti posto più dati a riguardo...

EDIT: non mi fa riconnettere, la restarto al volo

Ieri ho notato che dopo un po l heap e le surviving generation si sono stabilizzate (la prima sui 250 MB e l altra sulle 13 generazioni), ma da top su unix il processo continuava a crescere (addirittura 700 MB allocati, sebbene la maggior parte di essi risultasse anche free)...

[tylerdurden83]

Screenshot in arrivo, rieditero il post un po di volte...

Dump della memoria occupata dai char[]


Massima concentrazione di memoria e generations su StringBuffer.toString()


org.hibernate.sql.Select.toStatementString è quello che incide di più, ma siamo già arrivati a valori insignificanti di bit e surviving generations...


proseguendo ulteriormente da org.hibernate.sql.Select.toStatementString arrivo a


che è il mio main, ma non presenta nessun accumulo di memoria o generations...

[sottovento]

Non conosco il tool ma sembra che ti mostri l'allocazione di ogni oggetto, giusto? Sei riuscito a vedere se ci sono anche i tuoi? Hai controllato se il software che stai usando ti da anche una rappresentazione "gerarchica" (i.e. queste chiamate sono generate da questo oggetto e cosi' via). In genere lo fanno...

Scusa per i suggerimenti triviali, ma da qualche parte si deve pur partire, no?

EDIT - ho visto lo snapshot che hai postato e parla di "tree", quindi immagino che puoi dettagliare il singolo item. Prova a vedere se, percorrendo l'albero delle chiamate, arrivi ad oggetti familiari

[tylerdurden83]

Originariamente inviato da sottovento

Prova a vedere se, percorrendo l'albero delle chiamate, arrivi ad oggetti familiari

Più che altro non arrivo alla situazione che mi aspettavo. Su internet ho trovato esempi di interpretazione dell albero e classi per testare/generare leak. Ogni volta quando un oggetto di partenza è grosso, fai conto MyObject, ripercorrendo l'albero dei metodi (ammesso che siano molteplici) che li istanziano vedi sempre che la barra rossa di Live Bytes% è al 99% causata da un solo metodo (quello ke leaks). Espandendo quel metodo e navigando i metodi che hanno chiamato quel metodo si arriva ad una foglia che nuovamente ha la barra rossa LiveBytex% e Surviving generations che pesa praticamente il totale di quella segnata di fianco alla radice. Io navigando invece arrivo a metodi con peso in byte e generations assolutamente normali...

Non mi torna questo:


Perchè l'heap cresce vergognosamente addirittura quando lo used heap non solo non ne occupa manco una minima parte, ma addirittura decresce...

[banryu79]

Originariamente inviato da tylerdurden83

Perchè l'heap cresce vergognosamente addirittura quando lo used heap non solo non ne occupa manco una minima parte, ma addirittura decresce...

Infatti, anche a me ha colpito questo.

[tylerdurden83]

E di nuovo....





presto esplodera...senza motivo....

[sottovento]

Si, e' un po' strano.

Riassumendo: dagli ultimi snapshot che hai postato sembra che il tuo codice abbia effettuato chiamate a monitoraggiov4.factories.persistence.EntityManagerFactoryUtil.CreateEntityManagerFactoryUtil(), da cui sono usciti 40 begli oggetti, tutti vivi.

E' esattamente quello che ti serviva? Gli snapshot successivi indicano un incremento di questo valore?

[tylerdurden83]

Originariamente inviato da sottovento

Si, e' un po' strano.

Riassumendo: dagli ultimi snapshot che hai postato sembra che il tuo codice abbia effettuato chiamate a monitoraggiov4.factories.persistence.EntityManagerFactoryUtil.CreateEntityManagerFactoryUtil(), da cui sono usciti 40 begli oggetti, tutti vivi.

E' esattamente quello che ti serviva? Gli snapshot successivi indicano un incremento di questo valore?

Questo lo snapshot della memoria in questo istante... ovviamente sempre dumpando char[] e seguendo lo stesso percorso dei metodi chiamanti...



Direi che è tutto "normale" sotto questo punto di vista, 4 oggetti vivi (nel frattempo è passata la GS, 1 sola generation)...

[banryu79]

@tylerdurden83: dallo snapshot al post #8 si vede chiaramente che in corrispondeza di ogni diminuzione dello "Heap Used" (viola) c'è un aumento (praticamente speculare) dello "Heap Size" (rosa).

@EDIT
se guardi anche lo snapshot al post #6 vedrai che questo comportamento non si manifesta subito, ma solo dopo un tot. di tempo.

@RI-EDIT:
e si nota che capita proprio (molto probabilmente è solo un casò) quando lo "Heap Size" ha toccato i 100 MB.

[sottovento]

Non ho ancora capito: nella prima snapshot ce n'erano vivi 40, ora 4. Sbaglio?
Dici che e' "normale" ma io, ad istinto, andrei ad indagare proprio li'...
Ho capito male?

[tylerdurden83]

Originariamente inviato da banryu79

@tylerdurden83: dallo snapshot al post #8 si vede chiaramente che in corrispondeza di ogni diminuzione dello "Heap Used" (viola) c'è un aumento (praticamente speculare) dello "Heap Size" (rosa).

Al timestamp 12:50 l'aumento del rosa non è stato proprio speculare, ma diciamo che si, sono daccordo con te. Tuttavia o non ho capito nulla oppure non dovrebbe succedere questo, no? Che senso ha allocare memoria su memoria (ora 258 mega su 26 usati...)

[tylerdurden83]

Originariamente inviato da sottovento

Non ho ancora capito: nella prima snapshot ce n'erano vivi 40, ora 4. Sbaglio?
Dici che e' "normale" ma io, ad istinto, andrei ad indagare proprio li'...
Ho capito male?

Io invece penso vada bene se il numero di oggetti diminuisce. In pratica il punto è che se gli oggetti hanno generation=1 significa che sono "sopravvissuti" ad una GC. Il problema è se questo valore sale.
Guarda in fondo a questo breve link ad esempio. Nel mio caso i 4 oggetti sono "freschi". Che siano 40 prima della GC e 4 dopo puo essere dovuto al fatto che oggetti "temporanei" (tipo Stringhe etc) usati per inizializzarne altri siano stati collezionati dalla GC

[sottovento]

Originariamente inviato da tylerdurden83

Io invece penso vada bene se il numero di oggetti diminuisce. In pratica il punto è che se gli oggetti hanno generation=1 significa che sono "sopravvissuti" ad una GC. Il problema è se questo valore sale.
Guarda in fondo a questo breve link ad esempio. Nel mio caso i 4 oggetti sono "freschi". Che siano 40 prima della GC e 4 dopo puo essere dovuto al fatto che oggetti "temporanei" (tipo Stringhe etc) usati per inizializzarne altri siano stati collezionati dalla GC

Ok, finalmente ho capito. Sono tardo
Quindi stiamo guardando gli oggetti sbagliati, giusto? Per esserne davvero sicuri: hai visto se tutta la catena degli oggetti allocati (fino alle char[]) se ne va via una volta ammazzati gli oggetti di partenza? E' ovviamente un controllo di sicurezza.....

[tylerdurden83]

Originariamente inviato da sottovento

Ok, finalmente ho capito. Sono tardo
Quindi stiamo guardando gli oggetti sbagliati, giusto? Per esserne davvero sicuri: hai visto se tutta la catena degli oggetti allocati (fino alle char[]) se ne va via una volta ammazzati gli oggetti di partenza? E' ovviamente un controllo di sicurezza.....

Corretto, non riesco a trovare nessun accumulo di oggetti che continua a sopravvivere alla GC. A questo punto l out of memory mi pare più facilmente da attribuire alla curiosa allocazione di ulteriore spazio quando viene eseguita una GC...

[banryu79]

Originariamente inviato da tylerdurden83

Corretto, non riesco a trovare nessun accumulo di oggetti che continua a sopravvivere alla GC. A questo punto l out of memory mi pare più facilmente da attribuire alla curiosa allocazione di ulteriore spazio quando viene eseguita una GC...

E' questa, secondo me, l'anomalia.

Leggendo questo:

Ieri ho notato che dopo un po' lo heap e le surviving generations si sono stabilizzate (la prima sui 250 MB e l'altra sulle 13 generazioni), ma da top su unix il processo continuava a crescere (addirittura 700 MB allocati, sebbene la maggior parte di essi risultasse anche free)...

mi è venuto in mente che potresti provare a far girare l'applicazione anche in qualche altro sistema. Tanto per verificare che l'anomala alloacazione "fantasma" sullo heap si verifichi sempre (che so, magari è dovuto a qualche bug in qualche libreria di terze parti che si verifica solo in qualche sistema...)

Magari aggiungendoci qualche print su consolle o su un logger che ogni tot. e/o in vari punti dell'applicazione ti stampa lo stato della memoria (java.lang.Runtime ha dei metodi utili in questo senso); in punti strategici: ad esempio prima e dopo la chiamata a codice di librerie esterne (cioè non del JDK) e controllerei anche tutti i cicli in cui siano presenti queste chiamate.

Mi rendo conto che non è un metodo molto "scentifico" di procedere... non ho esperienza di profiling, e non saprei che pesci pigliare, così sui due piedi.

[tylerdurden83]

Originariamente inviato da banryu79

E' questa, secondo me, l'anomalia.

Leggendo questo:

mi è venuto in mente che potresti provare a far girare l'applicazione anche in qualche altro sistema.
Magari aggiungedoci qualche print su consolle o su un logger che ogni tot. e/o in vari punti dell'applicazione ti stampa lo stato della memoria (java.lang.Runtime ha dei metodi utili in questo senso).

Mi rendo conto che non è un metodo molto "scentifico" di procedere... non ho esperienza di profiling, e non saprei che pesci pigliare, così sui due piedi.

E' un po complicato perchè i dati che estrae sono disponibili solo su quella macchina... provo a fare qualche test

[tylerdurden83]

prstat -p 20546 300 > cacca.log

bash-2.03$ cat cacca.log
PID USERNAME SIZE RSS STATE PRI NICE TIME CPU PROCESS/NLWP
20546 esmon01 180M 99M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 180M 99M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 180M 99M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 180M 99M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 179M 101M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 179M 101M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 179M 101M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 177M 101M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 177M 101M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 177M 101M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 177M 101M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 177M 101M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 177M 101M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 177M 101M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 177M 102M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 177M 102M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 177M 102M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 177M 102M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 177M 102M sleep 59 0 0:00.07 0.0% java/31
20546 esmon01 175M 103M sleep 59 0 0:00.07 0.0% java/31

Niente niente erano le librerie di profiling a causare il leak...

[banryu79]

OMG, è un po' lollica come cosa.
Uno usa un profiler per sgamare i leak e il profiler, gentilissimo, per evitargli la fatica di scovarli glieli crea ad hoc

Ok, facendo tesoro di questa esperienza ho imparato che:
1) è meglio monitorare un'applicazione in esecuzione in un sistema da remoto, così cazzi & mazzi del profiler stesso non vanno ad inficiare i risultati (consumo di memoria, performance, anomalie varie come nel tuo caso).

2) non te l'ho suggerito prima perchè son poco avvezzo e non mi è venuto in mente, ma una cosa che potevi provare era mandare in esecuzione la tua applicazione non dall'IDE e lanciare JConsole da riga di comando.

L'importante è che alla fine ne sei venuto a capo