Today, another dry day. This is the first in a series of the most hardcore JVMS on the web, starting with TLAB. Since the article is very long and everyone has different reading habits, it is hereby divided into single and multiple editions

  • TLAB Analysis of the most hardcore JVM in the web (single version does not include additional ingredients)
  • TLAB analysis of the most core JVM in the whole network 1. Introduction of memory allocation idea
  • TLAB analysis of the most core JVM in the entire network 2. TLAB life cycle and problem thinking
  • 3. JVM EMA expectation algorithm and TLAB related JVM startup parameters
  • 4. Complete analysis of TLAB basic process
  • Network most core JVM TLAB analysis 5 TLAB source code full analysis
  • 6. TLAB related hot Q&A summary
  • 7. Tlab-related JVM log parsing
  • 8. Monitor TLAB through JFR

12. Monitor TLAB slow assignment and TLAB outside assignment – JFR related event resolution

We can monitor TLAB slow assignment or TLAB out-of-lab assignment events through JFR. Namely the JDK. ObjectAllocationOutsideTLAB and JDK. ObjectAllocationInNewTLAB these two events.

JDK. The JDK and ObjectAllocationOutsideTLAB. ObjectAllocationInNewTLAB these two events in default. (the default event JFR collection configuration) in JFC is not open to collect:

<event name="jdk.ObjectAllocationInNewTLAB">
  <setting name="enabled">false</setting>
  <setting name="stackTrace">true</setting>
</event>

<event name="jdk.ObjectAllocationOutsideTLAB">
  <setting name="enabled">false</setting>
  <setting name="stackTrace">true</setting>
</event>
Copy the code

Generally, collecting these two events should be collected together with the stack, but it is not possible to limit which events to collect by the duration (because there is no such concept as the duration of this event), so it is not recommended to enable the collection for a long time. Instead, the collection is dynamically turned on for a period of time, as needed, with some other monitoring items, and then closed and dumped to a JFR file for analysis.

So what are the general indicators to judge? In general, when Young GC is too frequent, we need to consider whether the FREQUENT GC is caused by the waste of a lot of space caused by TLAB. As for how to collect the Young GC frequency to dynamically turn it on, this is explained in the dynamic monitoring section below.

We also use the above procedures, according to the previous log, for 1 KB object, there should be two JDK. ObjectAllocationInNewTLAB events, is the first application TLAB thread for the first time, the second is the distribution of the 512th object, TLAB the remaining space is insufficient, Meanwhile, the remaining space is less than the maximum wasted space limit, so apply for a new TLAB allocation. About the distribution of the 1 KB, JDK. Not happening ObjectAllocationOutsideTLAB. For the object allocation of 100KB, in the fifth allocation, the remaining space of TLAB is insufficient, but the remaining space is larger than the maximum wasted space limit, so it is directly allocated in the Eden region, and the maximum wasted space limit is increased by 4. At the 114th object allocation, the maximum wasted space limit reached the remaining space, so a new TLAB allocation was requested. So for 200 times 100 KB object allocation, JDK. ObjectAllocationInNewTLAB only twice.

At the same time, as JFR is turned on, TLAB may be occupied in part, so these times may not be accurate, but it doesn’t matter, it should be correct in general.

