G1GC длинная пауза, создающая высокую задержку - PullRequest
Новая
       12

G1GC длинная пауза, создающая высокую задержку

0 голосов
/ 08 декабря 2018

Здесь я рассмотрел все вопросы, связанные с G1GC, которые были очень полезны.

Однако я наблюдаю странное поведение с G1GC.Видя, что пространство Эдема быстро очищается с большими размерами, но с небольшими размерами занимает много времени.Ожидаемая GC-пауза должна составлять около 250 мс, так как наше приложение очень чувствительно к задержке на P99.9

Пример из журналов: 

INFO  [Service Thread] 2018-12-07 20:31:45,854  - G1 Young Generation GC in 411ms.  G1 Eden Space: 10401873920 -> 0; G1 Old Gen: 5106505240 -> 5079237744; G1 Survivor Space: 738197504 -> 704643072; 
INFO  [Service Thread] 2018-12-07 20:33:04,997 - G1 Young Generation GC in 589ms.  G1 Eden Space: 14763950080 -> 0; G1 Old Gen: 5079237744 -> 5104384136; G1 Survivor Space: 704643072 -> 1040187392; 
INFO  [Service Thread] 2018-12-07 20:33:56,177  - G1 Young Generation GC in 710ms.  G1 Eden Space: 7516192768 -> 0; G1 Old Gen: 5104384136 -> 5315780600; G1 Survivor Space: 1040187392 -> 973078528; 
INFO  [Service Thread] 2018-12-07 20:34:39,166  - G1 Young Generation GC in 794ms.  G1 Eden Space: 5435817984 -> 0; G1 Old Gen: 5315780600 -> 5712717880; G1 Survivor Space: 973078528 -> 805306368; 
INFO  [Service Thread] 2018-12-07 20:35:04,318 - G1 Young Generation GC in 578ms.  G1 Eden Space: 4429185024 -> 0; G1 Old Gen: 5712717880 -> 6114606104; G1 Survivor Space: 805306368 -> 671088640; 
INFO  [Service Thread] 2018-12-07 20:36:21,297  - G1 Young Generation GC in 422ms.  G1 Eden Space: 10905190400 -> 0; G1 Old Gen: 6114606104 -> 6105201672; G1 Survivor Space: 671088640 -> 771751936;

Это нормально?В целом, как уменьшить это время паузы?Какие-либо конкретные настройки G1GC, на которые мне следует обратить внимание?

Текущие настройки:

Java-версия "1.8.0_131" Java (TM) SE Runtime Environment (сборка 1.8.0_131-b11) Java HotSpot (TM) 64-разрядная серверная виртуальная машина (сборка 25.131-b11, смешанный режим)

Система с 250 ГБ памяти и 64 Core.Мы используем Большие страницы и swapiness = 1.

Настройки GC: * ​​1016 * 

-Xms64G
-Xmx64G
-Xss256k
-XX:+AlwaysPreTouch
-XX:G1RSetUpdatingPauseTimePercent=5
-XX:GCLogFileSize=10485760
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/heap_dump/1543382478-pid129658.hprof
-XX:InitialHeapSize=68719476736
-XX:InitiatingHeapOccupancyPercent=60
-XX:LargePageSizeInBytes=2097152
-XX:+ManagementServer
-XX:MaxGCPauseMillis=500
//-XX:MaxHeapSize=68719476736
-XX:NumberOfGCLogFiles=10
-XX:+PerfDisableSharedMem
-XX:+PrintGC
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintHeapAtGC
-XX:+PrintPromotionFailure
-XX:+PrintTenuringDistribution
-XX:+ResizeTLAB
-XX:StringTableSize=1000003
-XX:ThreadPriorityPolicy=42
-XX:ThreadStackSize=256
-XX:-UseBiasedLocking
-XX:+UseG1GC
-XX:+UseGCLogFileRotation
-XX:+UseLargePages
-XX:+UseNUMA
-XX:+UseNUMAInterleaving
-XX:+UseTLAB
-XX:+UseThreadPriorities
-XX:+PerfDisableSharedMem



Duration (secs) No. of GCs  Percentage
0 - 1   3571    91.71%
1 - 2   232     5.96%
2 - 3   74      1.9% 
3 - 4   16      0.41%
4 - 5   1       0.03%

Из GCLog: G1 GC Time

Stats

РЕДАКТИРОВАТЬ: 2

После внесения некоторых изменений .. 

 -XX:+ParallelRefProcEnabled (Current value is false) -XX:G1NewSizePercent=10 -XX:G1MaxNewSizePercent=40 -XX:G1MixedGCCountTarget=24 (current value is 8) -XX:G1HeapWastePercent=15 (current value is 5) -XX:MaxGCPauseMillis=250


