最近有个同事找我来看一个Java 应用的内存问题: 他的一个Java应用运行在一个8G内存的机器上, 配置的 Java heap 最大值是2G, 然而这个应用还有个页面能看到系统剩余空闲内存, 上面显示只有500M多的剩余. 他们想给这个应用加大 heap, 却看到只有500M剩余, 不敢加了.

初步看了下机器的内存, 确实是 free 内存是500多M, 然而那是绝对剩余的内存, 没有去掉随时可以回收的 buffer/cache 占用的内存. 如果去掉 buffer/cache 可以释放的内存, 剩余有近5G.

类似如下图:

那么它看到的500M是哪里来的呢? 经过他们翻找源代码, 发现来自于 MBean:

OperatingSystemMXBean.getFreePhysicalMemorySize()

这个 OperatingSystemMXBean 是根据操作系统不同有不同的实现, 但是根据这个测试类 GetFreePhysicalMemorySize 我们可以发现, 它其实取之于: cat /proc/meminfo 的 MemFree, 由此推断, 它就是 free -m 里面的 free 列, 并不是 available 还可以通过释放 buffer/cache 去释放很多.

buffer/cache 就是操作系统为了最大化内存的使用价值而做的: buffer - 其实需要直接写到磁盘, 但是现在直接扔到内存, 等需要的时候, 再写到磁盘. cache - 不用直接从磁盘去取了, 而是把常用的放在内存随时快速使用.

找出源代码

写一段使用 OperatingSystemMXBean 获取空闲内存的代码:

import java.lang.management.ManagementFactory;
import com.sun.management.OperatingSystemMXBean;

public class FreeMemoryExample {
    @SuppressWarnings("restriction")
    public static void main(String[] args) {
        OperatingSystemMXBean osBean = (OperatingSystemMXBean) ManagementFactory.getOperatingSystemMXBean();
        long freePhysicalMemorySize = osBean.getFreePhysicalMemorySize();
        System.out.println("Free Physical Memory Size: " + freePhysicalMemorySize + " bytes");
    }
}

编译并用 jdb 执行:

$ javac -g FreeMemoryExample.java

$ jdb FreeMemoryExample
Initializing jdb ...
> stop at FreeMemoryExample:8
Deferring breakpoint FreeMemoryExample:8.
It will be set after the class is loaded.
> run
run FreeMemoryExample
Set uncaught java.lang.Throwable
Set deferred uncaught java.lang.Throwable
>
VM Started: Set deferred breakpoint FreeMemoryExample:8

Breakpoint hit: "thread=main", FreeMemoryExample.main(), line=8 bci=7
8            long freePhysicalMemorySize = osBean.getFreePhysicalMemorySize();

main[1] locals
Method arguments:
args = instance of java.lang.String[0] (id=831)
Local variables:
osBean = instance of com.sun.management.internal.OperatingSystemImpl(id=832)

main[1] methods com.sun.management.internal.OperatingSystemImpl
** methods list **
com.sun.management.internal.OperatingSystemImpl <init>(sun.management.VMManagement)
com.sun.management.internal.OperatingSystemImpl getCommittedVirtualMemorySize()
com.sun.management.internal.OperatingSystemImpl getFreePhysicalMemorySize()
com.sun.management.internal.OperatingSystemImpl getTotalPhysicalMemorySize()
com.sun.management.internal.OperatingSystemImpl getCommittedVirtualMemorySize0()
com.sun.management.internal.OperatingSystemImpl getFreePhysicalMemorySize0()
com.sun.management.internal.OperatingSystemImpl getFreeSwapSpaceSize0()
...

可以看到 osBean 的类是: com.sun.management.internal.OperatingSystemImpl. 查找 JDK 可以看到有 windows 和 unix 版本. 其中 unix 版本核心的代码是:

#else // solaris / linux
    jlong num_avail_physical_pages = sysconf(_SC_AVPHYS_PAGES);
    return (num_avail_physical_pages * page_size);

AI 对这2行代码的解释:

这段C代码用于获取系统中可用的物理页面数，并计算可用物理内存的总大小。

