자바의 자세한 가비지 수집

1. 개요

이 튜토리얼에서는 Java 애플리케이션에서 자세한 가비지 콜렉션을 켜는 방법을 살펴볼 것 입니다. 자세한 가비지 컬렉션이 무엇이며 왜 유용 할 수 있는지 소개하는 것으로 시작하겠습니다.

다음으로 몇 가지 다른 예를 살펴보고 사용 가능한 다양한 구성 옵션에 대해 알아 봅니다. 또한 자세한 로그의 출력을 해석하는 방법에 대해서도 중점적으로 다룹니다.

가비지 수집 (GC) 및 사용 가능한 다양한 구현에 대해 자세히 알아 보려면 Java 가비지 수집기에 대한 기사를 확인하십시오.

2. Verbose Garbage Collection에 대한 간략한 소개

많은 문제 , 특히 메모리 문제를 튜닝하고 디버깅 할 때 자세한 가비지 수집 로깅을 켜야하는 경우가 많습니다 . 실제로 일부 사람들은 애플리케이션 상태를 엄격하게 모니터링하려면 항상 JVM의 가비지 컬렉션 성능을 모니터링해야한다고 주장합니다.

앞으로 보게 될 GC 로그는 애플리케이션의 힙 및 GC 구성에 대한 잠재적 인 개선 사항을 표시하는 데 매우 중요한 도구입니다. 발생하는 각 GC에 대해 GC 로그는 결과 및 기간에 대한 정확한 데이터를 제공합니다.

시간이 지남에 따라이 정보를 분석하면 애플리케이션의 동작을 더 잘 이해하고 애플리케이션의 성능을 조정하는 데 도움이 될 수 있습니다. 또한 최상의 힙 크기, 기타 JVM 옵션 및 대체 GC 알고리즘을 지정하여 GC 빈도 및 수집 시간을 최적화 할 수 있습니다.

2.1. 간단한 자바 프로그램

간단한 Java 프로그램을 사용하여 GC 로그를 활성화하고 해석하는 방법을 보여줍니다.

public class Application { private static Map stringContainer = new HashMap(); public static void main(String[] args) { System.out.println("Start of program!"); String stringWithPrefix = "stringWithPrefix"; // Load Java Heap with 3 M java.lang.String instances for (int i = 0; i < 3000000; i++) { String newString = stringWithPrefix + i; stringContainer.put(newString, newString); } System.out.println("MAP size: " + stringContainer.size()); // Explicit GC! System.gc(); // Remove 2 M out of 3 M for (int i = 0; i < 2000000; i++) { String newString = stringWithPrefix + i; stringContainer.remove(newString); } System.out.println("MAP size: " + stringContainer.size()); System.out.println("End of program!"); } }

위의 예에서 볼 수 있듯이이 간단한 프로그램은 3 백만 개의 String 인스턴스를 Map 객체에 로드 합니다. 그런 다음 System.gc ()를 사용하여 가비지 수집기를 명시 적으로 호출합니다 .

마지막으로 Map 에서 2 백만 개의 String 인스턴스를 제거합니다 . 또한 출력을 더 쉽게 해석하기 위해 명시 적으로 System.out.println 을 사용 합니다.

다음 섹션에서는 GC 로깅을 활성화하는 방법을 살펴 보겠습니다.

3. "단순"GC 로깅 활성화

프로그램을 실행하고 JVM 시작 인수를 통해 자세한 GC를 활성화하여 시작하겠습니다.

-XX:+UseSerialGC -Xms1024m -Xmx1024m -verbose:gc

여기서 중요한 인수 는 가장 간단한 형식으로 가비지 수집 정보의 로깅을 활성화 하는 -verbose : gc 입니다. 기본적으로 GC 로그는 stdout에 기록되며 모든 젊은 세대 GC 및 모든 전체 GC에 대한 행을 출력해야합니다.

예제의 목적을 위해 -XX : + UseSerialGC 인수를 통해 가장 간단한 GC 구현 인 직렬 가비지 수집기를 지정했습니다 .

또한 최소 및 최대 힙 크기를 1024mb로 설정했지만 물론 조정할 수있는 JVM 매개 변수가 더 많습니다.

3.1. Verbose 출력에 대한 기본 이해

이제 간단한 프로그램의 출력을 살펴 보겠습니다.

Start of program! [GC (Allocation Failure) 279616K->146232K(1013632K), 0.3318607 secs] [GC (Allocation Failure) 425848K->295442K(1013632K), 0.4266943 secs] MAP size: 3000000 [Full GC (System.gc()) 434341K->368279K(1013632K), 0.5420611 secs] [GC (Allocation Failure) 647895K->368280K(1013632K), 0.0075449 secs] MAP size: 1000000 End of program!

위의 출력에서 ​​우리는 이미 JVM 내부에서 일어나는 일에 대한 많은 유용한 정보를 볼 수 있습니다.

처음에는이 출력이 상당히 벅차게 보일 수 있지만 이제 단계별로 살펴 보겠습니다.

우선, 우리는 4 개의 수집이 일어 났음을 볼 수 있습니다. 하나의 Full GC와 3 개의 청소 젊은 세대입니다.

3.2. 자세한 출력 정보

정확히 무슨 일이 일어나고 있는지 이해하기 위해 출력 라인을 더 자세히 분해 해 보겠습니다.

