kubernetes pod 内存 - java gc 日志

Posted 2023-02-21

【中文标题】kubernetes pod 内存 - java gc 日志

【英文标题】：kubernetes pod memory - java gc logs

【发布时间】：2020-08-13 19:08:21

【问题描述】：

在 kubernetes 仪表板上，有一个 pod，其中内存使用情况（字节）显示为 904.38Mi。

此 pod 包含使用 -Xms512m -Xmx1024m 运行的 java 应用程序，以及 kubernetes 部署文件 -> requests.memory = 512M、limits.memory = 1.5G。

我已启用 gc 日志并在 pod 日志中看到这些：

[2020-04-29T15:41:32.051+0000] GC(1533) Phase 1: Mark live objects
[2020-04-29T15:41:32.133+0000] GC(1533) Phase 1: Mark live objects 81.782ms
[2020-04-29T15:41:32.133+0000] GC(1533) Phase 2: Compute new object addresses
[2020-04-29T15:41:32.145+0000] GC(1533) Phase 2: Compute new object addresses 11.235ms
[2020-04-29T15:41:32.145+0000] GC(1533) Phase 3: Adjust pointers
[2020-04-29T15:41:32.199+0000] GC(1533) Phase 3: Adjust pointers 54.559ms
[2020-04-29T15:41:32.199+0000] GC(1533) Phase 4: Move objects
[2020-04-29T15:41:32.222+0000] GC(1533) Phase 4: Move objects 22.406ms
[2020-04-29T15:41:32.222+0000] GC(1533) Pause Full (Allocation Failure) 510M->127M(680M) 171.359ms
[2020-04-29T15:41:32.222+0000] GC(1532) DefNew: 195639K->0K(195840K)
[2020-04-29T15:41:32.222+0000] GC(1532) Tenured: 422769K->130230K(500700K)
[2020-04-29T15:41:32.222+0000] GC(1532) Metaspace: 88938K->88938K(1130496K)
[2020-04-29T15:41:32.228+0000] GC(1532) Pause Young (Allocation Failure) 603M->127M(614M) 259.018ms
[2020-04-29T15:41:32.228+0000] GC(1532) User=0.22s Sys=0.05s Real=0.26s

kubernetes 是如何达到904.38Mi 使用率的？如果我理解正确的话，目前的用法只有：

DefNew (young) -      0k
Tenured        - 130230K
Metaspace      -  88938K
Sum            - 216168K

运行 ps 表明除了这个 java 应用程序之外，pod 上没有其他进程在运行。 任何人都可以对此有所了解吗？

（已编辑） Pod刚启动运行几分钟，内存使用显示为500mb左右，然后让请求进来它会爆发到900mb-1gb，然后当所有处理完毕后，k8s仪表盘上的内存使用情况不要低于 900mb，即使根据 GC 日志，堆是 GC 好的。

【问题讨论】：

您可以尝试在容器中运行free -m 吗？它应该让您知道容器中实际使用了多少内存，并可能帮助您发现 Java 进程不知道的泄漏。

@YaronIdan free -m 在容器中是没用的。只需尝试docker run -m...，然后在容器内尝试free -m

你用的是哪个java版本？

@Pankaj，祖鲁 11

【参考方案1】：

这里发生了很多事情。让我们一个一个来。

您似乎在每个 pod 使用一个容器（尽管每个 pod 可以有 许多 个容器）。 requests.memory 和 limits.memory 特定于 容器，Kubernetes 计算每个 pod 的 limits 和 requests 作为所有容器限制的总和。 p>

所以想一想 - 你是说 pod 显示 904.38Mi，但你显示 requests.memory 和 limits.memory，这是每个 容器。这就是为什么我假设每个 pod 有一个容器。这是一个一般性的介绍，无法回答您的问题 - 但我们会到达那里。

然后是pod 由docker 启动，它以kubectl 开头，读取requires.memory 和limits.memory。为了简化一点：您在limits.memory 中设置的内容将作为docker -m 传递。因此，在您的情况下，用于 docker 进程的总内存为1.5GC。请记住，这是整个进程限制，而不仅仅是堆。 java 进程远不止堆，你用-Xms512m -Xmx1024m 指定。所以回答你的问题：

