Problem z GC który zajeżdza CPU

Witam,
od jakiegoś tygodnia mamy problem z GC na jednej instalacji efekt wygląda tam, że GC zajeżdza CPU jednak pierwszy raz się spotykam z taka sytuacją, że widzę na podstawie komendy jstat, że pamięć jest, podczas FGC wcale nie są wykorzystywane S0 i S1 a eden to już na minimalnym poziomie a jak widać w old gen jest jeszcze z 800MB

 S0C    S1C      S0U    S1U      EC       EU        OC         OU        MC     MU       CCSC   CCSU       YGC   YGCT    FGC  FGCT  GCT

102400.0 102400.0  0.0    0.0   409600.0  1971.5  1945600.0  1031169.3  512000.0 449708.2 66048.0 54318.1   4091  237  488  1219.374 1456
102400.0 102400.0  0.0    0.0   409600.0  1971.5  1945600.0  1031169.3  512000.0 449708.2 66048.0 54318.1   4091  237  488  1219.374 1456
102400.0 102400.0  0.0    0.0   409600.0   0.0    1945600.0  1031290.9  512000.0 449712.0 66048.0 54318.6   4091  237  489  1222.961 1460
102400.0 102400.0  0.0    0.0   409600.0   0.0    1945600.0  1031290.9  512000.0 449712.0 66048.0 54318.6   4091  237  489  1222.961 1460
102400.0 102400.0  0.0    0.0   409600.0   0.0    1945600.0  1031290.9  512000.0 449712.0 66048.0 54318.6   4091  237  489  1222.961 1460
102400.0 102400.0  0.0    0.0   409600.0  7213.4  1945600.0  1031208.7  512000.0 449712.0 66048.0 54318.6   4091  237  491  1226.375 1463
102400.0 102400.0  0.0    0.0   409600.0  7213.4  1945600.0  1031208.7  512000.0 449712.0 66048.0 54318.6   4091  237  491  1226.375 1463
102400.0 102400.0  0.0    0.0   409600.0  7213.4  1945600.0  1031208.7  512000.0 449712.0 66048.0 54318.6   4091  237  491  1226.375 1463
102400.0 102400.0  0.0    0.0   409600.0  7213.4  1945600.0  1031208.7  512000.0 449712.0 66048.0 54318.6   4091  237  491  1226.375 1463
102400.0 102400.0  0.0    0.0   409600.0  7213.4  1945600.0  1031208.7  512000.0 449712.0 66048.0 54318.6   4091  237  491  1226.375 1463
102400.0 102400.0  0.0    0.0   409600.0   0.0    1945600.0  1031376.2  512000.0 449715.7 66048.0 54319.2   4091  237  492  1231.654 1469
102400.0 102400.0  0.0    0.0   409600.0   0.0    1945600.0  1031376.2  512000.0 449715.7 66048.0 54319.2   4091  237  492  1231.654 1469
102400.0 102400.0  0.0    0.0   409600.0   0.0    1945600.0  1031376.2  512000.0 449715.7 66048.0 54319.2   4091  237  492  1231.654 1469
102400.0 102400.0  0.0    0.0   409600.0   0.0    1945600.0  1031376.2  512000.0 449715.7 66048.0 54319.2   4091  237  492  1231.654 1469
102400.0 102400.0  0.0    0.0   409600.0  367.9   1945600.0  1031239.2  512000.0 449715.7 66048.0 54319.2   4091  237  493  1235.218 1472

Możesz użyć parallel GC:
https://docs.oracle.com/javase/8/docs/technotes/guides/vm/gctuning/parallel.html

Aczkolwiek w pierwszej kolejności zastanowiłbym się na twoim miejscu czy przypadkiem nie tworzysz za dużo niepotrzebnych obiektów.

Dziwne logi, nie kojarzę takich, ale może przyczyną są inne sterty niż główna? Np M (metaspace?) czy CCS (class constants?) Spróbuj poregulować wielkość poszczególnych stert. Poza tym GC ma pewnie przełączniki do ustawiania przy jakiej zajętości konkretnej sterty powinien się uruchamiać. Może GC stwierdza, że w którejś stercie ma za mało zapasu i dlatego się w kółko odpala?

Aktualizacja:
Dobra, znalazłem: https://docs.oracle.com/javase/8/docs/technotes/tools/unix/jstat.html
Dodaj przełącznik -gccause i wygeneruj logi od nowa.

możesz proszę wrzucić takie flagi ? -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps - po takich logach z jstatu nic a nic nie zobaczysz i nie znajdziesz root cause. Dodatkowo, co to za GC ? CMS ? G1 ?

Wgl, najlepiej poka flagi z jakimi odpalasz aplikacje.

P.S Napisz też coś więcej, co to za appka, ile to ma pamięci dostępnej, gdzie to odpalasz.

