Обратите внимание, что можно визуально наблюдать состояние permanent generation, old generation, eden и сегментов survivor (S0 и S1). Цветные колонки показывают используемую память. Справа находится historical view, которое показывает, когда JVM проводило garbage collections и количество памяти в каждом из сегментов.
В окне приложения начните создавать объекты (опция 1) и наблюдайте, что будет происходить в Visual GC. Обратите внимание на то, что новые объекты всегда создаются в eden. Теперь сделайте пару объектов ненужными (опция 2). Возможно, вы не увидите изменений в Visual GC. Это потому, что JVM не чистит это пространство до тех пор, пока не закончена процедура garbage collection.
Чтобы инициировать garbage collection, создайте ещё объектов, заполнив Eden. Обратите внимание, что произойдет в момент заполнения. Если в Eden много мусора, вы увидите, как объекты из Eden «переезжают» в survivor. Однако, если в Eden мало мусора, вы увидите, как объекты «переезжают» в old generation. Это случается тогда, когда объекты, которые необходимо оставить, больше чем survival.
Пронаблюдайте также за постепенным увеличением Permanent Generation.
Попробуйте заполнить Eden, но не до конца, потом выбросьте почти все объекты, оставьте только 20 мб. Получиться так, что Eden на большую часть заполнен мусором. После этого создайте ещё объектов. На этот раз вы увидите, что объекты из Eden переходят в Survivor.
А теперь давайте посмотрим, что будет, если у нас не хватит памяти. Создавайте объекты до тех пор, пока их не будет на 460 мб. Обратите внимание, что и Eden и Old Generation заполнены практически полностью. Создайте ещё пару объектов. Когда больше не останется памяти, приложение «упадёт» с исключением OutOfMemoryException. Вы уже могли сталкиваться с подобным поведением и думать, почему же это произошло – особенно, если у вас большой объем физической памяти на компьютере и вы удивлялись, как такое вообще могло произойти, что не хватает памяти – теперь вы знаете, почему. Если так случится, что Permanent Generation заполнится (довольно сложно в случае нашего примера добиться этого), у вас будет брошено другое исключение, сообщающее, что PermGen заполнен.
И, наконец, ещё один способ посмотреть, что происходило, это обратиться к логу. Вот немного из моего:
13.373: [GC 13.373: [ParNew: 96871K->11646K(118016K), 0.1215535 secs] 96871K->73088K(511232K), 0.1216535 secs] [Times
: user=0.11 sys=0.07, real=0.12 secs]
16.267: [GC 16.267: [ParNew: 111290K->11461K(118016K), 0.1581621 secs] 172732K->166597K(511232K), 0.1582428 secs] [Ti
mes: user=0.16 sys=0.08, real=0.16 secs]
19.177: [GC 19.177: [ParNew: 107162K->10546K(118016K), 0.1494799 secs] 262297K->257845K(511232K), 0.1495659 secs] [Ti
mes: user=0.15 sys=0.07, real=0.15 secs]
19.331: [GC [1 CMS-initial-mark: 247299K(393216K)] 268085K(511232K), 0.0007000 secs] [Times: user=0.00 sys=0.00, real
=0.00 secs]
19.332: [CMS-concurrent-mark-start]
19.355: [CMS-concurrent-mark: 0.023/0.023 secs] [Times: user=0.01 sys=0.01, real=0.02 secs]
19.355: [CMS-concurrent-preclean-start]
19.356: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
19.356: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 24.417: [CMS-concurrent-abortable-preclean: 0.050/5.061 secs] [Times: user=0.10 sys=
0.01, real=5.06 secs]
24.417: [GC[YG occupancy: 23579 K (118016 K)]24.417: [Rescan (parallel) , 0.0015049 secs]24.419: [weak refs processin
g, 0.0000064 secs] [1 CMS-remark: 247299K(393216K)] 270878K(511232K), 0.0016149 secs] [Times: user=0.00 sys=0.00, rea
l=0.00 secs]
24.419: [CMS-concurrent-sweep-start]
24.420: [CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
24.420: [CMS-concurrent-reset-start]
24.422: [CMS-concurrent-reset: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
24.711: [GC [1 CMS-initial-mark: 247298K(393216K)] 291358K(511232K), 0.0017944 secs] [Times: user=0.00 sys=0.00, real
=0.01 secs]
24.713: [CMS-concurrent-mark-start]
24.755: [CMS-concurrent-mark: 0.040/0.043 secs] [Times: user=0.08 sys=0.00, real=0.04 secs]
24.755: [CMS-concurrent-preclean-start]
24.756: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
24.756: [CMS-concurrent-abortable-preclean-start]
25.882: [GC 25.882: [ParNew: 105499K->10319K(118016K), 0.1209086 secs] 352798K->329314K(511232K), 0.1209842 secs] [Ti
mes: user=0.12 sys=0.06, real=0.12 secs]
26.711: [CMS-concurrent-abortable-preclean: 0.018/1.955 secs] [Times: user=0.22 sys=0.06, real=1.95 secs]
26.711: [GC[YG occupancy: 72983 K (118016 K)]26.711: [Rescan (parallel) , 0.0008802 secs]26.712: [weak refs processin
g, 0.0000046 secs] [1 CMS-remark: 318994K(393216K)] 391978K(511232K), 0.0009480 secs] [Times: user=0.00 sys=0.00, rea
l=0.01 secs]
В логе можно увидеть, что происходило в JVM — обратите внимание, что использовался алгоритм Concurrent Mark Sweep Compact Collection algorithm (CMS), есть описание этапов и YG — Young Generation.
Можно воспользоваться этими настройками и в «продакшене». Есть даже инструменты, визуализирующие лог.
Ну, вот и закончилось наше краткое введение в теории и практики JVM garbage collection. Надеюсь, что приложение из примера помогло вам чётко представить, что происходит в JVM когда запущено ваше приложение.
Спасибо Rupesh Ramachandran за то, чему он научил меня относительно настроек JVM и garbage collection.
Теги: Java, JVM, garbage collection, garbage collectorХабы: Java