Linux性能優化實戰學習筆記：第四十六講

1、上節回顧

不知不覺，咱們已經學完了整個專欄的四大基礎模塊，即 CPU、內存、文件系統和磁盤 I/O、以及網絡的性能分析和優化。相信你已經掌握了這些基礎模塊的基本分析、定位思路，並熟悉了相
關的優化方法。

接下來，咱們將進入最後一個重要模塊—— 綜合實戰篇。這部分實戰內容，也將是咱們對前面所學知識的複習和深化。

咱們都知道，隨着 Kubernetes、Docker 等技術的普及，愈來愈多的企業，都已經走上了應用程序容器化的道路。我相信，你在瞭解學習這些技術的同時，必定也據說過很多，基於 Docker 的
微服務架構帶來的各類優點，好比：

• 使用 Docker ，把應用程序以及相關依賴打包到鏡像中後，部署和升級更快捷；把傳統的單體應用拆分紅多個更小的微服務應用後，
• 每一個微服務的功能都更簡單，而且能夠單獨管理和維護；
• 每一個微服務均可以根據需求橫向擴展。即便發生故障，也只是局部服務不可用，而不像之前那樣，致使整個服務不可用

不過，任何技術都不是銀彈。這些新技術，在帶來諸多便捷功能以外，也帶來了更高的複雜性，好比性能下降、架構複雜、排錯困難等等。

今天，我就經過一個 Tomcat 案例，帶你一塊兒學習，如何分析應用程序容器化後的性能問題。

2、案例準備

今天的案例，咱們只須要一臺虛擬機。仍是基於 Ubuntu 18.04，一樣適用於其餘的 Linux 系統。我使用的案例環境以下所示：

機器配置：2 CPU，8GB 內存。
預先安裝 docker、curl、jq、pidstat 等工具，如 apt install docker.io curl jq sysstat

其中，jq 工具專門用來在命令行中處理 json。爲了更好的展現 json 數據，咱們用這個工具，來格式化 json 輸出。

你須要打開兩個終端，登陸到同一臺虛擬機中，並安裝上述工具。

注意，如下全部命令都默認以 root 用戶運行，若是你用普通用戶身份登錄系統，請運行 sudosu root 命令切換到 root 用戶。

若是安裝過程有問題，你能夠先上網搜索解決，實在解決不了的，記得在留言區向我提問

到這裏，準備工做就完成了。接下來，咱們正式進入操做環節。

3、案例分析

咱們今天要分析的案例，是一個 Tomcat 應用。Tomcat 是 Apache 基金會旗下，Jakarta 項目開發的輕量級應用服務器，它基於 Java 語言開發。Docker 社區也維護着 Tomcat 的官方鏡像，
你能夠直接使用這個鏡像，來啓動一個 Tomcat 應用。

爲了方便你運行，我已經將它打包成了一個 Docker 鏡像 feisky/tomcat:8，並推送到了 DockerHub 中。你能夠直接按照下面的步驟來運行它。

咱們的案例，也基於 Tomcat 的官方鏡像構建，其核心邏輯很簡單，就是分配一點兒內存，並輸出 「Hello, world!」。

<%
byte data[] = new byte[256*1024*1024];
out.println("Hello, wolrd!");
%>

爲了方便你運行，我已經將它打包成了一個 Docker 鏡像 feisky/tomcat:8，並推送到了 DockerHub 中。你能夠直接按照下面的步驟來運行它。

在終端一中，執行下面的命令，啓動 Tomcat 應用，並監聽 8080 端口。若是一切正常，你應該能夠看到以下的輸出：

# -m 表示設置內存爲 512MB
$ docker run --name tomcat --cpus 0.1 -m 512M -p 8080:8080 -itd feisky/tomcat:8
Unable to find image 'feisky/tomcat:8' locally
8: Pulling from feisky/tomcat
741437d97401: Pull complete
...
22cd96a25579: Pull complete
Digest: sha256:71871cff17b9043842c2ec99f370cc9f1de7bc121cd2c02d8e2092c6e268f7e2
Status: Downloaded newer image for feisky/tomcat:8
WARNING: Your kernel does not support swap limit capabilities or the cgroup is not mounted. Memory limited without swap.
2df259b752db334d96da26f19166d662a82283057411f6332f3cbdbcab452249

