Java JFR 民間指南 - 事件詳解 - jdk.ThreadAllocationStatistics

乾貨滿滿張雜湊發表於2021-04-28

定時執行緒分配統計事件:jdk.ThreadAllocationStatistics

引入版本:Java 11

相關 ISSUES

  1. Test jdk/jfr/event/runtime/TestThreadAllocationEvent.java fails with null thread:在某些情況下,jdk.ThreadAllocationStatistics 沒有采集到 JFR 相關執行緒,導致空指標。這個 Bug 和 jdk/jfr/event/compiler/TestCompilerCompile.java failed due to "RuntimeException: No thread in event" 重複.該 BUG 對於使用沒有大影響,於 Java 16 修復。
  2. Per thread IO statistics in JFR,這是一個新特性,期望和 ThreadAllocationStatistics 事件類似,提供每個執行緒的 IO 資料統計,這個特性還沒有通過討論。

各版本配置:

從 Java 11 引入之後沒有改變過:

預設配置default.jfc of Java 11default.jfc of Java 12default.jfc of Java 13default.jfc of Java 14default.jfc of Java 15default.jfc of Java 16default.jfc of Java 17):

配置 描述
enabled false 預設不啟用
period everyChunk 在生成每個新 Chunk 檔案的時候採集一次

取樣配置profile.jfc of Java 11profile.jfc of Java 12profile.jfc of Java 13profile.jfc of Java 14profile.jfc of Java 15profile.jfc of Java 16profile.jfc of Java 17):

配置 描述
enabled true 預設啟用
period everyChunk 在生成每個新 Chunk 檔案的時候採集一次

為何需要這個事件?

Java 中業務執行緒都會分配物件,對於以下關鍵的業務,物件的分配可能更加頻繁。有時候我們可能會遇到以下兩個情況:

  1. 線上應用頻繁 GC,可能是先開始 Young GC(New GC,Light GC,不同 GC 叫法不一樣),之後伴隨著 Old GC 或者 Full GC,可以觀察到線上應用佔用 CPU 高的執行緒也是 GC 執行緒。這個很可能是某個業務 BUG 拉取了大量的資料,例如查詢資料庫沒加條件導致查詢整個表,三方介面沒限制 limit 返回了超級多的資料。想要直觀快速的定位這個問題,可以通過觀察那些執行緒突然分配了很多記憶體,然後檢視這些執行緒的堆疊進一步確認。jdk.ThreadAllocationStatistics 就是用來檢視這個的
  2. 線上 GC 變多,想要減少 GC,光看 jmap 物件統計太多抽象,並不直觀知道是那些程式碼建立的這些物件。堆 dump 太重,對於大記憶體程式分析成本也很大。可以通過 jdk.ThreadAllocationStatistics 檢視是那些執行緒分配物件比較多,採集這些執行緒的堆疊可以定位相關程式碼。

事件包含屬性

屬性 說明 舉例
startTime 事件開始時間 10:16:27.718
allocated 分配過的空間大小 10.0 MB
thread 執行緒資訊 "Thread-0" (javaThreadId = 27)

使用程式碼測試這個事件

package com.github.hashjang.jfr.test;

import com.sun.management.ThreadMXBean;
import jdk.jfr.Recording;
import jdk.jfr.consumer.RecordedEvent;
import jdk.jfr.consumer.RecordedThread;
import jdk.jfr.consumer.RecordingFile;
import sun.hotspot.WhiteBox;

import java.io.File;
import java.io.IOException;
import java.lang.management.ManagementFactory;
import java.nio.file.Path;
import java.time.Duration;
import java.util.Arrays;
import java.util.HashMap;
import java.util.Map;
import java.util.Random;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.TimeUnit;
import java.util.stream.Collectors;

public class TestThreadAllocationStatistics {
    private static String EVENT_NAME = "jdk.ThreadAllocationStatistics";
    //50ms採集一次
    private static long eventPeriodMillis = 50;
    //對於位元組陣列物件頭佔用16位元組
    private static final int BYTE_ARRAY_OVERHEAD = 16;
    //我們要測試的物件大小是1kb
    private static final int OBJECT_SIZE = 1024;

