[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 :muro:

Qualcuno può darmi una mano?

Grazie,
TD

[sottovento]

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 :muro:

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]

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[]
http://img341.imageshack.us/img341/5681/dump1.jpg (http://img341.imageshack.us/i/dump1.jpg/)

Massima concentrazione di memoria e generations su StringBuffer.toString()
http://img716.imageshack.us/img716/568/dump2.jpg (http://img716.imageshack.us/i/dump2.jpg/)

org.hibernate.sql.Select.toStatementString è quello che incide di più, ma siamo già arrivati a valori insignificanti di bit e surviving generations...
http://img121.imageshack.us/img121/5942/dump3.jpg (http://img121.imageshack.us/i/dump3.jpg/)

proseguendo ulteriormente da org.hibernate.sql.Select.toStatementString arrivo a
http://img808.imageshack.us/img808/4384/dump4.jpg (http://img808.imageshack.us/i/dump4.jpg/)

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]

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:
http://img440.imageshack.us/img440/6596/heap.jpg (http://img440.imageshack.us/i/heap.jpg/)

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

[banryu79]

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....

http://img826.imageshack.us/img826/1161/heap2.jpg (http://img826.imageshack.us/i/heap2.jpg/)

http://img195.imageshack.us/img195/2351/infole.jpg (http://img195.imageshack.us/i/infole.jpg/)

presto esplodera...senza motivo.... :muro: :muro: :muro:

[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]

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...

http://img831.imageshack.us/img831/2218/dump5.jpg (http://img831.imageshack.us/i/dump5.jpg/)

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]

@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]

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 (http://netbeans.org/kb/articles/nb-profiler-uncoveringleaks_pt1.html) 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]

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 (http://netbeans.org/kb/articles/nb-profiler-uncoveringleaks_pt1.html) 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]

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...:muro:

[banryu79]

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...:muro:
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]

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 :mc:

[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. :D
Uno usa un profiler per sgamare i leak e il profiler, gentilissimo, per evitargli la fatica di scovarli glieli crea ad hoc :asd:

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 :)

[tylerdurden83]

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

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 :)

Prima di profilare da remoto con netbeans (che ha il vantaggio di salvarsi il path dei metodi) ho provato varie alternative tipo jhat etc per fare dump e analizzarli, proprio perchè la jconsole mostrava un accenno di leak... ora non mi ci sono mai connesso da jmx, niente profiling etc. voglio proprio vedere come si comporta nell'arco di piu giorni...in compenso prstat è buggata su solaris e in nohup non va...pd non ne funziona 1 (ieri sera webdav buggato su windows 7 64 bit etc etc....)

[tylerdurden83]

ieri
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

oggi
20546 esmon01 135M 91M sleep 59 0 0:00.07 0.0% java/31

:doh:

[tylerdurden83]

06-08-2010
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

07-08-2010
20546 esmon01 135M 91M sleep 59 0 0:00.07 0.0% java/31

09-08-2010
20546 esmon01 115M 81M sleep 59 0 0:00.07 0.0% java/31

per ora diciamo che imputo ai profiler il leak e mi accontento così va :)