JVM-排查问题

2020-12-23 本文已影响0人麦大大吃不胖

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多线程写日志
1. TPS=0,内存2g->8g，gc回收器改为G1，TPS=0 -> TPS=几百
2. 用arthas和JMC分析出是因为多线程写日志导致TPS低
3. 首先直接用SiftingAppender进行分线程写日志，确实可以做到分线程写日志，但是观察TPS比之前更低
  - 原因:进入SiftingAppender前需要进入父类AppenderBase.doAppender(),这个是sync的，同步向上提高了，所以TPS比以前低很正常
4. 查看Appender接口，发现有实现类UnSyncAppenderBase,所以参考SiftingAppender实现
  - ➕类UnSyncSiftingAppenderBase extends UnSyncAppenderBase
  - ➕类ParrelSiftingAppender extends UnSyncSiftingAppenderBase
  - 修改SiftAction,注册上我写的ParrelSiftingAppender
5. 此时发现TPS提高了5倍左右，再用JMC分析，发现还有IO竞争
  - 原因:UnSyncSiftingAppenderBase类会调用AbstractComponentTracker的sync方法getOrCreate()
  - 因为AbstractComponentTracker用LinkedHashMap做LRU,LinkedHashMap非线程安全，➕sync正常
6. 用ConcurrentMap替代LinkedHashMap
  - ➕类AbstractConcurrentMapComponentTracker
  - ➕类ConcurrentMapAppenderTracker extends AbstractConcurrentMapComponentTracker
  - 修改UnSyncSiftingAppenderBase类调用AbstractConcurrentMapComponentTracker的getOrCreate()
7. TPS提高了10倍。
  - 原本业务中用到日志的地方都要修改，➕MDC.put("threadName", xxx)。
  - 自定义类ThreadDiscriminator继承ContextBasedDiscriminator就可以免去修改业务的所有日志的地方

JVM-排查问题

猜你喜欢

热点阅读