2018-12-09T12:08:11.887-0500: 923.353: Application time: 3.1835990 seconds
{Heap before GC invocations=25 (full 0):
 garbage-first heap   total 67108864K, used 7070479K [0x00007f47bc000000, 0x00007f47be004000, 0x00007f57bc000000)
  region size 32768K, 204 young (6684672K), 93 survivors (3047424K)
 Metaspace       used 60138K, capacity 63294K, committed 63488K, reserved 63488K
2018-12-09T12:08:11.889-0500: 923.355: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 436207616 bytes, new threshold 1 (max 15)
- age   1: 1601251544 bytes, 1601251544 total
- age   2:  127053616 bytes, 1728305160 total
- age   3:   10864104 bytes, 1739169264 total
- age   4:   36465952 bytes, 1775635216 total
- age   5:    3362656 bytes, 1778997872 total
- age   6:    5113872 bytes, 1784111744 total
- age   7:   25504240 bytes, 1809615984 total
- age   8:   29953320 bytes, 1839569304 total
- age   9:   12161368 bytes, 1851730672 total
- age  10:   16013320 bytes, 1867743992 total
- age  11:    5368336 bytes, 1873112328 total
- age  12:   22488536 bytes, 1895600864 total
- age  13:  106356352 bytes, 2001957216 total
- age  14:   85299392 bytes, 2087256608 total
- age  15:   65272728 bytes, 2152529336 total
2018-12-09T12:08:14.424-0500: 925.890: [SoftReference, 0 refs, 0.0034137 secs]2018-12-09T12:08:14.428-0500: 925.893: [WeakReference, 268465 refs, 0.0119008 secs]2018-12-09T12:08:14.439-0500: 925.905: [FinalReference, 2132 refs, 0.0024107 secs]2018-12-09T12:08:14.442-0500: 925.907: [PhantomReference, 376 refs, 3816 refs, 0.0037528 secs]2018-12-09T12:08:14.446-0500: 925.911: [JNI Weak Reference, 0.0000631 secs], 2.5710285 secs]
   [Parallel Time: 2530.8 ms, GC Workers: 43]
      [GC Worker Start (ms): Min: 923356.6, Avg: 923357.3, Max: 923357.9, Diff: 1.4]
      [Ext Root Scanning (ms): Min: 11.8, Avg: 23.3, Max: 429.6, Diff: 417.9, Sum: 1001.3]
      [Update RS (ms): Min: 0.0, Avg: 3.7, Max: 4.2, Diff: 4.2, Sum: 158.2]
         [Processed Buffers: Min: 0, Avg: 5.1, Max: 15, Diff: 15, Sum: 219]
      [Scan RS (ms): Min: 0.0, Avg: 1.0, Max: 1.4, Diff: 1.4, Sum: 43.7]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 1.3, Diff: 1.3, Sum: 9.9]
      [Object Copy (ms): Min: 2100.8, Avg: 2501.1, Max: 2512.1, Diff: 411.3, Sum: 107548.7]
      [Termination (ms): Min: 0.0, Avg: 0.4, Max: 0.5, Diff: 0.5, Sum: 18.9]
         [Termination Attempts: Min: 1, Avg: 1086.0, Max: 1257, Diff: 1256, Sum: 46696]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 4.8]
      [GC Worker Total (ms): Min: 2529.2, Avg: 2529.9, Max: 2530.6, Diff: 1.4, Sum: 108785.5]
      [GC Worker End (ms): Min: 925887.1, Avg: 925887.2, Max: 925887.3, Diff: 0.2]
   [Code Root Fixup: 0.8 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.7 ms]
   [Other: 38.7 ms]
      [Choose CSet: 0.1 ms]
      [Ref Proc: 23.1 ms]
      [Ref Enq: 1.5 ms]
      [Redirty Cards: 9.0 ms]
      [Humongous Register: 1.3 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 1.0 ms]

 [Eden: 3552.0M(3552.0M)->0.0B(5696.0M) Survivors: 2976.0M->832.0M Heap: 6904.8M(64.0G)->3336.4M(64.0G)]
Heap after GC invocations=26 (full 0):
 garbage-first heap   total 67108864K, used 3416438K [0x00007f47bc000000, 0x00007f47be004000, 0x00007f57bc000000)
  region size 32768K, 26 young (851968K), 26 survivors (851968K)
 Metaspace       used 60138K, capacity 63294K, committed 63488K, reserved 63488K
}
 [Times: user=108.68 sys=0.53, real=2.57 secs]
2018-12-09T12:08:14.461-0500: 925.926: Total time for which application threads were stopped: 2.5737713 seconds, Stopping threads took: 0.0006449 seconds
...