目錄
這篇文章是在公司做了不少的線上Java服務(wù)故障排查和優(yōu)化之后的一個(gè)總結(jié),可以作為一個(gè)工具清單夜畴,在分析問(wèn)題的時(shí)候需要有整體思路:全局觀,先從系統(tǒng)層面入手税灌,大致定位方向(內(nèi)存边酒,cpu翻擒,磁盤(pán)劳吠,網(wǎng)絡(luò)),然后再去分析具體的進(jìn)程。
內(nèi)存和cpu
內(nèi)存和cpu問(wèn)題是出問(wèn)題最多的一個(gè)點(diǎn)堕战,因?yàn)橛行┟钊鐃op同時(shí)可以觀察到內(nèi)存和cpu所以放在一起祠饺。
top命令
常用參數(shù): -H 打印具體的線程伐谈, -p 打印某個(gè)進(jìn)程 進(jìn)入后 按數(shù)字1 可以切換cpu的圖形看有幾個(gè)核
下面是我的測(cè)試環(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)注下磁盤(pá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)的是用戶代碼,如果超過(guò)了內(nèi)核數(shù)黔牵,表示系統(tǒng)已經(jīng)過(guò)載音瓷。也就是說(shuō)如果你是8核声邦,那么這個(gè)數(shù)字小于等于8的負(fù)載都是沒(méi)問(wèn)題的蛇受,我看網(wǎng)上的建議一般這個(gè)值不要超過(guò)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)長(zhǎng)inux的內(nèi)存分配纪铺,如果有剩余內(nèi)存蔬捷,他就會(huì)將內(nèi)存用于cache罕容,這樣可以較少磁盤(pán)的讀寫(xiě)提高效率沉噩,如果有應(yīng)用申請(qǐ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)程會(huì)出現(xiàn)T(暫停)這個(gè)狀態(tài)仗岖。
網(wǎng)絡(luò)
ss
netstat的高性能版,參數(shù)都基本一致
常用參數(shù): -n 打印數(shù)字端口號(hào) -t tcp連接 -l 監(jiān)聽(tīng)端口 -a 所有端口 -p 進(jìn)程號(hào) -s 打印統(tǒng)計(jì)信息
ss -s示例:
Total:1732(kernel1987) TCP:42373(estab1430, closed40910, orphaned2, synrecv0, timewait40906/0), ports1924Transport Total IP IPv6*1987- -? RAW1899UDP18117TCP1463503960
可以看到整體的連接情況轮锥,如timewait過(guò)高瓢捉,連接數(shù)過(guò)高等情況
然后使用ss -ntap|grep 進(jìn)程號(hào) or 端口號(hào)查看進(jìn)程的連接
ping
查看時(shí)延和丟包情況
mtr
查看丟包請(qǐng)求
磁盤(pán)
磁盤(pán)問(wèn)題在mysql服務(wù)器中非常常見(jiàn)拍摇,很多時(shí)候mysql服務(wù)器的CPU不高但是卻出現(xiàn)慢查詢?nèi)罩撅j升幕随,就是因?yàn)榇疟P(pán)出現(xiàn)了瓶頸篮昧。還有mysql的備份策略窄潭,如果沒(méi)有監(jiān)控磁盤(pán)空間春宣,可能出現(xiàn)磁盤(pán)滿了服務(wù)不可用的現(xiàn)象。
iostat命令
常用參數(shù): -k 用kb為單位 -d 監(jiān)控磁盤(pán) -x顯示詳情 num count 每個(gè)幾秒刷新 顯示次數(shù)
這個(gè)是我查看磁盤(pán)負(fù)載的主要工具嫉你,也可以顯示cpu的負(fù)載月帝,不過(guò)我一般用iostat -kdx 2 10,下面是我測(cè)試環(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: 分別對(duì)應(yīng)讀寫(xiě)速度
avgqu-sz: 讀寫(xiě)隊(duì)列的平均請(qǐng)求長(zhǎng)度,可以類(lèi)比top命令的load average
await r_await w_await: io請(qǐng)求的平均時(shí)間(毫秒)幽污,分別是讀寫(xiě)嚷辅,讀和寫(xiě)三個(gè)平均值。這個(gè)時(shí)間都包括在隊(duì)列中等待的時(shí)間和實(shí)際處理讀寫(xiě)請(qǐng)求的時(shí)間距误,還有svctm這個(gè)參數(shù)簸搞,他說(shuō)的是實(shí)際處理讀寫(xiě)請(qǐng)求的時(shí)間,照理來(lái)講w_await肯定是大于svctm的准潭,但是我在線上看到有w_await小于svctm的情況趁俊,不知道是什么原因。我看iostat的man手動(dòng)中說(shuō)svctm已經(jīng)廢棄刑然,所以一般我看的是這三個(gè)寺擂。
%util: 這個(gè)參數(shù)直觀的看磁盤(pán)的負(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ì)
場(chǎng)景:例如系統(tǒng)磁盤(pán)空間不足時(shí),先通過(guò)df命令定位到具體的掛載目錄沐鼠,在進(jìn)去掛載目錄后挚瘟,使用
du -sh *查看各個(gè)文件或者子目錄的大小定位具體文件
這里還有l(wèi)s命令叹谁,可以通過(guò)加-h和-S(按大小排序)
iostat命令
常用參數(shù): -k 用kb為單位 -d 監(jiān)控磁盤(pán) -x顯示詳情 num count 每個(gè)幾秒刷新 顯示次數(shù)
這個(gè)是我查看磁盤(pán)負(fù)載的主要工具,也可以顯示cpu的負(fù)載乘盖,不過(guò)我一般用iostat -kdx 2 10,下面是我測(cè)試環(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: 分別對(duì)應(yīng)讀寫(xiě)速度
avgqu-sz: 讀寫(xiě)隊(duì)列的平均請(qǐng)求長(zhǎng)度焰檩,可以類(lèi)比top命令的load average
await r_await w_await: io請(qǐng)求的平均時(shí)間(毫秒),分別是讀寫(xiě)订框,讀和寫(xiě)三個(gè)平均值析苫。這個(gè)時(shí)間都包括在隊(duì)列中等待的時(shí)間和實(shí)際處理讀寫(xiě)請(qǐng)求的時(shí)間,還有svctm這個(gè)參數(shù)穿扳,他說(shuō)的是實(shí)際處理讀寫(xiě)請(qǐng)求的時(shí)間衩侥,照理來(lái)講w_await肯定是大于svctm的,但是我在線上看到有w_await小于svctm的情況矛物,不知道是什么原因茫死。我看iostat的man手動(dòng)中說(shuō)svctm已經(jīng)廢棄,所以一般我看的是這三個(gè)履羞。
%util: 這個(gè)參數(shù)直觀的看磁盤(pán)的負(fù)載情況峦萎,我首先看的就是這個(gè)參數(shù)。和top的wa命令有關(guān)聯(lián)忆首。
lsof
列出當(dāng)前系統(tǒng)打開(kāi)文件爱榔,因?yàn)樵趌inux下一切皆是文件,連接糙及,硬件等均被描述為文件详幽,所以這個(gè)命令也十分有用。
常用參數(shù):
-p 查看某個(gè)進(jìn)程的文件
直接加文件名 查看哪些進(jìn)程打開(kāi)了文件
+d 目錄 查看哪些進(jìn)程打開(kāi)了目錄以及下面的文件(不遞歸浸锨,+D是遞歸)
Sar
最后補(bǔ)充一個(gè)sar(System Activity Reporter)命令唇聘,如果系統(tǒng)沒(méi)有一個(gè)良好的監(jiān)控,那么這個(gè)命令對(duì)于排查問(wèn)題是很好的補(bǔ)充揣钦,很多時(shí)候去排查問(wèn)題的時(shí)候發(fā)現(xiàn)問(wèn)題已經(jīng)沒(méi)了雳灾,可以通過(guò)這個(gè)命令查看系統(tǒng)的活動(dòng)情況,比如各個(gè)時(shí)間段cpu情況冯凹,內(nèi)存情況谎亩。
常用參數(shù):
-r 內(nèi)存信息
-q loader信息,運(yùn)行隊(duì)列情況
-u cpu信息
-W Swap換頁(yè)情況
/proc文件系統(tǒng)
/proc是個(gè)虛擬文件系統(tǒng)宇姚,是內(nèi)核的一些數(shù)據(jù)匈庭,很多l(xiāng)inux命令的都是通過(guò)解析/proc文件系統(tǒng)實(shí)現(xiàn)的,每個(gè)進(jìn)程都會(huì)有一個(gè)以pid為目錄名的子目錄存在浑劳,通過(guò)解析/proc下的進(jìn)程目錄可以得到很多進(jìn)程的設(shè)置信息和資源占用信息等阱持。
這里簡(jiǎn)單說(shuō)個(gè)排查過(guò)的問(wèn)題,當(dāng)時(shí)我們線上有個(gè)服務(wù)魔熏,正常ssh登錄的情況下,我們?cè)O(shè)置了ulimit中的open files為(進(jìn)程可打開(kāi)的最大描述符數(shù)量)100000衷咽,但是有一次在服務(wù)的日志中發(fā)現(xiàn)有報(bào)錯(cuò)說(shuō)文件描述符不夠用鸽扁。所以
java -XX:+PrintFlagsInitial 可以查看所以的jvm默認(rèn)參數(shù)镶骗,其中帶有manageable表示運(yùn)行時(shí)可以動(dòng)態(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元空間改動(dòng):
java 7種垃圾收集器:
常見(jiàn)搭配:
java8默認(rèn):Parallel Scavenge和 Parallel Old
低延遲:ParNew和CMS
java8以后可以直接使用G1,參數(shù)比較簡(jiǎn)單
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í)間不超過(guò)設(shè)定值相寇。不過(guò)大家不要異想天開(kāi)地認(rèn)為如果把這個(gè)參數(shù)的值設(shè)置得稍小一點(diǎn)就能使得系統(tǒng)的垃圾收集速度變得更快慰于,GC停頓時(shí)間縮短是以犧牲吞吐量和新生代空間來(lái)?yè)Q取的:系統(tǒng)把新生代調(diào)小一些,收集300MB新生代肯定比收集500MB快吧唤衫,這也直接導(dǎo)致垃圾收集發(fā)生得更頻繁一些婆赠,原來(lái)10秒收集一次、每次停頓100毫秒战授,現(xiàn)在變成5秒收集一次页藻、每次停頓70毫秒桨嫁。停頓時(shí)間的確在下降植兰,但吞吐量也降下來(lái)了。
直接設(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開(kāi)關(guān)參數(shù)
-XX:+UseAdaptiveSizePolicy是一個(gè)開(kāi)關(guān)參數(shù)巴元,當(dāng)這個(gè)參數(shù)打開(kāi)之后毡咏,就不需要手工指定新生代的大小(-Xmn)逮刨、Eden與Survivor區(qū)的比例(-XX:SurvivorRatio)呕缭、晉升老年代對(duì)象年齡(-XX:PretenureSizeThreshold)等細(xì)節(jié)參數(shù)了,虛擬機(jī)會(huì)根據(jù)當(dāng)前系統(tǒng)的運(yùn)行情況收集性能監(jiān)控信息修己,動(dòng)態(tài)調(diào)整這些參數(shù)以提供最合適的停頓時(shí)間或最大的吞吐量恢总,這種調(diào)節(jié)方式稱(chēng)為GC自適應(yīng)的調(diào)節(jié)策略(GC Ergonomics)。
說(shuō)說(shuō)UseAdaptiveSizePolicy參數(shù)睬愤,加了這個(gè)參數(shù)-XX:SurvivorRatio會(huì)失效片仿,所以有些人會(huì)發(fā)現(xiàn)新生代比例未如自己的預(yù)期,而UseAdaptiveSizePolicy有默認(rèn)是開(kāi)啟的
CMS
并發(fā)垃圾收集器尤辱,注重的是時(shí)延砂豌,有分配擔(dān)保失敗的風(fēng)險(xiǎn)
CMS收集器的GC周期由6個(gè)階段組成厢岂。其中4個(gè)階段(名字以Concurrent開(kāi)始的)與實(shí)際的應(yīng)用程序是并發(fā)執(zhí)行的,而其他2個(gè)階段需要暫停應(yīng)用程序線程阳距。
初始標(biāo)記:為了收集應(yīng)用程序的對(duì)象引用需要暫停應(yīng)用程序線程咪笑,該階段完成后,應(yīng)用程序線程再次啟動(dòng)娄涩。
并發(fā)標(biāo)記:從第一階段收集到的對(duì)象引用開(kāi)始窗怒,遍歷所有其他的對(duì)象引用。
并發(fā)預(yù)清理:改變當(dāng)運(yùn)行第二階段時(shí)蓄拣,由應(yīng)用程序線程產(chǎn)生的對(duì)象引用扬虚,以更新第二階段的結(jié)果。
重標(biāo)記:由于第三階段是并發(fā)的球恤,對(duì)象引用可能會(huì)發(fā)生進(jìn)一步改變辜昵。因此,應(yīng)用程序線程會(huì)再一次被暫停以更新這些變化咽斧,并且在進(jìn)行實(shí)際的清理之前確保一個(gè)正確的對(duì)象引用視圖堪置。這一階段十分重要,因?yàn)楸仨毐苊馐占饺员灰玫膶?duì)象张惹。
并發(fā)清理:所有不再被應(yīng)用的對(duì)象將從堆里清除掉舀锨。
并發(fā)重置:收集器做一些收尾的工作,以便下一次GC周期能有一個(gè)干凈的狀態(tài)宛逗。
-XX:CMSInitiatingOccupancyFraction=90 (jdk1.5默認(rèn)值68坎匿,1.6開(kāi)始默認(rèn)值92,指設(shè)定CMS在對(duì)內(nèi)存占用率達(dá)到70%的時(shí)候開(kāi)始GC(因?yàn)镃MS會(huì)有浮動(dòng)垃圾,所以一般都較早啟動(dòng)GC)
-XX:+UseCMSInitiatingOccupancyOnly 只是用設(shè)定的回收閾值(上面指定的70%),如果不指定,JVM僅在第一次使用設(shè)定值,后續(xù)則自動(dòng)調(diào)整
-XX:+CMSScavengeBeforeRemark 在CMS GC前啟動(dòng)一次ygc雷激,目的在于減少old gen對(duì)ygc gen的引用替蔬,降低remark時(shí)的開(kāi)銷(xiāo)
-XX:+CMSParallelRemarkEnabled 并發(fā)標(biāo)記
-XX:+ExplicitGCInvokesConcurrent命令JVM無(wú)論什么時(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í)自動(dòng)開(kāi)啟,因?yàn)镃MS不能和Parallel Scavenge搭配使用
上面的參數(shù)都建議開(kāi)啟根悼,CMS需要注意的一個(gè)問(wèn)題就是CMSInitiatingOccupancyFraction參數(shù)凶异,這個(gè)參數(shù)直接影響CMS回收老年代的時(shí)機(jī),需要結(jié)合自己的業(yè)務(wù)場(chǎng)景來(lái)調(diào)整番挺,一般情況下應(yīng)該盡量設(shè)置大一點(diǎn)唠帝,但是有一個(gè)嚴(yán)重的問(wèn)題,就是浮動(dòng)垃圾的問(wèn)題玄柏,如果CMS在并發(fā)收集的時(shí)候出現(xiàn)老年代不能存放晉升對(duì)象將直接進(jìn)行Full GC使用Serial Old垃圾收集器,所以不能一味追求最大化襟衰,如果老年代增長(zhǎng)比較慢,那么可以設(shè)置的稍微較大些粪摘,如果增長(zhǎng)比較快瀑晒,可以從增大新生代绍坝,調(diào)低CMSInitiatingOccupancyFraction入手
最后在提下-XX:+DisableExplicitGC :禁用顯示gc (system.gc())這個(gè)參數(shù),很多人因?yàn)閟ystem.gc()會(huì)導(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ī)制就是通過(guò)調(diào)用system.gc(),發(fā)起Full Gc向臀,F(xiàn)ull Gc會(huì)回收堆外內(nèi)存巢墅,如果將system.gc()禁用,則得等到Full Gc發(fā)生才能回收堆外內(nèi)存券膀,很有可能出現(xiàn)堆外內(nèi)存占用過(guò)高影響系統(tǒng)性能或者因?yàn)閮?nèi)存不足被系統(tǒng)Kill的問(wèn)題君纫。
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í)候是沒(méi)有年齡分布信息的)
-XX:+UseGCLogFileRotation 開(kāi)啟日志輪換
-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í)間表示真正過(guò)去的時(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:<庫(kù)名>[=<選項(xiàng)>] 加載本機(jī)代理庫(kù)<庫(kù)名>, 例如 -agentlib:jdwp 另請(qǐng)參閱 -agentlib:jdwp=help -agentpath:<路徑名>[=<選項(xiàng)>] 按完整路徑名加載本機(jī)代理庫(kù) -javaagent:[=<選項(xiàng)>] 加載 Java 編程語(yǔ)言代理, 請(qǐng)參閱 java.lang.instrument
JVMTI(Java Virtual Machine Tool Interface)即指Java虛擬機(jī)工具接口瓦宜,它是一套由虛擬機(jī)直接提供的 native 接口,通過(guò)這些接口岭妖,開(kāi)發(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++編寫(xiě)的動(dòng)態(tài)庫(kù)侧蘸,-agentlib和-javaagent是一個(gè)instrument的JVMTIAgent(linux下對(duì)應(yīng)的動(dòng)態(tài)庫(kù)是libinstrument.so)裁眯。
Attach機(jī)制
Jvm提供一種jvm進(jìn)程間通信的能力,能讓一個(gè)進(jìn)程傳命令給另外一個(gè)進(jìn)程讳癌,并讓它執(zhí)行內(nèi)部的一些操作穿稳,比如說(shuō)我們?yōu)榱俗屃硗庖粋€(gè)jvm進(jìn)程把線程dump出來(lái),那么我們跑了一個(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)程信號(hào)的線程骤菠,Attach Listener正式Attach機(jī)制處理線程埋虹。
java自帶工具
jps
查看Java進(jìn)程列表
常用參數(shù):
-l: 輸出應(yīng)用程序主類(lèi)完整package名稱(chēng)或jar完整名稱(chēng)
-m:輸出主函數(shù)傳入的參數(shù)
jmap
查看JVM堆的情況
常用參數(shù):
-heap
-dump 這個(gè)命令還有兩個(gè)常用參數(shù)live 只dump存活對(duì)象,會(huì)導(dǎo)致GCfile=file dump文件名
示例:jmap -dump:live,file=heap.dump <pid>
這里有兩點(diǎn)娩怎,一方面需要注意live會(huì)導(dǎo)致GC搔课,有時(shí)候在查問(wèn)題的時(shí)候可能不是你預(yù)期的效果,一般查內(nèi)存問(wèn)題時(shí)不加這個(gè)選項(xiàng)截亦,另外dump文件如果比較大爬泥,可以先壓縮在傳回本地
jstack
查看JVM的堆棧情況,監(jiān)測(cè)死鎖等
這個(gè)命令比較簡(jiǎn)單崩瓤,一般不用加什么參數(shù)袍啡,有時(shí)候JVM沒(méi)響應(yīng)時(shí)可以加-F參數(shù)。一般這個(gè)命令可以結(jié)合top却桶,在top定位到占用cpu高的線程后境输,在具體在Jstack打印的堆棧中查看線程,有時(shí)候也需要多次打印堆棧來(lái)進(jìn)行對(duì)比
jstat
查看JVM gc信息颖系,觀察JVM的GC活動(dòng)
常用參數(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ù)和啟動(dòng)時(shí)的命令行參數(shù)嗅剖,還可以動(dòng)態(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啟動(dòng)時(shí)加參數(shù):-agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=*:5005
遠(yuǎn)程調(diào)試非常有用嘁扼,有時(shí)候測(cè)試環(huán)境很難復(fù)現(xiàn)時(shí)信粮,可以用通過(guò)遠(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可以通過(guò)過(guò)濾只對(duì)指定類(lèi)進(jìn)行增強(qiáng)
Thread Status:選擇線程統(tǒng)計(jì)狀態(tài),Runnable顯示的是cpu時(shí)間,不包含sleep這種時(shí)間一般都是這個(gè)模式称龙。還可以使用IO Net模式分析io等待留拾,Wait分析鎖競(jìng)爭(zhēng)模式
Call tree filters :調(diào)用樹(shù)過(guò)濾:用于過(guò)濾不需要的類(lèi),例如你使用web框架鲫尊,棧中起始的方法都是框架中的代碼痴柔,最后才是你的業(yè)務(wù)代碼,這時(shí)候可以使用Call tree filters來(lái)過(guò)濾不需要的類(lèi)型疫向,減少統(tǒng)計(jì)造成的性能開(kāi)銷(xiāo)
內(nèi)存剖析
分析內(nèi)存泄漏的利器咳蔚,主要是看內(nèi)存中內(nèi)存占比和大對(duì)象。很多時(shí)候如果有內(nèi)存泄漏基本都是以為某些類(lèi)型的對(duì)象占用了大頭搔驼。
arthas (類(lèi)似btrace的工具)
Arthas 是Alibaba開(kāi)源的Java診斷工具谈火。線上debug的工具,很多時(shí)候因?yàn)樾阅芎桶踩仍蛭覀儾荒苤苯舆h(yuǎn)程調(diào)試線上的jvm舌涨,這時(shí)候我們可以使用arthas來(lái)查看內(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)站扭粱,
連接泄漏
場(chǎng)景描述:我們公司的用戶服務(wù)對(duì)接了第三方騰訊云通信服務(wù),在用戶注冊(cè)的時(shí)候我們需要走h(yuǎn)ttp接口調(diào)騰訊云琢蛤,問(wèn)題就出在http連接那塊蜓堕,同事當(dāng)時(shí)采用了,線上出現(xiàn)了cpu100%的問(wèn)題,日志出現(xiàn)java.lang.OutOfMemoryError: GC overhead limit exceeded博其。
排查思路:這個(gè)其實(shí)很好定位套才,本來(lái)還想打印線程棧看下到底是哪個(gè)導(dǎo)致的cpu100%贺奠,一看日志直接定位到gc出問(wèn)題霜旧。GC overhead limit exceeded是指gc占用了大量的cpu時(shí)間又回收不了內(nèi)存引起的,從內(nèi)存泄露去考慮儡率,重啟服務(wù) ,啟動(dòng)參數(shù)加上-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=./user.hprof -verbose:gc -Xloggc:user%t.log以清。問(wèn)題復(fù)現(xiàn)的時(shí)候獲得了堆的dump文件儿普,然后通過(guò)Jprofile分析,發(fā)現(xiàn)有大量的http.HttpKeepAliveCache實(shí)例掷倔,占用了80%的內(nèi)存眉孩,大致定位到是由于http連接泄露。同事封裝的HttpUtil中使用了HttpsURLConnection,在讀取完數(shù)據(jù)的時(shí)候沒(méi)有關(guān)閉InputStream導(dǎo)致連接沒(méi)有關(guān)閉浪汪。
說(shuō)明:GC overhead limit exceeded巴柿,默認(rèn)情況下,如果Java進(jìn)程花費(fèi)98%以上的時(shí)間執(zhí)行GC死遭,并且每次只有不到2%的堆被恢復(fù)广恢,則JVM拋出此錯(cuò)誤。這個(gè)錯(cuò)誤是parallel Scavenge 特有的
String拼接導(dǎo)致內(nèi)存溢出
公司的后臺(tái)有段時(shí)間會(huì)間歇性的卡頓呀潭,嚴(yán)重的情況下會(huì)導(dǎo)致cpu100%钉迷。在cpu100%的時(shí)候,通過(guò)top定位到進(jìn)程號(hào)钠署,然后輸入H切換到線程糠聪,記住具體的進(jìn)程號(hào),使用jstack打印java進(jìn)程的線程棧谐鼎,jstack輸出為十六進(jìn)制舰蟆,需要將top的轉(zhuǎn)換成十六進(jìn)制的然后入找線程經(jīng)常卡在哪個(gè)方法狸棍。定位到方法發(fā)現(xiàn)是查詢用戶關(guān)聯(lián)設(shè)備號(hào)的方法出問(wèn)題夭苗,方法的邏輯是從數(shù)據(jù)庫(kù)查詢?cè)O(shè)備號(hào),在內(nèi)存中以以逗號(hào)分隔拼接返回隔缀,如1,2,3题造。這個(gè)bug的原因是有如下:
sql出錯(cuò),導(dǎo)致查詢返回?cái)?shù)據(jù)量很多猾瘸,正常情況最多幾百個(gè)界赔,但是異常情況有七萬(wàn)個(gè)設(shè)備號(hào)
字符串拼接采用str+="1234"的形式,導(dǎo)致大量的內(nèi)存分配和回收牵触。
運(yùn)營(yíng)在點(diǎn)擊后臺(tái)查詢的時(shí)候發(fā)現(xiàn)沒(méi)返回淮悼,點(diǎn)掉就重新點(diǎn),導(dǎo)致服務(wù)器多個(gè)線程卡在這個(gè)方法造成cpu100%揽思。解決完sql袜腥,改用StringBuilder問(wèn)題解決。
堆內(nèi)存占用過(guò)大
我們的一個(gè)服務(wù)程序钉汗,老年代設(shè)置了10g羹令,新生代2g,偶會(huì)會(huì)出現(xiàn)內(nèi)存溢出的線程损痰,通過(guò)分析內(nèi)存發(fā)現(xiàn)deal數(shù)據(jù)占用了大量?jī)?nèi)存福侈,最高可達(dá)9.4g。
堆數(shù)據(jù):
問(wèn)題代碼:
優(yōu)化后堆數(shù)據(jù):
優(yōu)化后降低了老年代改為4g卢未,大大降低了Jvm的堆的大小肪凛,16g機(jī)器現(xiàn)在可部署兩個(gè)實(shí)例堰汉,且Full Gc穩(wěn)定在一天一次,Young Gc 5s一次伟墙,均處正常翘鸭。
CPU占用高問(wèn)題
最近在分析拍賣(mài)程序時(shí),發(fā)現(xiàn)com.miaozhen.bazaro.deal.PreferredDealFilterService#filter方法占用了90%的cpu時(shí)間戳葵。
cpu熱點(diǎn)圖:
問(wèn)題代碼:
分析該方法的時(shí)長(zhǎng):
查看耗時(shí)deal數(shù)據(jù)
aerospike線程阻塞導(dǎo)致內(nèi)存溢出問(wèn)題
問(wèn)題:拍賣(mài)在五點(diǎn)多收到網(wǎng)站推送數(shù)據(jù)的時(shí)候發(fā)生OOM就乓。
查看日志發(fā)現(xiàn),有很多關(guān)于線程阻塞的報(bào)錯(cuò)譬淳,是讀取aerospike卡住導(dǎo)致档址。報(bào)錯(cuò)如下:
觀察gc分析結(jié)果:
可以看到本來(lái)堆內(nèi)存始終穩(wěn)定在一個(gè)水平,在一個(gè)時(shí)間點(diǎn)之后邻梆,堆內(nèi)存開(kāi)始穩(wěn)步上漲守伸,十分符合內(nèi)存泄漏的特征。
觀察堆內(nèi)存數(shù)據(jù):
注:這個(gè)堆內(nèi)存不是當(dāng)時(shí)浦妄,當(dāng)時(shí)的堆內(nèi)存沒(méi)找到尼摹,占比是類(lèi)似的。這個(gè)圖內(nèi)存優(yōu)化之后的剂娄,所以老年代只有4g蠢涝。
可以看到其中OrderedExecutor占用了大量的內(nèi)存,這個(gè)數(shù)據(jù)接口是用來(lái)存放http請(qǐng)求的接口阅懦。
總結(jié):
晚上九點(diǎn)40線程阻塞和二,但是請(qǐng)求的任務(wù)不停地往他的tasks里面放,十分鐘后grafana監(jiān)控顯示上升了16%的超時(shí)率(六個(gè)verticle掛了一個(gè))耳胎,從4%到20%惯吕。
查看內(nèi)存監(jiān)控圖朽褪,9點(diǎn)40開(kāi)始內(nèi)存上升硬猫,不再回收肿嘲,最終存了2900萬(wàn)個(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核心知識(shí)點(diǎn)整理.pdf》“,覆蓋了JVM劝术、鎖、高并發(fā)、反射养晋、Spring原理
或個(gè)人主頁(yè)也有獲取方式