kubernetes 是如何达到 904.38Mi 使用率的？

这是整个进程当前正在使用的，而不仅仅是堆。从您发布的非常短的日志文件来看，您的应用程序很好。

编辑

实际上我的环境中没有 Kubernetes 仪表板来专门测试这个，所以必须安装它才能真正了解发生了什么。我对大多数事情都有暗示，但为了确保这一点，我做了一些测试。

第一件事：仪表板中的数字是什么意思？花了一段时间才找到/理解，但那是the actual resident memory of the process，这实际上是一件非常好的事情。

任何理智的OS 都知道，当有人向它请求内存时，它很少需要/利用它，因此，它以一种懒惰的方式给它内存。这在k8s 中很容易证明。假设我有一个jdk-13 JVM 并以：

kubectl run jdk-13 
    --image=jdk-13 
    --image-pull-policy=Never 
    --limits "memory=100Mi" 
    --requests "memory=10Mi" 
    --command -- /bin/sh -c "while true; do sleep 5; done".

通知requests.memory=10Mi 和limits.memory=100Mi。从头开始阅读答案，您已经知道特定的pod将以docker -m 100m...开头，因为limits.memory=100Mi。这很容易证明，只需将sh 转换为pod：

 kubectl exec -it jdk-13-b8d656977-rpzrg -- /bin/sh

看看cgroup 说了什么：

 # cat /sys/fs/cgroup/memory/memory.limit_in_bytes
 104857600 // 100MB

完美！所以 pod 的内存限制是100 MB max，但是 current 内存利用率是多少，也就是占用的常驻内存是多少？

kubectl top pod
   NAME                          CPU(cores)   MEMORY(bytes)
   jdk-13-b8d656977-rpzrg           1m           4Mi

好的，所以当前的内存利用率只有4MB。 如果这样做，您可以“确保”这确实是准确的：

kubectl exec -it jdk-13-b8d656977-rpzrg -- /bin/sh

在那个 pod 问题中：

top -o %MEM

并注意RES 内存与通过仪表板或kubectl top pod 报告的内存相当。

现在让我们做一个测试。假设我在那个 pod 中有这个非常简单的代码：

// run this with: java "-Xlog:gc*=debug" -Xmx100m -Xms20m  HeapTest
import java.time.temporal.ChronoUnit;
import java.util.Arrays;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.LockSupport;

public class HeapTest 

    public static void main(String[] args) throws Exception 

        // allocate 1 MB every 3 seconds
        for (int i = 0; i < 40; ++i) 
            byte[] b = new byte[1024 * 1024 * 1];
            b[i] = 1;
            System.out.println(Arrays.hashCode(b));
            LockSupport.parkNanos(TimeUnit.of(ChronoUnit.SECONDS).toNanos(3));
        
    


    

我每 3 秒分配一次1MB，持续大约 2 分钟。当我在仪表板中查看此过程时，我确实看到在某个时间点，内存会增长。程序结束后，仪表板会报告内存下降。好的！这意味着内存被归还并且 RSS 内存下降。这是仪表板中的样子：

现在让我们稍微修改一下这段代码。让我们在其中添加一些 GC，让我们永远不要完成这个过程（就像典型的 spring-boot 应用程序一样）：

import java.time.temporal.ChronoUnit;
import java.util.Arrays;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.LockSupport;

public class HeapTest 

    public static void main(String[] args) throws Exception 

        // allocate 1 MB every 3 seconds
        for (int i = 0; i < 40; ++i) 
            byte[] b = new byte[1024 * 1024 * 1];
            b[i] = 1;
            System.out.println(Arrays.hashCode(b));
            LockSupport.parkNanos(TimeUnit.of(ChronoUnit.SECONDS).toNanos(3));
        
        for (int i = 0; i < 10; i++) 
            Thread.sleep(500);
            System.gc();
        
        
        while (true) 
            try 
                Thread.sleep(TimeUnit.of(ChronoUnit.SECONDS).toMillis(5));
                Thread.onSpinWait();
             catch (Exception e) 
                throw new RuntimeException(e);
            
        

    