從輸出中，你能夠看到，docker run 命令，會自動拉取鏡像並啓動容器。
這裏順便提一下，以前不少同窗留言問，到底要怎麼下載 Docker 鏡像。其實，上面的 dockerrun，就是自動下載鏡像到本地後，纔開始運行的。

因爲 Docker 鏡像分多層管理，因此在下載時，你會看到每層的下載進度。除了像 docker run這樣自動下載鏡像外，你也能夠分兩步走，先下載鏡像，而後再運行容器。

好比，你能夠先運行下面的 docker pull 命令，下載鏡像：

docker pull feisky/tomcat:8
8: Pulling from feisky/tomcat
Digest: sha256:71871cff17b9043842c2ec99f370cc9f1de7bc121cd2c02d8e2092c6e268f7e2
Status: Image is up to date for feisky/tomcat:8

顯然，在個人機器中，鏡像已存在，因此就不須要再次下載，直接返回成功就能夠了。

一、發現問題

接着，在終端二中使用 curl，訪問 Tomcat 監聽的 8080 端口，確認案例已經正常啓動：

curl localhost:8080
curl: (56) Recv failure: Connection reset by peer

不過，很不幸，curl 返回了 「Connection reset by peer」 的錯誤，說明 Tomcat 服務，並不能正常響應客戶端請求

是否是 Tomcat 啓動出問題了呢？咱們切換到終端一中，執行 docker logs 命令，查看容器的日誌。這裏注意，須要加上 -f 參數，表示跟蹤容器的最新日誌輸出：

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

從這兒你能夠看到，Tomcat 容器只打印了環境變量，尚未應用程序初始化的日誌。也就是說，Tomcat 還在啓動過程當中，這時候去訪問它，固然沒有響應。

爲了觀察 Tomcat 的啓動過程，咱們在終端一中，繼續保留 docker logs -f 命令，並在終端二中執行下面的命令，屢次嘗試訪問 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!
curl: (52) Empty reply from server
curl: (7) Failed to connect to localhost port 8080: Connection refused
curl: (7) Failed to connect to localhost port 8080: Connection refused

觀察一下子，能夠看到，一段時間後，curl 終於給出了咱們想要的結果 「Hello, wolrd!」。可是，隨後又出現了 「Empty reply from server」 ，和一直持續的 「Connection refused」 錯
誤。換句話說，Tomcat 響應一次請求後，就不再響應了。

二、分析過程

這是怎麼回事呢？咱們回到終端一中，觀察 Tomcat 的日誌，看看能不能找到什麼線索。從終端一中，你應該能夠看到下面的輸出：

18-Feb-2019 12:43:32.719 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/docs]
18-Feb-2019 12:43:33.725 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/docs] has finished in [1,006] ms
18-Feb-2019 12:43:33.726 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/manager]
18-Feb-2019 12:43:34.521 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/manager] has finished in [795] ms
18-Feb-2019 12:43:34.722 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
18-Feb-2019 12:43:35.319 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["ajp-nio-8009"]
18-Feb-2019 12:43:35.821 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 24096 ms
root@ubuntu:~#

從內容上能夠看到，Tomcat 在啓動 24s 後完成初始化，而且正常啓動。從日誌上來看，沒有什麼問題。

不過，細心的你確定注意到了最後一行，明顯是回到了 Linux 的 SHELL 終端中，而沒有繼續等待 Docker 輸出的容器日誌。

輸出從新回到 SHELL 終端，一般表示上一個命令已經結束。而咱們的上一個命令，是 dockerlogs -f 命令。那麼，它的退出就只有兩種可能了，要麼是容器退出了，要麼就是 dockerd 進程
退出了。

一、到底是哪一種狀況呢？這就須要咱們進一步確認了。

咱們能夠在終端一中，執行下面的命令，查看容器的狀態：

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

你會看到，容器處於 Exited 狀態，說明是第一種狀況，容器已經退出。不過爲何會這樣呢？顯然，在前面容器的日誌裏，咱們並無發現線索，那就只能從 Docker 自己入手了。

