目錄
這篇文章是在公司做了不少的線上Java服務(wù)故障排查和優(yōu)化之后的一個(gè)總結(jié)，可以作為一個(gè)工具清單，在分析問題的時(shí)候需要有整體思路：全局觀，先從系統(tǒng)層面入手，大致定位方向（內(nèi)存，cpu，磁盤，網(wǎng)絡(luò)），然后再去分析具體的進(jìn)程。
內(nèi)存和cpu
內(nèi)存和cpu問題是出問題最多的一個(gè)點(diǎn)，因?yàn)橛行┟钊鐃op同時(shí)可以觀察到內(nèi)存和cpu所以放在一起。
top命令
常用參數(shù)： -H 打印具體的線程， -p 打印某個(gè)進(jìn)程 進(jìn)入后 按數(shù)字1 可以切換cpu的圖形看有幾個(gè)核
下面是我的測試環(huán)境shell:
top-14:28:49up7min,3users, load average:0.08,0.26,0.19Tasks:221total,2running,219sleeping,0stopped,0zombie %Cpu(s):5.1us,3.4sy,0.0ni,91.5id,0.0wa,0.0hi,0.0si,0.0st KiB Mem :985856total,81736free,646360used,257760buff/cache KiB Swap:2094076total,1915196free,178880used.141592avail Mem
我一般重點(diǎn)關(guān)注的指標(biāo)有：
%Cpu(s): 5.1 us, 3.4 sy, 0.0 wa
這里可以非常直觀的看到當(dāng)前cpu的負(fù)載情況，us用戶cpu占用時(shí)間，sy是系統(tǒng)調(diào)用cpu占用時(shí)間，wa是cpu等待io的時(shí)間，前面兩個(gè)比較直觀，但是第三個(gè)其實(shí)也很重要，如果wa很高，那么你就該重點(diǎn)關(guān)注下磁盤的負(fù)載了，尤其是像mysql這種服務(wù)器。
load average: 0.08, 0.26, 0.19
cpu任務(wù)隊(duì)列的負(fù)載，這個(gè)隊(duì)列包括正在運(yùn)行的任務(wù)和等待運(yùn)行的任務(wù)，三個(gè)數(shù)字分別是1分鐘、5分鐘和15分鐘的平均值。這個(gè)和cpu占用率一般是正相關(guān)的，反應(yīng)的是用戶代碼，如果超過了內(nèi)核數(shù)，表示系統(tǒng)已經(jīng)過載。也就是說如果你是8核，那么這個(gè)數(shù)字小于等于8的負(fù)載都是沒問題的，我看網(wǎng)上的建議一般這個(gè)值不要超過ncpu*2-2為好。
KiB Mem : 985856 total, 81736 free, 646360 used, 257760 buff/cache
內(nèi)存占用情況，total總內(nèi)存，free空余內(nèi)存， used已經(jīng)分配內(nèi)存，buff/cache塊設(shè)備和緩沖區(qū)占用的內(nèi)存，因?yàn)長inux的內(nèi)存分配，如果有剩余內(nèi)存，他就會將內(nèi)存用于cache，這樣可以較少磁盤的讀寫提高效率，如果有應(yīng)用申請內(nèi)存，buff/cache這部分內(nèi)存也是可用的，所以正真的剩余內(nèi)存應(yīng)該是free+buff/cache
swap
線上服務(wù)器一般都是禁用狀態(tài)，所以不用看這項(xiàng)。
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
這一欄主要是看進(jìn)程的詳情，重點(diǎn)是%CPU %MEM，上面看的是整個(gè)服務(wù)器的負(fù)載，這里是每個(gè)進(jìn)程的負(fù)載。還有看看S這個(gè)指標(biāo)，這個(gè)代碼了進(jìn)程的狀態(tài)，有時(shí)候有些進(jìn)程會出現(xiàn)T（暫停）這個(gè)狀態(tài)。
網(wǎng)絡(luò)
ss
netstat的高性能版，參數(shù)都基本一致
常用參數(shù)： -n 打印數(shù)字端口號 -t tcp連接 -l 監(jiān)聽端口 -a 所有端口 -p 進(jìn)程號 -s 打印統(tǒng)計(jì)信息
ss -s示例：
Total:1732(kernel1987) TCP:42373(estab1430, closed40910, orphaned2, synrecv0, timewait40906/0), ports1924Transport Total IP IPv6*1987- -? RAW1899UDP18117TCP1463503960
可以看到整體的連接情況，如timewait過高，連接數(shù)過高等情況
然后使用ss -ntap|grep 進(jìn)程號 or 端口號查看進(jìn)程的連接
ping
查看時(shí)延和丟包情況
mtr
查看丟包請求
磁盤
磁盤問題在mysql服務(wù)器中非常常見，很多時(shí)候mysql服務(wù)器的CPU不高但是卻出現(xiàn)慢查詢?nèi)罩撅j升，就是因?yàn)榇疟P出現(xiàn)了瓶頸。還有mysql的備份策略，如果沒有監(jiān)控磁盤空間，可能出現(xiàn)磁盤滿了服務(wù)不可用的現(xiàn)象。
iostat命令
常用參數(shù)： -k 用kb為單位 -d 監(jiān)控磁盤 -x顯示詳情 num count 每個(gè)幾秒刷新 顯示次數(shù)
這個(gè)是我查看磁盤負(fù)載的主要工具，也可以顯示cpu的負(fù)載，不過我一般用iostat -kdx 2 10,下面是我測試環(huán)境執(zhí)行情況：
root@ubuntu:~# iostat -kdx210Linux4.13.0-38-generic (ubuntu)11/18/2018_x86_64_ (1CPU) Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda24.75196.05121.669.752481.33961.2952.400.443.331.1230.950.516.71scd00.000.000.020.000.080.007.000.000.250.250.000.250.00
我一般重點(diǎn)關(guān)注的指標(biāo)有：
rkB/s和wkB/s: 分別對應(yīng)讀寫速度
avgqu-sz: 讀寫隊(duì)列的平均請求長度，可以類比top命令的load average
await r_await w_await: io請求的平均時(shí)間（毫秒），分別是讀寫，讀和寫三個(gè)平均值。這個(gè)時(shí)間都包括在隊(duì)列中等待的時(shí)間和實(shí)際處理讀寫請求的時(shí)間，還有svctm這個(gè)參數(shù)，他說的是實(shí)際處理讀寫請求的時(shí)間，照理來講w_await肯定是大于svctm的，但是我在線上看到有w_await小于svctm的情況，不知道是什么原因。我看iostat的man手動中說svctm已經(jīng)廢棄，所以一般我看的是這三個(gè)。
%util: 這個(gè)參數(shù)直觀的看磁盤的負(fù)載情況，我首先看的就是這個(gè)參數(shù)。和top的wa命令有關(guān)聯(lián)。
df
查看文件系統(tǒng)的容量
常用參數(shù)： -h 友好的單位 如Kb，Mb等
du
統(tǒng)計(jì)具體的文件大小
常用參數(shù)： -h 友好的單位 如Kb，Mb等 -s 總計(jì)，而不是進(jìn)入每個(gè)子目錄分別統(tǒng)計(jì)
場景：例如系統(tǒng)磁盤空間不足時(shí)，先通過df命令定位到具體的掛載目錄，在進(jìn)去掛載目錄后，使用
du -sh *查看各個(gè)文件或者子目錄的大小定位具體文件
這里還有l(wèi)s命令，可以通過加-h和-S（按大小排序）
iostat命令
常用參數(shù)： -k 用kb為單位 -d 監(jiān)控磁盤 -x顯示詳情 num count 每個(gè)幾秒刷新 顯示次數(shù)
這個(gè)是我查看磁盤負(fù)載的主要工具，也可以顯示cpu的負(fù)載，不過我一般用iostat -kdx 2 10,下面是我測試環(huán)境執(zhí)行情況：
root@ubuntu:~# iostat -kdx210Linux4.13.0-38-generic (ubuntu)11/18/2018_x86_64_ (1CPU) Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda24.75196.05121.669.752481.33961.2952.400.443.331.1230.950.516.71scd00.000.000.020.000.080.007.000.000.250.250.000.250.00
我一般重點(diǎn)關(guān)注的指標(biāo)有：
rkB/s和wkB/s: 分別對應(yīng)讀寫速度
avgqu-sz: 讀寫隊(duì)列的平均請求長度，可以類比top命令的load average
await r_await w_await: io請求的平均時(shí)間（毫秒），分別是讀寫，讀和寫三個(gè)平均值。這個(gè)時(shí)間都包括在隊(duì)列中等待的時(shí)間和實(shí)際處理讀寫請求的時(shí)間，還有svctm這個(gè)參數(shù)，他說的是實(shí)際處理讀寫請求的時(shí)間，照理來講w_await肯定是大于svctm的，但是我在線上看到有w_await小于svctm的情況，不知道是什么原因。我看iostat的man手動中說svctm已經(jīng)廢棄，所以一般我看的是這三個(gè)。
%util: 這個(gè)參數(shù)直觀的看磁盤的負(fù)載情況，我首先看的就是這個(gè)參數(shù)。和top的wa命令有關(guān)聯(lián)。
lsof
列出當(dāng)前系統(tǒng)打開文件，因?yàn)樵趌inux下一切皆是文件，連接，硬件等均被描述為文件，所以這個(gè)命令也十分有用。
常用參數(shù)：
-p 查看某個(gè)進(jìn)程的文件
直接加文件名 查看哪些進(jìn)程打開了文件
+d 目錄 查看哪些進(jìn)程打開了目錄以及下面的文件（不遞歸，+D是遞歸）
Sar
最后補(bǔ)充一個(gè)sar(System Activity Reporter)命令，如果系統(tǒng)沒有一個(gè)良好的監(jiān)控，那么這個(gè)命令對于排查問題是很好的補(bǔ)充，很多時(shí)候去排查問題的時(shí)候發(fā)現(xiàn)問題已經(jīng)沒了，可以通過這個(gè)命令查看系統(tǒng)的活動情況，比如各個(gè)時(shí)間段cpu情況，內(nèi)存情況。
常用參數(shù)：
-r 內(nèi)存信息
-q loader信息，運(yùn)行隊(duì)列情況
-u cpu信息
-W Swap換頁情況
/proc文件系統(tǒng)
/proc是個(gè)虛擬文件系統(tǒng)，是內(nèi)核的一些數(shù)據(jù)，很多l(xiāng)inux命令的都是通過解析/proc文件系統(tǒng)實(shí)現(xiàn)的，每個(gè)進(jìn)程都會有一個(gè)以pid為目錄名的子目錄存在，通過解析/proc下的進(jìn)程目錄可以得到很多進(jìn)程的設(shè)置信息和資源占用信息等。
這里簡單說個(gè)排查過的問題，當(dāng)時(shí)我們線上有個(gè)服務(wù)，正常ssh登錄的情況下,我們設(shè)置了ulimit中的open files為（進(jìn)程可打開的最大描述符數(shù)量）100000，但是有一次在服務(wù)的日志中發(fā)現(xiàn)有報(bào)錯說文件描述符不夠用。所以
java -XX:+PrintFlagsInitial 可以查看所以的jvm默認(rèn)參數(shù)，其中帶有manageable表示運(yùn)行時(shí)可以動態(tài)修改。
20:45 [root@centos]$ java -XX:+PrintFlagsInitial |grep manageable intx CMSAbortablePrecleanWaitMillis = 100 {manageable} intx CMSTriggerInterval = -1 {manageable} intx CMSWaitDuration = 2000 {manageable} bool HeapDumpAfterFullGC =false{manageable}boolHeapDumpBeforeFullGC=false{manageable}boolHeapDumpOnOutOfMemoryError=false{manageable}ccstrHeapDumpPath= {manageable} uintx MaxHeapFreeRatio = 70 {manageable} uintx MinHeapFreeRatio = 40 {manageable} bool PrintClassHistogram =false{manageable}boolPrintClassHistogramAfterFullGC=false{manageable}boolPrintClassHistogramBeforeFullGC=false{manageable}boolPrintConcurrentLocks=false{manageable}boolPrintGC=false{manageable}boolPrintGCDateStamps=false{manageable}boolPrintGCDetails=false{manageable}boolPrintGCID=false{manageable}boolPrintGCTimeStamps=false{manageable}
Java堆和垃圾收集器
java內(nèi)存結(jié)構(gòu)
堆內(nèi)存結(jié)構(gòu)：
java8元空間改動：
java 7種垃圾收集器：
常見搭配：
java8默認(rèn)：Parallel Scavenge和 Parallel Old
低延遲：ParNew和CMS
java8以后可以直接使用G1，參數(shù)比較簡單
ParNew
Serial的并行版本
Parallel Scavenge
注重的是吞吐量，吞吐量=運(yùn)行用戶代碼時(shí)間/(運(yùn)行用戶代碼時(shí)間+垃圾收集時(shí)間)，其具有自適應(yīng)的特性
控制最大垃圾收集停頓時(shí)間的-XX:MaxGCPauseMillis參數(shù)
MaxGCPauseMillis參數(shù)允許的值是一個(gè)大于0的毫秒數(shù)，收集器將盡力保證內(nèi)存回收花費(fèi)的時(shí)間不超過設(shè)定值。不過大家不要異想天開地認(rèn)為如果把這個(gè)參數(shù)的值設(shè)置得稍小一點(diǎn)就能使得系統(tǒng)的垃圾收集速度變得更快，GC停頓時(shí)間縮短是以犧牲吞吐量和新生代空間來換取的：系統(tǒng)把新生代調(diào)小一些，收集300MB新生代肯定比收集500MB快吧，這也直接導(dǎo)致垃圾收集發(fā)生得更頻繁一些，原來10秒收集一次、每次停頓100毫秒，現(xiàn)在變成5秒收集一次、每次停頓70毫秒。停頓時(shí)間的確在下降，但吞吐量也降下來了。
直接設(shè)置吞吐量大小的 -XX:GCTimeRatio參數(shù)
GCTimeRatio參數(shù)的值應(yīng)當(dāng)是一個(gè)大于0小于100的整數(shù)，也就是垃圾收集時(shí)間占總時(shí)間的比率。如果把此參數(shù)設(shè)置為19，那允許的最大GC時(shí)間就占總時(shí)間的5%（即1 /（1+19）），默認(rèn)值為99，就是允許最大1%（即1 /（1+99））的垃圾收集時(shí)間。
UseAdaptiveSizePolicy開關(guān)參數(shù)
-XX:+UseAdaptiveSizePolicy是一個(gè)開關(guān)參數(shù)，當(dāng)這個(gè)參數(shù)打開之后，就不需要手工指定新生代的大小（-Xmn）、Eden與Survivor區(qū)的比例（-XX:SurvivorRatio）、晉升老年代對象年齡（-XX:PretenureSizeThreshold）等細(xì)節(jié)參數(shù)了，虛擬機(jī)會根據(jù)當(dāng)前系統(tǒng)的運(yùn)行情況收集性能監(jiān)控信息，動態(tài)調(diào)整這些參數(shù)以提供最合適的停頓時(shí)間或最大的吞吐量，這種調(diào)節(jié)方式稱為GC自適應(yīng)的調(diào)節(jié)策略（GC Ergonomics）。
說說UseAdaptiveSizePolicy參數(shù)，加了這個(gè)參數(shù)-XX:SurvivorRatio會失效，所以有些人會發(fā)現(xiàn)新生代比例未如自己的預(yù)期，而UseAdaptiveSizePolicy有默認(rèn)是開啟的
CMS
并發(fā)垃圾收集器，注重的是時(shí)延，有分配擔(dān)保失敗的風(fēng)險(xiǎn)
CMS收集器的GC周期由6個(gè)階段組成。其中4個(gè)階段(名字以Concurrent開始的)與實(shí)際的應(yīng)用程序是并發(fā)執(zhí)行的，而其他2個(gè)階段需要暫停應(yīng)用程序線程。
初始標(biāo)記：為了收集應(yīng)用程序的對象引用需要暫停應(yīng)用程序線程，該階段完成后，應(yīng)用程序線程再次啟動。
并發(fā)標(biāo)記：從第一階段收集到的對象引用開始，遍歷所有其他的對象引用。
并發(fā)預(yù)清理：改變當(dāng)運(yùn)行第二階段時(shí)，由應(yīng)用程序線程產(chǎn)生的對象引用，以更新第二階段的結(jié)果。
重標(biāo)記：由于第三階段是并發(fā)的，對象引用可能會發(fā)生進(jìn)一步改變。因此，應(yīng)用程序線程會再一次被暫停以更新這些變化，并且在進(jìn)行實(shí)際的清理之前確保一個(gè)正確的對象引用視圖。這一階段十分重要，因?yàn)楸仨毐苊馐占饺员灰玫膶ο蟆?/p>
并發(fā)清理：所有不再被應(yīng)用的對象將從堆里清除掉。
并發(fā)重置：收集器做一些收尾的工作，以便下一次GC周期能有一個(gè)干凈的狀態(tài)。
-XX:CMSInitiatingOccupancyFraction=90 （jdk1.5默認(rèn)值68，1.6開始默認(rèn)值92，指設(shè)定CMS在對內(nèi)存占用率達(dá)到70%的時(shí)候開始GC(因?yàn)镃MS會有浮動垃圾,所以一般都較早啟動GC)
-XX:+UseCMSInitiatingOccupancyOnly 只是用設(shè)定的回收閾值(上面指定的70%),如果不指定,JVM僅在第一次使用設(shè)定值,后續(xù)則自動調(diào)整
-XX:+CMSScavengeBeforeRemark 在CMS GC前啟動一次ygc，目的在于減少old gen對ygc gen的引用，降低remark時(shí)的開銷
-XX:+CMSParallelRemarkEnabled 并發(fā)標(biāo)記
-XX:+ExplicitGCInvokesConcurrent命令JVM無論什么時(shí)候調(diào)用系統(tǒng)GC（system.gc()），都執(zhí)行CMS GC，而不是Full GC
-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses保證當(dāng)有系統(tǒng)GC調(diào)用時(shí)，永久代也被包括進(jìn)CMS垃圾回收的范圍內(nèi)
-XX：UseParNewGC 使用CMS時(shí)自動開啟，因?yàn)镃MS不能和Parallel Scavenge搭配使用
上面的參數(shù)都建議開啟，CMS需要注意的一個(gè)問題就是CMSInitiatingOccupancyFraction參數(shù)，這個(gè)參數(shù)直接影響CMS回收老年代的時(shí)機(jī)，需要結(jié)合自己的業(yè)務(wù)場景來調(diào)整，一般情況下應(yīng)該盡量設(shè)置大一點(diǎn)，但是有一個(gè)嚴(yán)重的問題，就是浮動垃圾的問題，如果CMS在并發(fā)收集的時(shí)候出現(xiàn)老年代不能存放晉升對象將直接進(jìn)行Full GC使用Serial Old垃圾收集器,所以不能一味追求最大化，如果老年代增長比較慢，那么可以設(shè)置的稍微較大些，如果增長比較快，可以從增大新生代，調(diào)低CMSInitiatingOccupancyFraction入手
最后在提下-XX:+DisableExplicitGC ：禁用顯示gc （system.gc()）這個(gè)參數(shù)，很多人因?yàn)閟ystem.gc()會導(dǎo)致Full gc而禁用顯示調(diào)用gc，但是這個(gè)參數(shù)最好不要禁用，現(xiàn)在很多服務(wù)端程序都使用了Nio，jvm為了減少內(nèi)存拷貝，采用了直接內(nèi)存，直接內(nèi)存屬于堆外內(nèi)存，java大多使用了Netty這個(gè)框架，他幫我們處理堆外內(nèi)存的回收，實(shí)現(xiàn)的機(jī)制就是通過調(diào)用system.gc()，發(fā)起Full Gc，F(xiàn)ull Gc會回收堆外內(nèi)存，如果將system.gc()禁用，則得等到Full Gc發(fā)生才能回收堆外內(nèi)存，很有可能出現(xiàn)堆外內(nèi)存占用過高影響系統(tǒng)性能或者因?yàn)閮?nèi)存不足被系統(tǒng)Kill的問題。
gc日志參數(shù)
-XX:+PrintGC 輸出GC日志
-XX:+PrintGCDetails 輸出GC的詳細(xì)日志
-XX:+PrintGCTimeStamps 輸出GC的時(shí)間戳（以基準(zhǔn)時(shí)間的形式）
-XX:+PrintGCDateStamps 輸出GC的時(shí)間戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）
-XX:+PrintHeapAtGC 在進(jìn)行GC的前后打印出堆的信息
-XX:+PrintGCApplicationStoppedTime // 輸出GC造成應(yīng)用暫停的時(shí)間
-Xloggc:../logs/gc.log 日志文件的輸出路徑
-XX:+PrintTenuringDistribution 打印新生代的年齡分布（這里需要注意，如果使用的是Parallel Scavenge，那么打印的時(shí)候是沒有年齡分布信息的）
-XX:+UseGCLogFileRotation 開啟日志輪換
-XX:NumberOfGCLogFiles=5 日志保留數(shù)量
-XX:GCLogFileSize=10m 每份日志保留大小
堆參數(shù)
-Xms 最小堆大小
-Xmx 最大堆大小
-Xmn 新生代大小
-XX:SurvivorRatio 新生代中Eden區(qū)與Survivor區(qū)的比例，默認(rèn)值為8
gc日志分析
ParNew Gc日志：
{HeapbeforeGCinvocations=4196(full3):parnewgenerationtotal1887488K,used1683093K[0x0000000640000000,0x00000006c0000000,0x00000006c0000000)edenspace1677824K,100%used[0x0000000640000000,0x00000006a6680000,0x00000006a6680000)fromspace209664K,2%used[0x00000006a6680000,0x00000006a6ba5430,0x00000006b3340000)tospace209664K,0%used[0x00000006b3340000,0x00000006b3340000,0x00000006c0000000)concurrentmark-sweepgenerationtotal4194304K,used1565111K[0x00000006c0000000,0x00000007c0000000,0x00000007c0000000)Metaspaceused59881K,capacity64953K,committed66588K,reserved1107968Kclassspaceused6615K,capacity7729K,committed8224K,reserved1048576K2019-10-29T23:48:00.181+0800:27966.548:[GC(AllocationFailure)2019-10-29T23:48:00.181+0800:27966.548:[ParNewDesiredsurvivorsize107347968bytes,newthreshold15(max15)-age 1:2287832bytes,2287832 total - age 2:132752bytes,2420584 total - age 3:102408bytes,2522992 total - age 4:125768bytes,2648760 total - age 5:145464bytes,2794224 total - age 6:82808bytes,2877032 total - age 7:104736bytes,2981768 total - age 8:79216bytes,3060984 total - age 9:89496bytes,3150480 total - age 10:81864bytes,3232344 total - age 11:91304bytes,3323648 total - age 12:78912bytes,3402560 total - age 13:80960bytes,3483520 total - age 14:91560bytes,3575080 total - age 15:78992bytes,3654072 total :1683093K->5343K(1887488K),0.0342117secs]3248204K->1570530K(6081792K),0.0343754secs] [Times:user=0.17sys=0.01,real=0.03secs]HeapafterGCinvocations=4197(full3):parnewgenerationtotal1887488K,used5343K[0x0000000640000000,0x00000006c0000000,0x00000006c0000000)edenspace1677824K,0%used[0x0000000640000000,0x0000000640000000,0x00000006a6680000)fromspace209664K,2%used[0x00000006b3340000,0x00000006b3877f50,0x00000006c0000000)tospace209664K,0%used[0x00000006a6680000,0x00000006a6680000,0x00000006b3340000)concurrentmark-sweepgenerationtotal4194304K,used1565186K[0x00000006c0000000,0x00000007c0000000,0x00000007c0000000)Metaspaceused59881K,capacity64953K,committed66588K,reserved1107968Kclassspaceused6615K,capacity7729K,committed8224K,reserved1048576K}
gc日志中打印了新生代，老年代和元空間等內(nèi)存信息，其中Times: user=0.02 sys=0.01, real=0.01 secs三個(gè)時(shí)間分別是用戶態(tài)的時(shí)間，內(nèi)核態(tài)的時(shí)間和墻鐘時(shí)間。墻鐘時(shí)間表示真正過去的時(shí)間，而用戶態(tài)和內(nèi)核態(tài)的時(shí)間則是乘了相應(yīng)的cpu核心數(shù)。
CMS GC日志：
2019-10-29T18:03:19.578+0800: 7285.945: [GC (CMS Initial Mark) [1 CMS-initial-mark: 3182477K(4194304K)] 3254261K(6081792K), 0.0044508 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 2019-10-29T18:03:19.582+0800: 7285.949: [CMS-concurrent-mark-start] 2019-10-29T18:03:20.812+0800: 7287.179: [CMS-concurrent-mark: 1.229/1.229 secs] [Times: user=3.86 sys=0.46, real=1.23 secs] 2019-10-29T18:03:20.812+0800: 7287.179: [CMS-concurrent-preclean-start] 2019-10-29T18:03:20.823+0800: 7287.190: [CMS-concurrent-preclean: 0.011/0.011 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] 2019-10-29T18:03:20.823+0800: 7287.190: [CMS-concurrent-abortable-preclean-start] {Heap before GC invocations=896 (full 3): par new generation total 1887488K, used 1747877K [0x0000000640000000, 0x00000006c0000000, 0x00000006c0000000) eden space 1677824K, 100% used [0x0000000640000000, 0x00000006a6680000, 0x00000006a6680000) from space 209664K, 33% used [0x00000006a6680000, 0x00000006aaae9780, 0x00000006b3340000) to space 209664K, 0% used [0x00000006b3340000, 0x00000006b3340000, 0x00000006c0000000) concurrent mark-sweep generation total 4194304K, used 3182477K [0x00000006c0000000, 0x00000007c0000000, 0x00000007c0000000) Metaspace used 60431K, capacity 66281K, committed 66588K, reserved 1107968K class space used 6828K, capacity 8138K, committed 8224K, reserved 1048576K 2019-10-29T18:03:25.649+0800: 7292.016: [GC (Allocation Failure) 2019-10-29T18:03:25.649+0800: 7292.016: [ParNew Desired survivor size 107347968 bytes, new threshold 15 (max 15) - age 1: 1362152 bytes, 1362152 total - age 3: 124920 bytes, 1487072 total - age 4: 115256 bytes, 1602328 total - age 5: 165000 bytes, 1767328 total - age 6: 99776 bytes, 1867104 total - age 7: 97728 bytes, 1964832 total - age 8: 94616 bytes, 2059448 total - age 9: 93176 bytes, 2152624 total - age 10: 111352 bytes, 2263976 total - age 11: 127800 bytes, 2391776 total - age 12: 85248 bytes, 2477024 total - age 13: 110984 bytes, 2588008 total - age 14: 101880 bytes, 2689888 total - age 15: 96288 bytes, 2786176 total : 1747877K->18163K(1887488K), 0.0364969 secs] 4930355K->3200776K(6081792K), 0.0366162 secs] [Times: user=0.17 sys=0.00, real=0.04 secs] Heap after GC invocations=897 (full 3): par new generation total 1887488K, used 18163K [0x0000000640000000, 0x00000006c0000000, 0x00000006c0000000) eden space 1677824K, 0% used [0x0000000640000000, 0x0000000640000000, 0x00000006a6680000) from space 209664K, 8% used [0x00000006b3340000, 0x00000006b44fcd88, 0x00000006c0000000) to space 209664K, 0% used [0x00000006a6680000, 0x00000006a6680000, 0x00000006b3340000) concurrent mark-sweep generation total 4194304K, used 3182613K [0x00000006c0000000, 0x00000007c0000000, 0x00000007c0000000) Metaspace used 60431K, capacity 66281K, committed 66588K, reserved 1107968K class space used 6828K, capacity 8138K, committed 8224K, reserved 1048576K } CMS: abort preclean due to time 2019-10-29T18:03:25.825+0800: 7292.192: [CMS-concurrent-abortable-preclean: 4.952/5.002 secs] [Times: user=10.51 sys=1.44, real=5.01 secs] 2019-10-29T18:03:25.826+0800: 7292.193: [GC (CMS Final Remark) [YG occupancy: 81039 K (1887488 K)]2019-10-29T18:03:25.826+0800: 7292.194: [Rescan (parallel) , 0.0142974 secs]2019-10-29T18:03:25.841+0800: 7292.208: [weak refs processing, 0.0019208 secs]2019-10-29T18:03:25.843+0800: 7292.210: [class unloading, 0.0230836 secs]2019-10-29T18:03:25.866+0800: 7292.233: [scrub symbol table, 0.0054818 secs]2019-10-29T18:03:25.871+0800: 7292.238: [scrub string table, 0.0707817 secs][1 CMS-remark: 3182613K(4194304K)] 3263652K(6081792K), 0.1182958 secs] [Times: user=0.17 sys=0.01, real=0.11 secs] 2019-10-29T18:03:25.946+0800: 7292.313: [CMS-concurrent-sweep-start] 2019-10-29T18:03:27.771+0800: 7294.138: [CMS-concurrent-sweep: 1.825/1.826 secs] [Times: user=3.98 sys=0.52, real=1.82 secs] 2019-10-29T18:03:27.771+0800: 7294.138: [CMS-concurrent-reset-start] 2019-10-29T18:03:27.781+0800: 7294.148: [CMS-concurrent-reset: 0.010/0.010 secs] [Times: user=0.02 sys=0.01, real=0.01 secs]
JVMTI介紹
JVM相關(guān)參數(shù)：
-agentlib:<庫名>[=<選項(xiàng)>] 加載本機(jī)代理庫<庫名>, 例如 -agentlib:jdwp 另請參閱 -agentlib:jdwp=help -agentpath:<路徑名>[=<選項(xiàng)>] 按完整路徑名加載本機(jī)代理庫 -javaagent:[=<選項(xiàng)>] 加載 Java 編程語言代理, 請參閱 java.lang.instrument
JVMTI(Java Virtual Machine Tool Interface)即指Java虛擬機(jī)工具接口，它是一套由虛擬機(jī)直接提供的 native 接口，通過這些接口，開發(fā)人員不僅調(diào)試在該虛擬機(jī)上運(yùn)行的 Java 程序，還能查看它們運(yùn)行的狀態(tài)，設(shè)置回調(diào)函數(shù)，控制某些環(huán)境變量(JMX)，從而優(yōu)化程序性能。Java Agent就是基于JVMTI的，所以眾多基于Java Agent的技術(shù)例如APM，遠(yuǎn)程調(diào)試，各種性能剖析同樣是基于這個(gè)技術(shù)。
JVMTI 接口：
JNIEXPORT jint JNICALLAgent_OnLoad(JavaVM *vm,char*options,void*reserved);JNIEXPORT jint JNICALLAgent_OnAttach(JavaVM* vm,char* options,void* reserved);JNIEXPORTvoidJNICALLAgent_OnUnload(JavaVM *vm);
-agentpath是c/c++編寫的動態(tài)庫，-agentlib和-javaagent是一個(gè)instrument的JVMTIAgent（linux下對應(yīng)的動態(tài)庫是libinstrument.so）。
Attach機(jī)制
Jvm提供一種jvm進(jìn)程間通信的能力，能讓一個(gè)進(jìn)程傳命令給另外一個(gè)進(jìn)程，并讓它執(zhí)行內(nèi)部的一些操作，比如說我們?yōu)榱俗屃硗庖粋€(gè)jvm進(jìn)程把線程dump出來，那么我們跑了一個(gè)jstack的進(jìn)程，然后傳了個(gè)pid的參數(shù)，告訴它要哪個(gè)進(jìn)程進(jìn)行線程dump。
Attach命令列表
staticAttachOperationFunctionInfo funcs[] = { {"agentProperties", get_agent_properties }, {"datadump", data_dump }, {"dumpheap", dump_heap }, {"load", JvmtiExport::load_agent_library }, {"properties", get_system_properties }, {"threaddump", thread_dump }, {"inspectheap", heap_inspection }, {"setflag", set_flag }, {"printflag", print_flag }, {"jcmd", jcmd }, {NULL,NULL} };
Attach流程：
Jstack源碼：
https://android.googlesource.com/platform/libcore/+/0ebbfbdbca73d6261a77183f68e1f3e56c339f9f/ojluni/src/main/java/sun/tools/jstack/JStack.java
查看java線程：
其中Siginal Dispatcher是處理進(jìn)程信號的線程，Attach Listener正式Attach機(jī)制處理線程。
java自帶工具
jps
查看Java進(jìn)程列表
常用參數(shù)：
-l: 輸出應(yīng)用程序主類完整package名稱或jar完整名稱
-m:輸出主函數(shù)傳入的參數(shù)
jmap
查看JVM堆的情況
常用參數(shù)：
-heap
-dump 這個(gè)命令還有兩個(gè)常用參數(shù)live 只dump存活對象，會導(dǎo)致GCfile=file dump文件名
示例：jmap -dump:live,file=heap.dump <pid>
這里有兩點(diǎn)，一方面需要注意live會導(dǎo)致GC，有時(shí)候在查問題的時(shí)候可能不是你預(yù)期的效果，一般查內(nèi)存問題時(shí)不加這個(gè)選項(xiàng)，另外dump文件如果比較大，可以先壓縮在傳回本地
jstack
查看JVM的堆棧情況，監(jiān)測死鎖等
這個(gè)命令比較簡單，一般不用加什么參數(shù)，有時(shí)候JVM沒響應(yīng)時(shí)可以加-F參數(shù)。一般這個(gè)命令可以結(jié)合top，在top定位到占用cpu高的線程后，在具體在Jstack打印的堆棧中查看線程，有時(shí)候也需要多次打印堆棧來進(jìn)行對比
jstat
查看JVM gc信息，觀察JVM的GC活動
常用參數(shù)： -gccause 這個(gè)參數(shù)包含了-gcutil的信息多了一個(gè)gc原因
示例： jstat -gccause <pid> 1000
11:19[supertool@y051]$jstat-gccause107111000 S0S1EOMCCSYGCYGCTFGCFGCTGCTLGCCGCC0.0021.2395.9969.8891.5682.621187 22.51140.14122.652AllocationFailureNoGC0.0021.2399.5169.8891.5682.621187 22.51140.14122.652AllocationFailureNoGC21.300.003.5169.8891.5682.621188 22.53040.14122.671AllocationFailureNoGC21.300.007.0269.8891.5682.621188 22.53040.14122.671AllocationFailureNoGC21.300.0010.1469.8891.5682.621188 22.53040.14122.671AllocationFailureNoGC21.300.0013.6269.8891.5682.621188 22.53040.14122.671AllocationFailureNoGC21.300.0016.7869.8891.5682.621188 22.53040.14122.671AllocationFailureNoGC
jinfo
查看設(shè)置的JVM參數(shù)和啟動時(shí)的命令行參數(shù)，還可以動態(tài)修改JVM參數(shù)
常用參數(shù)
-flags 查看jvm參數(shù)值
-sysprops 查看系統(tǒng)屬性值
示例：jinfo -flags 10711
Non-defaultVMflags:-XX:BiasedLockingStartupDelay=0-XX:CICompilerCount=4-XX:+CMSClassUnloadingEnabled -XX:CMSInitiatingOccupancyFraction=75-XX:+CMSParallelRemarkEnabled -XX:ErrorFile=null-XX:GCLogFileSize=10485760-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=null-XX:InitialHeapSize=1073741824-XX:MaxHeapSize=1073741824-XX:MaxNewSize=268435456-XX:MaxTenuringThreshold=15-XX:MinHeapDeltaBytes=196608-XX:NewSize=268435456-XX:NumberOfGCLogFiles=20-XX:OldPLABSize=16-XX:OldSize=805306368-XX:+PrintClassHistogram -XX:+PrintCommandLineFlags -XX:+PrintConcurrentLocks -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:StringTableSize=6000000-XX:+UseBiasedLocking -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseFastUnorderedTimeStamps -XX:+UseGCLogFileRotation -XX:+UseParNewGC Commandline:-XX:+UseBiasedLocking -XX:BiasedLockingStartupDelay=0-XX:+PrintCommandLineFlags -Xms1g -Xmx1g -Xmn256m -agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=5006-XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+CMSParallelRemarkEnabled -XX:CMSInitiatingOccupancyFraction=75-XX:+UseCMSInitiatingOccupancyOnly -Dfile.encoding=UTF-8-XX:MaxTenuringThreshold=15-XX:StringTableSize=6000000-XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution -XX:+PrintHeapAtGC -XX:+PrintClassHistogram -XX:+PrintConcurrentLocks -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=20-XX:GCLogFileSize=10m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/var/java/logs -XX:ErrorFile=/var/java/logs/jvm-error.log -Dlog4j.config.file=log4j_.properties -Dvertx.logger-delegate-factory-class-name=io.vertx.core.logging.Log4jLogDelegateFactory-Dvertx.options.maxEventLoopExecuteTime=100000000 -Dvertx.options.warningExceptionTime=300000000
JDPA(Java Platform Debugger Architecture)
java遠(yuǎn)程調(diào)試，需要jvm啟動時(shí)加參數(shù)：-agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=*:5005
遠(yuǎn)程調(diào)試非常有用，有時(shí)候測試環(huán)境很難復(fù)現(xiàn)時(shí)，可以用通過遠(yuǎn)程調(diào)試查看線程數(shù)據(jù)
jprofile
CPU性能分析
抽樣：每隔一段時(shí)間，獲取線程棧，分析各個(gè)棧上出現(xiàn)的方法的次數(shù)
優(yōu)點(diǎn)：性能高
缺點(diǎn)： 不適合做精確的分析
適用范圍：尋找程序的執(zhí)行熱點(diǎn)，cpu密集型
指令插入：使用增強(qiáng)的技術(shù)修改java class的字節(jié)碼，在函數(shù)的出入口增加埋點(diǎn)
優(yōu)點(diǎn)：數(shù)據(jù)準(zhǔn)確
缺點(diǎn)：導(dǎo)致jvm內(nèi)聯(lián)優(yōu)化失效，性能低
適用范圍：分析具體耗時(shí)路徑的各個(gè)執(zhí)行時(shí)間，io密集型
一般先使用抽樣在定位到大致的范圍，然后使用指令插入分析具體代碼執(zhí)行路徑中的耗時(shí)，jprofile可以通過過濾只對指定類進(jìn)行增強(qiáng)
Thread Status：選擇線程統(tǒng)計(jì)狀態(tài)，Runnable顯示的是cpu時(shí)間，不包含sleep這種時(shí)間一般都是這個(gè)模式。還可以使用IO Net模式分析io等待，Wait分析鎖競爭模式
Call tree filters ：調(diào)用樹過濾：用于過濾不需要的類，例如你使用web框架，棧中起始的方法都是框架中的代碼，最后才是你的業(yè)務(wù)代碼，這時(shí)候可以使用Call tree filters來過濾不需要的類型，減少統(tǒng)計(jì)造成的性能開銷
內(nèi)存剖析
分析內(nèi)存泄漏的利器，主要是看內(nèi)存中內(nèi)存占比和大對象。很多時(shí)候如果有內(nèi)存泄漏基本都是以為某些類型的對象占用了大頭。
arthas （類似btrace的工具）
Arthas 是Alibaba開源的Java診斷工具。線上debug的工具，很多時(shí)候因?yàn)樾阅芎桶踩仍蛭覀儾荒苤苯舆h(yuǎn)程調(diào)試線上的jvm，這時(shí)候我們可以使用arthas來查看內(nèi)存的數(shù)據(jù)，方法調(diào)用情況，打印日志信息等。
比較常用的：
watch 看方法調(diào)用情況 -c 統(tǒng)計(jì)周期，默認(rèn)值為120秒
monitor 統(tǒng)計(jì)方法調(diào)用信息
getstatic 查看靜態(tài)變量
logger 查看和修改logger
trace 方法內(nèi)部調(diào)用路徑，并輸出方法路徑上的每個(gè)節(jié)點(diǎn)上耗時(shí)
示例：
monitor -c 5 com.miaozhen.bazaro.deal.PreferredDealFilterService filter
watch com.miaozhen.bazaro.share.manager.util.DealManager getDspToDealsByPid "returnObj"
gceasy
https://gceasy.io/ 一個(gè)在線分析gc日志的網(wǎng)站，
連接泄漏
場景描述：我們公司的用戶服務(wù)對接了第三方騰訊云通信服務(wù)，在用戶注冊的時(shí)候我們需要走h(yuǎn)ttp接口調(diào)騰訊云，問題就出在http連接那塊，同事當(dāng)時(shí)采用了,線上出現(xiàn)了cpu100%的問題，日志出現(xiàn)java.lang.OutOfMemoryError: GC overhead limit exceeded。
排查思路：這個(gè)其實(shí)很好定位，本來還想打印線程?？聪碌降资悄膫€(gè)導(dǎo)致的cpu100%，一看日志直接定位到gc出問題。GC overhead limit exceeded是指gc占用了大量的cpu時(shí)間又回收不了內(nèi)存引起的，從內(nèi)存泄露去考慮，重啟服務(wù) ，啟動參數(shù)加上-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=./user.hprof -verbose:gc -Xloggc:user%t.log。問題復(fù)現(xiàn)的時(shí)候獲得了堆的dump文件，然后通過Jprofile分析，發(fā)現(xiàn)有大量的http.HttpKeepAliveCache實(shí)例，占用了80%的內(nèi)存，大致定位到是由于http連接泄露。同事封裝的HttpUtil中使用了HttpsURLConnection，在讀取完數(shù)據(jù)的時(shí)候沒有關(guān)閉InputStream導(dǎo)致連接沒有關(guān)閉。
說明：GC overhead limit exceeded，默認(rèn)情況下，如果Java進(jìn)程花費(fèi)98%以上的時(shí)間執(zhí)行GC，并且每次只有不到2%的堆被恢復(fù)，則JVM拋出此錯誤。這個(gè)錯誤是parallel Scavenge 特有的
String拼接導(dǎo)致內(nèi)存溢出
公司的后臺有段時(shí)間會間歇性的卡頓，嚴(yán)重的情況下會導(dǎo)致cpu100%。在cpu100%的時(shí)候，通過top定位到進(jìn)程號，然后輸入H切換到線程，記住具體的進(jìn)程號，使用jstack打印java進(jìn)程的線程棧，jstack輸出為十六進(jìn)制，需要將top的轉(zhuǎn)換成十六進(jìn)制的然后入找線程經(jīng)常卡在哪個(gè)方法。定位到方法發(fā)現(xiàn)是查詢用戶關(guān)聯(lián)設(shè)備號的方法出問題，方法的邏輯是從數(shù)據(jù)庫查詢設(shè)備號，在內(nèi)存中以以逗號分隔拼接返回，如1,2,3。這個(gè)bug的原因是有如下：
sql出錯，導(dǎo)致查詢返回?cái)?shù)據(jù)量很多，正常情況最多幾百個(gè)，但是異常情況有七萬個(gè)設(shè)備號
字符串拼接采用str+="1234"的形式，導(dǎo)致大量的內(nèi)存分配和回收。
運(yùn)營在點(diǎn)擊后臺查詢的時(shí)候發(fā)現(xiàn)沒返回，點(diǎn)掉就重新點(diǎn)，導(dǎo)致服務(wù)器多個(gè)線程卡在這個(gè)方法造成cpu100%。解決完sql，改用StringBuilder問題解決。
堆內(nèi)存占用過大
我們的一個(gè)服務(wù)程序，老年代設(shè)置了10g，新生代2g，偶會會出現(xiàn)內(nèi)存溢出的線程，通過分析內(nèi)存發(fā)現(xiàn)deal數(shù)據(jù)占用了大量內(nèi)存，最高可達(dá)9.4g。
堆數(shù)據(jù)：
問題代碼：
優(yōu)化后堆數(shù)據(jù)：
優(yōu)化后降低了老年代改為4g，大大降低了Jvm的堆的大小，16g機(jī)器現(xiàn)在可部署兩個(gè)實(shí)例，且Full Gc穩(wěn)定在一天一次，Young Gc 5s一次，均處正常。
CPU占用高問題
最近在分析拍賣程序時(shí)，發(fā)現(xiàn)com.miaozhen.bazaro.deal.PreferredDealFilterService#filter方法占用了90%的cpu時(shí)間。
cpu熱點(diǎn)圖：
問題代碼：
分析該方法的時(shí)長：
查看耗時(shí)deal數(shù)據(jù)
aerospike線程阻塞導(dǎo)致內(nèi)存溢出問題
問題：拍賣在五點(diǎn)多收到網(wǎng)站推送數(shù)據(jù)的時(shí)候發(fā)生OOM。
查看日志發(fā)現(xiàn)，有很多關(guān)于線程阻塞的報(bào)錯，是讀取aerospike卡住導(dǎo)致。報(bào)錯如下：
觀察gc分析結(jié)果：
可以看到本來堆內(nèi)存始終穩(wěn)定在一個(gè)水平，在一個(gè)時(shí)間點(diǎn)之后，堆內(nèi)存開始穩(wěn)步上漲，十分符合內(nèi)存泄漏的特征。
觀察堆內(nèi)存數(shù)據(jù)：
注：這個(gè)堆內(nèi)存不是當(dāng)時(shí)，當(dāng)時(shí)的堆內(nèi)存沒找到，占比是類似的。這個(gè)圖內(nèi)存優(yōu)化之后的，所以老年代只有4g。
可以看到其中OrderedExecutor占用了大量的內(nèi)存，這個(gè)數(shù)據(jù)接口是用來存放http請求的接口。
總結(jié)：
晚上九點(diǎn)40線程阻塞，但是請求的任務(wù)不停地往他的tasks里面放，十分鐘后grafana監(jiān)控顯示上升了16%的超時(shí)率（六個(gè)verticle掛了一個(gè)），從4%到20%。
查看內(nèi)存監(jiān)控圖，9點(diǎn)40開始內(nèi)存上升，不再回收，最終存了2900萬個(gè)tasks，一個(gè)線程占用了10g內(nèi)存，到晚上11.15左右日志出現(xiàn)大量的空指針和超時(shí)，十分鐘后監(jiān)控圖顯示全部超時(shí)，gc監(jiān)控顯示大量full gc，因?yàn)閮?nèi)存不夠大量的gc占用了進(jìn)程cpu時(shí)間。，5點(diǎn)多的時(shí)候推送物料，服務(wù)器內(nèi)存溢出。
關(guān)注我，私信回復(fù)“資料”獲取面試寶典《Java核心知識點(diǎn)整理.pdf》“，覆蓋了JVM、鎖、高并發(fā)、反射、Spring原理
或個(gè)人主頁也有獲取方式
