CYBERer.NET: JDK Flight Recorder で物理メモリを監視してみたけど何か変

Java 14 の新機能である、Foreign-Memory Access API の記事を書こうと思い、試しに 4GB のヒープ外メモリを割り当ててアクセスするプログラムを書いてみました。
メモリ確保状況を確認するため Java 14 の JFR Event Stream を使って、jdk.PhysicalMemory を監視してみたのですが、解放が反映される様子がありません。
top コマンドの出力を横に並べてみると、そちらではちゃんと即座に解放されていることが確認できました。その様子を動画に撮ってみました。

動画の46秒あたりでメモリが解放されています (コンソールに Memory released. と表示されたタイミング)。top の PhysMem はそのとき 16G から 12G に減っています。コンソールに赤い文字で出ているのが jdk.PhysicalMemory の usedMem なのですが、16G くらいから変化しません。GC triggered. のところで System.gc() を呼んでみたりしていますが、特に変わりません (top の方はその前から解放されているように見えている)。

top の PID 31270 の MEM もちゃんと解放されているように見えます。

これって JFR がおかしいんでしょうか？それとも何か違う問題？

別の記事にプログラム載せるつもりですが、一応ここにも貼っておきます。
監視している方のプログラムはこれです。

import java.text.DateFormat;
import java.text.SimpleDateFormat;
import java.time.Duration;
import java.util.logging.Logger;

import jdk.jfr.consumer.RecordingStream;

/**
 * 物理メモリ使用量を非同期で監視する. コンストラクタ呼び出し元スレッドの終了まで監視を行う.
 *
 * @author CYBERer.NET
 */
public class JFRPhysicalMemoryMonitor extends Thread {
  private final Thread monitoringThread;
  private final long intervalMillis;
  private final long waitMillisAfterDied;
  private static final Logger LOGGER = Logger.getLogger(JFRPhysicalMemoryMonitor.class.getName());
  /**
   * コンストラクタ. このコンストラクタを呼び出したスレッドの終了までをモニタする.
   *
   * @param intervalMillis      監視間隔 (ミリ秒)
   * @param waitMillisAfterDied コンストラクタを呼び出したスレッドが終了してから監視を継続する時間 (ミリ秒)
   */
  public JFRPhysicalMemoryMonitor(final long intervalMillis, final long waitMillisAfterDied) {
    this.monitoringThread = Thread.currentThread();
    this.intervalMillis = intervalMillis;
    this.waitMillisAfterDied = waitMillisAfterDied;
  }

  @Override
  public void run() {
    final DateFormat df = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");
    try (var rs = new RecordingStream()) {
      rs.enable("jdk.PhysicalMemory").withPeriod(Duration.ofMillis(intervalMillis));
      rs.onEvent("jdk.PhysicalMemory", event -> {
        LOGGER.info(toMBString(event.getLong("usedSize")) + "/" + toMBString(event.getLong("totalSize")));
      });
      rs.startAsync();
      try {
        monitoringThread.join();
        Thread.sleep(waitMillisAfterDied);
      } catch (InterruptedException e) {
        System.err.println("monitoringThread is interrupted.");
      }
    }
  }

  /**
   * バイトサイズをメガバイト換算した文字列に変換する.
   *
   * @param size バイトサイズ
   * @return メガバイト換算値 (0x100000 で割った値) + "MB"
   */
  private static String toMBString(final long size) {
    StringBuilder sb = new StringBuilder();
    sb.append(size / 0x100000);
    sb.append("MB");
    return sb.toString();
  }
}

メモリを使っている方のプログラムはこれ。

import java.lang.invoke.VarHandle;
import java.nio.ByteOrder;

import jdk.incubator.foreign.MemoryAddress;
import jdk.incubator.foreign.MemoryLayout;
import jdk.incubator.foreign.MemoryLayout.PathElement;
import jdk.incubator.foreign.MemorySegment;
import jdk.incubator.foreign.SequenceLayout;

