JVM系列(三十六) JVM调优实战-CPU过高 Log4j2异步日志IO问题定位本文已经通过top,iotop,dst

CPU过高 Log4j2异步日志问题定位实战

上面一篇文章，我们已经介绍了这次事故的经过，事故过程中我们处理问题的方式及事故的产生原因和事故问题排查定位，解决问题的过程

上次事故的出现，一共花费了2个小时，虽然1小时后，紧急切换流量已经能够正常访问，但是事故原因未定位到，对我们来说就是没有解决问题，如果再来相同的问题，我们能否有更快的解决办法，或者怎么样能够更快的排查定位到问题呢？

本文我们就通过实战，我们要首先能够定位是日志产生的问题，而不是别的问题，才能快速解决这个问题

本文就教会你如何快速的定位问题

1.实战并快速定位日志输出问题

1.1 新建SpringBoot项目配置如下

目录结构如下

application.properties 配置端口信息

server.port=8078

resources 目录下新建log4j2的配置信息log4j2.component.properties

# 设置异步日志系统属性
log4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

resources 目录下新建log4j2的配置信息log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration monitorInterval="60">

    <Properties>
        <!-- 日志输出格式 -->
        <Property name="log.pattern"
                  value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{30} - [%method,%line] - %msg%n"/>
        <!-- 活动文件的大小 -->
        <Property name="max.file.size" value="100MB"/>
        <Property name="logRootDir" value="aaa"/>
        <!-- 保留的归档文件的最大数量 -->
        <Property name="rolloverStrategy.max" value="30"/>
    </Properties>
    <Appenders>
        <!-- 控制台输出 -->
        <Console name="stdoutAppender" target="SYSTEM_OUT">
            <!--输出日志的格式-->
            <PatternLayout pattern="${log.pattern}" charset="UTF-8"/>
        </Console>

        <RollingFile name="rollingFileAppender" fileName="${logRootDir}/app.log"
                     filePattern="${logRootDir}/app-%d{yyyy-MM-dd}.%i.log">
            <PatternLayout pattern="${log.pattern}" charset="UTF-8"/>
            <Policies>
                <TimeBasedTriggeringPolicy/>
                <SizeBasedTriggeringPolicy size="${max.file.size}"/>
            </Policies>
            <DefaultRolloverStrategy max="${rolloverStrategy.max}"/>
        </RollingFile>

        <RollingFile name="callListLogFileAppender"
                     fileName="${logRootDir}/callist.log"
                     filePattern="${logRootDir}/callist-%d{yyyyMMdd}.%i.log">
            <Policies>
                <TimeBasedTriggeringPolicy/>
                <SizeBasedTriggeringPolicy size="${max.file.size}"/>
            </Policies>
            <DefaultRolloverStrategy max="200"/>
        </RollingFile>
    </Appenders>
    <Loggers>
        <Logger name="CallList" additivity="false">
            <appender-ref ref="callListLogFileAppender"/>
        </Logger>
        <Root level="INFO" includeLocation="true">
            <appender-ref ref="rollingFileAppender"/>
            <appender-ref ref="stdoutAppender"/>
        </Root>
    </Loggers>

</configuration>

1.2 代码如下

启动程序代码如下：

@SpringBootApplication
public class JvmtestApplication {

    public static void main(String[] args) {
        SpringApplication.run(JvmtestApplication.class, args);
    }

}

TestController 模拟日志输出

通过curl 127.0.0.1:8078/writelog url触发请求
然后Json输出大对象，打印日志
log4j2 会异步打印日志
此过程，我们分析下如何定位问题

package com.jzj.jvmtest.font;

import cn.hutool.json.JSONUtil;
import com.jzj.jvmtest.entity.UserInfo;
import com.jzj.jvmtest.mythread.MyTask;
import lombok.extern.slf4j.Slf4j;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;

@RestController
@Slf4j
public class TestController {

    /**
     * 新建一个固定大小的线程池
     */
    private static ExecutorService executorService = Executors.newFixedThreadPool(5);


    public static Object TEST_LOCK = new Object();


    @GetMapping("/ping")
    private String ping() {
        log.info("sssss");
        return "pong";
    }

    @GetMapping("/test")
    private String test(Integer num) {
        try {
            byte[] b = null;
            for (int i = 1; i <= num; i++) {
                //设置 2M的对象
                log.info("======== " + i + "次添加2M对象");
                b = new byte[2 * 1024 * 1024];
                Thread.sleep(3000);

            }
        } catch (Exception e) {
            log.error(e.getMessage(), e);
        }

        return "success";

    }


    @GetMapping("/cpu")
    private String cpu() {
        MyTask task1 = new MyTask();
        MyTask task2 = new MyTask();
        executorService.execute(task1);
        executorService.execute(task2);
        return "ok";
    }


