Почему большой HashMap вызывает длинные GC-паузы - PullRequest
Новая
       30

Почему большой HashMap вызывает длинные GC-паузы

0 голосов
/ 08 июля 2019

Я написал функцию тестирования паузы в GC и обнаружил большое время STW (> 1,5 с) с большим HashMap (~ 3 миллиона записей) при явном вызове System.gc ().

Я попробовал большой ArrayList, и он показал такие же длинные паузы GC (помет короче, чем Map).

Коды испытаний приведены ниже: 

package tool.gc;

import java.util.HashMap;
import java.util.Map;

public class HashMapTest {
  Map<Integer, byte[]> map = new HashMap<>();

  public static void main(String[] args) throws Exception {
    HashMapTest test = new HashMapTest();
    test.gcTestWithMap();
    System.out.println("prepare to gc, now:" + System.currentTimeMillis());
    while (true) {
      System.gc();
      System.out.println("finish a round of gc");
      Thread.sleep(4000);
    }
  }

  public void gcTestWithMap() {
    for (int i = 0; i < 3000000; i++) {
      byte[] bytes = new byte[2000];
      for (int j = 0; j < bytes.length; j++) {
        bytes[j] = 1;
      }
      map.put(i, bytes);
    }
  }
}

Параметры запуска JVM: 

java -Xmx10g -Xms10g  
-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDetails  
-XX:+PrintGCDateStamps -XX:+PrintGCDetails  -Xloggc:gc.log 
-XX:+UseConcMarkSweepGC -XX:ParallelCMSThreads=8 
-cp test-1.0.0.jar tool.gc.HashMapTest

Некоторые журналы GC, как показано ниже: 

2019-07-08T10:27:35.386+0800: 438.306: Total time for which application threads were stopped: 2.1067575 seconds, Stopping threads took: 0.0000317 seconds
2019-07-08T10:27:37.386+0800: 440.306: Total time for which application threads were stopped: 0.0006364 seconds, Stopping threads took: 0.0000209 seconds
2019-07-08T10:27:38.298+0800: 441.218: Total time for which application threads were stopped: 0.0036499 seconds, Stopping threads took: 0.0000249 seconds
2019-07-08T10:27:41.143+0800: 444.063: Total time for which application threads were stopped: 1.7568843 seconds, Stopping threads took: 0.0000237 seconds
2019-07-08T10:27:41.144+0800: 444.064: Total time for which application threads were stopped: 0.0006293 seconds, Stopping threads took: 0.0000453 seconds
2019-07-08T10:27:42.033+0800: 444.953: Total time for which application threads were stopped: 0.0039319 seconds, Stopping threads took: 0.0000295 seconds

В моем понимании, HashMap Object может быть одним из корней GC, но не всеми записями. Мой вопрос: что может быть основной причиной длительного STW.

1 Ответ

0 голосов
/ 08 июля 2019

Это не очень хороший способ проверить работоспособность вашего приложения.Вы должны запускать его с реалистичной рабочей нагрузкой несколько раз и наблюдать за поведением приложения с помощью инструментов мониторинга и включенной регистрации GC.Затем вы можете судить, приемлемы ли задержки, введенные GC.

После этого вы можете попытаться улучшить свой код и / или поэкспериментировать с другими настройками JVM.И, возможно, обновите версию JDK, которую вы используете, поскольку она кажется старше 8.

PS: Чтобы получить дополнительную информацию в журналах GC, вы также можете включить статистика безопасных точек (см. https://blog.jayan.kandathil.ca/gc_logging_in_java11.html).

...