1. jlong num_avail_physical_pages = sysconf(_SC_AVPHYS_PAGES);：

   1. sysconf() 是一个用于获取系统配置信息的函数，位于 <unistd.h> 头文件中。
   2. _SC_AVPHYS_PAGES 是一个参数，用于指示我们要获取系统中可用的物理页面数。这个参数是一个宏定义，表示系统中可用的物理内存页面的数量。
   3. sysconf(_SC_AVPHYS_PAGES) 调用返回的值将被赋给 num_avail_physical_pages 变量，该变量的类型为 jlong，通常在Java Native Interface (JNI) 中用于表示Java中的 long 类型。

2. return (num_avail_physical_pages * page_size);：

   1. page_size 变量应该是一个代表页面大小的值。在大多数情况下，页面大小是一个固定的值，通常在操作系统的头文件中定义。例如，在Linux系统中，PAGE_SIZE 宏定义了页面的大小。
   2. num_avail_physical_pages * page_size 计算了可用物理内存的总大小，即可用的物理页面数乘以页面大小。
   3. 最后，这个总大小被作为函数的返回值返回。

   综上所述，这段代码的主要作用是通过查询系统配置信息获取可用的物理页面数，然后计算可用物理内存的总大小，并将其作为函数的返回值返回。

所以,可以看到这里只是查看绝对空闲内存的数量, 然后再乘以每个页面大小.

我们分析 Java heap dump 的时候, 经常发现里面包含很多 java.lang.String, 可是让我们回想到底哪里用了这么多 String 的时候, 确实很难列举. 如此多的 String 肯定占用了很多宝贵的内存空间, 那么有什么办法能减少 String 的空间占用呢?

下面一个 heap dump 的 object histogram 的截图, 可以看到 String 的数量仅次于 byte[], 位居第二.

如果你去研究为啥这么多 byte[], 最终你会发现, 其实是 String 太多, 每个 String 对象的背后也是一个byte[].

String 也是 immutable 的对象, 也就是说你对 String 的任何修改会直接创建另外一个新的对象.

另外, 我们会发现, 其实我们的内存里面有很多重复的 String. 通过 MAT 的 “Java Basics” -> "Group by value", 我们对 java.lang.String 进行分组, 可以看到很多重复的字符串.

如下图, 在一个只有 158 MB的 heap 里面, https 这个 String 竟然有 70397 个实例对象.

如果我们添加 -XX:+UseStringDeduplication, 经过一段时间的稳定运行后, 我们可以看到, 虽然 String 还是那么多, 但是 byte[] 已经大幅减少:

对比上图我们发现:

1. String 数量还是差不多, 但是 byte[] 明显减少.
2. String 对象 retained size 明显减少, 就是因为它们引用的 bytes[] 很多都合并了.

我们以 https 这个字符串为例, 可以看到他们引用的 byte[] 都是一个:

对比 intern()

使用 intern()方法, 返回的字符串常量都是字符串常量池里面的同一个.
使用 UseStringDeduplication, 一开始是在EDEN 区域分配的时候, 每个String 都是新的, byte[] 也是不一样的, 当被GC 回收次数达到 StringDeduplicationAgeThreshold 的时候, 会有后台线程处理, 把 bytes[] 指向常量池里的那个字符串. 但是 String 对象本身还是之前的.

uint StringDeduplicationAgeThreshold          = 3                                         {product} {default}
bool UseStringDeduplication                   = false                                     {product} {default}
bool PrintStringTableStatistics               = false                                     {product} {default}

为什么 UseStringDeduplication 默认是关闭的

1. String 的 byte[] 一开始还少正常每个都分配空间的, 等被回收次数到达 StringDeduplicationAgeThreshold 后, 才会有后台线程更改 byte[], 所以需要在 GC 后额外占用时间.
2. 更改这些指针还需要额外CPU.
3. 需要额外内存记录被回收次数.

首先看下面一段代码:

public class StringTest {
    public static final String S = "Hello";

    private String s = "Hello";

    public static void main(String[] args) {
        String s1 = "Hello";
        String s2 = "Hello";
        String s3 = new String("Hello");
        String s4 = new String("Hello");
        String s5 = new String("Hello").intern();
        String s6 = "Hello".intern();

        StringTest st = new StringTest();
        System.out.println(s1 == st.s); // true
        System.out.println(s1 == StringTest.S); // true
        System.out.println(s1 == s2); // true
        System.out.println(s1 == s3); // false
        System.out.println(s3 == s4); // false
        System.out.println(s1 == s5); // true
        System.out.println(s1 == s6); // true

        System.out.println(s1.equals(s2) + " " + s1.equals(s3) + " " + s3.equals(s4) + " " + s1.equals(s5) + " " + s1.equals(s6));
    }
}