    @GetMapping("/writelog")
    private String writelog(Integer num) {

        //默认 循环 10次
        if (null == num) {
            num = 10;
        }

        //循环 number次
        for (int n = 0; n < num; n++) {

            //每一次都新开线程 处理，打印日志

                List<UserInfo> userInfos = new ArrayList<>();
                for (int i = 0; i < 3000; i++) {
                    userInfos.add(UserInfo.getInstance());
                }
                log.info("日志输出 userList:{}", JSONUtil.toJsonStr(userInfos));
            try {
                Thread.sleep(1);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }

        }

        return "ok";
    }
}

UserInfo对象如下：

package com.jzj.jvmtest.entity;

import cn.hutool.core.util.RandomUtil;
import lombok.Data;

@Data
public class UserInfo {
    private String name1;
    private String name2;
    private String name3;
    private String name4;
    private String name5;
    private String name6;
    private String name7;
    private String name8;
    private String name9;
    private String name11;
    private String name12;
    private String name13;
    private String name14;
    private String name15;
    private String name16;
    private String name17;
    private String name18;
    private String name19;

    public static UserInfo getInstance() {
        UserInfo user = new UserInfo();
        user.setName1(RandomUtil.randomString(50));
        user.setName2(RandomUtil.randomString(50));
        user.setName3(RandomUtil.randomString(50));
        user.setName4(RandomUtil.randomString(50));
        user.setName5(RandomUtil.randomString(50));
        user.setName6(RandomUtil.randomString(50));
        user.setName7(RandomUtil.randomString(50));
        user.setName8(RandomUtil.randomString(50));
        user.setName9(RandomUtil.randomString(50));
        user.setName11(RandomUtil.randomString(50));
        user.setName12(RandomUtil.randomString(50));
        user.setName13(RandomUtil.randomString(50));
        user.setName14(RandomUtil.randomString(50));
        user.setName15(RandomUtil.randomString(50));
        user.setName16(RandomUtil.randomString(50));
        user.setName17(RandomUtil.randomString(50));
        user.setName18(RandomUtil.randomString(50));
        user.setName19(RandomUtil.randomString(50));

        return user;
    }
}

1.3 打包启动

maven 打包 install 生成jar包

然后复制到Linux服务器，执行启动 java -jar demo-0.0.1-SNAPSHOT.jar

启动完成后，执行 jps，看下进程信息 63414

[jzj@localhost ~]$ jps
63571 Jps
63414 jar

2.TestController 访问及问题定位

下面我们安装几个神器，立马让你定位到IO问题

2.1 dstat -d 查看磁盘IO赌侠

Linux 服务器安装一个磁盘IO查看工具

[root@localhost jzj]#  yum -y install dstat
Running transaction
  正在安装    : dstat-0.7.2-12.el7.noarch                                                                                               1/1 
  验证中      : dstat-0.7.2-12.el7.noarch                                                                                               1/1 
已安装:
  dstat.noarch 0:0.7.2-12.el7                                                                   
完毕！

2.2 iotop 查看最高读写io的进程信息

Linux 服务器安装一个磁盘IO查看工具 iotop

[root@localhost jzj]#  yum install iotop 
已加载插件：fastestmirror, langpacks
Running transaction
  正在安装    : iotop-0.6-4.el7.noarch                                                                                                  1/1 
  验证中      : iotop-0.6-4.el7.noarch                                                                                                  1/1 
已安装:
  iotop.noarch 0:0.6-4.el7                                                                     
完毕！

3.IO读写实战

curl 127.0.0.1:8078/writelog?num=100 模拟大批量日志写入

3.1 datat -d 查看磁盘读写数据

执行dstat -d

可以看出来读972K，写12M，11M,11M,11M

明显磁盘在写入，这时候我们就要关注大日志了，因为磁盘在大量写入，1秒 12M的数据量

3.2 iotop 查看磁盘读写io量

执行 iotop 可以看到每秒 2M的数据在写入，进程信息是我们的 demo-0.0.1-SNASHOT.jar 进程，写入量特别大，也是大量日志在输出

3.3 pidstat -d 1 打印进程信息 io读写

执行 pidstat -d 1 1s打印1次进程信息

可以看到每秒 1711KB 或者 3126KB， 3M的数据在写入，进程pid是 63314 就是我们的 jar 进程，写入量特别大，也是大量日志在输出

至此我们已经通过工具，可以分析出来 IO写入量很大，我们要及时关注日志信息，可能是日志输出过大，导致的CPU 高的问题

这时候再去看日志，到底是哪个日志输出较多，定位到问题日志，消除即可

JVM系列(三十六) JVM调优实战-CPU过高 Log4j2异步日志IO问题定位