Verbose Garbage Collection trong Java

1. Khái quát chung

Trong hướng dẫn này, chúng ta sẽ xem xét cách bật tính năng thu gom rác trong một ứng dụng Java . Chúng tôi sẽ bắt đầu bằng cách giới thiệu chi tiết về thu gom rác là gì và tại sao nó có thể hữu ích.

Tiếp theo, chúng ta sẽ xem xét một số ví dụ khác nhau và chúng ta sẽ tìm hiểu về các tùy chọn cấu hình khác nhau có sẵn. Ngoài ra, chúng tôi cũng sẽ tập trung vào cách diễn giải đầu ra của các bản ghi dài dòng của chúng tôi.

Để tìm hiểu thêm về Garbage Collection (GC) và các triển khai khác nhau có sẵn, hãy xem bài viết của chúng tôi về Java Garbage Collectors.

2. Giới thiệu ngắn gọn về thu gom rác chi tiết

Chuyển sang ghi nhật ký thu thập rác dài dòng thường được yêu cầu khi điều chỉnh và gỡ lỗi nhiều vấn đề , đặc biệt là các vấn đề về bộ nhớ. Trên thực tế, một số người cho rằng để giám sát chặt chẽ tình trạng ứng dụng của chúng ta, chúng ta phải luôn theo dõi hiệu suất Thu gom rác của JVM.

Như chúng ta sẽ thấy, nhật ký GC là một công cụ rất quan trọng để tiết lộ những cải tiến tiềm năng đối với cấu hình heap và GC của ứng dụng của chúng tôi. Đối với mỗi GC xảy ra, nhật ký GC cung cấp dữ liệu chính xác về kết quả và thời lượng của nó.

Theo thời gian, việc phân tích thông tin này có thể giúp chúng tôi hiểu rõ hơn về hoạt động của ứng dụng và giúp chúng tôi điều chỉnh hiệu suất ứng dụng của mình. Hơn nữa, nó có thể giúp tối ưu hóa tần suất GC và thời gian thu thập bằng cách chỉ định kích thước đống tốt nhất, các tùy chọn JVM khác và các thuật toán GC thay thế.

2.1. Một chương trình Java đơn giản

Chúng tôi sẽ sử dụng một chương trình Java đơn giản để trình bày cách bật và diễn giải nhật ký GC của chúng tôi:

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!"); } }

Như chúng ta có thể thấy trong ví dụ trên, chương trình đơn giản này tải 3 triệu cá thể Chuỗi vào một đối tượng Bản đồ . Sau đó, chúng tôi thực hiện một cuộc gọi rõ ràng tới bộ thu gom rác bằng System.gc () .

Cuối cùng, chúng tôi xóa 2 triệu phiên bản Chuỗi khỏi Bản đồ . Chúng tôi cũng sử dụng System.out.println một cách rõ ràng để giúp việc diễn giải đầu ra dễ dàng hơn.

Trong phần tiếp theo, chúng ta sẽ xem cách kích hoạt ghi nhật ký GC.

3. Kích hoạt Ghi nhật ký GC “đơn giản”

Hãy bắt đầu bằng cách chạy chương trình của chúng tôi và bật GC chi tiết thông qua các đối số khởi động JVM của chúng tôi:

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

Đối số quan trọng ở đây là -verbose: gc , kích hoạt ghi nhật ký thông tin thu thập rác ở dạng đơn giản nhất . Theo mặc định, nhật ký GC được ghi thành stdout và sẽ xuất ra một dòng cho mọi GC thế hệ trẻ và mọi GC đầy đủ.

Đối với mục đích của ví dụ của chúng tôi, chúng tôi đã chỉ định trình thu gom rác nối tiếp, cách triển khai GC đơn giản nhất, thông qua đối số -XX: + UseSerialGC .

Chúng tôi cũng đã đặt kích thước heap tối thiểu và tối đa là 1024mb, nhưng tất nhiên, có nhiều thông số JVM hơn mà chúng tôi có thể điều chỉnh.

3.1. Hiểu biết cơ bản về đầu ra chi tiết

Bây giờ chúng ta hãy xem đầu ra của chương trình đơn giản của chúng ta:

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!

Trong kết quả đầu ra ở trên, chúng ta đã có thể thấy rất nhiều thông tin hữu ích về những gì đang diễn ra bên trong JVM.

Lúc đầu, kết quả này có thể trông khá khó khăn, nhưng bây giờ chúng ta hãy xem xét nó từng bước một.

Trước hết, chúng ta có thể thấy rằng bốn bộ sưu tập đã diễn ra, một Full GC và ba thế hệ trẻ dọn dẹp.

3.2. Đầu ra dài dòng chi tiết hơn

Hãy phân tích các dòng đầu ra chi tiết hơn để hiểu chính xác những gì đang xảy ra:

  1. GC hoặc GC đầy đủ - Loại Thu gom rác, GC hoặc GC đầy đủ để phân biệt một bộ sưu tập rác nhỏ hoặc đầy đủ
  2. (Phân bổ không thành công) hoặc (System.gc ()) - Nguyên nhân của tập hợp - Lỗi phân bổ chỉ ra rằng không còn không gian trong Eden để phân bổ các đối tượng của chúng tôi
  3. 279616K-> 146232K - Bộ nhớ heap bị chiếm trước và sau GC, tương ứng (phân tách bằng mũi tên)
  4. (1013632K) - Dung lượng hiện tại của heap
  5. 0,3318607 giây - Thời gian của sự kiện GC tính bằng giây