P.S.2 co to znaczy że zajeżdza CPU ? skąd pewność że to GC ?

P.S.3 jeżeli możesz się na te instancje wbić i masz tam linuxa to (o ile Ci sie chce) to odpal sobie tam flamegraphs (https://github.com/jvm-profiling-tools/async-profiler) będzisz widział na co schodzi Ci to CPU, bo, nie żebym nie wierzył, ale jakoś mi tu coś śmierdzi z tym CPU XD

Przyznam się że średnio się na tym znam, ale wygląda jakby Ci coś triggerowało Full GC które jest "show stopperem".
Jest taka opcja "-XX:+FullGCALot" - sprawdź czy ktoś jej przypadkiem nie włączył.

Co jeszcze może się przydać:
https://stackoverflow.com/questions/9546392/what-triggers-a-full-garbage-collection-in-java
https://developer.jboss.org/thread/159052?_sscc=t

Dzięki za odpowiedzi sprawdzę jstata z przełącznikiem -gccause, dodatkowo dodam -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps
Ustawienia

-Xms2500m -Xmx2500m -XX:NewSize=600m -XX:MaxNewSize=600m -XX:MetaspaceSize=500M -XX:MaxMetaspaceSize=500M -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -XX:+ScavengeBeforeFullGC -XX:+CMSScavengeBeforeRemark -XX:SurvivorRatio=4 

Dam znać co jest w logach PrintGCDetails jak problem znów się pojawi ale średnio co 3 dni....

-Xms2500m -Xmx2500m -XX:NewSize=600m -XX:MaxNewSize=600m -XX:MetaspaceSize=500M -XX:MaxMetaspaceSize=500M

śmiem twierdzić że te opcje nie będą działać ponieważ od Javy 5, flaga -XX:+UseAdaptiveSizePolicy jest ustawiana by default (pamiętam też że bez tej flagi OracleJDK nie pozwalał sobie ustawić tego ratio - musiałem dodać -XX:-UseAdaptiveSizePolicy ) - Może ktoś wie coś więcej ?

@Szczery: masz te logi ?

A właśnie dzisiaj się pojawiło, jak widać co 3 sekundy idzie FULL GC który trwa 3 sekundy i na tym cały czas procek spędza, ale z tych logów nie widzę dlaczego wchodzi w faze FULL GC skoro ma jeszcze miejsce może problemem jest wpis "concurrent mode failure"

317371.287: [Full GC (Last ditch collection) 317371.287: [CMS: 1194516K->1194319K(1945600K), 3.7343781 secs] 1194516K->1194319K(2457600K), [Metaspace: 451487K->451487K(1497088K)], 3.7348592 secs] [Times: user=3.74 sys=0.00, real=3.73 secs] 
317375.027: [Full GC (Metadata GC Threshold) 317375.027: [CMS: 1194319K->1194301K(1945600K), 3.8097677 secs] 1198927K->1194301K(2457600K), [Metaspace: 451487K->451487K(1497088K)], 3.8101548 secs] [Times: user=3.81 sys=0.00, real=3.81 secs] 
317378.838: [Full GC (Last ditch collection) 317378.838: [CMS: 1194301K->1194248K(1945600K), 3.6554190 secs] 1194301K->1194248K(2457600K), [Metaspace: 451487K->451487K(1497088K)], 3.6558698 secs] [Times: user=3.66 sys=0.00, real=3.66 secs] 
317382.495: [Full GC (Metadata GC Threshold) 317382.495: [CMS: 1194248K->1194249K(1945600K), 3.7338971 secs] 1194254K->1194249K(2457600K), [Metaspace: 451487K->451487K(1497088K)], 3.7342993 secs] [Times: user=3.73 sys=0.00, real=3.73 secs] 
317386.229: [Full GC (Last ditch collection) 317386.229: [CMS: 1194249K->1194241K(1945600K), 3.7522308 secs] 1194249K->1194241K(2457600K), [Metaspace: 451487K->451487K(1497088K)], 3.7526294 secs] [Times: user=3.75 sys=0.00, real=3.75 secs] 
317389.987: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1194241K(1945600K)] 1194718K(2457600K), 0.0155701 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
317390.003: [CMS-concurrent-mark-start]
317390.032: [Full GC (Metadata GC Threshold) 317390.032: [CMS317391.993: [CMS-concurrent-mark: 1.977/1.991 secs] [Times: user=2.01 sys=0.00, real=1.99 secs] 
 (concurrent mode failure): 1194241K->1194352K(1945600K), 5.7088985 secs] 1200697K->1194352K(2457600K), [Metaspace: 451487K->451487K(1497088K)], 5.7093616 secs] [Times: user=5.71 sys=0.00, real=5.70 secs] 