  1. GC 또는 Full GC가비지 콜렉션의 유형 ( GC 또는 Full GC) 으로 부 또는 전체 가비지 콜렉션을 구분합니다.
  2. (할당 실패) 또는 (System.gc ()) – 수집의 원인 – 할당 실패는 객체를 할당 할 공간이 더 이상 Eden에 남지 않았 음을 나타냅니다.
  3. 279616K-> 146232K – 각각 GC 전후에 사용 된 힙 메모리 (화살표로 구분)
  4. (1013632K) – 힙의 현재 용량
  5. 0.3318607 초 – GC 이벤트 기간 (초)

따라서 첫 번째 줄을 사용하면 279616K-> 146232K (1013632K) 는 GC가 점유 힙 메모리를 279616K 에서 146232K였음의미 합니다. GC 시점의 힙 용량은 1013632K 였고 GC는 0.3318607 초가 걸렸 습니다 .

그러나 간단한 GC 로깅 형식이 유용 할 수 있지만 제한된 세부 정보를 제공합니다. 예를 들어, GC가 젊은 세대에서 이전 세대로 개체를 이동했는지 또는 각 컬렉션 전후에 젊은 세대의 총 크기를 알 수 없습니다 .

따라서 상세한 GC 로깅이 단순한 것보다 더 유용합니다.

4. "상세한"GC 로깅 활성화

자세한 GC 로깅을 활성화하려면 -XX : + PrintGCDetails 인수를 사용합니다 . 그러면 다음과 같은 각 GC에 대한 자세한 정보가 제공됩니다.