咱們能夠調用 Docker 的 API，查詢容器的狀態、退出碼以及錯誤信息，而後肯定容器退出的緣由。這些能夠經過 docker inspect 命令來完成，好比，你能夠繼續執行下面的命令，經過 -f 選
項設置只輸出容器的狀態：

# 顯示容器狀態，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": "",
  ...
}

實際測試截圖以下：

此次你能夠看到，容器已經處於 exited 狀態，OOMKilled 是 true，ExitCode 是 137。這其中，OOMKilled 表示容器被 OOM 殺死了。

二、爲何內存會不足呢？

咱們前面提到過，OOM 表示內存不足時，某些應用會被系統殺死。但是，爲何內存會不足呢？咱們的應用分配了 256 MB 的內存，而容器啓動時，明明經過 -m 選項，設置了 512 MB 的

內存，按說應該是足夠的。

到這裏，我估計你應該還記得，當 OOM 發生時，系統會把相關的 OOM 信息，記錄到日誌中。

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
[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

實際測試代碼以下：

[  871.858437] java invoked oom-killer: gfp_mask=0xcc0(GFP_KERNEL), order=0, oom_score_adj=0
[  871.858445] Call Trace:
[  871.858455]  dump_stack+0x63/0x88
[  871.858459]  dump_header+0x56/0x310
[  871.858472]  mem_cgroup_out_of_memory+0xb9/0xd0
[  871.858475]  try_charge+0x6e3/0x760
[  871.858478]  ? __alloc_pages_nodemask+0x16c/0x320
[  871.858482]  mem_cgroup_try_charge+0x8c/0x1e0
[  871.858484]  mem_cgroup_try_charge_delay+0x22/0x50
[  871.858488]  do_anonymous_page+0x11a/0x650
[  871.858491]  __handle_mm_fault+0xc1d/0xe80
[  871.858495]  ? __switch_to_asm+0x40/0x70
[  871.858498]  handle_mm_fault+0x102/0x220
[  871.858502]  __do_page_fault+0x1f9/0x480
[  871.858505]  do_page_fault+0x37/0x140
[  871.858510]  ? page_fault+0x8/0x30
[  871.858513]  page_fault+0x1e/0x30
[  871.858516] RIP: 0033:0x7f965c14620d
[  871.858519] Code: 01 00 00 48 83 fa 40 77 77 c5 fe 7f 44 17 e0 c5 fe 7f 07 c5 f8 77 c3 66 0f 1f 44 00 00 c5 f8 77 48 89 d1 40 0f b6 c6 48 89 fa <f3> aa 48 89 d0 c3 0f 1f 00 66 2e 0f 1f 84 00 00 00 00 00 48 39 d1
[  871.858520] RSP: 002b:00007f96120bb9e8 EFLAGS: 00010206
[  871.858522] RAX: 0000000000000000 RBX: 00007f965441e800 RCX: 000000000959d570
[  871.858523] RDX: 00000000b4933570 RSI: 0000000000000000 RDI: 00000000bb396000
[  871.858524] RBP: 00007f96120bba60 R08: 0000000002000002 R09: 00007f965bff68a1
[  871.858525] R10: 00007f9654018b80 R11: 0000000000000206 R12: 0000000100000768
[  871.858526] R13: 00007f965441e800 R14: 0000000100000768 R15: 0000000010000000
[  871.858530] memory: usage 524248kB, limit 524288kB, failcnt 44403
[  871.858531] memory+swap: usage 1048576kB, limit 1048576kB, failcnt 27
[  871.858532] kmem: usage 5460kB, limit 9007199254740988kB, failcnt 0
[  871.858532] Memory cgroup stats for /docker/65cbfee83fc3f2edbea65c31fe66ca16b602c2e5fb156ca8123971e29e69f046: cache:0KB rss:518620KB rss_huge:8192KB shmem:0KB mapped_file:0KB dirty:132KB writeback:0KB swap:524304KB inactive_anon:259508KB active_anon:259268KB inactive_file:0KB active_file:0KB unevictable:0KB
[  871.858546] Tasks state (memory values in pages):
[  871.858546] [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
[  871.858744] [   9974]     0  9974  1151709   118643  2502656   146642             0 java
[  871.858749] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=65cbfee83fc3f2edbea65c31fe66ca16b602c2e5fb156ca8123971e29e69f046,mems_allowed=0,oom_memcg=/docker/65cbfee83fc3f2edbea65c31fe66ca16b602c2e5fb156ca8123971e29e69f046,task_memcg=/docker/65cbfee83fc3f2edbea65c31fe66ca16b602c2e5fb156ca8123971e29e69f046,task=java,pid=9974,uid=0
[  871.860229] Memory cgroup out of memory: Killed process 9974 (java) total-vm:4606836kB, anon-rss:454480kB, file-rss:20092kB, shmem-rss:0kB
[  871.934438] oom_reaper: reaped process 9974 (java), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
[  872.151156] vethab42650: renamed from eth0
[  872.177935] docker0: port 1(vethaff12d5) entered disabled state
[  872.178590] docker0: port 1(vethaff12d5) entered disabled state
[  872.181224] device vethaff12d5 left promiscuous mode
[  872.181230] docker0: port 1(vethaff12d5) entered disabled state

因此，接下來，咱們能夠在終端中執行 dmesg 命令，查看系統日誌，並定位 OOM 相關的日誌：

從 dmesg 的輸出，你就能夠看到很詳細的 OOM 記錄了。你應該能夠看到下面幾個關鍵點。

• 第一，被殺死的是一個 java 進程。從內核調用棧上的 mem_cgroup_out_of_memory 能夠看出，它是由於超過 cgroup 的內存限制，而被 OOM 殺死的。
• 第二，java 進程是在容器內運行的，而容器內存的使用量和限制都是 512M（524288kB）。目前使用量已經達到了限制，因此會致使 OOM。
• 第三，被殺死的進程，PID 爲 27281，虛擬內存爲 4.3G（total-vm:4613208kB），匿名內存爲 505M（anon-rss:517316kB），頁內存爲 19M（20168kB）。換句話說，匿名內存是主要的內存佔用。並且，匿名內存加上頁內存，總共是 524M，已經超過了 512M 的限制。

綜合這幾點，能夠看出，Tomcat 容器的內存主要用在了匿名內存中，而匿名內存，其實就是主動申請分配的堆內存。

三、爲何 Tomcat 會申請這麼多的堆內存呢？

不過，爲何 Tomcat 會申請這麼多的堆內存呢？要知道，Tomcat 是基於 Java 開發的，因此應該不難想到，這極可能是 JVM 堆內存配置的問題。

咱們知道，JVM 根據系統的內存總量，來自動管理堆內存，不明確配置的話，堆內存的默認限制是物理內存的四分之一。不過，前面咱們已經限制了容器內存爲 512 M，java 的堆內存究竟是
多少呢？

咱們繼續在終端中，執行下面的命令，從新啓動 tomcat 容器，並調用 java 命令行來查看堆內存大小：

# 從新啓動容器
$ 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 爲它設置的內存限制。雖然在啓動容器時，咱們經過 -m 512M 選項，給容器設置了 512M 的內存限制。但實際上，從容器內部看到的
限制，卻並非 512M。

咱們在終端中，繼續執行下面的命令：

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 就能夠了。

好比，你能夠執行下面的命令，經過環境變量 JAVA_OPTS=’-Xmx512m -Xms512m’ ，把JVM 的初始內存和最大內存都設爲 512MB：

# 刪除問題容器
$ 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

接着，再切換到終端二中，從新在循環中執行 curl 命令，查看 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!

能夠看到，剛開始時，顯示的仍是 「Connection reset by peer」 錯誤。不過，稍等一下子後，就是連續的 「Hello, wolrd!」 輸出了。這說明， Tomcat 已經正常啓動。

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

實際測試代碼以下：

23-Sep-2019 07:18:26.560 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/host-manager] has finished in [1,000] ms
23-Sep-2019 07:18:26.560 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/manager]
23-Sep-2019 07:18:27.362 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/manager] has finished in [802] ms
23-Sep-2019 07:18:28.062 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
23-Sep-2019 07:18:29.362 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["ajp-nio-8009"]
23-Sep-2019 07:18:31.064 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 36602 ms

