給我1萬字,也講Java不清內存排查。1萬不行來2萬~.~
本文轉載自微信公眾號「小姐姐味道」,可以通過以下二維碼關注。轉載本文請聯系小姐姐味道公眾號。
對于內存問題排查來說,搞理論的痛苦,搞實踐的也痛苦,沒有一片清凈之地。
why?因為內存溢出是Java碼農永遠的傷。
溢出有很多種解釋,有精滿自溢,有緩沖區溢出攻擊,還有另外一種叫做領導的溢出。不知道什么叫作溢出理論,xjjdog在此普及一下。
《領導看了會炸毛的溢出理論》
內存溢出什么最重要?其實,內存溢出就像是一場交通事故。事故的發生方,就是具體的服務;事故的處理方,就是相關的程序員。其中有一個最重要的環節,就是在事故現場需要拍照取證。
如果沒有照片沒有行車記錄儀沒有證據,就只能靠那張嘴,怎么說都是不可信的。
**這句話很重要很重要:內存問題排查什么最重要?當然是信息收集,留下一些為我們的排查提供支持的依據。**千萬不要舍本逐末,對內存問題排查本身感興趣,那是自虐行為。
有很多工具可以幫助我們定位問題,但前提是你得把它留下來。下面這篇文章是xjjdog很久之前留下來的,由于標題的緣故,你可能忽略了,但這些工具能夠快速幫我們定位問題。
- ss -antp > $DUMP_DIR/ss.dump 2>&1
- netstat -s > $DUMP_DIR/netstat-s.dump 2>&1
- top -Hp $PID -b -n 1 -c > $DUMP_DIR/top-$PID.dump 2>&1
- sar -n DEV 1 2 > $DUMP_DIR/sar-traffic.dump 2>&1
- lsof -p $PID > $DUMP_DIR/lsof-$PID.dump
- iostat -x > $DUMP_DIR/iostat.dump 2>&1
- free -h > $DUMP_DIR/free.dump 2>&1
- jstat -gcutil $PID > $DUMP_DIR/jstat-gcutil.dump 2>&1
- jstack $PID > $DUMP_DIR/jstack.dump 2>&1
- jmap -histo $PID > $DUMP_DIR/jmap-histo.dump 2>&1
- jmap -dump:format=b,file=$DUMP_DIR/heap.bin $PID > /dev/null 2>&1
GC日志配置
但并不是每次出現故障,你都在機器的身邊。靠人工也不能保證實時性。所以,強烈建議你把GC日志輸出的詳細一些,那么出現問題的時候就舒坦一些。
實際上,這個要求在我看來是強制的。
很多同學上來就說,我的內存溢出了。但你和它要一些日志信息,要堆棧,要現場保存的快照。都沒有。這就是純粹來搞笑的。
下面是JDK8或者以下的GC日志參數,可以看到還是很長的。
- #!/bin/sh
- LOG_DIR="/tmp/logs"
- JAVA_OPT_LOG=" -verbose:gc"
- JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintGCDetails"
- JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintGCDateStamps"
- JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintGCApplicationStoppedTime"
- JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintTenuringDistribution"
- JAVA_OPT_LOG="${JAVA_OPT_LOG} -Xloggc:${LOG_DIR}/gc_%p.log"
- JAVA_OPT_OOM=" -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=${LOG_DIR} -XX:ErrorFile=${LOG_DIR}/hs_error_pid%p.log "
- JAVA_OPT="${JAVA_OPT_LOG} ${JAVA_OPT_OOM}"
- JAVA_OPT="${JAVA_OPT} -XX:-OmitStackTraceInFastThrow"
下面是JDK9及其以上的日志配置。可以看到它的配置方式全變了,而且不向下兼容。Java搞的這個變化還是挺蛋疼的。
- #!/bin/sh
- LOG_DIR="/tmp/logs"
- JAVA_OPT_LOG=" -verbose:gc"
- JAVA_OPT_LOG="${JAVA_OPT_LOG} -Xlog:gc,gc+ref=debug,gc+heap=debug,gc+age=trace:file=${LOG_DIR}/gc_%p.log:tags,uptime,time,level"
- JAVA_OPT_LOG="${JAVA_OPT_LOG} -Xlog:safepoint:file=${LOG_DIR}/safepoint_%p.log:tags,uptime,time,level"
- JAVA_OPT_OOM=" -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=${LOG_DIR} -XX:ErrorFile=${LOG_DIR}/hs_error_pid%p.log "
- JAVA_OPT="${JAVA_OPT_LOG} ${JAVA_OPT_OOM}"
- JAVA_OPT="${JAVA_OPT} -XX:-OmitStackTraceInFastThrow"
- echo $JAVA_OPT
一旦發現了問題,就可以拿GC日志來快速定位堆內問題。但是并不是讓你一行行去看,那太低效了。因為日志可能會很長很長,而且也不一定看得懂。這個時候,就可以使用一些在線工具輔助解決。我經常使用的是gceasy,下面是它的一張截圖。
- http://gceasy.io
有了GC日志還不行,因為它僅僅是記錄了堆空間的一些變化,至于操作系統的一些資源變動,它是無從知曉的。所以,如果你有一個監控系統的話,在尋找問題的時候也能幫到忙。從下圖可以看到系統資源的一些變動。
溢出示例
堆溢出
代碼。
日志。
- java -Xmx20m -Xmn4m -XX:+HeapDumpOnOutOfMemoryError - OOMTest
- [18.386s][info][gc] GC(10) Concurrent Mark 5.435ms
- [18.395s][info][gc] GC(12) Pause Full (Allocation Failure) 18M->18M(19M) 10.572ms
- [18.400s][info][gc] GC(13) Pause Full (Allocation Failure) 18M->18M(19M) 5.348ms
- Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
- at OldOOM.main(OldOOM.java:20)
jvisualvm的反應。
元空間溢出
代碼。
日志。
- java -Xmx20m -Xmn4m -XX:+HeapDumpOnOutOfMemoryError -XX:MetaspaceSize=16M -XX:MaxMetaspaceSize=16M MetaspaceOOMTest
- 6.556s][info][gc] GC(30) Concurrent Cycle 46.668ms
- java.lang.OutOfMemoryError: Metaspace
- Dumping heap to /tmp/logs/java_pid36723.hprof ..
jvisualvm的反應。
直接內存溢出
代碼。
日志。
- java -XX:MaxDirectMemorySize=10M -Xmx10M OffHeapOOMTest
- Exception in thread "Thread-2" java.lang.OutOfMemoryError: Direct buffer memory
- at java.nio.Bits.reserveMemory(Bits.java:694)
- at java.nio.DirectByteBuffer.<init>(DirectByteBuffer.java:123)
- at java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:311)
- at OffHeapOOMTest.oom(OffHeapOOMTest.java:27)...
棧溢出
代碼。
日志。
- java -Xss128K StackOverflowTest
- Exception in thread "main" java.lang.StackOverflowError
- at java.io.PrintStream.write(PrintStream.java:526)
- at java.io.PrintStream.print(PrintStream.java:597)
- at java.io.PrintStream.println(PrintStream.java:736)
- at StackOverflowTest.a(StackOverflowTest.java:5)
哪些代碼容易出現問題
忘記重寫hashCode和equals
看下面的代碼。由于沒有重寫Key類的hashCode和equals方法。造成了放入HashMap的所有對象,都無法被取出來。它們和外界失聯了。
下面這篇文章詳細的描述了它的原理。
結果集失控
不要覺得這段代碼可笑。在實際工作中的review中,xjjdog不止一次發現這種蛋疼的代碼。這有可能是趕工期,也有可能是剛學會寫Java。這行代碼有很大的可能性踩坑。
條件失控
代碼。與之類似的就是條件失控,當某個條件不滿足的時候,將會造成結果集的失控。大家可以看下面的代碼,fullname 和 other為空的時候,會出現什么后果?
萬能參數
還有的同學使用各種Object和HashMap來進行信息交換。這種代碼正常運行的時候沒什么問題,但一旦出錯,幾乎無法排查。排查參數、排查堆棧、排查調用鏈,全部失效。
一些預防的措施
- 減少創建大對象的頻率:比如byte數組的傳遞
- 不要緩存太多的堆內數據:使用guava的weak引用模式
- 查詢的范圍一定要可控:如分庫分表中間件;ES等有同樣問題
- 用完的資源一定要close掉:可以使用新的 try-with-resources語法
- 少用intern:字符串太長,且無法復用,就會造成內存泄漏
- 合理的Session超時時間
- 少用第三方本地代碼,使用Java方案替代
- 合理的池大小
- XML(SAX/DOM)、JSON解析要注意對象大小
案例分析一
這是最常見的一種情況。了解了這種方式,能夠應對大多數內存溢出和內存泄漏問題。
現象
- 環境:CentOS7,JDK1.8,SpringBoot
- G1垃圾回收器
- 剛啟動沒什么問題,慢慢放量后,發生了OOM
- 系統自動生成了heapdump文件
- 臨時解決方式:重啟,但問題依然發現
信息收集
- 日志:GC的日志信息:內存突增突降,變動迅速
- 堆棧:Thread Dump文件:大部分阻塞在某個方法上
- 壓測:使用wrk進行壓測,發現20個用戶并發,內存溢出
- wrk -t20 -c20 -d300s http://127.0.0.1:8084/api/test
MAT分析
堆棧文件獲取:
- jmap -dump:format=b,file=heap.bin 37340
- jhsdb jmap --binaryheap --pid 37340
MAT工具是基于eclipse平臺開發的,本身是一個Java程序。分析Heap Dump文件:發現內存創建了大量的報表對象。
通過菜單Find Leaks,一鍵找出黑李逵。
根據提示向下挖就可以。
解決
分析結果:
- 系統存在大數據量查詢服務,并在內存做合并
- 當并發量達到一定程度,會有大量數據堆積到內存進行運算
解決方式:
- 重構查詢服務,減少查詢的字段
- 使用SQL查詢代替內存拼接,避免對結果集的操作
- 舉例:查找兩個列表的交集
案例分析二
現象
- 環境:CentOS7,JDK1.8,JBoss
- CMS垃圾回收器
- 操作系統CPU資源耗盡
- 訪問任何接口,響應都非常的慢
分析
- 發現每次GC的效果都特別好,但是非常頻繁
- 了解到使用了堆內緩存,而且設置的容量比較大
- 緩存填充的速度特別快!
結論:
- 開了非常大的緩存,GC之后迅速占滿,造成GC頻繁
案例分析三
- 現象java進程異常退出
- java進程直接消失
- 沒有留下dump文件
- GC日志正常
- 監控發現死亡時,堆內內存占用很少,堆內仍有大量剩余空間
分析
- XX:+HeapDumpOnOutOfMemoryError不起作用
- 監控發現操作系統內存持續增加
下面這些情況都會造成程序退出而沒什么響應。
- 被操作系統殺死 dmesg oom-killer
- System.exit()
- java com.cn.AA & 后終端關閉
- kill -9
解決
發現:
- 在dmesg命令中發現確實被oom-kill
解決:
- 給JVM少分配一些內存,騰出空間給其他進程