运行在 JDK 17 上.
这是除了 StringTest.S 这个静态字段之外的其他是 "Hello" 的字符串在内存的表示. 可以得出:

1. 除了 s3, s4 其它都指向同一个内存对象.
2. 所有这些字符串都指向同一个 byte[], 里面存储的是 “Hello” 的 ascii 码.
   
   静态字段, 静态字段也同其它字面量一样, 都指向同一个.
   

这段代码里面, 有声明字面量(literal) 和 String 对象. 所有的字面量(常量或变量)都是指向内存字符串常量池的同一个字符串地址, 所以使用 == 对比也是相等的.

Java 常量池是什么?

Java 的字符串都是 Immutable 的, 也就是更改都会产生新的字符串. 常量池是在内存中开辟出来的一块专门存储字符串的空间. 由 String 类管理(native 代码). 它是一个很大的 HashMap 维护.

Java 常量池存在的意义什么?

所谓池, 就是共享同一份. 因为对很多程序来说, 很多字符串都是反复使用, 只要内存保存一份就好了.

为什么 new String() 不能返回常量池字符串?

常量池大小调节

可以看到如下参数, 默认是 65536. 调的太小, 容易产生hash 碰撞. 如果字符串不多, 调的太大, 占用太多空间.

uintx StringTableSize                          = 65536                                     {product} {default}

最近写了一段shell 脚本, 执行过程中遇到一些错误, 这里记录一下.

脚本内容

脚本的用意是: 有 pod 在 kubenetes cluster 里面, 要去 profiling 里面 Java 进程. 所以要先 copy profiler 工具上去, 然后解压缩, 之后找到 Java 进程, 最后 profiling.

下面是改正后的脚本:

#!/bin/bash

#set -x
# Set variables
pod="my_pod_1"
ns="my_ns"
cluster_id="37"
local_profiler="~/work/tools/async-profiler-1.7.1-linux-x64.tar.gz"
base_cmd="/tmp/profiler.sh -e itimer -d 30 -o svg -f /mnt/data/profile_eric.log.html"
# -e alloc | -e lock, -t <tid>, --reverse

# Copy profiler to target pod
echo "Copying profiler to target pod"
kubectl cp "${local_profiler}" "${pod}:/tmp/async-profiler-1.7.1-linux-x64.tar.gz" -n "${ns}" --context="${cluster_id}" -c app

# Unzip the profiler
echo "Unzipping the profiler"
kubectl exec -it "${pod}" -n "${ns}" --context="${cluster_id}" -c app -- tar -xf /tmp/async-profiler-1.7.1-linux-x64.tar.gz -C /tmp/

# Get target pod's Java PID
pid=$(kubectl exec "${pod}" -n "${ns}" --context="${cluster_id}" -c app -- pgrep java)
echo "Target pod Java PID is ${pid}"

# Construct the full command
cmd="${base_cmd} ${pid}"
echo "Command is ${cmd}"

# Run profiling
echo "Running profiling"
kubectl exec "${pod}" -n "${ns}" --context="${cluster_id}" -c app -- ${cmd}

遇到的问题

所有的步骤都能被执行, 但是最后一行代码本应该执行 30 秒, 因为在 profiler 的参数里面设置了 -d 30, 可是每次profiling 工具都是开始执行, 立马结束. 打印执行的命令, 把命令单独执行, 也都没有问题.

问题原因

经过 Shell 脚本大师 Peter Deng 的指点, 加了 set -x 参数, 就可以看出到底执行到了哪一步. 发现在 profiler.sh 里面去 kill -0 $PID 的时候, 发现目标进程不存在, 就结束了. 仔细察看代码, 发现传入的进程号竟然是 $25\r, 但其实应该是25.

在进一步排查为什么是$25\r, 发现最初获取进程号的代码是:

pid=$(kubectl exec -it "${pod}" -n "${ns}" --context="${cluster_id}" -c app -- pgrep java)

里面有 -it, 那么它的返回就是 $25\r, 也就是先是一个命令开始符号, 接着是进程号输出, 然后换行. 这正是一般命令行的输出形式. 所以去掉 -it 就只返回进程号了.

另外一个离奇的是: 虽然变量值是 $25\r, 但是当用 echo 打印的时候, 它只显示 25.