這時，咱們切換回終端一，執行 docker logs 命令，查看 Tomcat 容器的日誌：

此次，Tomcat 也正常啓動了。不過，最後一行的啓動時間，彷佛比較刺眼。啓動過程，竟然須要 22 秒，這也太慢了吧。

因爲這個時間是花在容器啓動上的，要排查這個問題，咱們就要重啓容器，並藉助性能分析工具來分析容器進程。至於工具的選用，回顧一下咱們前面的案例，我以爲能夠先用 top 看看。

四、雖然 CPU 使用率（%CPU）很低，但等待運行的使用率（%wait）卻很是高

咱們切換到終端二中，運行 top 命令；而後再切換到終端一，執行下面的命令，重啓容器：

# 刪除舊容器
$ 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

接着，再切換到終端二，觀察 top 的輸出：

top
top - 12:57:18 up 2 days,  5:50,  2 users,  load average: 0.00, 0.02, 0.00
Tasks: 131 total,   1 running,  74 sleeping,   0 stopped,   0 zombie
%Cpu0  :  3.0 us,  0.3 sy,  0.0 ni, 96.6 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu1  :  5.7 us,  0.3 sy,  0.0 ni, 94.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  8169304 total,  2465984 free,   500812 used,  5202508 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  7353652 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
29457 root      20   0 2791736  73704  19164 S  10.0  0.9   0:01.61 java                         27349 root      20   0 1121372  96760  39340 S   0.3  1.2   4:20.82 dockerd
27376 root      20   0 1031760  43768  21680 S   0.3  0.5   2:44.47 docker-containe              29430 root      20   0    7376   3604   3128 S   0.3  0.0   0:00.01 docker-containe
    1 root      20   0   78132   9332   6744 S   0.0  0.1   0:16.12 systemd

