kubernetes pod内存-Java gc日志 [英] kubernetes pod memory - java gc logs
问题描述
在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进行堆操作.
这里发生了很多事情.让我们一次接一个.
似乎每个吊舱使用单个容器(尽管每个吊舱可以具有许多 个容器). requests.memory和limits.memory特定于容器，Kubernetes计算limits和requests每个 pod 作为所有容器限制的总和.
考虑一下-您说的是pod显示904.38Mi，但显示的是requests.memory和limits.memory，它们是每个容器.这就是为什么我假设您每个吊舱只有一个容器.这是一个一般性的简介，它不能回答您的问题-但是我们会到达那里.
然后出现一个事实，即pod由docker启动，而docker由kubectl开始，并且读取requires.memory和limits.memory.为了简化一点:您在limits.memory中设置的内容将作为docker -m传递.因此，在您的情况下，用于docker进程的总内存为1.5GC.请记住，这是整个进程的限制，而不仅仅是堆.一个Java进程比您用-Xms512m -Xmx1024m指定的堆要多得多.因此，回答您的问题:
kubernetes是如何达到904.38Mi使用率的?
这是 entire 进程当前正在采取的措施，而不仅仅是堆.从您发布的简短日志文件中，您的应用程序就可以了.
编辑
在我的环境中，我实际上没有kubernetes仪表板来对此进行专门测试，因此必须安装它才能真正了解正在发生的事情.我对大多数事情有暗示，但为确保确定，我进行了一些测试.
第一件事:仪表板上的数字是什么意思?花费了一段时间查找/理解，但这进程的实际居民内存，这实际上是一件好事.
任何理智的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，但是当前的内存利用率是多少，即占用的常驻内存是什么?
kubectl top pod
NAME CPU(cores) MEMORY(bytes)
jdk-13-b8d656977-rpzrg 1m 4Mi
好，因此当前的内存利用率仅为4MB.
您可以确保"如果这样做的话，这确实是正确的:
kubectl exec -it jdk-13-b8d656977-rpzrg -- /bin/sh
在该广告连播问题中:
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占用内存，就不太渴望将其返回给操作系统.它可以在极少数情况下做到这一点，这是您可以指示其这样做.
这两种方法都比较痛苦，相反，有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
这是您要看到的:
此行为在使用资源付费的容器环境中尤其不利.即使在VM由于不活动而仅使用其分配的内存资源的一小部分的阶段中，G1也会保留所有Java堆.这导致客户一直在为所有资源付费，而云提供商则无法充分利用其硬件.
P.S.我还要补充一点，其他吊舱也遭受了痛苦，因为一个吊舱决定在一个特定的高峰期占用尽可能多的内存，并且永不退还.
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屋！