public class ForeignMemory {
  private static final long K = 0x400L;
  private static final long M = K * K;
  private static final long G = M * K;
  public static void main(final String[] args) throws InterruptedException {
    new JFRPhysicalMemoryMonitor(1000L, 10000L).start();

    SequenceLayout intArrayLayout = MemoryLayout.ofSequence(1L * G,
        MemoryLayout.ofValueBits(32, ByteOrder.nativeOrder()));
    VarHandle intElemHandle = intArrayLayout.varHandle(int.class, PathElement.sequenceElement());
    System.out.println("Before allocate:");
    Thread.sleep(2000L);
    try (MemorySegment segment = MemorySegment.allocateNative(intArrayLayout)) {
      System.out.println("After allocate:");
      Thread.sleep(2000L);
      MemoryAddress base = segment.baseAddress();
      long n = intArrayLayout.elementCount().orElse(0L);
      System.out.println("elementCount = " + n);
      for (long i = 0; i < n; i++) {
        intElemHandle.set(base, i, (int) i * 100);
      }
      for (long i = 0; i < n; i++) {
        int x = (Integer) intElemHandle.get(base, i);
        if (i % (512L * M) == 0) {
          System.out.println("i=" + i + ", x=" + x);
        }
      }
    }
    System.out.println("Memory released.");
    Thread.sleep(2000L);
    System.gc();
    System.out.println("GC triggered.");
  }
}

(追記) OpenJDK/Hotspot VM 開発者で、JFR の中心人物の Erik Gahlin 氏がわざわざ返事をくれました。

Perhaps it is this bug:https://t.co/JD0NGTkzrE
— Erik Gahlin (@ErikGahlin) April 17, 2020

JDK-8087325 を見ると、Linux では cached が used に含まれてしまっているとのこと。確かに MacOSX も似たような話の可能性は高いですね。MacOSX はけっこう昔に cached が used に含まれないように変更されていて、top コマンドはそう見えてます。vm_stat でも Pages free に戻っているように見えます。

$ vm_stat
Mach Virtual Memory Statistics: (page size of 4096 bytes)
Pages free:                                4740.
Pages active:                           1461457.
Pages inactive:                         1459397.
Pages speculative:                         1120.
Pages throttled:                              0.
Pages wired down:                        820260.
Pages purgeable:                           5342.
"Translation faults":                4944684965.
Pages copy-on-write:                  122832789.
Pages zero filled:                   2565732594.
Pages reactivated:                     55502320.
Pages purged:                          18150871.
File-backed pages:                       358763.
Anonymous pages:                        2563211.
Pages stored in compressor:             4005771.
Pages occupied by compressor:            446893.
Decompressions:                        55339261.
Compressions:                          80556428.
Pageins:                               84891281.
Pageouts:                                593881.
Swapins:                               18975501.
Swapouts:                              20951392.
$ vm_stat
Mach Virtual Memory Statistics: (page size of 4096 bytes)
Pages free:                             1079780.
Pages active:                            941492.
Pages inactive:                          924097.
Pages speculative:                        16359.
Pages throttled:                              0.
Pages wired down:                        817330.
Pages purgeable:                          12680.
"Translation faults":                4944754350.
Pages copy-on-write:                  122837277.
Pages zero filled:                   2565759728.
Pages reactivated:                     55522202.
Pages purged:                          18150875.
File-backed pages:                       374456.
Anonymous pages:                        1507492.
Pages stored in compressor:             4001331.
Pages occupied by compressor:            414732.
Decompressions:                        55352360.
Compressions:                          80567881.
Pageins:                               84907463.
Pageouts:                                593929.
Swapins:                               18975821.
Swapouts:                              20981460.

上が実行中で、下が終了後。終了後に Pages free が 1M pages × 4kbytes/page = 4Gbytes 増えてます。
JFR はどうにかして cached を特定して used に合わせて返しているんですかね？

2020/04/18

JDK Flight Recorder で物理メモリを監視してみたけど何か変