一、上節回顧
不知不覺，我們已經學完了整個專欄的四大基礎模塊，即 CPU、內存、文件系統和磁盤 I/O、以及網絡的性能分析和優化。相信你已經掌握了這些基礎模塊的基本分析、定位思路，並熟悉了相
關的優化方法。
接下來，我們將進入最后一個重要模塊—— 綜合實戰篇。這部分實戰內容，也將是我們對前面所學知識的復習和深化。
我們都知道，隨着 Kubernetes、Docker 等技術的普及，越來越多的企業，都已經走上了應用程序容器化的道路。我相信，你在了解學習這些技術的同時，一定也聽說過不少，基於 Docker 的
微服務架構帶來的各種優勢，比如：
- 使用 Docker ，把應用程序以及相關依賴打包到鏡像中后，部署和升級更快捷；把傳統的單體應用拆分成多個更小的微服務應用后，
- 每個微服務的功能都更簡單，並且可以單獨管理和維護；
- 每個微服務都可以根據需求橫向擴展。即使發生故障，也只是局部服務不可用，而不像以前那樣，導致整個服務不可用
不過，任何技術都不是銀彈。這些新技術，在帶來諸多便捷功能之外，也帶來了更高的復雜性，比如性能降低、架構復雜、排錯困難等等。
今天，我就通過一個 Tomcat 案例，帶你一起學習，如何分析應用程序容器化后的性能問題。
二、案例准備
今天的案例，我們只需要一台虛擬機。還是基於 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 用戶。
如果安裝過程有問題，你可以先上網搜索解決，實在解決不了的，記得在留言區向我提問
到這里，准備工作就完成了。接下來，我們正式進入操作環節。
三、案例分析
我們今天要分析的案例，是一個 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
顯然，在我的機器中，鏡像已存在，所以就不需要再次下載，直接返回成功就可以了。
1、發現問題
接着，在終端二中使用 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 響應一次請求后，就再也不響應了。
2、分析過程
這是怎么回事呢？我們回到終端一中，觀察 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 進程
退出了。
1、究竟是哪種情況呢？這就需要我們進一步確認了。
我們可以在終端一中，執行下面的命令，查看容器的狀態：
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 殺死了。
2、為什么內存會不足呢？
我們前面提到過，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 容器的內存主要用在了匿名內存中，而匿名內存，其實就是主動申請分配的堆內存。
3、為什么 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 看看。
4、雖然 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 后再試試。
5、為什么 CPU 使用率這么低，線程的大部分時間還要等待 CPU 呢？
為什么 CPU 使用率這么低，線程的大部分時間還要等待 CPU 呢？由於這個現象因 Docker 而起，自然的，你應該想到，這可能是因為 Docker 為容器設置了限制。
再回顧一下，案例開始時容器的啟動命令。我們用 --cpus 0.1 ，為容器設置了 0.1 個 CPU 的限制，也就是 10% 的 CPU。這里也就可以解釋，為什么 java 進程只有 10% 的 CPU 使用率，也
會大部分時間都在等待了。
3、解決問題
找出原因，最后的優化也就簡單了，把 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）等，讓容器的性能分析更加復雜。如果你需要分析容器性能，
別忘了考慮它們對性能的影響。