Почему GC не работает в том же методе - PullRequest
Новая
       28

Почему GC не работает в том же методе

0 голосов
/ 09 июня 2019

Я играю с gc и обнаружил интересную ситуацию, когда gc (я использую параллельный gc) не участвует Это мой код 

public static void main(String[] args) {
       System.out.println(Runtime.getRuntime().freeMemory() / (1024 * 1024) + " free");

    String[] strings = new String[(40 * 1024 * 1024) / Integer.BYTES];
    System.out.println(strings.length);

    System.out.println(Runtime.getRuntime().freeMemory() / (1024 * 1024) + " free");

    strings = new String[(40 * 1024 * 1024) / Integer.BYTES];
    System.out.println(strings.length);

    System.out.println(Runtime.getRuntime().freeMemory() / (1024 * 1024) + " free");

    }

Моя версия Java: 

java version "1.8.0_191"
Java(TM) SE Runtime Environment (build 1.8.0_191-b12)
Java HotSpot(TM) 64-Bit Server VM (build 25.191-b12, mixed mode)

Эта программа была связана со следующим argc: 

-Xmx64m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps

Это вывод: 

59 free
10485760
19 free
2019-06-09T14:53:18.868+0600: 0.105: [GC (Allocation Failure) [PSYoungGen: 1640K->480K(18944K)] 42600K->41448K(62976K), 0.0018199 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-06-09T14:53:18.870+0600: 0.107: [Full GC (Ergonomics) [PSYoungGen: 480K->0K(18944K)] [ParOldGen: 40968K->41339K(44032K)] 41448K->41339K(62976K), [Metaspace: 3033K->3033K(1056768K)], 0.0174681 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 
2019-06-09T14:53:18.888+0600: 0.125: [GC (Allocation Failure) [PSYoungGen: 0K->0K(18944K)] 41339K->41339K(62976K), 0.0017270 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-06-09T14:53:18.889+0600: 0.126: [Full GC (Allocation Failure) [PSYoungGen: 0K->0K(18944K)] [ParOldGen: 41339K->41321K(44032K)] 41339K->41321K(62976K), [Metaspace: 3033K->3033K(1056768K)], 0.0140842 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] 
Heap
 PSYoungGen      total 18944K, used 491K [0x00000000feb00000, 0x0000000100000000, 0x0000000100000000)
  eden space 16384K, 3% used [0x00000000feb00000,0x00000000feb7afa0,0x00000000ffb00000)
  from space 2560K, 0% used [0x00000000ffd80000,0x00000000ffd80000,0x0000000100000000)
  to   space 2560K, 0% used [0x00000000ffb00000,0x00000000ffb00000,0x00000000ffd80000)
 ParOldGen       total 44032K, used 41321K [0x00000000fc000000, 0x00000000feb00000, 0x00000000feb00000)
  object space 44032K, 93% used [0x00000000fc000000,0x00000000fe85a6d0,0x00000000feb00000)
 Metaspace       used 3064K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 336K, capacity 388K, committed 512K, reserved 1048576K
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
    at lightbox.GcWIthoutComp.main(GcWIthoutComp.java:11)

Согласно журналам, JVM не смог выделить память для строки во второй раз, но если я добавлю JVM arg -Xcomp, он будет работать и выдает этот вывод 

59 free
10485760
19 free
2019-06-09T15:01:06.593+0600: 0.830: [GC (Allocation Failure) [PSYoungGen: 1982K->512K(18944K)] 42942K->41480K(62976K), 0.0008554 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2019-06-09T15:01:06.594+0600: 0.831: [Full GC (Ergonomics) [PSYoungGen: 512K->0K(18944K)] [ParOldGen: 40968K->411K(37376K)] 41480K->411K(56320K), [Metaspace: 3377K->3377K(1056768K)], 0.0100865 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
10485760
20 free
Heap
 PSYoungGen      total 18944K, used 1147K [0x00000000feb00000, 0x0000000100000000, 0x0000000100000000)
  eden space 16384K, 7% used [0x00000000feb00000,0x00000000fec1ed48,0x00000000ffb00000)
  from space 2560K, 0% used [0x00000000ffb00000,0x00000000ffb00000,0x00000000ffd80000)
  to   space 2560K, 0% used [0x00000000ffd80000,0x00000000ffd80000,0x0000000100000000)
 ParOldGen       total 44032K, used 41371K [0x00000000fc000000, 0x00000000feb00000, 0x00000000feb00000)
  object space 44032K, 93% used [0x00000000fc000000,0x00000000fe866c90,0x00000000feb00000)
 Metaspace       used 3399K, capacity 4500K, committed 4864K, reserved 1056768K
  class space    used 334K, capacity 388K, committed 512K, reserved 1048576K

Как я понимаю, скомпилированный код очень удобен для GC с точки зрения обнаружения неиспользуемой памяти. Более того, если я удалю -Xcomp и перенесу создание массива в отдельный метод, он не выдаст исключение OOM: 

public static void main(String[] args) {
        System.out.println(Runtime.getRuntime().freeMemory() / (1024 * 1024) + " free");

        allocate();

        System.out.println(Runtime.getRuntime().freeMemory() / (1024 * 1024) + " free");
        allocate();
        System.out.println(Runtime.getRuntime().freeMemory() / (1024 * 1024) + " free");

    }

    private static void allocate() {
        String[] strings = new String[(40 * 1024 * 1024) / Integer.BYTES];
        System.out.println(strings.length);
    }

Мои вопросы:

  1. Почему -Xcomp решает проблему с распределением, как показано выше?

  2. Почему перемещение выделения в отдельный метод решило мою проблему?

Если у вас есть полезные ссылки, укажите их в комментариях.

1 Ответ

1 голос
/ 09 июня 2019

Комментарий просто помещается в одну строку, и там сложно что-то объяснить.Важным отличием является то, что с -Xcomp строки локальной переменной уже доступны для сбора.Таким образом, вы получаете: 

2019-06-09T15:01:06.593+0600: 0.830: [GC (Allocation Failure) [PSYoungGen: 1982K->512K(18944K)] 42942K->41480K(62976K), 0.0008554 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2019-06-09T15:01:06.594+0600: 0.831: [Full GC (Ergonomics) [PSYoungGen: 512K->0K(18944K)] [ParOldGen: 40968K->411K(37376K)] 41480K->411K(56320K), [Metaspace: 3377K->3377K(1056768K)], 0.0100865 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]

Таким образом, вы получаете ошибку распределения, но ГХ может освободить достаточно памяти.

Без -Xcomp строки переменной loal не могут быть собраны, поэтому полученное сообщениечто-то вроде: 

2019-06-09T14:53:18.868+0600: 0.105: [GC (Allocation Failure) [PSYoungGen: 1640K->480K(18944K)] 42600K->41448K(62976K), 0.0018199 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-06-09T14:53:18.870+0600: 0.107: [Full GC (Ergonomics) [PSYoungGen: 480K->0K(18944K)] [ParOldGen: 40968K->41339K(44032K)] 41448K->41339K(62976K), [Metaspace: 3033K->3033K(1056768K)], 0.0174681 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 
2019-06-09T14:53:18.888+0600: 0.125: [GC (Allocation Failure) [PSYoungGen: 0K->0K(18944K)] 41339K->41339K(62976K), 0.0017270 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-06-09T14:53:18.889+0600: 0.126: [Full GC (Allocation Failure) [PSYoungGen: 0K->0K(18944K)] [ParOldGen: 41339K->41321K(44032K)] 41339K->41321K(62976K), [Metaspace: 3033K->3033K(1056768K)], 0.0140842 secs] [Times: user=0.03 sys=0.01, real=0.01 secs]

, которое показывает, что GC пытается освободить память, но не может этого сделать.

(Посмотрите на PSYoungGen: он показывает, как происходит сбой памяти. Когда произошел сбойбез -Xcomp не так много было бы возможно. С -Xcomp она снижается с 1982К до 512K. Также см. https://dzone.com/articles/understanding-garbage-collection-log)

Мне не удалось найти точные данные, которые делает -Xcomp. Поэтому я сожалеючто я могу дать вам только интерпретацию журнала прямо сейчас. Так что это похоже на установку строк в null до назначения вновь сгенерированного массива. Так что если вы добавляете strings = null, прежде чем назначать массив во второй раз: Даже без -Xcompвы получаете более или менее то же самое сообщение от gc.

И относительно использования его внутри метода: у вас есть локальная переменная внутри вашего метода. Таким образом, вы присваиваете массив, а затемметод заканчивается, и сборщик мусора может собирать локальную переменную.

...