Private static final int BYTE_ARRAY_OVERHEAD = 16; Private static final int OBJECT_SIZE = 100 * 1024; Public static byte[] TMP; public static byte[] TMP; public static void main(String[] args) throws Exception { WhiteBox whiteBox = WhiteBox.getWhiteBox(); Recording Recording = new Recording(); / / enabled JDK. ObjectAllocationOutsideTLAB event monitoring and recording. The enable (" JDK. ObjectAllocationOutsideTLAB "); recording.enable("jdk.ObjectAllocationInNewTLAB"); // The JFR record starts recording.start(); // Force fullGC to prevent GC from occurring in the next program // Also distinguish tLAB-related logs of other threads from initialization whitebox.fullgc (); For (int I = 0; i < 512; ++i) { tmp = new byte[OBJECT_SIZE - BYTE_ARRAY_OVERHEAD]; } // Force fullGC to reclaim all TLAB whitebox.fullgc (); For (int I = 0; i < 200; ++i) { tmp = new byte[OBJECT_SIZE * 100 - BYTE_ARRAY_OVERHEAD]; } whiteBox.fullGC(); // Dump JFR records to a File Path Path = new File(new File(".").geTabSolutePath (), "recording-" + recording.getId() + "-pid" + ProcessHandle.current().pid() + ".jfr").toPath(); recording.dump(path); int countOf1KBObjectAllocationInNewTLAB = 0; int countOf100KBObjectAllocationInNewTLAB = 0; int countOf1KBObjectAllocationOutsideTLAB = 0; int countOf100KBObjectAllocationOutsideTLAB = 0; For (RecordedEvent event: RecordingFile. ReadAllEvents (path)) {/ / for the type of object allocation String className = event. Get String (" objectClass. The name "); If (// Make sure the allocation type is byte[] byte_array_classname.equalSignoRecase (className)) {RecordedFrame RecordedFrame = event.getStackTrace().getFrames().get(0); // It must also be the object allocated by our main method. And is the main method of Java stack the if (recordedFrame. IsJavaFrame () && "main". The equalsIgnoreCase (recordedFrame. GetMethod (). The getName ())) { Long allocationSize = event.getLong("allocationSize"); / / statistical number if events (" JDK. ObjectAllocationOutsideTLAB ". EqualsIgnoreCase (event. The getEventType (). The getName ())) {if (allocationSize == 102400) { countOf100KBObjectAllocationOutsideTLAB++; } else if (allocationSize == 1024) { countOf1KBObjectAllocationOutsideTLAB++; } } else if ("jdk.ObjectAllocationInNewTLAB".equalsIgnoreCase(event.getEventType().getName())) { if (allocationSize == 102400) { countOf100KBObjectAllocationInNewTLAB++; } else if (allocationSize == 1024) { countOf1KBObjectAllocationInNewTLAB++; } } else { throw new Exception("unexpected size of TLAB event"); } System.out.println(event); } } } System.out.println("countOf1KBObjectAllocationInNewTLAB: " + countOf1KBObjectAllocationInNewTLAB); System.out.println("countOf100KBObjectAllocationInNewTLAB: " + countOf100KBObjectAllocationInNewTLAB); System.out.println("countOf1KBObjectAllocationOutsideTLAB: " + countOf1KBObjectAllocationOutsideTLAB); System.out.println("countOf100KBObjectAllocationOutsideTLAB: " + countOf100KBObjectAllocationOutsideTLAB); Thread currentThread().join(); Thread currentThread().join(); }Copy the code

The output should look something like:

// Omit details of other events, Here each pick a showcase for the JDK. ObjectAllocationInNewTLAB {startTime = 13:07:51. 681 objectClass = byte [] (this = the bootstrap) EventThread = "main" (javaThreadId = 1) stackTrace = [ com.github.hashjang.jfr.test.TestAllocOutsideTLAB.main(String[]) line: 96]} JDK. ObjectAllocationInNewTLAB {startTime = 13:07:51. 777 objectClass = byte [] (this = the bootstrap) EventThread = "main" (javaThreadId = 1) stackTrace = [ com.github.hashjang.jfr.test.TestAllocOutsideTLAB.main(String[]) line: 102]} JDK. ObjectAllocationOutsideTLAB {startTime = 13:07:51. 784 objectClass = byte [] (this = the bootstrap) EventThread = "main" (javaThreadId = 1) stackTrace = [ com.github.hashjang.jfr.test.TestAllocOutsideTLAB.main(String[]) line: 102]} / / omit the detailed information of the other event here each pick a showcase countOf1KBObjectAllocationInNewTLAB: 2 countOf100KBObjectAllocationInNewTLAB: 2 countOf1KBObjectAllocationOutsideTLAB: 0 countOf100KBObjectAllocationOutsideTLAB: 190Copy the code

It can be seen that the JDK. ObjectAllocationInNewTLAB include:

  • Start time:StartTime = 13:07:51. 784
  • Assign an object type:objectClass = byte[] (classLoader = bootstrap)
  • Allocate size:AllocationSize = 100.0 kB
  • New TLAB size:TlabSize = 512.0 kB
  • Thread:eventThread = "main" (javaThreadId = 1)
  • The stack

The JDK. ObjectAllocationOutsideTLAB include:

  • Start time:StartTime = 13:07:51. 784
  • Assign an object type:objectClass = byte[] (classLoader = bootstrap)
  • Allocate size:AllocationSize = 100.0 kB
  • Thread:eventThread = "main" (javaThreadId = 1)
  • The stack

We generally view JFR monitored files through JMC, and we can view the events in the event viewer. Refer to my other series: JFR Full Solution