    public static void main(String[] args) throws IOException {

        Recording recording = new Recording();
        recording.enable(EVENT_NAME).withPeriod(Duration.ofMillis(eventPeriodMillis));
        recording.start();
        //使用 WhiteBox 執行 FullGC,清除干擾
        WhiteBox whiteBox = WhiteBox.getWhiteBox();
        whiteBox.fullGC();

        Allocator allocators[] = new Allocator[4];
        CountDownLatch allocationsDoneLatch = new CountDownLatch(allocators.length);
        for (int i = 0; i < allocators.length; i++) {
            allocators[i] = new Allocator(allocationsDoneLatch, OBJECT_SIZE * (i + 1) - BYTE_ARRAY_OVERHEAD);
            allocators[i].setDaemon(true);
            allocators[i].start();
        }
        Map<Long, Allocator> map = Arrays.stream(allocators).collect(Collectors.toMap(Thread::getId, v -> v));
        Map<Long, Long> threadAllocatedMap = new HashMap<>();
        try {
            allocationsDoneLatch.await();
            //再等待一段時間讓定時採集 jdk.ThreadAllocationStatistics 採集到最新的
            TimeUnit.SECONDS.sleep(1);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

        recording.stop();
        Path path = new File(new File(".").getAbsolutePath(), "recording-" + recording.getId() + "-pid" + ProcessHandle.current().pid() + ".jfr").toPath();
        recording.dump(path);
        for (RecordedEvent event : RecordingFile.readAllEvents(path)) {
            if (!EVENT_NAME.equals(event.getEventType().getName())) {
                continue;
            }
            long javaThreadId = ((RecordedThread) event.getValue("thread")).getJavaThreadId();
            if (map.containsKey(javaThreadId)) {
                //事件是時間有序的(採集時間比較短),所以放入的最後一個就是採集到的執行緒最終的分配大小
                threadAllocatedMap.put(javaThreadId, event.getLong("allocated"));
                System.out.println(event);
            }
        }

        map.forEach((id, thread) -> {
            System.out.println("Thread " + id + " allocated(from JMX): " + thread.totalAllocated + "; allocated(from jdk.ThreadAllocationStatistics): " + threadAllocatedMap.get(id));
        });
    }

    public static class Allocator extends Thread {
        private volatile long totalAllocated = -1;
        private final int allocationSize;
        public byte[] buffer;
        private final CountDownLatch allocationsDoneLatch;

        public Allocator(CountDownLatch allocationsDoneLatch, int allocationSize) {
            this.allocationsDoneLatch = allocationsDoneLatch;
            this.allocationSize = allocationSize;
        }

        @Override
        public void run() {
            for (int batches = 0; batches < 100; batches++) {
                for (int i = 0; i < 1024; i++) {
                    buffer = new byte[allocationSize];
                }
                try {
                    //期望每個採集週期之間的分配次數為 5
                    Thread.sleep(eventPeriodMillis / 5);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
            //獲取當前執行緒分配的物件大小
            totalAllocated = getThreadAllocatedBytes();
            allocationsDoneLatch.countDown();
            //設定執行緒為守護執行緒,等待主執行緒結束之後會自動結束
            //這裡進入死迴圈是因為防止定時採集 jdk.ThreadAllocationStatistics 事件的時候採集不到
            while (true) {
                Thread.yield();
            }
        }

        private long getThreadAllocatedBytes() {
            ThreadMXBean bean = (ThreadMXBean) ManagementFactory.getThreadMXBean();
            return bean.getThreadAllocatedBytes(Thread.currentThread().getId());
        }
    }
}

使用以下 JVM 引數啟動:

-Xbootclasspath/a:D:\github\jfr-spring-all\jdk-white-box\target\jdk-white-box-17.0-SNAPSHOT.jar  -Xms512m -Xmx512m  -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -Xlog:gc

輸出結果:

[0.016s][info][gc] Using G1
[0.679s][info][gc] GC(0) Pause Full (WhiteBox Initiated Full GC) 19M->2M(512M) 8.804ms
[0.714s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 27M->2M(512M) 1.309ms
[1.099s][info][gc] GC(2) Pause Young (Normal) (G1 Evacuation Pause) 308M->2M(512M) 0.943ms
[1.445s][info][gc] GC(3) Pause Young (Normal) (G1 Evacuation Pause) 308M->2M(512M) 1.141ms
[1.788s][info][gc] GC(4) Pause Young (Normal) (G1 Evacuation Pause) 308M->2M(512M) 1.117ms
jdk.ThreadAllocationStatistics {
  startTime = 12:41:29.915
  allocated = 1.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:29.915
  allocated = 2.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:29.915
  allocated = 3.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:29.915
  allocated = 4.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:29.965
  allocated = 6.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:29.965
  allocated = 12.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:29.965
  allocated = 15.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:29.965
  allocated = 20.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.015
  allocated = 10.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.015
  allocated = 20.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.015
  allocated = 27.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.015
  allocated = 36.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.066
  allocated = 15.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.066
  allocated = 28.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.066
  allocated = 39.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.066
  allocated = 50.3 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.116
  allocated = 19.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.116
  allocated = 36.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.116
  allocated = 51.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.116
  allocated = 64.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.167
  allocated = 24.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.167
  allocated = 44.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.167
  allocated = 63.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.167
  allocated = 80.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.217
  allocated = 28.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.217
  allocated = 52.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.217
  allocated = 75.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.217
  allocated = 96.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.268
  allocated = 32.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.268
  allocated = 61.3 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.268
  allocated = 87.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.268
  allocated = 109.5 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.319
  allocated = 37.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.319
  allocated = 68.3 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.319
  allocated = 99.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.319
  allocated = 124.3 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.370
  allocated = 41.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.370
  allocated = 78.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.370
  allocated = 111.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.370
  allocated = 144.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.420
  allocated = 45.4 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.420
  allocated = 86.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.420
  allocated = 126.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.420
  allocated = 160.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.470
  allocated = 50.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.470
  allocated = 96.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.470
  allocated = 138.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.470
  allocated = 180.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.520
  allocated = 54.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.520
  allocated = 104.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.520
  allocated = 150.4 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.520
  allocated = 196.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.571
  allocated = 58.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.571
  allocated = 112.3 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.571
  allocated = 165.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.571
  allocated = 212.5 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.621
  allocated = 63.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.621
  allocated = 122.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.621
  allocated = 180.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.621
  allocated = 232.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.671
  allocated = 67.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.671
  allocated = 130.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.671
  allocated = 192.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.671
  allocated = 248.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.722
  allocated = 72.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.722
  allocated = 140.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.722
  allocated = 207.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.722
  allocated = 268.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.772
  allocated = 76.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.772
  allocated = 148.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.772
  allocated = 219.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.772
  allocated = 284.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.581
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.581
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.581
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.581
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.631
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.631
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.631
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.631
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.682
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.682
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.682
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.682
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.732
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.732
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.732
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.732
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.823
  allocated = 81.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.823
  allocated = 158.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.823
  allocated = 234.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.823
  allocated = 304.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.874
  allocated = 85.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.874
  allocated = 166.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.874
  allocated = 246.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.874
  allocated = 320.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.925
  allocated = 90.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.925
  allocated = 176.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.925
  allocated = 258.5 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.925
  allocated = 340.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.975
  allocated = 94.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.975
  allocated = 184.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.975
  allocated = 273.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.975
  allocated = 356.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.024
  allocated = 99.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.024
  allocated = 194.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.024
  allocated = 285.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.024
  allocated = 372.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.075
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.075
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.075
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.075
  allocated = 392.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.126
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.126
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.126
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.126
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.177
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.177
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.177
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.177
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.228
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.228
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.228
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.228
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.278
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.278
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.278
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.278
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.329
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.329
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.329
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.329
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.379
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.379
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.379
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.379
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.429
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.429
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.429
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.429
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.479
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.479
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.479
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.479
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.530
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.530
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.530
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.530
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.791
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.791
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.791
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.791
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.842
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.842
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.842
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.842
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.892
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.892
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.892
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.892
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.943
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.943
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.943
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.943
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.993
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.993
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.993
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.993
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:32.043
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:32.043
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:32.043
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:32.043
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:32.093
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:32.093
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:32.093
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:32.093
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


Thread 27 allocated(from JMX): 105179160; allocated(from jdk.ThreadAllocationStatistics): 105179160
Thread 28 allocated(from JMX): 209780040; allocated(from jdk.ThreadAllocationStatistics): 209780040
Thread 29 allocated(from JMX): 314573616; allocated(from jdk.ThreadAllocationStatistics): 314573616
Thread 30 allocated(from JMX): 419431216; allocated(from jdk.ThreadAllocationStatistics): 419431216

底層原理以及相關 JVM 原始碼

每隔配置的間隔,就會呼叫 requestThreadAllocationStatistics(void) 方法採集每一個執行緒的分配資訊:

jfrPeriodic.cpp

#define TRACE_REQUEST_FUNC(id)    void JfrPeriodicEventSet::request##id(void)

//使用了巨集定義函式,實際函式就是 requestThreadAllocationStatistics(void)
TRACE_REQUEST_FUNC(ThreadAllocationStatistics) {
  ResourceMark rm;
  //獲取執行緒數量,雖然後面執行緒數量在採集過程中可能會改變,利用這個值初始化陣列
  int initial_size = Threads::number_of_threads();
  //建立一個陣列記錄每個執行緒的分配大小
  GrowableArray<jlong> allocated(initial_size);
  //建立一個陣列記錄執行緒號,和上面那個陣列一一對應
  GrowableArray<traceid> thread_ids(initial_size);
  //記錄當前時間
  JfrTicks time_stamp = JfrTicks::now();
  //新建一個 JfrJavaThreadIterator 來遍歷每個執行緒
  JfrJavaThreadIterator iter;
  while (iter.has_next()) {
    JavaThread* const jt = iter.next();
    assert(jt != NULL, "invariant");
    //讀取每個執行緒的 cooked_allocated_bytes()
    allocated.append(jt->cooked_allocated_bytes());
    //記錄執行緒號(包括系統執行緒號以及 Java 執行緒號)
    thread_ids.append(JFR_THREAD_ID(jt));
  }

  //遍歷陣列,生成 JFR 事件並採集
  for(int i = 0; i < thread_ids.length(); i++) {
    EventThreadAllocationStatistics event(UNTIMED);
    //設定當前執行緒已分配大小
    event.set_allocated(allocated.at(i));
    //設定執行緒資訊
    event.set_thread(thread_ids.at(i));
    //設定結束時間
    event.set_endtime(time_stamp);
    event.commit();
  }
}

統計執行緒的分配記憶體的大小方法即 cooked_allocated_bytes() 方法的原始碼如下:
thread.inline.hpp

inline jlong Thread::cooked_allocated_bytes() {
  //原子讀取 _allocated_bytes
  jlong allocated_bytes = Atomic::load_acquire(&_allocated_bytes);
  //如果開啟了 TLAB(預設開啟),則需要檢視下當前執行緒的 TLAB 已經分配的物件大小
  if (UseTLAB) {
    //統計當前執行緒的 TLAB 已經分配的大小
    size_t used_bytes = tlab().used_bytes();
    //如果當前 TLAB 在初始化,或者全域性 TLAB 在初始化,會發生 used_bytes > max_size 的情況,忽略這種情況。
    if (used_bytes <= ThreadLocalAllocBuffer::max_size_in_bytes()) {
      //這樣統計其實有可能有點問題,即發生 TLAB retire 的時候,_allocated_bytes 會加上 used_bytes 之後申請一個新的 TLAB,這時候呼叫這個方法可能會把這個 used_bytes 加了兩遍
      return allocated_bytes + used_bytes;
    }
  }
  return allocated_bytes;
}

那麼哪裡會修改 _allocated_bytes 這個變數呢?有兩個地方,一個是發生 TLAB 外分配的時候,另一個是發生 TLAB retire 的時候。 TLAB retire 是在發生 GC 以及 TLAB 滿了並且剩餘空間小於當前最大浪費空間限制的時候會重新申請一個新的 TLAB 進行分配,申請新的之前需要將當前 TLAB retire。
發生 TLAB 外分配修改 _allocated_bytes 對應原始碼:

memAllocator.cpp

//如果是 TLAB 外分配,會呼叫這個方法
HeapWord* MemAllocator::allocate_outside_tlab(Allocation& allocation) const {
  //標記當前分配為 TLAB 外分配
  allocation._allocated_outside_tlab = true;
  //執行 TLAB 外分配,不同 GC 不同
  HeapWord* mem = Universe::heap()->mem_allocate(_word_size, &allocation._overhead_limit_exceeded);
  if (mem == NULL) {
    return mem;
  }

  NOT_PRODUCT(Universe::heap()->check_for_non_bad_heap_word_value(mem, _word_size));
  //計算當前分配的位元組大小
  size_t size_in_bytes = _word_size * HeapWordSize;
  //增加 _allocated_bytes 當前分配的位元組大小
  _thread->incr_allocated_bytes(size_in_bytes);

  return mem;
}

TLAB retire 對應原始碼:
threadLocalAllocBuffer.cpp

void ThreadLocalAllocBuffer::retire(ThreadLocalAllocStats* stats) {
  if (stats != NULL) {
    accumulate_and_reset_statistics(stats);
  }

  if (end() != NULL) {
    invariants();
    //將當前 TLAB 使用的位元組數加到 _allocated_bytes
    //從這裡可以看出,如果這個方法和 cooked_allocated_bytes() 同時被呼叫,可能 used_bytes 被加了兩遍。
    thread()->incr_allocated_bytes(used_bytes());
    insert_filler();
    initialize(NULL, NULL, NULL);
  }
}

我們再來看看 JMX 中檢視執行緒分配記憶體大小的具體實現。首先對應的 JMX 的程式碼是:

//我們示例中底層呼叫的實際就是這個方法獲取執行緒分配的記憶體大小
protected long getThreadAllocatedBytes(long id) {
    boolean verified = verifyThreadAllocatedMemory(id);

    if (verified) {
        //呼叫 getThreadAllocatedMemory0 獲取分配的記憶體大小
        return getThreadAllocatedMemory0(
            Thread.currentThread().getId() == id ? 0 : id);
    }
    return -1;
}

//getThreadAllocatedMemory0 是一個 native 方法
private static native long getThreadAllocatedMemory0(long id);

這個 native 方法對應的 JVM 原始碼是:
ThreadImpl.c

JNIEXPORT jlong JNICALL
Java_sun_management_ThreadImpl_getThreadAllocatedMemory0
  (JNIEnv *env, jclass cls, jlong tid)
{
  //實際實現方法是 GetOneThreadAllocatedMemory
  return jmm_interface->GetOneThreadAllocatedMemory(env, tid);
}

management.cpp

JVM_ENTRY(jlong, jmm_GetOneThreadAllocatedMemory(JNIEnv *env, jlong thread_id))
  if (thread_id < 0) {
    THROW_MSG_(vmSymbols::java_lang_IllegalArgumentException(),
               "Invalid thread ID", -1);
  }
  //獲取當前執行緒
  if (thread_id == 0) { // current thread
    //呼叫 cooked_allocated_bytes,和採集 jdk.ThreadAllocationStatistics 呼叫的底層方法一樣
    return thread->cooked_allocated_bytes();
  }

  //根據執行緒號獲取執行緒
  ThreadsListHandle tlh;
  JavaThread* java_thread = tlh.list()->find_JavaThread_from_java_tid(thread_id);

  if (java_thread != NULL) {
    //呼叫 cooked_allocated_bytes,和採集 jdk.ThreadAllocationStatistics 呼叫的底層方法一樣
    return java_thread->cooked_allocated_bytes();
  }
  return -1;
JVM_END

可以看出,其實底層呼叫的和 JFR 採集 jdk.ThreadAllocationStatistics 事件一樣,都是呼叫 Thread 的 cooked_allocated_bytes() 方法。

針對這個 JFR 事件的一些思考

首先,提出一個觀點,jdk.ThreadAllocationStatistics 這個事件並不太消耗效能。原因有二:

  1. 統計執行緒分配大小是近似統計,並不需要進入全域性安全點統計。同時也代表,jdk.ThreadAllocationStatistics 同一時間的不同執行緒事件的分配大小實際並不是同一時間點的,因為沒有進入安全點暫停所有執行緒
  2. 統計僅僅是原子讀取每個執行緒的分配物件大小這個變數,之後加上每個執行緒當前 TLAB 分配物件大小(這個大小是通過讀取兩個指標地址獲取的),可以看出操作是很輕量級的。即使有很多執行緒,也不會增加多少效能負擔

然後,預設配置的採集週期,並不能滿足我們的需求。預設的採集週期是 everyChunk,預設的 chunk 大小(maxchunksize)是 12M,也就是每採集 12M 的 JFR 事件之後,採集一次 jdk.ThreadAllocationStatistics。這是不太可控的,我一般配置為每過 5s 採集一次。這樣對於我們上面提到的那兩個需要這個事件的場景也是很適合的。

微信搜尋“我的程式設計喵”關注公眾號,加作者微信,每日一刷,輕鬆提升技術,斬獲各種offer

image

相關文章