本节我们来学习Linux性能优化的第二个案例容器问题。来自极客时间专栏-Linux性能优化实战-46讲
1. 容器问题简介
容器封装了环境了依赖，给运维部署带来了非常大的遍历。但是任何技术都不是银弹。这些新技术，在带来诸多便捷功能之外，也带来了更高的复杂性，比如性能降低、架构复杂、排错困难等等。
容器对应用程序的影响体现在以下几个方面:
- 容器本身通过 cgroups 进行资源隔离，所以，在分析时要考虑 cgroups 对应用程序的影响。
- 容器的文件系统、网络协议栈等跟主机隔离。虽然在容器外面，我们也可以分析容器的行为，不过有时候，进入容器的命名空间内部，可能更为方便。
- 资源隔离导致的另一个问题是，很多动态追踪工具因为获取不到应用程序的符号链接文件，而我们通常也不会在容器内安装过多的性能排查工具，这样就导致了排查问题受阻
- 容器的运行可能还会依赖于其他组件，比如各种网络插件（比如 CNI）、存储插件（比如 CSI）、设备插件（比如 GPU）等，让容器的性能分析更加复杂。如果你需要分析容器性能，别忘了考虑它们对性能的影响。
1.1 案例准备
本节我们使用一个 tomcat 服务器作为实例，来看看容器对服务的影响。
1
2
3
4
5
6
7
8
|
# 1. 镜像准备
git clone https://github.com/feiskyer/linux-perf-examples.git
cd tomcat
cd nat
sudo make build
# 2. 容器启动
$ docker run --name tomcat --cpus 0.1 -m 512M -p 8080:8080 -itd feisky/tomcat:8
|
docker 命令参数:
- -m 512M: 限制容器内存为 512M
- –cpus 0.1: 限制容器的 CPU 使用率
1.2 问题发现
容器启动后，我们去请求 tomcat 服务:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
|
# 1. 请求tomcat 服务
$ curl localhost:8080
curl: (56) Recv failure: Connection reset by peer
# 2. 查看 tomcat 容器日志
$ docker logs -f tomcat
Using CATALINA_BASE: /usr/local/tomcat
Using CATALINA_HOME: /usr/local/tomcat
Using CATALINA_TMPDIR: /usr/local/tomcat/temp
Using JRE_HOME: /docker-java-home/jre
Using CLASSPATH: /usr/local/tomcat/bin/bootstrap.jar:/usr/local/tomcat/bin/tomcat-juli.jar
# 3. 查看 tomcat 容器状态
$ docker ps -a
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
0f2b3fcdd257 feisky/tomcat:8 "catalina.sh run" 2 minutes ago Exited (137) About a minute ago tomcat
# 显示容器状态，jq用来格式化json输出
$ docker inspect tomcat -f '{{json .State}}' | jq
{
"Status": "exited",
"Running": false,
"Paused": false,
"Restarting": false,
"OOMKilled": true,
"Dead": false,
"Pid": 0,
"ExitCode": 137,
"Error": "",
...
}
|
上面列示的命令是我们查看容器服务常用的命令。显然容器已经被 OOMKilled 了。问题是我们为 tomcat 分配了 512M 内存，大于 tomcat 应用所需的内存256M(容器内的 tomcat 程序只申请了一个 256M 的数组)，为什么容器会 OOMKilled 呢？
1.3 dmesg 查看 OOM 异常
系统会把相关的 OOM 信息，记录到日志中，通过 dmesg 命令我们可以定位 OOM 的异常信息:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
|
$ dmesg
[193038.106393] java invoked oom-killer: gfp_mask=0x14000c0(GFP_KERNEL), nodemask=(null), order=0, oom_score_adj=0
[193038.106396] java cpuset=0f2b3fcdd2578165ea77266cdc7b1ad43e75877b0ac1889ecda30a78cb78bd53 mems_allowed=0
[193038.106402] CPU: 0 PID: 27424 Comm: java Tainted: G OE 4.15.0-1037 #39-Ubuntu
[193038.106404] Hardware name: Microsoft Corporation Virtual Machine/Virtual Machine, BIOS 090007 06/02/2017
[193038.106405] Call Trace:
[193038.106414] dump_stack+0x63/0x89
[193038.106419] dump_header+0x71/0x285
[193038.106422] oom_kill_process+0x220/0x440
[193038.106424] out_of_memory+0x2d1/0x4f0
[193038.106429] mem_cgroup_out_of_memory+0x4b/0x80 # 内存超 cgroups 限制
[193038.106432] mem_cgroup_oom_synchronize+0x2e8/0x320
[193038.106435] ? mem_cgroup_css_online+0x40/0x40
[193038.106437] pagefault_out_of_memory+0x36/0x7b
[193038.106443] mm_fault_error+0x90/0x180
[193038.106445] __do_page_fault+0x4a5/0x4d0
[193038.106448] do_page_fault+0x2e/0xe0
[193038.106454] ? page_fault+0x2f/0x50
[193038.106456] page_fault+0x45/0x50
[193038.106459] RIP: 0033:0x7fa053e5a20d
[193038.106460] RSP: 002b:00007fa0060159e8 EFLAGS: 00010206
[193038.106462] RAX: 0000000000000000 RBX: 00007fa04c4b3000 RCX: 0000000009187440
[193038.106463] RDX: 00000000943aa440 RSI: 0000000000000000 RDI: 000000009b223000
[193038.106464] RBP: 00007fa006015a60 R08: 0000000002000002 R09: 00007fa053d0a8a1
[193038.106465] R10: 00007fa04c018b80 R11: 0000000000000206 R12: 0000000100000768
[193038.106466] R13: 00007fa04c4b3000 R14: 0000000100000768 R15: 0000000010000000
[193038.106468] Task in /docker/0f2b3fcdd2578165ea77266cdc7b1ad43e75877b0ac1889ecda30a78cb78bd53 killed as a result of limit of /docker/0f2b3fcdd2578165ea77266cdc7b1ad43e75877b0ac1889ecda30a78cb78bd53
[193038.106478] memory: usage 524288kB, limit 524288kB, failcnt 77
[193038.106480] memory+swap: usage 0kB, limit 9007199254740988kB, failcnt 0
[193038.106481] kmem: usage 3708kB, limit 9007199254740988kB, failcnt 0
[193038.106481] Memory cgroup stats for /docker/0f2b3fcdd2578165ea77266cdc7b1ad43e75877b0ac1889ecda30a78cb78bd53: cache:0KB rss:520580KB rss_huge:450560KB shmem:0KB mapped_file:0KB dirty:0KB writeback:0KB inactive_anon:0KB active_anon:520580KB inactive_file:0KB active_file:0KB unevictable:0KB
[193038.106494] [ pid ] uid tgid total_vm rss pgtables_bytes swapents oom_score_adj name
[193038.106571] [27281] 0 27281 1153302 134371 1466368 0 0 java
[193038.106574] Memory cgroup out of memory: Kill process 27281 (java) score 1027 or sacrifice child
[193038.148334] Killed process 27281 (java) total-vm:4613208kB, anon-rss:517316kB, file-rss:20168kB, shmem-rss:0kB
[193039.607503] oom_reaper: reaped process 27281 (java), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
|
total-vm:4613208kB, anon-rss:517316kB, file-rss:20168kB 表示总的虚拟内存，匿名页常驻内存和页缓存。为什么 Tomcat 会申请这么多的堆内存呢？
1.4 JVM 配置问题
JVM 根据系统的内存总量，来自动管理堆内存，不明确配置的话，堆内存的默认限制是物理内存的四分之一。
1
2
3
4
5
6
7
8
9
10
11
|
# 重新启动容器
$ docker rm -f tomcat
$ docker run --name tomcat --cpus 0.1 -m 512M -p 8080:8080 -itd feisky/tomcat:8
# 查看堆内存，注意单位是字节
$ docker exec tomcat java -XX:+PrintFlagsFinal -version | grep HeapSize
uintx ErgoHeapSizeLimit = 0 {product}
uintx HeapSizePerGCThread = 87241520 {product}
uintx InitialHeapSize := 132120576 {product}
uintx LargePageHeapSizeThreshold = 134217728 {product}
uintx MaxHeapSize := 2092957696 {product}
|
可以看到，初始堆内存的大小（InitialHeapSize）是 126MB，而最大堆内存则是 1.95GB，这可比容器限制的 512 MB 大多了。
之所以会这么大，其实是因为，容器内部看不到 Docker 为它设置的内存限制。虽然我们限制了容器的最大内存 512M，但是，从容器内部看到的限制，却并不是 512M。
1
2
3
4
|
$ docker exec tomcat free -m
total used free shared buff/cache available
Mem: 7977 521 1941 0 5514 7148
Swap: 0 0 0
|
问题找到了，现在只要给 JVM 正确配置内存限制为 512M 就可以了。
1
2
3
4
|
# 删除问题容器
$ docker rm -f tomcat
# 运行新的容器
$ docker run --name tomcat --cpus 0.1 -m 512M -e JAVA_OPTS='-Xmx512m -Xms512m' -p 8080:8080 -itd feisky/tomcat:8
|
在 Docker 容器中运行 Java 应用，一定要确保，在设置容器资源限制的同时，配置好 JVM 的资源选项（比如堆内存等）。当然，如果你可以升级 Java 版本，那么升级到 Java 10 ，就可以自动解决类似问题了。
1.5 CPU 限制问题
现在我们重新测试，看看 tomcat 服务是否已经正常:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
|
# 请求 tomcat 服务
$ for ((i=0;i<30;i++)); do curl localhost:8080; sleep 1; done
curl: (56) Recv failure: Connection reset by peer
curl: (56) Recv failure: Connection reset by peer
Hello, wolrd!
Hello, wolrd!
Hello, wolrd!
# 查看容器日志
$ docker logs -f tomcat
...
18-Feb-2019 12:52:00.823 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/manager]
18-Feb-2019 12:52:01.422 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/manager] has finished in [598] ms
18-Feb-2019 12:52:01.920 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
18-Feb-2019 12:52:02.323 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["ajp-nio-8009"]
18-Feb-2019 12:52:02.523 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 22798 ms
|
日志显示 tomcat 启动过程，居然需要 22 秒。那么 tomcat 启动过程到底慢在哪呢？top 应该是我们很自然想到的第一个命令，但是我们需要查看的仅仅是 tomcat 服务，所以我们可以使用 pidstat 命令。
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
|
# 删除旧容器
$ docker rm -f tomcat
# 运行新容器
$ docker run --name tomcat --cpus 0.1 -m 512M -e JAVA_OPTS='-Xmx512m -Xms512m' -p 8080:8080 -itd feisky/tomcat:8
# 查询新容器中进程的Pid
$ PID=$(docker inspect tomcat -f '{{.State.Pid}}')
# 执行 pidstat
$ pidstat -t -p $PID 1
12:59:28 UID TGID TID %usr %system %guest %wait %CPU CPU Command
12:59:29 0 29850 - 10.00 0.00 0.00 0.00 10.00 0 java
12:59:29 0 - 29850 0.00 0.00 0.00 0.00 0.00 0 |__java
12:59:29 0 - 29897 5.00 1.00 0.00 86.00 6.00 1 |__java
...
12:59:29 0 - 29905 3.00 0.00 0.00 97.00 3.00 0 |__java
12:59:29 0 - 29906 2.00 0.00 0.00 49.00 2.00 1 |__java
12:59:29 0 - 29908 0.00 0.00 0.00 45.00 0.00 0 |__java
|
输出显示等待运行的使用率（%wait）非常高，这说明，这些线程大部分时间都在等待调度，而不是真正的运行。原因很简单，因为我们设置了 --cpus 0.1 的限制。所以放开 CPU 限制即可解决 tomcat 启动慢的问题。
在容器云的环境，我们通常都要预先评估应用程序的性能，然后据此设置容器的资源限制。没有资源限制，意味着容器可以占用整个系统的资源。这样，一旦任何应用程序发生异常，就可能拖垮整个环境。