317395.742: [Full GC (Last ditch collection) 317395.742: [CMS: 1194352K->1194271K(1945600K), 3.7635212 secs] 1194352K->1194271K(2457600K), [Metaspace: 451487K->451487K(1497088K)], 3.7640570 secs] [Times: user=3.77 sys=0.00, real=3.77 secs] 
317399.507: [Full GC (Metadata GC Threshold) 317399.507: [CMS: 1194271K->1194271K(1945600K), 3.5699031 secs] 1198347K->1194271K(2457600K), [Metaspace: 451487K->451487K(1497088K)], 3.5702485 secs] [Times: user=3.57 sys=0.00, real=3.57 secs] 
317403.078: [Full GC (Last ditch collection) 317403.078: [CMS: 1194271K->1194271K(1945600K), 3.5002440 secs] 1194271K->1194271K(2457600K), [Metaspace: 451487K->451487K(1497088K)], 3.5005708 secs] [Times: user=3.49 sys=0.00, real=3.50 secs] 
317406.602: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1194271K(1945600K)] 1200101K(2457600K), 0.0152558 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
317406.617: [CMS-concurrent-mark-start]
317406.633: [Full GC (Metadata GC Threshold) 317406.633: [CMS317408.475: [CMS-concurrent-mark: 1.850/1.858 secs] [Times: user=1.87 sys=0.00, real=1.86 secs] 
 (concurrent mode failure): 1194271K->1194356K(1945600K), 5.4373545 secs] 1200540K->1194356K(2457600K), [Metaspace: 451487K->451487K(1497088K)], 5.4377452 secs] [Times: user=5.44 sys=0.00, real=5.43 secs] 
317412.071: [Full GC (Last ditch collection) 317412.071: [CMS: 1194356K->1194251K(1945600K), 3.4538327 secs] 1194356K->1194251K(2457600K), [Metaspace: 451487K->451487K(1497088K)], 3.4541665 secs] [Times: user=3.45 sys=0.00, real=3.46 secs] 
317415.529: [Full GC (Metadata GC Threshold) 317415.529: [CMS: 1194251K->1194315K(1945600K), 3.7218781 secs] 1194998K->1194315K(2457600K), [Metaspace: 451487K->451487K(1497088K)], 3.7222700 secs] [Times: user=3.72 sys=0.00, real=3.72 secs] 
317419.252: [Full GC (Last ditch collection) 317419.252: [CMS: 1194315K->1194280K(1945600K), 3.5040370 secs] 1194315K->1194280K(2457600K), [Metaspace: 451487K->451487K(1497088K)], 3.5043831 secs] [Times: user=3.50 sys=0.00, real=3.50 secs] 
317422.764: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1194280K(1945600K)] 1194348K(2457600K), 0.0145751 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
317422.779: [CMS-concurrent-mark-start]
317422.798: [Full GC (Metadata GC Threshold) 317422.798: [CMS317424.705: [CMS-concurrent-mark: 1.923/1.926 secs] [Times: user=1.94 sys=0.00, real=1.93 secs] 
 (concurrent mode failure): 1194280K->1194346K(1945600K), 5.3917935 secs] 1199608K->1194346K(2457600K), [Metaspace: 451487K->451487K(1497088K)], 5.3922140 secs] [Times: user=5.39 sys=0.00, real=5.39 secs] 

I dobrze. Teraz wystarczy zebys zrobil "jvm heap dump" i go przeanalizowal.

Np
https://www.javaworld.com/article/2072864/heap-dump-and-analysis-with-visualvm.html

https://dzone.com/articles/memory-analysis-how-to-obtain-java-heat-dump

Nie wnosi to może zbytnio do tematu nic nowego, ale tak mi się przypomniało jak lata temu w kodzie źródłowym aplikacji widziałem przypadki wołania:

System.gc();

albo

System.exit(0);

Ten drugi był ciekawy, bo wejście na jakiegoś specyficznego *.jsp aplikacji generowało zatrzymanie serwera aplikacyjnego :-)

Heap dump się nie udał bo JVM już był tak zmęczony

yarel napisał(a):

Nie wnosi to może zbytnio do tematu nic nowego, ale tak mi się przypomniało jak lata temu w kodzie źródłowym aplikacji widziałem przypadki wołania:

System.gc();

albo

System.exit(0);

Ten drugi był ciekawy, bo wejście na jakiegoś specyficznego *.jsp aplikacji generowało zatrzymanie serwera aplikacyjnego :-)

System.gc - widać w logach, JVM mówi co go striggerowało.
Odnośnie tych logów, to nie mam jakiegoś wielkiego doświadczenia z tunowaniem GC, ale pierwszy raz widzę tylke Meta faili XD korzystając z okazji że jesteś w robocie, to jak masz tam troche wolnego ramu, weź go dołóż do Metastaspace (MetaspaceSize) - i zrób dumpa, tak jak pisze @vpiotr , bo ten Metaspace nie powinien się tak zapychać.

