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

乾貨滿滿張雜湊發表於2021-04-22
Java事件JDKObject

物件分配取樣：jdk.ObjectAllocationSample

引入版本：Java 16

相關 ISSUE：Introduce JFR Event Throttling and new jdk.ObjectAllocationSample event (enabled by default)

各版本配置：

Java 16：

預設配置（default.jfc）:

配置 值 描述
enabled true 預設啟用
throttle 150/s 每秒最多采集 150 個
stackTrace true 採集事件的時候，也採集堆疊

取樣配置（profile.jfc）:

配置 值 描述
enabled true 預設啟用
throttle 300/s 每秒最多采集 300 個
stackTrace true 採集事件的時候，也採集堆疊

為何需要這個事件？

對於大部分的 JVM 應用，大部分的物件是在 TLAB 中分配的。如果 TLAB 外分配過多，或者 TLAB 重分配過多，那麼我們需要檢查程式碼，檢查是否有大物件，或者不規則伸縮的物件分配，以便於優化程式碼。對於 TLAB 外分配和重分配分別有對應的事件：jdk.ObjectAllocationOutsideTLAB和jdk.ObjectAllocationInNewTLAB。但是這兩個事件，如果不採集堆疊，則沒有什麼實際參考意義，如果採集堆疊的話，這兩個事件數量非常大，尤其是出現問題的時候。那麼採集堆疊的次數也會變得非常多，這樣會非常影響效能。採集堆疊，是一個比較耗效能的操作，目前大部分的 Java 線上應用，尤其是微服務應用，都使用了各種框架，堆疊非常深，可能達到幾百，如果涉及響應式程式設計，這個堆疊就更深了。JFR 考慮到這一點，預設採集堆疊深度最多是 64，即使是這樣，也還是比較耗效能的。並且，在 Java 11 之後，JDK 一直在優化獲取堆疊的速度，例如堆疊方法字串放入緩衝池，優化緩衝池過期策略與 GC 策略等等，但是目前效能損耗還是不能忽視。所以，引入這個事件，減少對於堆疊的採集導致的消耗。

事件包含屬性

屬性 說明 舉例
startTime 事件開始時間 10:16:27.718
objectClass 觸發本次事件的物件的類 byte[] (classLoader = bootstrap)
weight 注意，這個不是物件大小，而是該執行緒距離上次被採集 jdk.ObjectAllocationSample 事件到這個事件的這段時間，執行緒分配的物件總大小 10.0 MB
eventThread 執行緒 "Thread-0" (javaThreadId = 27)
stackTrace 執行緒堆疊 略

測試這個事件

package com.github.hashjang.jfr.test;

import jdk.jfr.Recording;
import jdk.jfr.consumer.RecordedEvent;
import jdk.jfr.consumer.RecordingFile;
import sun.hotspot.WhiteBox;

import java.io.File;
import java.io.IOException;
import java.nio.file.Path;
import java.util.concurrent.TimeUnit;

public class TestObjectAllocationSample {
    //對於位元組陣列物件頭佔用16位元組
    private static final int BYTE_ARRAY_OVERHEAD = 16;
    //分配物件的大小，1MB
    private static final int OBJECT_SIZE = 1024 * 1024;
    //要分配的物件個數
    private static final int OBJECTS_TO_ALLOCATE = 20;
    //分配物件的 class 名稱
    private static final String BYTE_ARRAY_CLASS_NAME = new byte[0].getClass().getName();
    private static final String INT_ARRAY_CLASS_NAME = new int[0].getClass().getName();
    //測試的 JFR 事件名稱
    private static String EVENT_NAME = "jdk.ObjectAllocationSample";
    //分配的物件放入這個靜態變數，防止編譯器優化去掉沒有使用的分配程式碼
    public static byte[] tmp;
    public static int[] tmp2;