  • 각 GC 전후의 젊은 세대와 노인 세대의 규모
  • 젊은 세대와 노인 세대에서 GC가 발생하는 데 걸리는 시간
  • 모든 GC에서 승격 된 개체의 크기
  • 총 힙 크기 요약

다음 예에서는 -verbose : gc 를이 추가 인수와 결합하여 로그에서 더 자세한 정보를 캡처하는 방법을 살펴 보겠습니다 .

하십시오 참고 -XX : + PrintGCDetails의 플래그가 (나중에에 대한) 새로운 통합 로깅 메커니즘에 찬성, 자바 (9)에서 사용되지 않습니다. 어쨌든 -XX : + PrintGCDetails에 해당하는 새로운 기능 은 -Xlog : gc * 옵션입니다.

5. "상세한"자세한 출력 해석

샘플 프로그램을 다시 실행 해 보겠습니다.

-XX:+UseSerialGC -Xms1024m -Xmx1024m -verbose:gc -XX:+PrintGCDetails

이번에는 출력이 좀 더 장황합니다.

Start of program! [GC (Allocation Failure) [DefNew: 279616K->34944K(314560K), 0.3626923 secs] 279616K->146232K(1013632K), 0.3627492 secs] [Times: user=0.33 sys=0.03, real=0.36 secs] [GC (Allocation Failure) [DefNew: 314560K->34943K(314560K), 0.4589079 secs] 425848K->295442K(1013632K), 0.4589526 secs] [Times: user=0.41 sys=0.05, real=0.46 secs] MAP size: 3000000 [Full GC (System.gc()) [Tenured: 260498K->368281K(699072K), 0.5580183 secs] 434341K->368281K(1013632K), [Metaspace: 2624K->2624K(1056768K)], 0.5580738 secs] [Times: user=0.50 sys=0.06, real=0.56 secs] [GC (Allocation Failure) [DefNew: 279616K->0K(314560K), 0.0076722 secs] 647897K->368281K(1013632K), 0.0077169 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] MAP size: 1000000 End of program! Heap def new generation total 314560K, used 100261K [0x00000000c0000000, 0x00000000d5550000, 0x00000000d5550000) eden space 279616K, 35% used [0x00000000c0000000, 0x00000000c61e9370, 0x00000000d1110000) from space 34944K, 0% used [0x00000000d3330000, 0x00000000d3330188, 0x00000000d5550000) to space 34944K, 0% used [0x00000000d1110000, 0x00000000d1110000, 0x00000000d3330000) tenured generation total 699072K, used 368281K [0x00000000d5550000, 0x0000000100000000, 0x0000000100000000) the space 699072K, 52% used [0x00000000d5550000, 0x00000000ebcf65e0, 0x00000000ebcf6600, 0x0000000100000000) Metaspace used 2637K, capacity 4486K, committed 4864K, reserved 1056768K class space used 283K, capacity 386K, committed 512K, reserved 1048576K

간단한 GC 로그의 모든 요소를 ​​인식 할 수 있어야합니다. 그러나 몇 가지 새로운 항목이 있습니다.

이제 다음 섹션에서 파란색으로 강조 표시된 출력의 새 항목을 고려해 보겠습니다.

5.1. 젊은 세대의 마이너 GC 해석

작은 GC에서 새 부품을 분석하는 것으로 시작합니다.

  • [GC (할당 실패) [DefNew : 279616K-> 34944K (314560K), 0.3626923 초] 279616K-> 146232K (1013632K), 0.3627492 초] [Times : user = 0.33 sys = 0.03, real = 0.36 secs]

이전과 마찬가지로 라인을 여러 부분으로 나누겠습니다.

  1. DefNew – 사용 된 가비지 수집기의 이름입니다. 이 명확하지 않은 이름은 단일 스레드 mark-copy stop-the-world 가비지 수집기를 나타내며 Young 세대를 청소하는 데 사용됩니다.
  2. 279616K-> 34944K – 수집 전후의 젊은 세대 사용
  3. (314560K) – 젊은 세대의 전체 크기
  4. 0.3626923 초 – 기간 (초)
  5. [Times : user = 0.33 sys = 0.03, real = 0.36 secs ] – 다양한 카테고리에서 측정 된 GC 이벤트 기간

이제 다양한 카테고리를 설명하겠습니다.