验证

使用下面的代码验证:

#!/bin/bash

num="$34\r"
echo "the num is: ${num}"
echo "the num length is ${#num}"

执行输出的结果:

$sh test.sh
the num is: 4
the num length is 3

获得

1. 使用 set -x 能帮助很快的去debug
2. 在 $后面的字符很多都有转义, 要小心注意.

自从2016年左右开始干SRE, 就了解到 JFR 是一个非常有用的工具, 尤其在性能调优这一块. 在好几本书和一些文章中都有人提及过, 但是很少见有人用它来解决实际的问题. 可能的原因包括: JFR的很多事件都是JVM本身暴露的稍底层的一些时间, 不熟悉JVM运行机制的话, 很难从这边比较容易的看出问题. JFR 如果用在生产环境是需要付费的.

为了从理论到实践, 这里就在本地开发环境打开JFR, 然后收集一些数据, 然后解读.

设置环境, 开启JFR

本地正好有个 Java 应用: Pycharm, 通过下面的命令可以看到它的一些启动参数:

$ jcmd
60759 jdk.jcmd/sun.tools.jcmd.JCmd
22348 com.intellij.idea.Main

$ jcmd 22348 VM.command_line

$ jcmd 22348 VM.flags -all | grep FlightRecorder
     bool FlightRecorder                           = false                                     {product} {default}
    ccstr FlightRecorderOptions                    =                                           {product} {default}

我们修改 Pycharm 的 JVM 参数. 从 Pycharm 菜单依次点击: Help -> Edit Custom VM Options. 就打开了 ~/Library/Application\ Support/JetBrains/PyCharmCE2023.3/pycharm.vmoptions. 添加下面选项:

-XX:+UnlockCommercialFeatures
-XX:+FlightRecorder

上面的修改类似于 java -XX:+UnlockCommercialFeatures -XX:+FlightRecorder MyApp

重启 Pycharm, 我们再次检查它的参数:

jcmd 62236 VM.flags -all | grep FlightRecorder
     bool FlightRecorder                           = true                                      {product} {command line}
    ccstr FlightRecorderOptions                    =                                           {product} {default}

收集数据

上面的-XX:+FlightRecorder 选项只是说明我们打开了 JFR 的开关, 真正的收集事件并未开始. 通常我们可以通过 jcmd 命令行或者一些GUI工具(JConsole, Java Mission Control等)来开始收集.

通过运行 jcmd 命令, 我们可以看到有关 JFR 的一些命令, 然后通过 help 能看到对应子命令的更多内容:

$ jcmd <pid> help | grep JFR
JFR.check
JFR.configure
JFR.dump
JFR.start
JFR.stop

$ jcmd 62236 help JFR.start
   ... 可以看到很多参数省略 ...

通过如下的命令, 我们可以启动收集:

$ jcmd 62236 JFR.start name=sample1,filename=/tmp/sample1.jfr,during=1m
62236:
Started recording 1. No limit specified, using maxsize=250MB as default.

Use jcmd 62236 JFR.dump name=sample1,filename=/tmp/sample1.jfr,during=1m filename=FILEPATH to copy recording data to file.

查看这个收集任务 并把数据保存到文件

$ jcmd 62236 JFR.check
62236:
Recording 1: name=sample1,filename=/tmp/sample1.jfr,during=1m maxsize=250.0MB (running)

jcmd 62236 JFR.dump name=sample1,filename=/tmp/sample1.jfr,during=1m filename=/tmp/sample1.jfr
62236:
Dumped recording "sample1,filename=/tmp/sample1.jfr,during=1m", 6.2 MB written to:

/private/tmp/sample1.jfr

关于这几个子命令的更多信息: https://docs.oracle.com/javacomponents/jmc-5-4/jfr-runtime-guide/comline.htm#JFRUH188

解读数据

解读数据需要 Java Mission Control (JMC), 下载页面: https://www.oracle.com/java/technologies/javase/products-jmc8-downloads.html

启动 JMC, 然后打开刚才的文件.

事件类型

JFR 收集3类数据类型:

1. 持续事件: 需要一段时间才会发生，并在完成时记录。你可以设置持续事件的阈值，以便只记录持续时间超过指定时间段的事件。
2. 瞬时事件: 立即发生，并立即记录。
3. 样本事件: 以固定间隔记录，以提供系统活动的样本。你可以配置采样发生的频率。