kubernetes pod 内存 - java gc 日志 [英] kubernetes pod memory - java gc logs
问题描述
在 kubernetes 仪表板上，有一个 pod，其中内存使用情况(字节)显示为 904.38Mi.
这个 pod 包含使用 -Xms512m -Xmx1024m 运行的 java 应用程序，以及在 kubernetes 部署文件 -> requests.memory = 512M 上，limits.内存 = 1.5G.
我已启用 gc 日志并在 pod 日志中看到这些:
[2020-04-29T15:41:32.051+0000] GC(1533) 第一阶段:标记存活对象[2020-04-29T15:41:32.133+0000] GC(1533) 第一阶段:标记存活对象 81.782ms[2020-04-29T15:41:32.133+0000] GC(1533) 阶段 2:计算新的对象地址[2020-04-29T15:41:32.145+0000] GC(1533) 第二阶段:计算新对象地址 11.235ms[2020-04-29T15:41:32.145+0000] GC(1533) 第 3 阶段:调整指针[2020-04-29T15:41:32.199+0000] GC(1533) 第 3 阶段:调整指针 54.559ms[2020-04-29T15:41:32.199+0000] GC(1533) 第 4 阶段:移动对象[2020-04-29T15:41:32.222+0000] GC(1533) 第 4 阶段:移动对象 22.406 毫秒[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) 终身任职:422769K->130230K(500700K)[2020-04-29T15:41:32.222+0000] GC(1532) 元空间: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.26skubernetes 是如何到达904.38Mi 使用的?如果我理解正确，目前的用法只是:
DefNew (年轻) - 0k终身任职 - 130230K元空间 - 88938K总和 - 216168K运行 ps 表明除了这个 Java 应用程序外，pod 上没有其他进程在运行.
任何人都可以对此有所了解吗?
(已编辑)当pod第一次启动并运行几分钟时，内存使用量仅显示为500mb左右，然后让请求进来它会突然增加到900mb-1gb，然后当所有处理完毕后，k8s仪表板上的内存使用量没有不会低于 900mb，即使基于 GC 日志，堆也可以通过 GC.
这里有很多事情要做.让我们一次一个.
您似乎每个 pod 使用一个容器(尽管每个 pod 可以有 许多 个容器).requests.memory 和 limits.memory 特定于 container，Kubernetes 计算 limits 和 requests 每个 pod 作为所有容器限制的总和.
所以想一想 - 你是说 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 仪表板来专门测试这个，所以必须安装它才能真正了解发生了什么.我对大多数事情都有一些暗示，但为了确保安全，我做了一些测试.
首先要注意的是:仪表板中的数字是什么意思?花了一段时间才找到/理解，但那是
现在让我们稍微更改一下这段代码.让我们在那里添加一些 GC，让我们永远不要完成这个过程(你知道就像典型的 spring-boot 应用程序那样):
import java.time.temporal.ChronoUnit;导入 java.util.Arrays;导入 java.util.concurrent.TimeUnit;导入 java.util.concurrent.locks.LockSupport;公共类堆测试{public static void main(String[] args) 抛出异常 {//每 3 秒分配 1 MBfor (int i = 0; i <40; ++i) {字节[] b = 新字节[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++) {线程睡眠(500)；System.gc();}而(真){尝试 {Thread.sleep(TimeUnit.of(ChronoUnit.SECONDS).toMillis(5));线程.onSpinWait();} 捕获(异常 e){抛出新的运行时异常(e)；}}}}我用:
java "-Xlog:heap*=debug";-Xlog:gc*=debug"-Xlog:ergo*=debug"-Xmx100 米-Xms20m堆测试在检查日志时(就像在您的示例中一样)，我确实看到堆收集得很好.但是当我看仪表盘时，内存并没有下降(与前面的示例不同).
一旦G1GC 占用了内存，它就不会急于将其还给操作系统.它可以在极少数情况下做到这一点，这里是
你应该关心这个:
<块引用>这种行为在资源按使用付费的容器环境中尤其不利.即使在 VM 由于不活动而仅使用其分配的内存资源的一小部分的阶段，G1 也将保留所有 Java 堆.这导致客户一直为所有资源付费，而云提供商无法充分利用他们的硬件.
附言我还要补充一点，其他 Pod 也受到影响，因为一个 Pod 决定在特定峰值时尽可能多地占用内存，并且永不归还.
On the kubernetes dashboard, there's a pod wherein the Memory Usage (bytes) is displayed as 904.38Mi.
This pod holds the java app that was ran with -Xms512m -Xmx1024m, and on kubernetes deployment file -> requests.memory = 512M, limits.memory = 1.5G.
I've enabled gc logs and seeing these on the pod logs:
[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
How did kubernetes arrived at 904.38Mi usage? If I understood correctly, the current usages are only:
DefNew (young) - 0k
Tenured - 130230K
Metaspace - 88938K
Sum - 216168K
Running ps shows there are no other processes running on the pod aside from this java app.
Anyone can shed some light to this?
(edited) When the pod first started and let run for few mins, the memory usage is displayed as around 500mb only, then let the requests come in it will burst to 900mb-1gb, then when all has been processed, the memory usage on k8s dashboard doesn't go down below 900mb, even though based on GC logs, heap is GC'ed ok.
There are a lot of things going on here. Let's take each at a time.
It seems you are using a single container per pod (though you could have many containers per pod). The requests.memory and limits.memory are specific to the container, Kubernetes computes limits and requests per pod as the sum of all the containers limitations.
So think about it - you are saying that a pod shows 904.38Mi, but you show requests.memory and limits.memory, which is per container. That is why I assume you have one container per pod. This is a general intro that does not answer your question - but we will get there.
Then comes the fact that a pod is started by docker, which is started with kubectl and that reads requires.memory and limits.memory. To make this a bit simpler : what you set in limits.memory, will be passed as docker -m. So, in your case, the total memory used for the docker process is 1.5GC. Remember that is the entire process limit, not just the heap. A java process is a lot more than the heap, which you specify with -Xms512m -Xmx1024m. So to answer your question:
How did kubernetes arrived at 904.38Mi usage?
This is what the entire process is currently taking, not just the heap. From the very short log files that you posted - your application is just fine.
EDIT
I actually did not had kubernetes dashboard in my environment to test this specifically, so had to install it to really understand what is going on. I had a hint against the majority of things, but to make sure, I did some tests.
First things first: what does that number in the dashboard mean? Took a while to find/understand, but that is the actual resident memory of the process, which actually is a very good thing.
Any sane OS knows that when someone requests memory from it, it rarely needs/utilizes it all, as such, it gives the memory to it in a lazy fashion. This is easy to prove in k8s. Suppose I have a jdk-13 JVM and start it with:
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".
Notice requests.memory=10Mi and limits.memory=100Mi. Reading the answer from the beginning, you already know that the specific pod will be started with docker -m 100m... because limits.memory=100Mi. That is easy to prove, just sh into the pod:
kubectl exec -it jdk-13-b8d656977-rpzrg -- /bin/sh
and find out what the cgroup says:
# cat /sys/fs/cgroup/memory/memory.limit_in_bytes
104857600 // 100MB
perfect! so the pod's memory limitation is 100 MB max, but what is the current memory utilization, that is what is the resident memory taken?
kubectl top pod
NAME CPU(cores) MEMORY(bytes)
jdk-13-b8d656977-rpzrg 1m 4Mi
OK, so the current memory utilization is only 4MB.
You can "make sure" that this is indeed accurate, if you do:
kubectl exec -it jdk-13-b8d656977-rpzrg -- /bin/sh
and inside that pod issue:
top -o %MEM
and notice that RES memory is on par with the one reported via dashboard or kubectl top pod.
And now let's do a test. Suppose I have this very simple code in that 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));
}
}
}
I allocate 1MB every 3 seconds for around 2 minutes. When I look at this process in dashboard, I do see that at some point in time, the memory grows. After the program ends, dashboard reports the drop in memory back. Good! That means the memory is given back and RSS memory drops. This is how it looks like in dashboard:
Now let's change this code just a bit. Let's add some GC in there and let's never finish this process (you know like typical spring-boot applications do):
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);
}
}
}
}
I run this with:
java "-Xlog:heap*=debug"
"-Xlog:gc*=debug"
"-Xlog:ergo*=debug"
-Xmx100m
-Xms20m
HeapTest
on inspecting logs (just like in your example), I do see that heap is collected just fine. But when I look at the dashboard, the memory does not drop (unlikes the previous example).
Once G1GC takes memory, it is not very eager to give it back to the OS. It can do that in rare cases, here is one example or you can instruct it to do so.
Both ways are rather painful, instead there are GC algorithms that are smarter (and in general a lot better). My personal love goes to Shenandoah, let's see what it does. If I slightly change the code (so that I could prove my point better):
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);
}
}
}
}
And run it with:
java "-Xlog:gc*=debug"
"-Xlog:ergo*=debug"
"-Xlog:heap*=debug"
-XX:+UnlockExperimentalVMOptions
-XX:+UseShenandoahGC
-XX:+ShenandoahUncommit
-XX:ShenandoahGCHeuristics=compact
-Xmx1g
-Xms1m
HeapTest
Here is what you are going to see:
And you should, for a fact care about this:
This behavior is particularly disadvantageous in container environments where resources are paid by use. Even during phases where the VM only uses a fraction of its assigned memory resources due to inactivity, G1 will retain all of the Java heap. This results in customers paying for all resources all the time, and cloud providers not being able to fully utilize their hardware.
P.S. I would also add to that the fact that other pods are suffering too, because one pod decided to take as much memory as it could, at a particular spike, and never give it back.
这篇关于kubernetes pod 内存 - java gc 日志的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！
