Почему перед первым g c существует неотблокированный полный g c, куча до вызовов G C = 0 (полный 1)? - PullRequest
Новая
       57

Почему перед первым g c существует неотблокированный полный g c, куча до вызовов G C = 0 (полный 1)?

1 голос
/ 30 апреля 2020

Я нашел странную вещь в журналах g c. Это показывает, что перед первым g c (это младший g c, как мы можем видеть в журналах), был запущен полный g c.

Приложение работает в java 8 с CMS g c collector 

OpenJDK 64-Bit Server VM (25.232-b04) for linux-amd64 JRE (1.8.0_232-b04), built on Sep 24 2019 10:14:17 by "root" with gcc 4.8.5
Memory: 4k page, physical 98726220k(2969212k free), swap 0k(0k free)
CommandLine flags: -XX:CMSInitiatingOccupancyFraction=70 -XX:+CMSParallelRemarkEnabled -XX:+DisableExplicitGC -XX:InitialHeapSize=2147483648 -XX:LargePageSizeInBytes=134217728 -XX:+ManagementServer -XX:MaxHeapSize=2147483648 -XX:MaxNewSize=715829248 -XX:MaxTenuringThreshold=6 -XX:NewSize=715829248 -XX:OldPLABSize=16 -XX:OldSize=1431654400 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:ThreadStackSize=256 -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseFastAccessorMethods -XX:+UseParNewGC 
2020-04-29T11:05:44.412+0800: 2.088: [GC (CMS Initial Mark) [1 CMS-initial-mark: 0K(1398144K)] 549082K(2027264K), 0.2121146 secs] [Times: user=0.21 sys=0.00, real=0.21 secs] 
2020-04-29T11:05:44.625+0800: 2.300: [CMS-concurrent-mark-start]
2020-04-29T11:05:44.626+0800: 2.301: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2020-04-29T11:05:44.626+0800: 2.301: [CMS-concurrent-preclean-start]
2020-04-29T11:05:44.629+0800: 2.304: [CMS-concurrent-preclean: 0.003/0.003 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2020-04-29T11:05:44.629+0800: 2.304: [CMS-concurrent-abortable-preclean-start]
{Heap before GC invocations=0 (full 1):
 par new generation   total 629120K, used 559232K [0x0000000080000000, 0x00000000aaaa0000, 0x00000000aaaa0000)
  eden space 559232K, 100% used [0x0000000080000000, 0x00000000a2220000, 0x00000000a2220000)
  from space 69888K,   0% used [0x00000000a2220000, 0x00000000a2220000, 0x00000000a6660000)
  to   space 69888K,   0% used [0x00000000a6660000, 0x00000000a6660000, 0x00000000aaaa0000)
 concurrent mark-sweep generation total 1398144K, used 0K [0x00000000aaaa0000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 34529K, capacity 35407K, committed 35572K, reserved 1081344K
  class space    used 4175K, capacity 4382K, committed 4440K, reserved 1048576K
2020-04-29T11:05:44.679+0800: 2.354: [GC (Allocation Failure) 2020-04-29T11:05:44.679+0800: 2.354: [ParNew: 559232K->42422K(629120K), 0.0639801 secs] 559232K->42422K(2027264K), 0.0640614 secs] [Times: user=0.41 sys=0.76, real=0.07 secs] 
Heap after GC invocations=1 (full 1):
 par new generation   total 629120K, used 42422K [0x0000000080000000, 0x00000000aaaa0000, 0x00000000aaaa0000)
  eden space 559232K,   0% used [0x0000000080000000, 0x0000000080000000, 0x00000000a2220000)
  from space 69888K,  60% used [0x00000000a6660000, 0x00000000a8fcd840, 0x00000000aaaa0000)
  to   space 69888K,   0% used [0x00000000a2220000, 0x00000000a2220000, 0x00000000a6660000)
 concurrent mark-sweep generation total 1398144K, used 0K [0x00000000aaaa0000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 34529K, capacity 35407K, committed 35572K, reserved 1081344K
  class space    used 4175K, capacity 4382K, committed 4440K, reserved 1048576K
}
2020-04-29T11:05:46.060+0800: 3.736: [CMS-concurrent-abortable-preclean: 1.196/1.432 secs] [Times: user=7.10 sys=0.87, real=1.43 secs] 
2020-04-29T11:05:46.060+0800: 3.736: [GC (CMS Final Remark) [YG occupancy: 337273 K (629120 K)]2020-04-29T11:05:46.060+0800: 3.736: [Rescan (parallel) , 0.0166530 secs]2020-04-29T11:05:46.077+0800: 3.753: [weak refs processing, 0.0000398 secs]2020-04-29T11:05:46.077+0800: 3.753: [class unloading, 0.0089091 secs]2020-04-29T11:05:46.086+0800: 3.762: [scrub symbol table, 0.0101553 secs]2020-04-29T11:05:46.096+0800: 3.772: [scrub string table, 0.0007144 secs][1 CMS-remark: 0K(1398144K)] 337273K(2027264K), 0.0385882 secs] [Times: user=0.48 sys=0.00, real=0.04 secs] 
2020-04-29T11:05:46.099+0800: 3.775: [CMS-concurrent-sweep-start]
2020-04-29T11:05:46.099+0800: 3.775: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2020-04-29T11:05:46.099+0800: 3.775: [CMS-concurrent-reset-start]
2020-04-29T11:05:46.113+0800: 3.788: [CMS-concurrent-reset: 0.014/0.014 secs] [Times: user=0.07 sys=0.00, real=0.02 secs]

После того, как я выполнил поиск в Интернете, я подумал, что это вызвано размером метапространства вопрос. Поэтому я установил большой размер для метапространства с помощью -XX:MetaspaceSize=128m, и полное значение g c исчезло 

OpenJDK 64-Bit Server VM (25.232-b04) for linux-amd64 JRE (1.8.0_232-b04), built on Sep 24 2019 10:14:17 by "root" with gcc 4.8.5
Memory: 4k page, physical 98726220k(2957504k free), swap 0k(0k free)
CommandLine flags: -XX:CMSInitiatingOccupancyFraction=70 -XX:+CMSParallelRemarkEnabled -XX:+DisableExplicitGC -XX:InitialHeapSize=2147483648 -XX:LargePageSizeInBytes=134217728 -XX:+ManagementServer -XX:MaxHeapSize=2147483648 -XX:MaxNewSize=715829248 -XX:MaxTenuringThreshold=6 -XX:MetaspaceSize=134217728 -XX:NewSize=715829248 -XX:OldPLABSize=16 -XX:OldSize=1431654400 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:ThreadStackSize=256 -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseFastAccessorMethods -XX:+UseParNewGC 
{Heap before GC invocations=0 (full 0):
 par new generation   total 629120K, used 559232K [0x0000000080000000, 0x00000000aaaa0000, 0x00000000aaaa0000)
  eden space 559232K, 100% used [0x0000000080000000, 0x00000000a2220000, 0x00000000a2220000)
  from space 69888K,   0% used [0x00000000a2220000, 0x00000000a2220000, 0x00000000a6660000)
  to   space 69888K,   0% used [0x00000000a6660000, 0x00000000a6660000, 0x00000000aaaa0000)
 concurrent mark-sweep generation total 1398144K, used 0K [0x00000000aaaa0000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 34127K, capacity 35034K, committed 35200K, reserved 1079296K
  class space    used 4184K, capacity 4410K, committed 4480K, reserved 1048576K
2020-04-29T10:16:16.735+0800: 2.189: [GC (Allocation Failure) 2020-04-29T10:16:16.735+0800: 2.189: [ParNew: 559232K->42224K(629120K), 0.0639467 secs] 559232K->42224K(2027264K), 0.0640639 secs] [Times: user=0.48 sys=0.88, real=0.06 secs] 
Heap after GC invocations=1 (full 0):
 par new generation   total 629120K, used 42224K [0x0000000080000000, 0x00000000aaaa0000, 0x00000000aaaa0000)
  eden space 559232K,   0% used [0x0000000080000000, 0x0000000080000000, 0x00000000a2220000)
  from space 69888K,  60% used [0x00000000a6660000, 0x00000000a8f9c0a8, 0x00000000aaaa0000)
  to   space 69888K,   0% used [0x00000000a2220000, 0x00000000a2220000, 0x00000000a6660000)
 concurrent mark-sweep generation total 1398144K, used 0K [0x00000000aaaa0000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 34127K, capacity 35034K, committed 35200K, reserved 1079296K
  class space    used 4184K, capacity 4410K, committed 4480K, reserved 1048576K
}

Мой вопрос:

  1. Почему может быть незарегистрированный г c? Как я могу узнать, как это происходит?
  2. Если это связано с изменением размера метапространства, почему я не вижу журнал, подобный Full GC (Metadata GC Threshold). Есть ли что-то отличное от этих двух?

ОБНОВЛЕНИЕ

Я также тестирую на ParallelG C, я обнаружил, что полный g c срабатывает, как и ожидалось, что "Полный G C (метаданные G C Threshold) "регистрируется. И первый g c записывается "{куча до G C вызовов = 1 (полный 0)" 

OpenJDK 64-Bit Server VM (25.232-b04) for linux-amd64 JRE (1.8.0_232-b04), built on Sep 24 2019 10:14:17 by "root" with gcc 4.8.5
Memory: 4k page, physical 98726220k(4949696k free), swap 0k(0k free)
CommandLine flags: -XX:+DisableExplicitGC -XX:InitialHeapSize=2147483648 -XX:LargePageSizeInBytes=134217728 -XX:+ManagementServer -XX:MaxHeapSize=2147483648 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:ThreadStackSize=256 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseFastAccessorMethods -XX:+UseParallelGC 
{Heap before GC invocations=1 (full 0):
 PSYoungGen      total 611840K, used 262425K [0x00000000d5580000, 0x0000000100000000, 0x0000000100000000)
  eden space 524800K, 50% used [0x00000000d5580000,0x00000000e55c6798,0x00000000f5600000)
  from space 87040K, 0% used [0x00000000fab00000,0x00000000fab00000,0x0000000100000000)
  to   space 87040K, 0% used [0x00000000f5600000,0x00000000f5600000,0x00000000fab00000)
 ParOldGen       total 1398272K, used 0K [0x0000000080000000, 0x00000000d5580000, 0x00000000d5580000)
  object space 1398272K, 0% used [0x0000000080000000,0x0000000080000000,0x00000000d5580000)
 Metaspace       used 20773K, capacity 21204K, committed 21296K, reserved 1069056K
  class space    used 2445K, capacity 2598K, committed 2608K, reserved 1048576K
2020-05-06T15:45:09.843+0800: 1.045: [GC (Metadata GC Threshold) [PSYoungGen: 262425K->22590K(611840K)] 262425K->22678K(2010112K), 0.0234524 secs] [Times: user=0.19 sys=0.23, real=0.03 secs] 
Heap after GC invocations=1 (full 0):
 PSYoungGen      total 611840K, used 22590K [0x00000000d5580000, 0x0000000100000000, 0x0000000100000000)
  eden space 524800K, 0% used [0x00000000d5580000,0x00000000d5580000,0x00000000f5600000)
  from space 87040K, 25% used [0x00000000f5600000,0x00000000f6c0f960,0x00000000fab00000)
  to   space 87040K, 0% used [0x00000000fab00000,0x00000000fab00000,0x0000000100000000)
 ParOldGen       total 1398272K, used 88K [0x0000000080000000, 0x00000000d5580000, 0x00000000d5580000)
  object space 1398272K, 0% used [0x0000000080000000,0x0000000080016010,0x00000000d5580000)
 Metaspace       used 20773K, capacity 21204K, committed 21296K, reserved 1069056K
  class space    used 2445K, capacity 2598K, committed 2608K, reserved 1048576K
}
{Heap before GC invocations=2 (full 1):
 PSYoungGen      total 611840K, used 22590K [0x00000000d5580000, 0x0000000100000000, 0x0000000100000000)
  eden space 524800K, 0% used [0x00000000d5580000,0x00000000d5580000,0x00000000f5600000)
  from space 87040K, 25% used [0x00000000f5600000,0x00000000f6c0f960,0x00000000fab00000)
  to   space 87040K, 0% used [0x00000000fab00000,0x00000000fab00000,0x0000000100000000)
 ParOldGen       total 1398272K, used 88K [0x0000000080000000, 0x00000000d5580000, 0x00000000d5580000)
  object space 1398272K, 0% used [0x0000000080000000,0x0000000080016010,0x00000000d5580000)
 Metaspace       used 20773K, capacity 21204K, committed 21296K, reserved 1069056K
  class space    used 2445K, capacity 2598K, committed 2608K, reserved 1048576K
2020-05-06T15:45:09.867+0800: 1.068: [Full GC (Metadata GC Threshold) [PSYoungGen: 22590K->0K(611840K)] [ParOldGen: 88K->21585K(1398272K)] 22678K->21585K(2010112K), [Metaspace: 20773K->20771K(1069056K)], 0.1216866 secs] [Times: user=1.81 sys=0.14, real=0.12 secs] 
Heap after GC invocations=2 (full 1):
 PSYoungGen      total 611840K, used 0K [0x00000000d5580000, 0x0000000100000000, 0x0000000100000000)
  eden space 524800K, 0% used [0x00000000d5580000,0x00000000d5580000,0x00000000f5600000)
  from space 87040K, 0% used [0x00000000f5600000,0x00000000f5600000,0x00000000fab00000)
  to   space 87040K, 0% used [0x00000000fab00000,0x00000000fab00000,0x0000000100000000)
 ParOldGen       total 1398272K, used 21585K [0x0000000080000000, 0x00000000d5580000, 0x00000000d5580000)
  object space 1398272K, 1% used [0x0000000080000000,0x0000000081514778,0x00000000d5580000)
 Metaspace       used 20771K, capacity 21198K, committed 21296K, reserved 1069056K
  class space    used 2445K, capacity 2597K, committed 2608K, reserved 1048576K
}
...