2015-11-19 39 views
9

Po uruchomieniu kilku godzin mój serwer http zaczyna często gc, ale nie ma wolnej sterty.częste duże gc ale nie wolne sterty?

kilka razy późniejszy gc później, promotion failed i concurrent mode failure, a następnie sterty zostały zwolnione. Mój dziennik GC jest poniżej:

{Heap before GC invocations=7172 (full 720): 
par new generation total 737280K, used 667492K [0x000000076b800000, 0x000000079d800000, 0x000000079d800000) 
    eden space 655360K, 100% used [0x000000076b800000, 0x0000000793800000, 0x0000000793800000) 
    from space 81920K, 14% used [0x0000000793800000, 0x00000007943d91d0, 0x0000000798800000) 
    to space 81920K, 0% used [0x0000000798800000, 0x0000000798800000, 0x000000079d800000) 
concurrent mark-sweep generation total 1482752K, used 1479471K [0x000000079d800000, 0x00000007f8000000, 0x00000007f8000000) 
concurrent-mark-sweep perm gen total 131072K, used 58091K [0x00000007f8000000, 0x0000000800000000, 0x0000000800000000) 
2015-11-19T21:50:02.692+0800: 113963.532: [GC2015-11-19T21:50:02.692+0800: 113963.532: [ParNew (promotion failed) 
Desired survivor size 41943040 bytes, new threshold 15 (max 15) 
- age 1: 3826144 bytes, 3826144 total 
- age 2:  305696 bytes, 4131840 total 
- age 3:  181416 bytes, 4313256 total 
- age 4:  940632 bytes, 5253888 total 
- age 5:  88368 bytes, 5342256 total 
- age 6:  159840 bytes, 5502096 total 
- age 7:  733856 bytes, 6235952 total 
- age 8:  64712 bytes, 6300664 total 
- age 9:  314304 bytes, 6614968 total 
- age 10:  587160 bytes, 7202128 total 
- age 11:  38728 bytes, 7240856 total 
- age 12:  221160 bytes, 7462016 total 
- age 13:  648376 bytes, 8110392 total 
- age 14:  33296 bytes, 8143688 total 
- age 15:  380768 bytes, 8524456 total 
: 667492K->665908K(737280K), 0.7665810 secs]2015-11-19T21:50:03.459+0800: 113964.299: [CMS2015-11-19T21:50:05.161+0800: 113966.001: [CMS-concurrent-mark: 3.579/4.747 secs] [Times: user=13.41 sys=0.35, rea 
l=4.75 secs] 
(concurrent mode failure): 1479910K->44010K(1482752K), 4.7267420 secs] 2146964K->44010K(2220032K), [CMS Perm : 58091K->57795K(131072K)], 5.4939440 secs] [Times: user=9.07 sys=0.13, real=5.49 secs] 
Heap after GC invocations=7173 (full 721): 
par new generation total 737280K, used 0K [0x000000076b800000, 0x000000079d800000, 0x000000079d800000) 
    eden space 655360K, 0% used [0x000000076b800000, 0x000000076b800000, 0x0000000793800000) 
    from space 81920K, 0% used [0x0000000798800000, 0x0000000798800000, 0x000000079d800000) 
    to space 81920K, 0% used [0x0000000793800000, 0x0000000793800000, 0x0000000798800000) 
concurrent mark-sweep generation total 1482752K, used 44010K [0x000000079d800000, 0x00000007f8000000, 0x00000007f8000000) 
concurrent-mark-sweep perm gen total 131072K, used 57795K [0x00000007f8000000, 0x0000000800000000, 0x0000000800000000) 
} 

Wydaje się CMS GC nie ma żadnego sensu. Czy możesz mi wyjaśnić?

To mój gc config:

/usr/local/jdk1.7.0_79/bin/java 
-server 
-Xms2248m 
-Xmx2248m 
-Xmn800m 
-XX:PermSize=128m 
-XX:MaxPermSize=128m 
-XX:MaxTenuringThreshold=15 
-XX:+UseCMSCompactAtFullCollection 
-XX:CMSFullGCsBeforeCompaction=0 
-XX:+UseConcMarkSweepGC 
-XX:+PrintGCDetails 
-XX:+PrintGCTimeStamps 
-XX:+PrintGCDateStamps 
-Xloggc:gc.log 
-XX:+PrintHeapAtGC 
-XX:+PrintTenuringDistribution 
-XX:+UseFastAccessorMethods 