從 top 的輸出，咱們能夠發現，

• 從系統總體來看，兩個 CPU 的使用率分別是 3% 和 5.7% ，都不算高，大部分仍是空閒的；可用內存還有 7GB（7353652 avail Mem），也很是充足。
• 具體到進程上，java 進程的 CPU 使用率爲 10%，內存使用 0.9%，其餘進程就都很低了。

這些指標都不算高，看起來都沒啥問題。不過，事實究竟如何呢？咱們還得繼續找下去。因爲java 進程的 CPU 使用率最高，因此要把它當成重點，繼續分析其性能狀況。

說到進程的性能分析工具，你必定也想起了 pidstat。接下來，咱們就用 pidstat 再來分析一下。咱們回到終端一中，執行 pidstat 命令：

# -t 表示顯示線程，-p 指定進程號
$ pidstat -t -p 29457 1
12:59:59      UID      TGID       TID    %usr %system  %guest   %wait    %CPU   CPU  Command
13:00:00        0     29457         -    0.00    0.00    0.00    0.00    0.00     0  java
13:00:00        0         -     29457    0.00    0.00    0.00    0.00    0.00     0  |__java
13:00:00        0         -     29458    0.00    0.00    0.00    0.00    0.00     1  |__java
...
13:00:00        0         -     29491    0.00    0.00    0.00    0.00    0.00     0  |__java

結果中，各類 CPU 使用率全是 0，看起來不對呀。再想一想，咱們有沒有漏掉什麼線索呢？對了，這時候容器啓動已經結束了，在沒有客戶端請求的狀況下，Tomcat 自己啥也不用作，CPU 使用
率固然是 0。

爲了分析啓動過程當中的問題，咱們須要再次重啓容器。繼續在終端一，按下 Ctrl+C 中止 pidstat命令；而後執行下面的命令，重啓容器。成功重啓後，拿到新的 PID，再從新運行 pidstat 命令：

# 刪除舊容器
$ 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

實際測試截圖以下：

 

 

仔細觀察此次的輸出，你會發現，雖然 CPU 使用率（%CPU）很低，但等待運行的使用率（%wait）卻很是高，最高甚至已經達到了 97%。這說明，這些線程大部分時間都在等待調度，
而不是真正的運行。