  • user – 가비지 콜렉터가 사용한 총 CPU 시간
  • sys – OS 호출 또는 시스템 이벤트 대기에 소요 된 시간
  • real – 다른 프로세스에서 사용하는 시간 조각을 포함하여 모든 경과 시간입니다.

항상 단일 스레드 만 사용하는 Serial Garbage Collector를 사용하여 예제를 실행하고 있으므로 실시간은 사용자 및 시스템 시간의 합계와 같습니다.

5.2. 전체 GC 해석

이 두 번째 예에서는 시스템 호출에 의해 트리거 된 주요 컬렉션 (Full GC)의 경우 사용 된 수집기가 Tenured라는 것을 알 수 있습니다.

추가 정보의 마지막 부분은 Metaspace에 대해 동일한 패턴을 따르는 분석입니다 .

[Metaspace: 2624K->2624K(1056768K)], 0.5580738 secs]

Metaspace is a new memory space introduced in Java 8 and is an area of native memory.

5.3. Java Heap Breakdown Analysis

The final part of the output includes a breakdown of the heap including a memory footprint summary for each part of memory.

We can see that Eden space had a 35% footprint and Tenured had a 52% footprint. A summary for Metadata space and class space is also included.

From the above examples, we can now understand exactly what was happening with memory consumption inside the JVM during the GC events.

6. Adding Date and Time Information

No good log is complete without date and time information.

This extra information can be highly useful when we need to correlate GC log data with data from other sources, or it can simply help facilitate searching.

We can add the following two arguments when we run our application to get date and time information to appear in our logs:

-XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps

Each line now starts with the absolute date and time when it was written followed by a timestamp reflecting the real-time passed in seconds since the JVM started:

2018-12-11T02:55:23.518+0100: 2.601: [GC (Allocation ...

Please note that these tuning flags have been removed in Java 9. The new alternative is:

-Xlog:gc*::time

7. Logging to a File

As we've already seen, by default the GC log is written to stdout. A more practical solution is to specify an output file.

We can do this by using the argument -Xloggc: where file is the absolute path to our output file:

-Xloggc:/path/to/file/gc.log

Similar to other tuning flags, Java 9 deprecated the -Xloggc flag in favor of the new unified logging. To be more specific, now the alternative for logging to a file is:

-Xlog:gc:/path/to/file/gc.log

8. Java 9: Unified JVM Logging

As of Java 9, most of the GC related tuning flags have been deprecated in favor of the unified logging option -Xlog:gc. The verbose:gc option, however, still works in Java 9 and newer version.

For instance, as of Java 9, the equivalent of the -verbose:gc flag in the new unified logging system is:

-Xlog:gc

This will log all the info level GC logs to the standard output. It's also possible to use the -Xlog:gc= syntax to change the log level. For instance, to see all debug level logs:

-Xlog:gc=debug

As we saw earlier, we can change the output destination via the -Xlog:gc=: syntax. By default, the output is stdout, but we can change it to stderr or even a file:

-Xlog:gc=debug:file=gc.txt

Also, it's possible to add a few more fields to the output using decorators. For instance:

-Xlog:gc=debug::pid,time,uptime

Here we're printing the process id, uptime, and current timestamp in each log statement.

To see more examples of the Unified JVM Logging, see the JEP 158 standard.

9. A Tool to Analyze GC Logs

It can be time-consuming and quite tedious to analyze GC logs using a text editor. Depending on the JVM version and the GC algorithm that is used, the GC log format could differ.

가비지 수집 로그를 분석하고 잠재적 인 가비지 수집 문제에 대한 많은 메트릭을 제공하며 이러한 문제에 대한 잠재적 솔루션을 제공하는 매우 훌륭한 무료 그래픽 분석 도구가 있습니다.

Universal GC Log Analyzer를 확실히 확인하십시오!

10. 결론

요약하면이 자습서에서는 Java의 자세한 가비지 수집을 자세히 살펴 보았습니다.

먼저, 자세한 가비지 컬렉션이 무엇이며 왜 사용하고 싶은지 소개하는 것으로 시작했습니다. 그런 다음 간단한 Java 애플리케이션을 사용하여 몇 가지 예를 살펴 보았습니다. 몇 가지 더 자세한 예제와 출력을 해석하는 방법을 탐색하기 전에 가장 간단한 형태로 GC 로깅을 활성화하는 것으로 시작했습니다.

마지막으로 시간 및 날짜 정보를 기록하고 로그 파일에 정보를 쓰는 방법에 대한 몇 가지 추가 옵션을 탐색했습니다.

코드 예제는 GitHub에서 찾을 수 있습니다.