UPDATE

Jest okresowe zadanie od początku serwera. Jego zadaniem jest ładowanie danych z mysql i trzymanie w stosie jvm. Gdy przychodzi żądanie klienta, serwer powinien obliczyć dane. Kod zadania w następujący sposób:

private volatile List<ActivityInfo> activityInfos; 

public void run() { 
    activityInfos = db.loadActivity(); 
} 

public ActivityInfo getActivityByClient() { 
    // 
    List<ActivityInfo> local = activityInfos; 
    // biz code 
    ActivityInfo response = // biz code 
    return response; 
} 

// executor 
executor.scheduleWithFixedDelay(task, 0, 1, TimeUnit.MINUTES); 

Co najbardziej mnie zdezorientowało, dlaczego stertę uwolniono po pełnym gc, a nie po dużym gc?

UPDATE

full gc log is here

Odpowiedz

4

To wskazywałoby, że używasz bardzo zbliżone do maksymalnego rozmiaru sterty, więc nie są częste GC ale bardzo mało jest zwolniona. Spróbuj zwiększyć to znacznie, powiedzmy, 1,5 x lub 2x.

+0

Myliłem to, dlaczego sterty zostały zwolnione po pełnym gc, a nie po dużym gc? – znlyj

+0

Błąd, ponieważ cała GC uwolniła coś, do czego nie dotarł główny GC? – EJP

+0

Zużycie sterty po dużej kolekcji wynosi tylko 44 MB, więc sterty są już bardzo duże i zwiększenie ich nie pomoże. –

3

przedszkola sterty jest ustawiony na 800MB z -Xmn800m ale wykorzystanie sterty przedszkola po pobraniu jest tylko 8MB

- age 15: 380768 bytes, 8524456 total

więc aplikacja może działać przez długi czas po prostu śmieci gromadzenia sterty przedszkola. Jednak w pewnym momencie napięta stacka wypełni się. Według kolekcji 7172 pozostało tylko około 3 MB - różnica między całkowitą a używaną wartością sterty.

concurrent mark-sweep generation total 1482752K, used 1479471K

Garbage Collector zauważył, że zwyczajnych sterty jest blisko pojemności i jednoczesne znak zostaną wywołane przed rozpoczęciem aktywności dziennika pisał. Podczas równoczesnej fazy znakowania obiekty są nadal przydzielane, a sterta wypełnia się, uruchamiając zbiór przedszkolny.

Po odebraniu pokoju dziecinnego nie ma już wystarczająco miejsca w stosie, aby pomieścić przedmioty, które mają być promowane na stertę. W wyniku tego promotion failed i śmieciarz jest zmuszony do przetworzenia całego sterty, a nie tylko przedszkola. Ponieważ ma to miejsce przed zakończeniem równoczesnej fazy znakowania, rejestrowane jest także concurrent mode failure. Po pełnej kolekcji jest 1,4GB w kupie sterty.

concurrent mark-sweep generation total 1482752K, used 44010K

ten sposób, że sprawy mają się wydarzyć. Kolekcje przedszkolne są tanie, jeśli większość nowych przedmiotów szybko wykracza poza zakres, a JVM z radością będzie tylko zbierać przedszkole tak długo, jak może. Ostatecznie jednak napięta sterty zapełnia się, a droższy pełny GC jest wymagany.

Co by się stało, gdybyś zredukował żłobek, powiedzmy do połowy jego wielkości? Zakładając, że twoja aplikacja tworzy obiekty ze stałą szybkością, żłobek wypełniłby mniej więcej połowę czasu. Ponieważ ilość danych używanych przez aplikację jest niezależna od GC, ta sama liczba obiektów byłaby zachowywana i promowana tak jak w przypadku większych szkółek. Tak więc regularna kolekcja również zapełnia się szybciej.