我运行这个：

java "-Xlog:heap*=debug" 
     "-Xlog:gc*=debug" 
     "-Xlog:ergo*=debug" 
     -Xmx100m 
     -Xms20m
     HeapTest

在检查日志时（就像在您的示例中一样），我确实看到堆收集得很好。但是当我查看仪表板时，内存并没有下降（与前面的示例不同）。

一旦G1GC 占用了内存，它就不太急于将它还给操作系统。在极少数情况下它可以做到这一点，这里是 one example 或 you can instruct it to do so。

这两种方式都相当痛苦，取而代之的是GC 算法更智能（并且通常很多更好）。我个人的爱去Shenandoah，让我们看看它做了什么。如果我稍微修改一下代码（这样我可以更好地证明我的观点）：

import java.time.temporal.ChronoUnit;
import java.util.Arrays;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.LockSupport;

public class HeapTest 

    public static void main(String[] args) throws Exception 

        // allocate 1/4 MB every 100 ms
        for (int i = 0; i < 6000; ++i) 
            byte[] b = new byte[1024 * 256];
            b[i] = 1;
            System.out.println(Arrays.hashCode(b));
            LockSupport.parkNanos(TimeUnit.of(ChronoUnit.MILLIS).toNanos(100));
        

        while (true) 
            try 
                Thread.sleep(TimeUnit.of(ChronoUnit.SECONDS).toMillis(5));
                Thread.onSpinWait();
             catch (Exception e) 
                throw new RuntimeException(e);
            
        

    

然后运行它：

 java "-Xlog:gc*=debug" 
      "-Xlog:ergo*=debug" 
      "-Xlog:heap*=debug" 
       -XX:+UnlockExperimentalVMOptions 
       -XX:+UseShenandoahGC 
       -XX:+ShenandoahUncommit 
       -XX:ShenandoahGCHeuristics=compact  
       -Xmx1g 
       -Xms1m  
       HeapTest

您将看到以下内容：

还有你should, for a fact care about this:

这种行为在资源按使用付费的容器环境中尤其不利。即使在虚拟机由于不活动而仅使用其分配的内存资源的一小部分的阶段，G1 也会保留所有 Java 堆。这导致客户一直为所有资源付费，而云提供商无法充分利用他们的硬件。

附：我还要补充一点，其他 pod 也在遭受痛苦，因为一个 pod 决定在特定的峰值处尽可能多地占用内存，并且永远不会归还它。

【讨论】：

感谢@Eugene，是的，每个 pod 有 1 个容器。实际上，我问这个的另一个原因（我将用这个查询编辑我的帖子）是因为在启动时使用量只有大约 500mb，然后让处理它的请求会激增到 900mb-1gb，然后毕竟过程中，它似乎不再低于 900mb，但从 GC 日志来看，看起来堆正在被 gc 处理。因此，如果堆被 gc'ed，我想知道它没有被收回的内存在哪里。

@villager 你不需要添加更多日志，从你的日志中可以看到内存已经被 GCed 的事实，但它没有返回给操作系统，它仍然是 JVM 下的堆内存裁决。

感谢@Eugene，您能否进一步详细说明为什么它没有返回给操作系统，这是否意味着k8s 仪表板上的内存使用量预计不会下降？

【参考方案2】：

GC 处理进程使用的内存子集。 JVM 内存中有一些区域不受垃圾回收的影响。

以下是堆/元空间中不包含的几个内存区域

线程堆栈空间 压缩类空间 JIT 编译代码 NIO 直接缓冲内存

上面的列表并不完整，这些只是最大的内存消耗者。

Here is JVM memory hierarchy diagram 带有相关的配置选项。

总之，实际的 JVM 内存需求总是大于堆限制。

多大取决于应用的性质，可以凭经验确定。

更新

Java Native Memory Tracking 可以在 JVM 中启用，以提供与不同功能区域的内存使用情况相关的详细报告。

【讨论】：

谢谢@Alexey Regozin，有什么方法可以检查其他内存区域的使用情况吗？

@villager 添加了指向本机内存跟踪的链接