by shihang.mai
rocketMq监控界面TPS上不去
Cloud-nms-dlq模块
rocketMq监控界面显示Tps很低，只有几十
疯狂GC->内存增大到8G，垃圾回收器改为G1，从TPS0->几百
-
用arthas
thread -n all发现很多业务线程在waiting状态,再用
thread 线程号查看某个waiting线程的堆栈,发现在wait另外一个线程,然后拿到线程的16进制数转换10执行后
thread 线程号在线程栈中找到究竟waiting什么鬼，最终发现是关于logback日志的,CachingDateFormatter类加了Sync
JVM优化CachingDateFormatter.png
-
同时引入了JMC
启动时加入jvm参数
-Djava.net.preferIPv4Stack=true -XX:+FlightRecorder -XX:FlightRecorderOptions=stackdepth=128 -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints然后命令开始搜集、结束
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文件用飞行器分析，结果和arthas分析一样
-
就是多线程写日志文件，导致IO竞争(原本直接在yml直接设置日志)
- 异步日志。但会有溢出，重启时会丢失日志
- 按线程写文件
-
选择按线程写文件解决IO竞争(改为引入logback.xml配置)
-
logback有一个叫SiftingAppender的类，可以做按线程写日志，只需注入自定义Discriminator，日志名分发器
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> -
确实可以按线程写日志，然后再看RocketMq的TPS，竟然性能没所提升，还会下降。
-
然后再用JMC分析发现这次在AppenderBase.doAppender()，然后查看源码，发现这个方法是sync的，而这个方法是我上面的SiftingAppender入口
JMC分析结果
-
分析原因，在我获取自己的SiftingAppender时，要经过父类的这个方法，所以肯定更低Tps
-
-
然后看接口Appender的实现类有两个基础的抽象
-
非同步:UnsynchronizedAppenderBase,用了ThreadLocal
- 同步:AppenderBase,用sync
增加类UnsynchronizedSiftingAppenderBase extends UnsynchronizedAppenderBase
创建类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分析，然后我崩溃了，竟然还有，出现在类UnsynchronizedSiftingAppenderBase
protected void append(E event) { if (this.isStarted()) { String discriminatingValue = this.discriminator.getDiscriminatingValue(event); long timestamp = this.getTimestamp(event); //竞争出现在这 Appender<E> appender = (Appender)this.appenderTracker.getOrCreate(discriminatingValue, timestamp); if (this.eventMarksEndOfLife(event)) { this.appenderTracker.endOfLife(discriminatingValue); } this.appenderTracker.removeStaleComponents(timestamp); appender.doAppend(event); } } -
这不能忍，看一下源码，发现synchronized，getOrCreate是同步的。点进去看LinkedHashMap做lru，怪不得要加synchronized
-
然后开始修改appenderTracker
- 增加AbstractConcurrentMapComponentTracker,参考AbstractComponentTracker
- 增加ConcurrentMapAppenderTracker继承AbstractConcurrentMapComponentTracker
- 修改UnsynchronizedSiftingAppenderBase使用ConcurrentMapAppenderTracker进行Appender管理
-
最终提高了10倍。终于结束
-
总结
JVM调休logback多线程写日志
- TPS=0,内存2g->8g，gc回收器改为G1，TPS=0 -> TPS=几百
- 用arthas和JMC分析出是因为多线程写日志导致TPS低
- 首先直接用SiftingAppender进行分线程写日志，确实可以做到分线程写日志，但是观察TPS比之前更低
- 原因:进入SiftingAppender前需要进入父类AppenderBase.doAppender(),这个是sync的，同步向上提高了，所以TPS比以前低很正常
- 查看Appender接口，发现有实现类UnSyncAppenderBase,所以参考SiftingAppender实现
- ➕类UnSyncSiftingAppenderBase extends UnSyncAppenderBase
- ➕类ParrelSiftingAppender extends UnSyncSiftingAppenderBase
- 修改SiftAction,注册上我写的ParrelSiftingAppender
- 此时发现TPS提高了5倍左右，再用JMC分析，发现还有IO竞争
- 原因:UnSyncSiftingAppenderBase类会调用AbstractComponentTracker的sync方法getOrCreate()
- 因为AbstractComponentTracker用LinkedHashMap做LRU,LinkedHashMap非线程安全，➕sync正常
- 用ConcurrentMap替代LinkedHashMap
- ➕类AbstractConcurrentMapComponentTracker
- ➕类ConcurrentMapAppenderTracker extends AbstractConcurrentMapComponentTracker
- 修改UnSyncSiftingAppenderBase类调用AbstractConcurrentMapComponentTracker的getOrCreate()
- TPS提高了10倍。
- 原本业务中用到日志的地方都要修改，➕MDC.put("threadName", xxx)。
- 自定义类ThreadDiscriminator继承ContextBasedDiscriminator就可以免去修改业务的所有日志的地方
网友评论