史詩級java低時延調優(yōu)案例1
?
-- 西門幽月
?
序章
生產(chǎn)環(huán)境調優(yōu)往往是一件復雜又痛苦的事，互聯(lián)網(wǎng)公司尤其嚴重，主要表現(xiàn)在
人員流動大痪署，工程師往往負責的是別人留下的代碼
單個服務內部邏輯混亂，補丁繁多
服務之間依賴糾纏不清
服務分布式部署
近期作者剛好遇到了一個問題，由于排查此問題涉及
hystrix,鏈路追蹤,分布式服務日志搜索,http,gc,thread pool,c3p0 connection pool,jdbc驅動,netty nio,cache,finalizer,Memory Aanlysis Tool,jvisualvm,yourkit
等諸多技術和工具绩蜻，個人認為是一個非常好的復雜問題排查的示例。
作者并非意圖借此文傳達問題的解決方案室埋。而是希望引領讀者能探索出自己解決問題的思路办绝，因此正文將采用問答式行文。
另外姚淆，本文也指出了國內技術網(wǎng)站上某些非常常見的錯誤結論孕蝉，由于cv大法(copy and paste)盛行的原因，那些錯誤流傳甚廣腌逢。任何從事高并發(fā)編程的工程師都應該避免那些常見錯誤降淮。
本文的相關鏈接和未出現(xiàn)在文中但在排查問題過程中參考的文章都會在文末給出，方便讀者后續(xù)研讀
第一章 源于告警
最近收到告警顯示，某接口偶爾有超時情況佳鳖，該接口調用鏈路復雜霍殴，從日志作為出發(fā)點去分析有種無從著力之感，好在最近剛部署了skywalking系吩，通過可視化頁面可看到調用鏈路的耗時情況来庭。
skywalking是Apache下的鏈路追蹤工具
[圖片上傳失敗...(image-2d361f-1602167711919)]
上圖左方是接口名，右方橫線表示執(zhí)行開始至結束的時間穿挨。
從上圖可以一目了然的看出月弛，a接口超時，是因為調用b接口引起科盛。接下來通過traceId分析日志帽衙，當時的情況是，ab項目都接入了skywalking贞绵，但是b項目沒有打印traceId厉萝；b項目是分布式部署的，但沒有使用elk收集日志但壮。
如何通過上述調用信息冀泻，知道此次調用路由到b接口對應服務的哪臺機器嘶居？ 通過時間戳去篩查日志顯然不是一個好主意缩挑，尤其是在日志量非常大的情況下。雖然b沒有接入skywalking宏胯，但是項目之間使用http協(xié)議進行交互溯祸，traceid將會通過http協(xié)議的header傳給b肢专。b中只要打印下請求的header即可。通過研究skywalking源碼可知header名稱焦辅，或者可以通過日志去大致推斷博杖。最終得到，traceid會使用base64編碼后在header中傳遞筷登。
b項目沒有接入elk剃根，如何搜索日志，要在所有機器挨個搜索嗎前方？ 作者寫了個python腳本狈醉，使用多線程執(zhí)行ssh遠程命令，并將命令的stdout重定向到當前程序的stdout(控制臺)惠险，臨時解決了此問題苗傅。
感悟:
日志是最重要的技術之一，先把日志系統(tǒng)做好班巩，才能避免996
第二章 心不喚物物不至渣慕，問題終于浮出水面
請求方使用的是Apache httpClient庫，處理方使用公司自研框架，底層使用netty處理http協(xié)議逊桦。
- 從圖中看出眨猎，a接口發(fā)出請求后，一段時間后b才開始執(zhí)行强经，這個時間差是什么原因導致的宵呛？ 通過日志確認，請求方提交請求時間和圖中鏈路開始時間一致夕凝。請求方提交請求時間指
調用hystrix方法或者http庫api(如httpClient.execute)的時間，提交后一定會被立刻執(zhí)行嗎户秤？不一定码秉，還要看庫內部使用的連接池執(zhí)行請求的策略。假如連接池無空閑時任務入隊等待鸡号，就會出現(xiàn)提交時間和請求開始執(zhí)行時間有較大時差的情況转砖。同時日志顯示，處理方任務處理開始時間和圖中鏈路開始時間一致鲸伴。在為自研框架寫的skywalking的agent插件中府蔗，處理方任務處理開始時間是指netty通過eventloop機制接受到完整http報文后，處理方執(zhí)行該請求對應任務的開始時間汞窗。
因此問題轉換為：
a中的hystrix任務是否在線程池隊列中排隊姓赤？ hystrix-dashboard提供線程池實時狀態(tài)查看，查看時并不繁忙仲吏，沒有任務在隊列中不铆，但不排除發(fā)生超時事件時恰巧出現(xiàn)了排隊情況。
a中的httpClient請求是否在線程池隊列中排隊裹唆？ 沒有類似hystrix-dashboard的工具可以看線程池情況誓斥，但可以借助一些其他工具。作者猜測jmx也許可以许帐，但并沒有去研究劳坑。
b中的netty eventloop是否出現(xiàn)排隊情況 通過查看自研框架代碼，發(fā)現(xiàn)框架使用bossGroup成畦，workerGroup兩個線程池距芬。workerGroup線程進行非阻塞讀寫的同時還要處理任務，一旦任務阻塞羡鸥，則會出現(xiàn)請求排隊的情況蔑穴。這個不太合理的設計可能是個突破口。繼續(xù)查看代碼
private int workerThreadSize = Runtime.getRuntime().availableProcessors() * 2 - 1;登錄服務器查看cpu信息惧浴，2個cpu存和，每個12核心，每個核心2個超線程，共48個邏輯processors捐腿，那么workerGroup的線程數(shù)為48*2-1=95纵朋，實際上非常多，因此排隊的情況也不太可能出現(xiàn)茄袖。
由于沒有足夠的信息分析上述情況操软，因此暫時放棄從此方向探索。
更深入的思考: 也可以查看skywalking源碼宪祥，確認hystrix和httpclient記錄起始時間聂薪。
使用grep "xxxx-xx-xx xx:xx:xx" full.log > simple.log命令導出臨近時間的日志。由于作者只關注超時請求的日志蝗羊，因此花費了大量時間卻什么都沒有發(fā)現(xiàn)藏澳。直到作者想查看b執(zhí)行任務之前發(fā)生了什么的時候，意外發(fā)現(xiàn)耀找，有將近4s的時間沒有打印任何日志翔悠，這和圖中超時時間吻合。該服務24小時都有大量流量野芒，不應該出現(xiàn)這種情況蓄愁，除非發(fā)生了gc，也就是stop the world狞悲。
<pre spellcheck="false" class="md-fences md-end-block ty-contain-cm modeLoaded" lang="" cid="n55" mdtype="fences" style="box-sizing: border-box; overflow: visible; font-family: var(--monospace); font-size: 0.9em; display: block; break-inside: avoid; text-align: left; white-space: normal; background-image: inherit; background-size: inherit; background-attachment: inherit; background-origin: inherit; background-clip: inherit; background-color: rgb(248, 248, 248); position: relative !important; border: 1px solid rgb(231, 234, 237); border-top-left-radius: 3px; border-top-right-radius: 3px; border-bottom-right-radius: 3px; border-bottom-left-radius: 3px; padding: 8px 4px 6px; margin-bottom: 15px; margin-top: 15px; width: inherit; background-position: inherit inherit; background-repeat: inherit inherit;">1074370.765: [GC (CMS Final Remark) [YG occupancy: 1161721 K (2831168 K)]1074370.765: [Rescan (parallel) , 0.0282716 secs]1074370.793: [weak refs processing, 3.9080203 secs]1074374.701: [class unloading, 0.0895909 secs]1074374.791: [scrub symbol table, 0.0193149 secs]1074374.810: [scrub string table, 0.0073974 secs][1 CMS-remark: 4456982K(5242880K)] 5618704K(8074048K), 4.0599904 secs] [Times: user=3.06 sys=1.86, real=4.06 secs]</pre>
-
使用的垃圾回收器是撮抓？
UseParNewGC + UseConcMarkSweepGC
-
這個日志的時間戳有什么問題嗎？
這個日志使用的時間戳是當前時間和應用啟動時間的差值摇锋，非常不便于排查問題胀滚，后續(xù)將添加-XX:+PrintGCDateStamps參數(shù)打印日期格式的時間戳。
-
這個日志反映了gc的什么情況乱投？
細心的同事從gc日志看出咽笼，weak refs processing使用了相當多的時間。作者推斷WeakReference往往用于緩存戚炫〗Ｐ蹋可能該問題是應用程序中的緩存導致的。(但weak refs processing真的是處理WeakReference嗎双肤？)
更深入的思考：
- WeakRefrence的引用對象何時被回收施掏？
參考WeakRefrence and gc，WeakRefrence引用的對象沒有其他強引用時茅糜，如果發(fā)生了gc會被回收七芭。很多文章錯誤地認為一旦發(fā)生gc，WeakRefrence的引用對象就會被回收蔑赘。
-
得到了什么處理方案狸驳？
本地緩存是正常代碼预明，無法去除，嘗試添加-XX:+ParallelRefProcEnabled并行處理引用耙箍，節(jié)省時間撰糠。請讀者注意，不要將此參數(shù)作為救命稻草辩昆，而忽略了真正的問題阅酪。
-
還有其他的措施嗎？
為了獲取更詳細的gc信息汁针，作者添加了更多打印gc日志的參數(shù)术辐，從現(xiàn)在來看當時這個操作，是非常有意義的施无。另外請注意最后一個參數(shù)术吗，原來最大年齡閾值為6，現(xiàn)改為15帆精。作者本是希望減少晉升到老年代的對象，沒想到無心插柳柳成蔭隧魄，此事后文會繼續(xù)討論卓练。
<pre spellcheck="false" class="md-fences md-end-block ty-contain-cm modeLoaded" lang="" cid="n82" mdtype="fences" style="box-sizing: border-box; overflow: visible; font-family: var(--monospace); font-size: 0.9em; display: block; break-inside: avoid; text-align: left; white-space: normal; background-image: inherit; background-size: inherit; background-attachment: inherit; background-origin: inherit; background-clip: inherit; background-color: rgb(248, 248, 248); position: relative !important; border: 1px solid rgb(231, 234, 237); border-top-left-radius: 3px; border-top-right-radius: 3px; border-bottom-right-radius: 3px; border-bottom-left-radius: 3px; padding: 8px 4px 6px; margin-bottom: 15px; margin-top: 15px; width: inherit; background-position: inherit inherit; background-repeat: inherit inherit;">-XX:+PrintReferenceGC
-XX:+PrintHeapAtGC
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintGC
-XX:+PrintAdaptiveSizePolicy
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails
-XX:+PrintTenuringDistribution
-XX:MaxTenuringThreshold=15</pre><pre spellcheck="false" class="md-fences md-end-block ty-contain-cm modeLoaded" lang="" cid="n84" mdtype="fences" style="box-sizing: border-box; overflow: visible; font-family: var(--monospace); font-size: 0.9em; display: block; break-inside: avoid; text-align: left; white-space: normal; background-image: inherit; background-size: inherit; background-attachment: inherit; background-origin: inherit; background-clip: inherit; background-color: rgb(248, 248, 248); position: relative !important; border: 1px solid rgb(231, 234, 237); border-top-left-radius: 3px; border-top-right-radius: 3px; border-bottom-right-radius: 3px; border-bottom-left-radius: 3px; padding: 8px 4px 6px; margin-bottom: 15px; margin-top: 15px; width: inherit; background-position: inherit inherit; background-repeat: inherit inherit;">2020-07-06T13:41:27.510+0800: 98027.086: [GC (CMS Final Remark) [YG occupancy: 1143054 K (2831168 K)]2020-07-06T13:41:27.511+0800: 98027.086: [Rescan (parallel) , 0.1128933 secs]2020-07-06T13:41:27.624+0800: 98027.199: [weak refs processing2020-07-06T13:41:27.624+0800: 98027.199: [SoftReference, 1487 refs, 0.0040026 secs]2020-07-06T13:41:27.628+0800: 98027.203: [WeakReference, 15243 refs, 0.0061822 secs]2020-07-06T13:41:27.634+0800: 98027.209: [FinalReference, 45882 refs, 0.3683047 secs]2020-07-06T13:41:28.002+0800: 98027.578: [PhantomReference, 0 refs, 1 refs, 0.0032547 secs]2020-07-06T13:41:28.005+0800: 98027.581: [JNI Weak Reference, 0.0000793 secs], 0.3819463 secs]2020-07-06T13:41:28.005+0800: 98027.581: [class unloading, 0.1211467 secs]2020-07-06T13:41:28.127+0800: 98027.702: [scrub symbol table, 0.0214804 secs]2020-07-06T13:41:28.148+0800: 98027.724: [scrub string table, 0.0116539 secs][1 CMS-remark: 4457263K(5242880K)] 5600318K(8074048K), 0.6552275 secs] [Times: user=11.70 sys=3.07, real=0.65 secs] </pre>
<pre spellcheck="false" class="md-fences md-end-block ty-contain-cm modeLoaded" lang="java" cid="n196" mdtype="fences" style="box-sizing: border-box; overflow: visible; font-family: var(--monospace); font-size: 0.9em; display: block; break-inside: avoid; text-align: left; white-space: normal; background-image: inherit; background-size: inherit; background-attachment: inherit; background-origin: inherit; background-clip: inherit; background-color: rgb(248, 248, 248); position: relative !important; border: 1px solid rgb(231, 234, 237); border-top-left-radius: 3px; border-top-right-radius: 3px; border-bottom-right-radius: 3px; border-bottom-left-radius: 3px; padding: 8px 4px 6px; margin-bottom: 15px; margin-top: 15px; width: inherit; background-position: inherit inherit; background-repeat: inherit inherit;">dataSource.setMinPoolSize(properties.getMinPoolSize());
dataSource.setMaxPoolSize(properties.getMaxPoolSize());
dataSource.setInitialPoolSize(10);
dataSource.setMaxIdleTime(60);</pre><pre spellcheck="false" class="md-fences md-end-block ty-contain-cm modeLoaded" lang="" cid="n211" mdtype="fences" style="box-sizing: border-box; overflow: visible; font-family: var(--monospace); font-size: 0.9em; display: block; break-inside: avoid; text-align: left; white-space: normal; background-image: inherit; background-size: inherit; background-attachment: inherit; background-origin: inherit; background-clip: inherit; background-color: rgb(248, 248, 248); position: relative !important; border: 1px solid rgb(231, 234, 237); border-top-left-radius: 3px; border-top-right-radius: 3px; border-bottom-right-radius: 3px; border-bottom-left-radius: 3px; padding: 8px 4px 6px; margin-bottom: 15px; margin-top: 15px; width: inherit; background-position: inherit inherit; background-repeat: inherit inherit;">C3P0
dataSource.setMinPoolSize(100);
dataSource.setMaxPoolSize(100);
dataSource.setInitialPoolSize(100);
dataSource.setMaxIdleTime(10);
?
hikari
config.setMaximumPoolSize(100);
hikari此配置的含義是最小值和最大值都是100</pre>weakRefrence and gc How do I find what's getting promoted to my old generation? is memory leak?why java.lang.ref.Finalizer eat so much memory The Secret Life Of The Finalizer JVM 源碼分析之 FinalReference 完全解讀
參考文獻
由于日常還需要響應業(yè)務需求，以及cms gc每隔10小時觸發(fā)一次购啄，此問題排查共計耗時2周
調整年齡閾值為15時襟企，線上Survivor區(qū)可能會溢出，需要關注狮含。
如果內存快照太大顽悼，需要調節(jié)mat和jvisualvm的jvm啟動參數(shù)
作者使用5.0.5版本jdbc驅動，而在5.1.21及以上版本不再使用finalizer機制
為了知道FinalReference回收機制几迄，作者曾試圖編譯一個debug版本的jdk打印更詳細的日志蔚龙。
jedis client連接池也存在類似配置錯誤的問題，但由于其內存占用小映胁，并沒有產(chǎn)生很大影響
作者之后會調研G1收集器對中長期存活對象是否有更好的處理方式
第七章 其他細節(jié)
-
如果下次遇到類似的gc問題木羹，如何去思考？
首先解孙，解決問題后坑填，需要去思考問題的本質。UseParNewGC + UseConcMarkSweepGC將gc分為了年輕代和老年代弛姜。但有些對象生命周期既不短脐瑰，也不長，他們熬過了多次young gc進入老年代廷臼，然后生命才終結苍在。這常見于本地緩存绝页，連接池，監(jiān)控忌穿，這些技術都會涉及到將對象存儲一段較長時間的行為抒寂。當站在這個維度總結上述c3p0的問題，舉一反三會更容易掠剑。
-
如何在復雜的問題中屈芜，一步一步找到突破口
工欲善其事，必先利其器朴译，使用優(yōu)秀的工具井佑。
有一定的知識儲備才知道思考的方向。
解決問題時遇到不了解的知識需要臨時學習眠寿。
第六章 深入探討
深入的思考：
c3p0參數(shù)眾多躬翁，作者若干年前曾看過c3p0很容易誤配的文章，今日終于親身體驗盯拱。
- 為什么c3p0容易誤配呢盒发？
- 參數(shù)名稱曖昧不清
- 源碼無注釋
- 官方文檔為英文，中文用戶更容易誤配
- cv大法(copy and paste)
hikari的wiki會非常貼心的告訴你哪些是重要配置狡逢，哪些不重要宁舰。不得不說，日本人的工匠精神值得學習奢浑。后續(xù)作者將替換c3p0連接池為hikari蛮艰。
- c3p0為何設置maxIdleTime這樣的參數(shù)？它和maxConnectionAge看上去很像
這是個好問題雀彼，但作者目前不知道確切答案壤蚜。
- 為什么調大年齡閾值，jdbc連接數(shù)減少了徊哑？
- 未調大年齡閾值之前袜刷，線上默認最大年齡閾值為6
- young gc間隔約10s
- MaxIdleTime為60s
下面詳細說下jdbc連接生命周期，請注意gc前莺丑，gc后水泉，gc時等用語的區(qū)分。
- c3p0創(chuàng)建連接后窒盐，第1次young gc前草则，此時連接age為0
- 第6次young gc前，age為5蟹漓，此時連接空閑時間有可能超過60s炕横，連接池釋放連接，第6次young gc會被回收葡粒。連接生命周期終結份殿。
- 若空閑時間沒有超過60s膜钓，連接池未釋放連接，第6次young gc不會回收卿嘲。
- 第6次young gc后颂斜，此時age為6，在第7次gc前拾枣，空閑時間肯定超過60s了沃疮，連接池釋放連接。
- 第7次young gc時梅肤，年齡為7司蔬，盡管連接池已經(jīng)釋放連接，但連接年齡超過閾值從而晉升到老年代姨蝴。
可以看到俊啼，這是個精妙的巧合，有可能在連接池釋放連接后左医，下次gc本來可以回收了授帕，但卻因為滿足最大年齡閾值，晉升到了老年代浮梢。因此調大年齡閾值避免了這種情況的晉升跛十。
如果你只想丟棄高于minPoolSize數(shù)目的空閑連接，你的選擇應該是maxIdleTimeExcessConnections黔寇。
問題在于一旦連接被丟棄后，若數(shù)目小于minPoolSize斩萌，c3p0連接池將會立即重建連接以保證連接數(shù)不會低于minPoolSize缝裤。
maxIdleTime：一個連接可保持的最大空閑時間，單位秒颊郎，大于此時間就會被丟棄憋飞。請注意丟棄規(guī)則和minPoolSize完全沒關系。
maxIdleTime
Default: 0
Seconds a Connection can remain pooled but unused before being discarded. Zero means idle connections never expire.
maxIdleTimeExcessConnections
Default: 0
Number of seconds that Connections in excess of
minPoolSizeshould be permitted to remain idle in the pool before being culled. Intended for applications that wish to aggressively minimize the number of open Connections, shrinking the pool back towards minPoolSize if, following a spike, the load level diminishes and Connections acquired are no longer needed. IfmaxIdleTimeis set,maxIdleTimeExcessConnectionsshould be smaller if the parameter is to have any effect. Zero means no enforcement, excess Connections are not idled out.c3p0源碼無注釋姆吭，查詢官方文檔榛做。
測試發(fā)現(xiàn)hikari連接數(shù)長期穩(wěn)定在100，10s后c3p0連接數(shù)劇增99内狸。
之后作者使用如下配置检眯，對c3p0和hikari連接池進行了對比測試。循環(huán)執(zhí)行：取出一個jdbc連接并關閉昆淡。
數(shù)目比為 17000+:2000+锰瘸，連接數(shù)大幅下降，但2000+仍然不太正常昂灵。項目中只有幾個連接池而已避凝。最大理論值為100舞萄。從快照得知每個jdbc連接的retained size為0.1M。則內存占用比為：1700M:200M管削。
請注意倒脓，此操作會導致短暫的stop the world。作者的機器是24c + 8g含思，gc pause不到2s崎弃。有趣的是，后來作者還因為這個操作引起的高耗時排查了好久呢茸俭。
jmap -histo pid | grep com.mysql.jdbc.Connection
查看jdbc連接數(shù)目命令：
[圖片上傳失敗...(image-564a8b-1602167711915)]
[圖片上傳失敗...(image-846d89-1602167711915)]
曲線比之前平穩(wěn)很多吊履。gc前后速率對比如下，后者是前者的1/3!
[圖片上傳失敗...(image-80220-1602167711914)]
我們繼續(xù)探究调鬓。由于之前加了-XX:MaxTenuringThreshold=15參數(shù)艇炎，有了新的gc情況。
這最終被證明是錯誤的想法
請注意setMaxIdleTime(60)腾窝，作者認為其邏輯是缀踪，如果當前空閑連接數(shù)大于minPoolSize,且空閑時間超過60s，連接池就會銷毀多余的空閑連接虹脯。
查看項目代碼驴娃，都是采用jdbcTemplate，沒有發(fā)現(xiàn)連接未回收情況循集。然后去查看c3p0連接池配置情況唇敞。
第五章 是誰在頻繁創(chuàng)建jdbc連接并丟棄
感悟：踏破鐵鞋無覓處，得來全不費功夫
后話：
由于首先使用jvisualvm的retained size沒有查出問題咒彤，因此后續(xù)就沒有使用mat的retained heap了疆柔。這又讓作者繞了遠路，在mat中镶柱，根據(jù)histogram -> retained heap排序旷档，Connection排在第一位。
histogram -> retained heap展示了某個類的保留大小
[圖片上傳失敗...(image-f2fff1-1602167711913)]
[圖片上傳失敗...(image-57c646-1602167711914)]
-
在作者的系統(tǒng)中歇拆，F(xiàn)inalizer都引用了哪些類
作者根據(jù)id鞋屈，大小排序，主要關注了三個類
id是對象在jvm內存中的地址故觅，根據(jù)gc日志可以看到內存地址的范圍
-
java.net.SocksSocketImpl
作者懷疑項目中是否有httpClient資源釋放問題,遺憾的是沒發(fā)現(xiàn)
-
com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallerImpl
作者寫了測試用例生成大量的UnmarshallerImpl厂庇，但是gc時Finalizer處理的很快
-
com.mysql.jdbc.Connection
作者關注它只是因為經(jīng)常見到它，但不認為是jdbc連接的問題输吏，直到看了這個次要答案is memory leak?why java.lang.ref.Finalizer eat so much memory宋列。jdbc連接池也會資源泄露嗎？在堆快照中搜索發(fā)現(xiàn)评也。
-
更深入的思考：
當一個類(以下稱為a)覆寫了Object的finalize方法炼杖，且該方法不為空方法灭返。那么在a創(chuàng)建過程中。還會同時創(chuàng)建一個Finalizer對象坤邪，F(xiàn)inalizer對象會維護一個指向a的引用熙含。當發(fā)生gc(包括老年代gc)時，垃圾收集器會檢查除Finalizer對象引用a外是否還有其他引用指向a艇纺。如果沒有怎静，則將Finalizer對象加入x隊列，并通過FinalizerThread異步執(zhí)行Finalizer引用的a對象的finalize方法黔衡。執(zhí)行完畢后移除x隊列蚓聘。此時a的所有引用均不可達，可以對a進行回收盟劫。
- 可以看出夜牡，覆寫Object的finalize方法且方法不為空的類的實例，至少需要兩次gc才能回收侣签，第一次gc后只能先入隊塘装，為什么需要先入隊呢？
因為執(zhí)行finalize需要時間影所，如果在gc中執(zhí)行這部分代碼會讓gc的時間變得更長且不可控蹦肴。- 很多文章說FinalizerThread優(yōu)先級低，是這樣嗎猴娩？
不一定阴幌，作者使用的jdk中FinalizerThread優(yōu)先級為8，比普通線程優(yōu)先級5高卷中。更何況即使優(yōu)先級低矛双，只要cpu負載不高，也能分到足夠的cpu時間片執(zhí)行任務仓坞。作者在堆快照中看到背零，x隊列為空腰吟。- jdk為什么設計Finalizer類
有一類對象无埃，需要通過調用api的方式宣告其生命的結束，如Socket對象需要調用close方法(持有Tcp連接資源的對象往往都是這樣的)毛雇。這類對象的引用被gc了嫉称，不代表底層的資源釋放了。為了解決用戶忘記調用釋放資源的api而導致的資源泄露問題灵疮，設計了Finalizer類- 需要設計這個Finalizer類嗎织阅？
這是個哲學問題，如果你認為底層資源的釋放也屬于gc的范疇震捣，那么應該設計這個類荔棉。如果你認為底層資源的釋放是jdk用戶應該考慮的問題闹炉，那么不應該設計這個類。但是這個設計被認為是糟糕的設計润樱，并在jdk9廢棄渣触，但問題沒有解決。本質上來說壹若，所有引用釋放后嗅钻，資源也要釋放，但是資源釋放需要時間店展，若在gc中釋放資源會導致gc時間變長养篓。因此資源的釋放總是需要異步去處理的。- Finalizer機制可以避免用戶忘記資源釋放赂蕴，是否可以用來保證分布式鎖的釋放柳弄？
放棄這個想法。- Finalizer機制還有其他缺點嗎睡腿？
很多语御，可參考*Effective Java* 筆者也試用了yourkit，其中有統(tǒng)計實現(xiàn)finalize的類的實例數(shù)的功能席怪。-
Finalizer對象是什么应闯？
Finalizer是上文中提到的FinalReference的子類。
可以看到保留空間最大的是Finalizer對象
[圖片上傳失敗...(image-8e21ff-1602167711914)]
該視圖展示實例對象的各項指標
以下是mat的dominator_tree挂捻。
人是有惰性的碉纺，作者也如此。作者使用過多次jvisualvm刻撒，因此并不想嘗試使用mat骨田。后來在使用過程中發(fā)現(xiàn)mat的shallow heap,retained heap與jvisualvm的shallow size(大小)和retained size(保留)值差距很大，不知道是不是兼容性問題声怔。但是mat的數(shù)據(jù)對作者更有用态贤。最終也是通過mat確定了問題。使用mat需要注意打開preferences -> Memory Aanlysis -> keep unreacheable objects醋火。
[圖片上傳失敗...(image-155947-1602167711914)]
[圖片上傳失敗...(image-413fea-1602167711914)]
類總數(shù)有21,274個悠汽。
使用jvisualvm裝載快照后，根據(jù)大小和保留大小排序芥驳，完全看不到任何線索柿冲。作者迷失在了各種對象堆砌而成的汪洋大海中。
-
主要問題是cms remark耗時過長兆旬，手頭的資源是gc日志假抄，有什么更好的辦法去排查問題嗎？
先想想是否有一些可視化的工具，作者使用的是easygc
[圖片上傳失敗...(image-f9bf70-1602167711912)]
-
老年代增長速度正常嗎宿饱？
作者也無法確定其增長速度是否正常熏瞄，但很想知道是什么對象在不斷晉升到老年代，以下是作者服務的一些情況谬以。
作者的服務是web服務巴刻，并不維護用戶狀態(tài)。
緩存主要使用redis蛉签，也使用了少量本地緩存胡陪。
-
下一步朝什么方向探索？
由于線上環(huán)境不方便dump內存快照碍舍，因此先嘗試分析測試環(huán)境內存快照柠座。
-
分析內存快照面臨的主要的難題是什么？
這對作者來說是一個比較陌生的領域片橡，而相關文章多是分析內存泄露妈经。作者想知道什么對象在不斷晉升到老年代。此文給了作者一些啟發(fā)捧书，How do I find what's getting promoted to my old generation?
上述文章使作者明白object id是對象在jvm內存中的地址吹泡。
-
使用什么工具分析
作者首先使用java自帶的jvisualvm，在使用oql查詢語言時發(fā)現(xiàn)和網(wǎng)上部分文章介紹的語法不兼容经瓷，后改用eclipse的Memory Aanlysis Tool(簡稱mat)爆哑，后來也使用了yourkit(收費,15天試用期)。工具各有優(yōu)缺點舆吮。
根據(jù)上面講到的gc日志揭朝，發(fā)現(xiàn)最耗時的是FinalReference。由于當時作者對此認知不足色冀，沒有第一時間查此問題潭袱，導致走了不少彎路，這里麻煩讀者一起重走一趟彎路锋恬。
第四章 大海撈針
感悟：既然做屯换，就拼盡全力做到最好。
-
-XX:+ParallelRefProcEnabled有效果嗎与学？
有很大的效果彤悔。使用
java -XX:+UseConcMarkSweepGC -XX:+PrintFlagsFinal | grep ParallelGCThreads
命令查看并發(fā)執(zhí)行的線程數(shù)目為33，由于實際核心數(shù)目為24(超線程后為48)癣防，不妨按24計算蜗巧，如果原來的情況gc還是3.9080203s的話掌眠，粗略計算蕾盯，時間應該會下降至3.908/24=0.1628s，此處FinalReference 處理時間為0.3683047s。因為無法得知此次gc在沒有-XX:+ParallelRefProcEnabled參數(shù)下會是多久级遭，但從數(shù)量級上來看望拖，這個數(shù)據(jù)是基本合理的。
-
weak refs processing是指WeakReference處理嗎挫鸽？
不说敏！顯然，weak refs processing包含了SoftReference丢郊，WeakReference盔沫，F(xiàn)inalReference，PhantomReference枫匾，JNI Weak Reference架诞。而最耗時的是FinalReference。
-
FinalReference是什么干茉？
當時作者沒有給與足夠關注谴忧，后文會繼續(xù)談論此問題。如果早點關注到此類角虫，會讓后續(xù)的探索更加堅定沾谓。
對于作者來說，并不缺乏堅定的信念戳鹅，因此這不會導致問題均驶。但是對于意志不夠堅定的人來說，可能會導致后續(xù)的探索無法完成枫虏。
-
問題解決了嗎辣恋？
沒有。這個優(yōu)化已經(jīng)非常大模软，老年代回收650ms時間不長伟骨，但差強人意。即使不繼續(xù)探究也無可厚非燃异。但以作者的性格來講携狭，這個問題沒有解決。
此時有更充分的日志了回俐，一天后逛腿，再次查看full gc
第三章 問題已經(jīng)解決？
感悟:
問題總是偶然發(fā)現(xiàn)的仅颇，但它似乎聽到了你的呼喚单默。