    public static void main(String[] args) throws IOException, InterruptedException {
        //使用 WhiteBox 執行 FullGC，清楚干擾
        WhiteBox whiteBox = WhiteBox.getWhiteBox();
        whiteBox.fullGC();

        Recording recording = new Recording();
        //設定 throttle 為 1/s，也就是每秒最多采集一個
        //目前 throttle 只對 jdk.ObjectAllocationSample 有效，還不算是標準配置，所以只能這樣配置
        recording.enable(EVENT_NAME).with("throttle", "1/s");
        recording.start();
        //main 執行緒分配物件
        for (int i = 0; i < OBJECTS_TO_ALLOCATE; ++i) {
            //由於 main 執行緒在 JVM 初始化的時候分配了一些其他物件，所以第一次採集的大小可能不準確，或者採集的類不對，後面結果中我們會看到
            tmp = new byte[OBJECT_SIZE - BYTE_ARRAY_OVERHEAD];
            TimeUnit.MILLISECONDS.sleep(100);
        }
        //測試多執行緒分配物件
        Runnable runnable = () -> {
            for (int i = 0; i < OBJECTS_TO_ALLOCATE; ++i) {
                tmp = new byte[OBJECT_SIZE - BYTE_ARRAY_OVERHEAD];
                try {
                    TimeUnit.MILLISECONDS.sleep(100);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
        };
        Thread thread = new Thread(runnable);
        Runnable runnable2 = () -> {
            for (int i = 0; i < OBJECTS_TO_ALLOCATE; ++i) {
                tmp2 = new int[OBJECT_SIZE - BYTE_ARRAY_OVERHEAD];
                try {
                    TimeUnit.MILLISECONDS.sleep(100);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
        };
        Thread thread2 = new Thread(runnable2);
        thread.start();
        thread2.start();
        long threadId = thread.getId();
        long threadId2 = thread2.getId();
        thread.join();
        thread2.join();
        recording.stop();
        Path path = new File(new File(".").getAbsolutePath(), "recording-" + recording.getId() + "-pid" + ProcessHandle.current().pid() + ".jfr").toPath();
        recording.dump(path);
        long size = 0;
        for (RecordedEvent event : RecordingFile.readAllEvents(path)) {
            if (!EVENT_NAME.equals(event.getEventType().getName())) {
                continue;
            }
            String objectClassName = event.getString("objectClass.name");
            boolean isMyEvent = (
                    Thread.currentThread().getId() == event.getThread().getJavaThreadId()
                    || threadId == event.getThread().getJavaThreadId()
                    || threadId2 == event.getThread().getJavaThreadId()
                    ) && (
                            objectClassName.equals(BYTE_ARRAY_CLASS_NAME) ||
                            objectClassName.equals(INT_ARRAY_CLASS_NAME)
                    );
            if (!isMyEvent) {
                continue;
            }
            System.out.println(event);
        }
    }
}

輸出示例：

//main執行緒在初始化 JVM 的時候，分配了一些其他物件，所以這裡 weight 很大
jdk.ObjectAllocationSample {
  startTime = 10:16:24.677
  //觸發本次事件的物件的類
  objectClass = byte[] (classLoader = bootstrap)
  //注意，這個不是物件大小，而是該執行緒距離上次被採集 jdk.ObjectAllocationSample 事件到這個事件的這段時間，執行緒分配的物件總大小
  weight = 15.9 MB
  eventThread = "main" (javaThreadId = 1)
  stackTrace = [
    com.github.hashjang.jfr.test.TestObjectAllocationSample.main(String[]) line: 42
  ]
}


jdk.ObjectAllocationSample {
  startTime = 10:16:25.690
  objectClass = byte[] (classLoader = bootstrap)
  weight = 10.0 MB
  eventThread = "main" (javaThreadId = 1)
  stackTrace = [
    com.github.hashjang.jfr.test.TestObjectAllocationSample.main(String[]) line: 42
  ]
}


jdk.ObjectAllocationSample {
  startTime = 10:16:26.702
  objectClass = byte[] (classLoader = bootstrap)
  weight = 1.0 MB
  eventThread = "Thread-0" (javaThreadId = 27)
  stackTrace = [
    com.github.hashjang.jfr.test.TestObjectAllocationSample.lambda$main$0() line: 48
    java.lang.Thread.run() line: 831
  ]
}


jdk.ObjectAllocationSample {
  startTime = 10:16:27.718
  objectClass = byte[] (classLoader = bootstrap)
  weight = 10.0 MB
  eventThread = "Thread-0" (javaThreadId = 27)
  stackTrace = [
    com.github.hashjang.jfr.test.TestObjectAllocationSample.lambda$main$0() line: 48
    java.lang.Thread.run() line: 831
  ]
}

各位讀者可以將採集頻率改成 "100/s"，就能看到基本所有程式碼裡面的物件分配都被採整合為一個事件了。

底層原理與相關 JVM 原始碼

首先我們來看下 Java 物件分配的流程：

image

對於 HotSpot JVM 實現，所有的 GC 演算法的實現都是一種對於堆記憶體的管理，也就是都實現了一種堆的抽象，它們都實現了介面 CollectedHeap。當分配一個物件堆記憶體空間時，在 CollectedHeap 上首先都會檢查是否啟用了 TLAB，如果啟用了，則會嘗試 TLAB 分配；如果當前執行緒的 TLAB 大小足夠，那麼從執行緒當前的 TLAB 中分配；如果不夠，但是當前 TLAB 剩餘空間小於最大浪費空間限制，則從堆上（一般是 Eden 區） 重新申請一個新的 TLAB 進行分配。否則，直接在 TLAB 外進行分配。TLAB 外的分配策略，不同的 GC 演算法不同。例如G1：

  • 如果是 Humongous 物件（物件在超過 Region 一半大小的時候），直接在 Humongous 區域分配（老年代的連續區域）。
  • 根據 Mutator 狀況在當前分配下標的 Region 內分配

jdk.ObjectAllocationSample 事件只關心 TLAB 外分配，因為這也是程式主要需要的優化點。throttle 配置，是限制在一段時間內只能採集這麼多的事件。但是我們究竟怎麼篩選採集哪些事件呢？假設我們配置的是 100/s，首先想到的是時間視窗，採集這一視窗內開頭的 100 個事件。這樣顯然是不符合我們的要求的，我們並不能保證效能瓶頸的事件就在每秒的前 100 個，並且我們的程式可能每秒發生很多很多次 TLAB 外分配，僅憑前 100 個事件並不能很好的採集我們想看到的事件。所以，JDK 內部通過 EWMA（Exponential Weighted Moving Average）的演算法估計何時的採集時間以及越大分配上報次數越多的這樣的優化來實現更準確地取樣。
如果是直接在 TLAB 外進行分配，才可能生成 jdk.ObjectAllocationSample 事件。

參考原始碼：

allocTracer.cpp

//在每次發生 TLAB 外分配的時候，呼叫這個方法上報
void AllocTracer::send_allocation_outside_tlab(Klass* klass, HeapWord* obj, size_t alloc_size, Thread* thread) {
  JFR_ONLY(JfrAllocationTracer tracer(obj, alloc_size, thread);)
  //立刻生成 jdk.ObjectAllocationOutsideTLAB 這個事件
  EventObjectAllocationOutsideTLAB event;
  if (event.should_commit()) {
    event.set_objectClass(klass);
    event.set_allocationSize(alloc_size);
    event.commit();
  }
  //歸一化分配資料並取樣 jdk.ObjectAllocationSample 事件
  normalize_as_tlab_and_send_allocation_samples(klass, static_cast<intptr_t>(alloc_size), thread);
}

再來看歸一化分配資料並生成 jdk.ObjectAllocationSample 事件的具體內容：

static void normalize_as_tlab_and_send_allocation_samples(Klass* klass, intptr_t obj_alloc_size_bytes, Thread* thread) {
  //讀取當前執行緒分配過的位元組大小
  const int64_t allocated_bytes = load_allocated_bytes(thread);
  assert(allocated_bytes > 0, "invariant"); // obj_alloc_size_bytes is already attributed to allocated_bytes at this point.
  //如果沒有使用 TLAB，那麼不需要處理，allocated_bytes 肯定只包含 TLAB 外分配的位元組大小
  if (!UseTLAB) {
    //取樣 jdk.ObjectAllocationSample 事件
    send_allocation_sample(klass, allocated_bytes);
    return;
  }
  //獲取當前執行緒的 TLAB 期望大小
  const intptr_t tlab_size_bytes = estimate_tlab_size_bytes(thread);
  //如果當前執行緒分配過的位元組大小與上次讀取的當前執行緒分配過的位元組大小相差不超過 TLAB 期望大小，證明可能是由於 TLAB 快滿了導致的 TLAB 外分配，並且大小不大，沒必要上報。
  if (allocated_bytes - _last_allocated_bytes < tlab_size_bytes) {
    return;
  }
  assert(obj_alloc_size_bytes > 0, "invariant");
  //利用這個迴圈，如果當前執行緒分配過的位元組大小越大，則取樣次數越多，越容易被採集到。
  do {
    if (send_allocation_sample_with_result(klass, allocated_bytes)) {
      return;
    }
    obj_alloc_size_bytes -= tlab_size_bytes;
  } while (obj_alloc_size_bytes > 0);
}

這裡我們就觀察到了 JDK 做的第一個上報優化演算法：如果本次分配物件大小越大，那麼這個迴圈次數就會越多，取樣次數就越多，被採集到的概率也越大
接下來來看具體的取樣方法：

inline bool send_allocation_sample_with_result(const Klass* klass, int64_t allocated_bytes) {
  assert(allocated_bytes > 0, "invariant");
  EventObjectAllocationSample event;
  //判斷事件是否應該 commit，只有 commit 的事件才會被採集
  if (event.should_commit()) {
    //weight 等於上次記錄當前執行緒的 threadLocal 的 allocated_bytes 減去當前執行緒的 allocated_bytes
    //由於不是每次執行緒發生 TLAB 外分配的時候上報都會被採集，所以需要記錄上次被採集時候的執行緒分配的 allocated_bytes 大小，計算與當前的差值就是本次上報的事件中的執行緒距離上次上報分配的物件大小。
    const size_t weight = allocated_bytes - _last_allocated_bytes;
    assert(weight > 0, "invariant");
    //objectClass 即觸發上報的分配物件的 class
    event.set_objectClass(klass);
    //weight 並不代表 objectClass 的物件的大小，而是這個執行緒距離上次上報被採集分配的物件大小
    event.set_weight(weight);
    event.commit();
    //只有事件 commit，也就是被採集，才會更新 _last_allocated_bytes 這個 threadLocal 變數
    _last_allocated_bytes = allocated_bytes;
    return true;
  }
  return false;
}

通過這裡的程式碼我們明白了：

  • ObjectClass 是 TLAB 外分配物件的 class，也是本次觸發記錄jdk.ObjectAllocationSample 事件的物件的 class
  • weight 是執行緒距離上次記錄 jdk.ObjectAllocationSample 事件到當前這個事件時間內，執行緒分配的物件大小。

這裡通常會誤以為 weight 就是本次事件 ObjectClass 的物件大小。這個需要著重注意下。

那麼如何判斷的事件是否應該 commit？ 這裡走的是 JFR 通用邏輯：
jfrEvent.hpp

bool should_commit() {
    if (!_started) {
      return false;
    }
    if (_untimed) {
      return true;
    }
    if (_evaluated) {
      return _should_commit;
    }
    _should_commit = evaluate();
    _evaluated = true;
    return _should_commit;
}
bool evaluate() {
    assert(_started, "invariant");
    if (_start_time == 0) {
      set_starttime(JfrTicks::now());
    } else if (_end_time == 0) {
      set_endtime(JfrTicks::now());
    }
    if (T::isInstant || T::isRequestable) {
      return T::hasThrottle ? JfrEventThrottler::accept(T::eventId, _untimed ? 0 : _start_time) : true;
    }
    if (_end_time - _start_time < JfrEventSetting::threshold(T::eventId)) {
      return false;
    }
    //這裡我們先只關心 Throttle
    return T::hasThrottle ? JfrEventThrottler::accept(T::eventId, _untimed ? 0 : _end_time) : true;
}

這裡涉及 JfrEventThrottler 控制實現 throttle 配置。主要通過 EWMA 演算法實現對於下次合適的採集時間間隔的不斷估算優化更新，來採集到最合適的 jdk.ObjectAllocationSample，同時這種演算法並不像滑動視窗那樣記錄歷史資料導致佔用很大記憶體，指數移動平均（exponential moving average），或者叫做指數加權移動平均（exponentially weighted moving average），是以指數式遞減加權的移動平均，各數值的加權影響力隨時間呈指數式遞減，可以用來估計變數的區域性均值，使得變數的更新與一段時間內的歷史取值有關。

假設每次採集資料為 P(n)，權重衰減程度為 t，t 在 0~1 之間：

image

上面的公式，也可以寫作：

image

從這個公式可以看出，權重係數 t 以指數等比形式縮小，時間越靠近當前時刻的資料加權影響力越大。
這個 t 越小，過去過去累計值的權重越低，當前抽樣值的權重越高，平均值的實時性就越強。反之 t 越大，吸收瞬時突發值的能力變強，平均值的平穩性更好。

對於 jdk.ObjectAllocationSample 這個事件，演算法實現即 jfrEventThrottler.hpp。如果大家感興趣，可以在執行例項程式的時候，增加如下的啟動引數 -Xlog:jfr+system+throttle=debug 來檢視這個 EWMA 採集視窗的相關資訊，從而理解學習原始碼。日誌示例：

[0.743s][debug][jfr,system,throttle] jdk.ObjectAllocationSample: avg.sample size: 0.0000, window set point: 0, sample size: 0, population size: 0, ratio: 0.0000, window duration: 0 ms

[1.761s][debug][jfr,system,throttle] jdk.ObjectAllocationSample: avg.sample size: 0.0400, window set point: 1, sample size: 1, population size: 19, ratio: 0.0526, window duration: 1000 ms

[2.775s][debug][jfr,system,throttle] jdk.ObjectAllocationSample: avg.sample size: 0.0784, window set point: 1, sample size: 1, population size: 19, ratio: 0.0526, window duration: 1000 ms

[3.794s][debug][jfr,system,throttle] jdk.ObjectAllocationSample: avg.sample size: 0.1153, window set point: 1, sample size: 1, population size: 118, ratio: 0.0085, window duration: 1000 ms

[4.815s][debug][jfr,system,throttle] jdk.ObjectAllocationSample: avg.sample size: 0.1507, window set point: 1, sample size: 1, population size: 107, ratio: 0.0093, window duration: 1000 ms

總結

  1. jdk.ObjectAllocationSample 是 Java 16 引入，用來優化物件分配不容易高效監控的事件。
  2. jdk.ObjectAllocationSample 事件裡面的 ObjectClass 是觸發事件的 class，weight 是執行緒分配的物件總大小。所以實際觀察的時候，採集會與實際情況有些偏差。這是高效採集無法避免的。
  3. JVM 通過 EMWA 做了演算法優化，採集到的事件隨著程式執行會越來越是你的效能瓶頸或者熱點程式碼相關的事件。

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

image

相關文章