注：若是你看不到 %wait 指標，請先升級 sysstat 後再試試。

五、爲何 CPU 使用率這麼低，線程的大部分時間還要等待 CPU 呢？

爲何 CPU 使用率這麼低，線程的大部分時間還要等待 CPU 呢？因爲這個現象因 Docker 而起，天然的，你應該想到，這多是由於 Docker 爲容器設置了限制。

再回顧一下，案例開始時容器的啓動命令。咱們用 --cpus 0.1 ，爲容器設置了 0.1 個 CPU 的限制，也就是 10% 的 CPU。這裏也就能夠解釋，爲何 java 進程只有 10% 的 CPU 使用率，也
會大部分時間都在等待了。

三、解決問題

找出緣由，最後的優化也就簡單了，把 CPU 限制增大就能夠了。好比，你能夠執行下面的命令，將 CPU 限制增大到 1 ；而後再重啓，並觀察啓動日誌：

# 刪除舊容器
$ docker rm -f tomcat
# 運行新容器
$ docker run --name tomcat --cpus 1 -m 512M -e JAVA_OPTS='-Xmx512m -Xms512m' -p 8080:8080 -itd feisky/tomcat:8
# 查看容器日誌
$ docker logs -f tomcat
...
18-Feb-2019 12:54:02.139 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 2001 ms

實際測試代碼以下：

cal/tomcat/webapps/examples] has finished in [983] ms
23-Sep-2019 07:27:17.583 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/host-manager]
23-Sep-2019 07:27:17.673 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/host-manager] has finished in [89] ms
23-Sep-2019 07:27:17.673 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/manager]
23-Sep-2019 07:27:17.783 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/manager] has finished in [110] ms
23-Sep-2019 07:27:17.822 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
23-Sep-2019 07:27:17.899 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["ajp-nio-8009"]
23-Sep-2019 07:27:17.908 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 2807 ms

如今能夠看到，Tomcat 的啓動過程，只須要 2 秒就完成了，果真比前面的 22 秒快多了。

雖然咱們經過增大 CPU 的限制，解決了這個問題。不過再碰到相似問題，你可能會以爲這種方法太麻煩了。由於要設置容器的資源限制，還須要咱們預先評估應用程序的性能。顯然還有更簡
單的方法，好比說直接去掉限制，讓容器跑就是了。

不過，這種簡單方法，卻極可能帶來更嚴重的問題。沒有資源限制，就意味着容器能夠佔用整個系統的資源。這樣，一旦任何應用程序發生異常，都有可能拖垮整臺機器。

實際上，這也是在各大容器平臺上最多見的一個問題。一開始圖省事不設限，但當容器數量增加上來的時候，就會常常出現各類異常問題。最終查下來，可能就是由於某個應用資源使用太高，

致使整臺機器短時間內沒法響應。只有設置了資源限制，才能確保杜絕相似問題

小結

今天，我帶你學習了，如何分析容器化後應用程序性能降低的問題。

若是你在 Docker 容器中運行 Java 應用，必定要確保，在設置容器資源限制的同時，配置好JVM 的資源選項（好比堆內存等）。固然，若是你能夠升級 Java 版本，那麼升級到 Java 10 ，
就能夠自動解決相似問題了。

當碰到容器化的應用程序性能時，你依然可使用，咱們前面講過的各類方法來分析和定位。只不過要記得，容器化後的性能分析，跟前面內容稍微有些區別，好比下面這幾點。

容器自己經過 cgroups 進行資源隔離，因此，在分析時要考慮 cgroups 對應用程序的影響。容器的文件系統、網絡協議棧等跟主機隔離。雖然在容器外面，咱們也能夠分析容器的行爲，
不過有時候，進入容器的命名空間內部，可能更爲方便。

容器的運行可能還會依賴於其餘組件，好比各類網絡插件（好比 CNI）、存儲插件（好比CSI）、設備插件（好比 GPU）等，讓容器的性能分析更加複雜。若是你須要分析容器性能，別忘了考慮它們對性能的影響。