Jednak z tym samym łącznym rozmiarem sterty. powierzchnia do wynajęcia jest większa niż poprzednio, więc potrzeba więcej zbiorów przedszkolnych, aby wypełnić obszar na stałe, więc są kompromisy. Dobrą zasadą jest wielkość przedszkola o jedną czwartą wielkości obszaru na stałe.

UPDATE

Pełne gc.log jest z innej perspektywie GC, ale myślę, że zachowanie aplikacji jest podobna. W nim widzę wiele wiadomości CMS: abort preclean due to time. Są one opisane w Jon Masamitsu's Weblog. Ze względu na wydajność, kolektor CMS opiera się na kolekcji przedszkola, zanim nastąpi zatrzymanie wszystkich wykonywalnych wątków. Jeśli taka kolekcja nie nastąpi w określonym czasie, kolekcja CMS zostanie przerwana.

Gdy obciążenie aplikacji jest niskie, ale zużycie stosu jest wysokie, kolektor CMS zacznie działać i przechodzi przez początkową fazę oceny. Gdy kolekcja szkółki nie działa, kolekcja CMS zostaje przerwana. Może się to zdarzyć kilka razy. Następnie powstaje hałda szkółkarska i cykl się powtarza. Będzie to kontynuowane do czasu zbierania się CMS i zestawu przedszkolnego lub wypełnionego sterty całkowicie się zapełni.

Ponieważ obiekty są powoli promowane tylko na stertę, zachowanie to może trwać przez pewien czas. Tutaj trwa od 2015-11-24T00: 28: 23.921 do 2015-11-24T01: 55: 52.461 - półtorej godziny. W tym czasie marnuje się czas, wykonując początkowe oznaczenie tylko po to, aby przerwać operację.

Istnieje wiele możliwości naprawienia tego zachowania.

  • Zmniejsz rozmiar przedszkola. Pozwoli to na zwiększenie liczby przedszkoli, dzięki czemu będą częściej zbierać się w kolekcjach CMS. Jednak duża szkółka wydaje się działać dobrze, a jej zmniejszenie spowoduje więcej zbiorów CMS z gorszą wydajnością przy dużym obciążeniu.
  • Zwiększyć CMSMaxAbortablePrecleanTime. Będzie to oznaczać, że CMS będzie czekać na dłużej, zanim przerwie kolekcję. Jednak im dłuższy czas oczekiwania, tym droższa kolekcja CMS będzie
  • Włącz CMSScavengeBeforeRemark. To jest moja rekomendacja. Spowoduje to wymuszenie pobrania przedszkola we właściwym czasie, a kolekcja CMS nigdy nie zostanie przerwana. Czas oczekiwania na fazę uwagi będzie dłuższy, ponieważ odbędą się także zbiórki szkółek, ale ponieważ dodatkowy czas jest mały i pełne kolekcje są tak rzadkie, jest to mało prawdopodobne.

Należy zauważyć, że stertę żłobka nazywa się czasami młodym pokoleniem i stacją roboczą starszego pokolenia. Aby uzyskać więcej informacji zajrzyj na Understanding Garbage Collection lub Garbage Collection Basics

+0

Może powinienem ustawić mniejszy? -Xmn'? Co mnie zdezorientowało, to dlaczego stertę uwolniono po pełnym gc, a nie po dużym gc? – znlyj

+0

Zaadresowałem pierwsze pytanie z aktualizacją mojej odpowiedzi. Co do drugiego, nie jestem świadomy żadnej różnicy między "pełnymi" i "ważnymi" gcs. Co ci mówi, że miały miejsce ważne gcs? –

+0

Mogę powiedzieć, że główny gc wystąpił w gc log. – znlyj

4

dla rozwiązywania go, można użyć Eclipse Memory Analyzer. Pokaże ci szczegółowo wszystkie te problemy związane z pamięcią i wątkiem. Możesz również dla niego jConsole.

+0

Narzędzie do analizy pamięci jest doskonałym narzędziem do badania zawartości sterty, ale na koniec nie widziałem możliwości sprawdzania dzienników gc ani wydajności algorytmów GC. –