by shihang.mai
rocketMq監(jiān)控界面TPS上不去
Cloud-nms-dlq模塊
rocketMq監(jiān)控界面顯示Tps很低买猖，只有幾十
瘋狂GC->內(nèi)存增大到8G改橘，垃圾回收器改為G1，從TPS0->幾百
-
用arthas
thread -n all發(fā)現(xiàn)很多業(yè)務(wù)線程在waiting狀態(tài),再用
thread 線程號查看某個(gè)waiting線程的堆棧,發(fā)現(xiàn)在wait另外一個(gè)線程,然后拿到線程的16進(jìn)制數(shù)轉(zhuǎn)換10執(zhí)行后
thread 線程號在線程棧中找到究竟waiting什么鬼玉控，最終發(fā)現(xiàn)是關(guān)于logback日志的,CachingDateFormatter類加了Sync
JVM優(yōu)化CachingDateFormatter.png -
同時(shí)引入了JMC
啟動(dòng)時(shí)加入jvm參數(shù)
-Djava.net.preferIPv4Stack=true -XX:+FlightRecorder -XX:FlightRecorderOptions=stackdepth=128 -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints然后命令開始搜集飞主、結(jié)束
jcmd 9955 JFR.start name=MyRecording settings=profile jcmd 9955 JFR.dump name=MyRecording filename=/home/yundiao/1736.jfr jcmd 9955 JFR.stop name=MyRecording然后將jfr文件用飛行器分析，結(jié)果和arthas分析一樣
-
就是多線程寫日志文件，導(dǎo)致IO競爭(原本直接在yml直接設(shè)置日志)
- 異步日志碌识。但會(huì)有溢出碾篡，重啟時(shí)會(huì)丟失日志
- 按線程寫文件
選擇按線程寫文件解決IO競爭(改為引入logback.xml配置)
-
logback有一個(gè)叫SiftingAppender的類，可以做按線程寫日志筏餐，只需注入自定義Discriminator开泽，日志名分發(fā)器
public class ThreadDiscriminator extends ContextBasedDiscriminator { String KEY ="threadName"; public String getDiscriminatingValue(ILoggingEvent event) { return event.getThreadName(); } public String getDefaultValue() { return KEY; } public String getKey() { return KEY; } public void setKey(String key) { this.KEY = key; } }日志配置增加appender
<appender name="frameworkthread" class="ch.qos.logback.classic.sift.SiftingAppender"> <discriminator class="com.iwhalecloud.dlq.commonbean.ThreadDiscriminator"> <key>threadName</key> </discriminator> <sift> <appender name="FILE-${threadName}" class="ch.qos.logback.core.rolling.RollingFileAppender"> <encoder> <Encoding>UTF-8</Encoding> <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS}[%c][%thread][%X{tradeNo}][%p]-%m%n</pattern> </encoder> <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"> <fileNamePattern>${log.path}/%d{yyyy-MM-dd,aux}/${threadName}-%d{yyyy-MM-dd}.%i.log </fileNamePattern> <maxFileSize>100MB</maxFileSize> <maxHistory>3</maxHistory> </rollingPolicy> </appender> </sift> </appender> -
確實(shí)可以按線程寫日志，然后再看RocketMq的TPS魁瞪，竟然性能沒所提升穆律，還會(huì)下降。
-
然后再用JMC分析發(fā)現(xiàn)這次在AppenderBase.doAppender()导俘，然后查看源碼峦耘，發(fā)現(xiàn)這個(gè)方法是sync的，而這個(gè)方法是我上面的SiftingAppender入口
JMC分析結(jié)果 分析原因旅薄，在我獲取自己的SiftingAppender時(shí)辅髓，要經(jīng)過父類的這個(gè)方法，所以肯定更低Tps
-
然后看接口Appender的實(shí)現(xiàn)類有兩個(gè)基礎(chǔ)的抽象
-
非同步:UnsynchronizedAppenderBase,用了ThreadLocal
- 同步:AppenderBase,用sync
增加類UnsynchronizedSiftingAppenderBase extends UnsynchronizedAppenderBase
創(chuàng)建類ParrelSiftingAppender extends UnsynchronizedSiftingAppenderBase
修改SiftAction類,增加我的ParrelSiftingAppender的注冊分支
public class SiftAction extends Action implements InPlayListener { List<SaxEvent> seList; public SiftAction() { } public void begin(InterpretationContext ic, String name, Attributes attributes) throws ActionException { this.seList = new ArrayList(); ic.addInPlayListener(this); } public void end(InterpretationContext ic, String name) throws ActionException { ic.removeInPlayListener(this); Object o = ic.peekObject(); if (o instanceof SiftingAppender) { SiftingAppender sa = (SiftingAppender)o; Map<String, String> propertyMap = ic.getCopyOfPropertyMap(); AppenderFactoryUsingJoran appenderFactory = new AppenderFactoryUsingJoran(this.seList, sa.getDiscriminatorKey(), propertyMap); sa.setAppenderFactory(appenderFactory); } //增加判斷分支 } public void inPlay(SaxEvent event) { this.seList.add(event); } public List<SaxEvent> getSeList() { return this.seList; } }
-
看TPS 提高了大概5倍左右少梁，效果還行利朵，再用jmc分析，然后我崩潰了猎莲，竟然還有绍弟，出現(xiàn)在類UnsynchronizedSiftingAppenderBase
protected void append(E event) { if (this.isStarted()) { String discriminatingValue = this.discriminator.getDiscriminatingValue(event); long timestamp = this.getTimestamp(event); //競爭出現(xiàn)在這 Appender<E> appender = (Appender)this.appenderTracker.getOrCreate(discriminatingValue, timestamp); if (this.eventMarksEndOfLife(event)) { this.appenderTracker.endOfLife(discriminatingValue); } this.appenderTracker.removeStaleComponents(timestamp); appender.doAppend(event); } } 這不能忍，看一下源碼著洼，發(fā)現(xiàn)synchronized樟遣，getOrCreate是同步的。點(diǎn)進(jìn)去看LinkedHashMap做lru身笤，怪不得要加synchronized
-
然后開始修改appenderTracker
- 增加AbstractConcurrentMapComponentTracker,參考AbstractComponentTracker
- 增加ConcurrentMapAppenderTracker繼承AbstractConcurrentMapComponentTracker
- 修改UnsynchronizedSiftingAppenderBase使用ConcurrentMapAppenderTracker進(jìn)行Appender管理
最終提高了10倍豹悬。終于結(jié)束
-
總結(jié)
JVM調(diào)休logback多線程寫日志- TPS=0,內(nèi)存2g->8g，gc回收器改為G1液荸，TPS=0 -> TPS=幾百
- 用arthas和JMC分析出是因?yàn)槎嗑€程寫日志導(dǎo)致TPS低
- 首先直接用SiftingAppender進(jìn)行分線程寫日志瞻佛，確實(shí)可以做到分線程寫日志，但是觀察TPS比之前更低
- 原因:進(jìn)入SiftingAppender前需要進(jìn)入父類AppenderBase.doAppender(),這個(gè)是sync的娇钱，同步向上提高了伤柄，所以TPS比以前低很正常
- 查看Appender接口，發(fā)現(xiàn)有實(shí)現(xiàn)類UnSyncAppenderBase,所以參考SiftingAppender實(shí)現(xiàn)
- ?類UnSyncSiftingAppenderBase extends UnSyncAppenderBase
- ?類ParrelSiftingAppender extends UnSyncSiftingAppenderBase
- 修改SiftAction,注冊上我寫的ParrelSiftingAppender
- 此時(shí)發(fā)現(xiàn)TPS提高了5倍左右文搂，再用JMC分析适刀，發(fā)現(xiàn)還有IO競爭
- 原因:UnSyncSiftingAppenderBase類會(huì)調(diào)用AbstractComponentTracker的sync方法getOrCreate()
- 因?yàn)锳bstractComponentTracker用LinkedHashMap做LRU,LinkedHashMap非線程安全，?sync正常
- 用ConcurrentMap替代LinkedHashMap
- ?類AbstractConcurrentMapComponentTracker
- ?類ConcurrentMapAppenderTracker extends AbstractConcurrentMapComponentTracker
- 修改UnSyncSiftingAppenderBase類調(diào)用AbstractConcurrentMapComponentTracker的getOrCreate()
- TPS提高了10倍煤蹭。
- 原本業(yè)務(wù)中用到日志的地方都要修改笔喉，?MDC.put("threadName", xxx)取视。
- 自定義類ThreadDiscriminator繼承ContextBasedDiscriminator就可以免去修改業(yè)務(wù)的所有日志的地方