Heap dump się nie udał bo JVM już był tak zmęczony

Co to znaszy ? musi się dać, jeżeli JVM odpowiada.

1. Ale metaspace [Metaspace: 451487K->451487K(1497088K)] więc jest miejsce nie ma teoretycznie możliwości aby się to zapychało skoro ma jeszcze tyle miejsca, chociaz -XX:MaxMetaspaceSize=500M

2. Nie zawsze możemy zrobić HeapDumpa za pomocą CoreDumpa Linuxa czyli twardy zrzut pamięci Linux, nieraz JVM mówi "can not attach to procvess" i tyle

Nie mam doświadczenia w analizie logów gc, ale czy Full GC (Metadata GC Threshold) nie oznacza, że kolekcja jest spowodowana przez przekroczenie progu zajęcia metaspace? 451487K->451487K(1497088K) oznacza, że podczas kolekcji nie odzyskano pamięci w metaspace? Wybaczcie pytania, ale sam nie jestem tego pewien. Jeśli miałbym strzelać, to możesz sprawdzić działanie bez flag ograniczających rozmiar metaspace.

Aktualnie również obstawiam Metadata GC Threshold, co ciekawe na JAVA 7 nie było problemów z PermGen dla tych samych ustawień, ale teraz MetaSpace fragment Heap'a to podlega GC. Na teraz robimy zabieg zwiększenia MetaSpace o 100MB

EDIT:

NIE MIALEM RACJI

Możesz spróbować się podpiąć do jvm'a za pomocą visualvm (najlepiej z pluginem visualgc) i zobaczyć jak wyglądają obszary pamięci. Obstawiam, że metaspace jest na granicy zajętości. Metaspace siedzi w native memory, więc nie do końca jestem pewien jak interpretować liczbę wskazującą dostępną pamięć dla metaspace w 451487K->451487K(1497088K). Nie mniej jednak 451487K jest ewidentnie blisko maskymalnej wartości określonej przez metaspaceSize i maxMetaspaceSize.

@Szczery wywal te parametry dla metaspaceu i zobacz co się stanie, pozwól GC samemu dobrać sobie rozmiar.

Na razie 600MB na MaxMetaspaceSize za parę dnia zobaczymy do jakiej wartości dojdzie możliwe ze 450MB z 500MB czyli 90% zajętości wzbudza GC

Znalazłem pewną poradę na SO: https://stackoverflow.com/a/37273422

Dodaj -XX:+PrintGCDetails -XX:+TraceClassUnloading -XX:+TraceClassLoading by prześledzić co zapycha metaspace. Dodatkowo możesz poeksperymentować z class unloading (o ile nie jest już włączone).

Ja bym się zastanowił co wam zapycha metaspace bo to nie do końca normalne. Nie używacie tam cgliba w dziwny sposób albo jakiejś libki która to robi, albo nie generujecie non stop klas anonimowych? Pamiętam swego czasu że przed Javą 8 były biblioteki z "lambdami", które potrafiły zjeść cały ram permgenem...

No na pewno Meta trochę cierpi przez JasperReports w którym jet mnóstwo wyrażeń kompilowanych do grooviego czyli pewnie klasy dynamiczne

Shalom napisał(a):

Ja bym się zastanowił co wam zapycha metaspace bo to nie do końca normalne. Nie używacie tam cgliba w dziwny sposób albo jakiejś libki która to robi, albo nie generujecie non stop klas anonimowych? Pamiętam swego czasu że przed Javą 8 były biblioteki z "lambdami", które potrafiły zjeść cały ram permgenem...

I w drugą stronę - spotkałem się z sytuacją, w której niektóre biblioteki działały poprawnie w 7, natomiast zapychały pamięć w wersji 8.

@Szczery: masz coś nowego ?

Po zwiększeniu na 600M MetaSpace na razie cisza (7 dnie bez restartu) wykorzystanie MetaSpace na poziomie 483M tak jak ostatnio.
Nie chcę znosić limitu na MaxMetaSpace bo nieraz to może doprowadzić do rozrostu JVM i później tylko KernelPanic i pewnie kill bazy Oracle, a baza nie lubi jak się zabija proces

Szczery napisał(a):

Po zwiększeniu na 600M MetaSpace na razie cisza (7 dnie bez restartu) wykorzystanie MetaSpace na poziomie 483M tak jak ostatnio.
Nie chcę znosić limitu na MaxMetaSpace bo nieraz to może doprowadzić do rozrostu JVM i później tylko KernelPanic i pewnie kill bazy Oracle, a baza nie lubi jak się zabija proces

Masz odpaloną baze danych na tej samej maszynie co Aplikacja ? XD XD nieważne.

Nie chcę znosić limitu na MaxMetaSpace bo nieraz to może doprowadzić do rozrostu JVM i

po to masz xmx