Do đó, nếu chúng ta lấy dòng đầu tiên, 279616K-> 146232K (1013632K) có nghĩa là GC đã giảm bộ nhớ heap bị chiếm dụng từ 279616K xuống còn 146232K . Dung lượng đống tại thời điểm của GC là 1013632K và GC mất 0,3318607 giây.

Tuy nhiên, mặc dù định dạng ghi nhật ký GC đơn giản có thể hữu ích, nhưng nó cung cấp các chi tiết hạn chế. Ví dụ, chúng tôi không thể biết liệu GC có di chuyển bất kỳ đối tượng nào từ thế hệ trẻ sang thế hệ già hay tổng kích thước của thế hệ trẻ trước và sau mỗi lần thu thập .

Vì lý do đó, ghi nhật ký GC chi tiết hữu ích hơn ghi nhật ký đơn giản.

4. Kích hoạt Ghi nhật ký GC “chi tiết”

Để kích hoạt ghi nhật ký GC chi tiết, chúng tôi sử dụng đối số -XX: + PrintGCDetails . Điều này sẽ cung cấp cho chúng tôi thêm chi tiết về từng GC, chẳng hạn như:

  • Quy mô của thế hệ trẻ và già trước và sau mỗi Tổng công ty
  • Thời gian cần thiết để GC xảy ra ở thế hệ trẻ và già
  • Kích thước của các đối tượng được quảng bá ở mọi GC
  • Tóm tắt về kích thước của tổng đống

Trong ví dụ tiếp theo, chúng ta sẽ xem cách nắm bắt thông tin chi tiết hơn nữa trong nhật ký của chúng tôi, kết hợp -verbose: gc với đối số bổ sung này.

Xin lưu ý rằng cờ -XX: + PrintGCDetails đã không được chấp nhận trong Java 9, ủng hộ cơ chế ghi nhật ký hợp nhất mới (sẽ nói thêm về điều này sau). Dù sao, tương đương mới của -XX: + PrintGCDetails là tùy chọn -Xlog: gc * .

5. Diễn giải đầu ra dài dòng “chi tiết”

Hãy chạy lại chương trình mẫu của chúng tôi:

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

Lần này đầu ra khá dài dòng hơn:

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

Chúng ta có thể nhận ra tất cả các phần tử từ nhật ký GC đơn giản. Nhưng có một số mặt hàng mới.

Bây giờ chúng ta hãy xem xét các mục mới trong đầu ra được đánh dấu bằng màu xanh lam trong phần tiếp theo:

5.1. Phiên dịch một GC nhỏ trong thế hệ trẻ

Chúng tôi sẽ bắt đầu bằng cách phân tích các phần mới trong một GC nhỏ:

  • [GC (Lỗi phân bổ) [DefNew: 279616K-> 34944K (314560K), 0,3626923 giây] 279616K-> 146232K (1013632K), 0,3627492 giây] [Thời gian: người dùng = 0,33 sys = 0,03, real = 0,36 giây]

Như trước đây, chúng tôi sẽ chia các dòng thành các phần:

  1. DefNew - Tên của bộ thu gom rác được sử dụng. Cái tên không quá rõ ràng này là viết tắt của bộ thu gom rác thế giới đánh dấu một luồng và là thứ được sử dụng để dọn dẹp thế hệ Trẻ
  2. 279616K-> 34944K - Cách sử dụng của thế hệ trẻ trước và sau khi thu thập
  3. (314560K) - Tổng quy mô của thế hệ trẻ
  4. 0,3626923 giây - Thời gian tính bằng giây
  5. [Thời gian: người dùng = 0,33 sys = 0,03, real = 0,36 giây ] - Thời lượng của sự kiện GC, được đo theo các danh mục khác nhau

Bây giờ hãy giải thích các danh mục khác nhau:

  • user – The total CPU time that was consumed by Garbage Collector
  • sys – The time spent in OS calls or waiting for system events
  • real – This is all elapsed time including time slices used by other processes

Since we're running our example using the Serial Garbage Collector, which always uses just a single thread, real-time is equal to the sum of user and system times.

5.2. Interpreting a Full GC

In this penultimate example, we see that for a major collection (Full GC), which was triggered by our system call, the collector used was Tenured.

The final piece of additional information we see is a breakdown following the same pattern for the 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.

Có một công cụ phân tích đồ họa miễn phí rất tốt giúp phân tích nhật ký thu gom Rác, cung cấp nhiều số liệu về các sự cố Thu gom rác tiềm ẩn và thậm chí cung cấp các giải pháp tiềm năng cho những vấn đề này.

Chắc chắn hãy kiểm tra Trình phân tích nhật ký GC chung!

10. Kết luận

Tóm lại, trong hướng dẫn này, chúng tôi đã khám phá chi tiết về bộ sưu tập rác trong Java.

Đầu tiên, chúng tôi bắt đầu bằng cách giới thiệu chi tiết về bộ sưu tập rác là gì và tại sao chúng tôi có thể muốn sử dụng nó. Sau đó, chúng tôi xem xét một số ví dụ sử dụng một ứng dụng Java đơn giản. Chúng tôi đã bắt đầu với việc bật ghi nhật ký GC ở dạng đơn giản nhất trước khi khám phá một số ví dụ chi tiết hơn và cách diễn giải đầu ra.

Cuối cùng, chúng tôi đã khám phá một số tùy chọn bổ sung để ghi thông tin ngày giờ và cách ghi thông tin vào tệp nhật ký.

Các ví dụ mã có thể được tìm thấy trên GitHub.