欢迎访问悦橙教程（wld5.com），关注java教程。悦橙教程  java问答|  每日更新
页面导航 : > > 文章正文

侦探剧场：堆内存神秘溢出事件，侦探剧场溢出事件

来源： javaer 分享于  点击 15660 次 点评：145

侦探剧场：堆内存神秘溢出事件，侦探剧场溢出事件


摘要: 小光是一名私家侦探，是小光侦探事务所的负责人。这天，他正在事务所中喝茶，突然接到警官M的电话，说接到线上总共三台机器，有一台机器报警，Java堆内存占用超过95%，无法正常得到服务器的响应。小光安排警官M保留好现场，急匆匆的赶往了现场…

案发

小光是一名私家侦探，是小光侦探事务所的负责人。这天，他正在事务所中喝茶，突然接到警官M的电话，说接到线上总共三台机器，有一台机器报警，Java堆内存占用超过95%，无法正常得到服务器的响应。小光安排警官M保留好现场，急匆匆的赶往了现场…

路上

在前往现场的路上，小光思考了以下几个问题：

  1. 什么情况下会出现堆内存

    猜测可能是：

    • 瞬时并发数增大，且不能快速返回。这种情况需要一些线程的调用栈中，引用了大量的实例才可以占满堆内存。
    • 程序中有bug，导致死循环，在循环体中一直有分配内存的操作，且不是临时变量。

    关键是分配大量内存，且无法被有效GC。

  2. 如何去定位问题
    • 最直接的方式，堆dump，使用MAT或者JVisualVm来分析dump文件，找出是哪里占用了大量的堆内存。
    • 当1无法执行时，可以使用jdk自带的一些工具，如jmap来分析内存。堆有可能是dump不出来的，因为线上堆大小是8G，且同一台物理机有多个服务在运行，可能会影响其他服务。
    • 内存作为主要分析对象，基于上述猜测1，还需要使用jstack导出线程栈信息。

现场

到达现场后，小光立即着手从现场找到有用的线索，分别在案发现场(问题JVM)做了以下几件事

  1. 尝试进行整个案发现场的备份，即堆dump，但被告知堆内存太大，无法进行dump
  2. 尝试使用JMX连接目标JVM

    以失败告终，JVisualVM长时间无法连接。(为什么无法连接成功，参考思考1)

  3. SSH连接线上服务器，使用JDK自带工具尝试获取线索
    • ps -ef | grep java：找到目标jvm的pid
    • jmap -histo 目标jvm的pid | head -20：查看Class与对应实例占用情况。但是以失败告终，提示： Attaching to process ID 3991, please wait…
      Error attaching to process: sun.jvm.hotspot.debugger.DebuggerException: Can’t attach to the process
    • 尝试jmap无果，接着尝试jstack：jstack 目标jvm的pid：一样以失败告终，提示基本同上

    可能是当前用户无权限导致的。但是jmx应该不是，思考失败原因，参考归档1

    好在警官M在之前已经jmap出来一部分有效信息了，参考如下图：

    jmap情况

    但是，根据这个线索，只能定位到是String导致堆内存占满的，并没有其他有效的信息，而String对象是整个程序运行期间处处都有使用的，很难去直接定位到问题所在…

至此，现场勘查基本完成，但是并没有什么收获有效的可一次定位问题的信息。只能清理现场、重启服务，以防止影响后续服务。

现场监控信息

现场已经被清理了，但是现场还有一些监控信息。同时询问大致案发时间，是八点三十分左右，对部分内容取8-9点之间的信息，包括有以下内容：

  1. 应用日志

    请求M警官协助，拉取了问题机当天的所有日志，一起另外一台没有问题的机器的所有日志，方便做差异分析。

  2. GC日志

    在堆内存几乎占满时，GC时间也变的很长，GC日志有一定的参考价值。

  3. 监控日志

    查看应用日志目录，发现有dkimi目录，看了下里面大致内容，发现是dkimi这个agent层的一些日志，也包括了一些有用信息，但是文件较大没有拉出来，有需要的时候自己去服务器上查看。

  4. 监控平台matrix

    monitor-matrix.zeus 监控平台图

线索分析

线索有以下内容：

  1. 一张jmap图
  2. 应用所有日志
  3. GC日志
  4. dkimi日志
  5. 监控平台图表
  6. 项目源码

直接从1、3、4、5中并不能直接分析出问题所在，但是可以根据这些信息得出一个非常有价值的线索：案发时间

1. 确定案发时间

由图4可知，案发时间在8:24分左右，但不确定该监控平台的监控间隔，以及时间的准确性。通过检查dkimi日志，发现每隔30s会自动上报当前jvm状态json数据，状态中包括了jvm:gc:ParNew:time，即gc时间。

cat dkimi-agent.2018-01-10.log | grep '2018-01-10 08:2[2-5]:.*HeartB.*jvm:gc:ParNew:time'

2018-01-10 08:22:26 - jvm:gc:ParNew:time:2107
2018-01-10 08:22:56 - jvm:gc:ParNew:time:2107
2018-01-10 08:23:26 - jvm:gc:ParNew:time:2128
2018-01-10 08:23:56 - jvm:gc:ParNew:time:9462
2018-01-10 08:24:28 - jvm:gc:ParNew:time:19735
2018-01-10 08:24:59 - jvm:gc:ParNew:time:21332
2018-01-10 08:25:44 - jvm:gc:ParNew:time:22556

取22分到25分的数据，大致定位了时间为23-24分钟之间。

2. 取案发时间区间监控日志

cat all_is_well.log | grep '20180110-08:2[3-4]'

在拉取日志后，小光的智商突然下线…通过通读两台机器这一分钟的所有日志后，没有发现任何异常，所以也就没有得到任何结论…

在漫无目的的查看日志没有结果之后，开始怀疑起了日志区间，从此开始进入了误区…

3. 进入误区

先从日志中报error的地方入手，虽然error不会导致堆内存溢出，但是或许会有一些有用的信息。

cat all_is_well.log | grep '20180110-08:2.*ERROR'
20180110-08:25:44.743 [ZkClient-EventThread-40] ERROR org.I0Itec.zkclient.ZkEventThread [44263889_40_754] [] - Error handling event ZkEvent[Children of /fake changed sent to com.alibaba.dubbo.remoting.zookeeper.zkclient.ZkclientZookeeperClient$2@68c3c43c]
20180110-08:25:44.745 [ZkClient-EventThread-40] ERROR org.I0Itec.zkclient.ZkEventThread [44263889_40_754] [] - Error handling event ZkEvent[Children of /fake changed sent to com.alibaba.dubbo.remoting.zookeeper.zkclient.ZkclientZookeeperClient$2@6cfc4dfc]
20180110-08:25:44.746 [ZkClient-EventThread-40] ERROR org.I0Itec.zkclient.ZkEventThread [44263889_40_754] [] - Error handling event ZkEvent[Children of /fake changed sent to com.alibaba.dubbo.remoting.zookeeper.zkclient.ZkclientZookeeperClient$2@29fece07]
20180110-08:25:44.747 [ZkClient-EventThread-40] ERROR org.I0Itec.zkclient.ZkEventThread [44263889_40_754] [] - Error handling event ZkEvent[Children of /fake changed sent to com.alibaba.dubbo.remoting.zookeeper.zkclient.ZkclientZookeeperClient$2@6e09bdf2]
20180110-08:25:44.748 [ZkClient-EventThread-40] ERROR org.I0Itec.zkclient.ZkEventThread [44263889_40_754] [] - Error handling event ZkEvent[Children of /fake changed sent to com.alibaba.dubbo.remoting.zookeeper.zkclient.ZkclientZookeeperClient$2@189d662b]
20180110-08:25:44.749 [ZkClient-EventThread-40] ERROR org.I0Itec.zkclient.ZkEventThread [44263889_40_754] [] - Error handling event ZkEvent[Children of /fake changed sent to com.alibaba.dubbo.remoting.zookeeper.zkclient.ZkclientZookeeperClient$2@16804b69]
20180110-08:25:44.750 [ZkClient-EventThread-40] ERROR org.I0Itec.zkclient.ZkEventThread [44263889_40_754] [] - Error handling event ZkEvent[Children of /fake changed sent to com.alibaba.dubbo.remoting.zookeeper.zkclient.ZkclientZookeeperClient$2@49d13148]

发现大量的Zookeeper异常，正常机器上的日志上并没有这个异常。莫非是这里的问题？开始看这里的源码…结果并没有什么收获(这就是所谓的病急乱投医吧)。

在仔细思考后，小光觉得这个异常一定与堆内存泄漏相关，莫非是这个报错之前有其他操作导致了这个问题？

在查看该时间点附近相关日志后，发现了

20180110-08:25:44.727 [localhost-startStop-1-EventThread] INFO  org.apache.zookeeper.ZooKeeper [44263935_42_78] [] - Initiating client connection, connectString=xxx sessionTimeout=30000 

20180110-08:24:59.034 [localhost-startStop-1-SendThread(111.222.111.222)] WARN  org.apache.zookeeper.ClientCnxn [44263926_41_516] [] - Client session timed out, have not heard from server in 30475ms for sessionid 0x25f06ee8bd75078

莫非是这个sessionTimeout导致了上面的error， 超时时间30s，那么是否有什么操作导致整个zookeeper连接阻塞了将近30s，无法有效与zookeeper进行交互导致的？上面发现session timed out个WARN从24:59开始就有了，查看这段日志相关的源码。没有发现任何异常……那么从这个前面开始找…

突然小光注意到了日志的事件，在8:24:59之前，最近一条日志竟然是8:24:37，中间二十多秒的日志去哪儿了？

20180110-08:24:37.821 [catalina-exec-60] INFO  com.web.filter.WebFilter [1477821_495_995] [25216534600963] - time http://xxx.com/,7
20180110-08:24:59.034 [localhost-startStop-1-SendThread(11.11.111.11:2181)] WARN  org.apache.zookeeper.ClientCnxn [44263926_41_516] [] - Client session timed out, have not heard from server in 30475ms for sessionid 0x25f06ee8bd75078

缺少的二十多秒的日志，不可能是应用二十多秒没有日志输出，那么可以做到这种事情的，只有JVM的Stop The World!查看GC日志，发现GC时间确实有二十多秒。

由此判断ERROR日志基本上可以确定为GC暂定导致的，又回归了线索的原点。。

4. 结合监控尝试找出嫌疑人

既然无法从ERROR中得到嫌疑人的有效信息，那就回归最开始的猜想：不能快速返回的请求。

可以看到上面日志中，有个WebFilter日志，最后有耗费的时长，拉取这段时间所有WebFilter日志

cat all_is_well.log | grep '20180110-08:2[3-5].*WebFilter'

看了下时间，并没有发现较长的响应时间。莫非是非Web请求导致的问题？

通过结构化日志到数据库，分析是否有非web线程的日志，并与正常机器的日志线程做对比，观察线程不一致的日志。如何结构化请看归档2

结构化日志

其中n1是log4j的一个token，n2是一次web请求的生命周期中唯一的id，使用ThreadLocal实现的。

SELECT * FROM log150 where thread not like '%catalina-exec%';
查找非web线程，除了workflowMessageListenerContainer没有其他的
SELECT * FROM log151 where thread not like '%catalina-exec%';
查找非web线程，除了workflowMessageListenerContainer没有其他的
SELECT * FROM log151 where thread not in (select thread from log150)
查找log151中没有150的线程，并没有..
SELECT * FROM log150 where thread not in (select thread from log151)
查找log150中没有151的线程，有一堆workflowMessageListenerContainer

查了下151的workflowMessageListenerContainer日志，并没有什么异常…

至此，通过查看web相关请求的响应时间，排除了web相关请求，通过两台机器对比线程，排除了非web相关请求。这样问题就死在这里了…

小光抬眼看了下时间，已经到了晚上，思路也渐渐的不清晰了，暂时休息，明天继续。

5. 第二天，根据不在场证明确定嫌疑人

第二天，小光早早的起了床，并立了一个Flag，今天肯定能查到原因。因为昨晚他突然想到，当一个请求很耗时，甚至都不返回成为死循环时，可能连日志都没有。

同时，WebFilter的日志打印，是在finally中，当请求无法返回时，当然不会打印日志，昨天确实是忽略了这个问题，走了个大的弯路。

public void doFilter(ServletRequest request, ServletResponse response,
					 FilterChain arg2) throws IOException, ServletException {
    long startTime = System.currentTimeMillis();
    StringBuffer url = new StringBuffer();
    try {
        url = url.append(((HttpServletRequest)request).getRequestURL().toString());
        arg2.doFilter(request, response);
    } catch (Throwable e){
        request.setAttribute("errmsg", e.getClass()+"-"+e.getMessage());
        RequestDispatcher rd = request.getRequestDispatcher("/resources/error.jsp");
        try {  
            rd.forward(request, response);  
            return;  
        }catch(Exception ex){}  
    } finally{
        if (!url.toString().contains("resources")) {
            logger.info(String.format("time %s,%s", url, System.currentTimeMillis() - startTime));
        }
    }
}

可以看到，只有finally中打印了日志，请求之前并没有打印日志。

那么是否有before和after都打印了日志，只要分析一下有before但是没有after的请求，那么就可以定位到问题点了！

想到这里，小光立马兴奋了一起，打开代码，找寻其他切入点，果然找到了一个WebInterceptor：

public class RequestLoggerHandler extends HandlerInterceptorAdapter {
    private static Logger logger = LogManager.getLogger(RequestLoggerHandler.class);
    private ThreadLocal<Long> startTime = new ThreadLocal();

    public RequestLoggerHandler() {
    }

    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        this.startTime.set(System.currentTimeMillis());
        User user = SessionUserUtil.getCurrentSessionUser();
        logger.info("[http]preHandle url: {}, user:{}, inParams: {}", new Object[]{request.getRequestURL(), user, this.toJSONString(request.getParameterMap())});
        return true;
    }

    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
        logger.info("[http]postHandle url: {}, cause [{}] ms", new Object[]{request.getRequestURL(), System.currentTimeMillis() - ((Long)this.startTime.get()).longValue()});
        ThreadTokenHelper.clear();
    }

    private String toJSONString(Object object) {
        try {
            return JSON.toJSONString(object);
        } catch (Exception var3) {
            logger.warn("request请求参数序列化{}异常......");
            var3.printStackTrace();
            return null;
        }
    }
}

这里的before和after都打印了日志，且日志可以通过上面的n2即日志id来关联，没有日志id的时候可以使用请求地址来做对比。

结构化该请求相关的日志

cat all_is_well.log | grep '20180110-08:2[2-4].*com.xxx.commons.log.RequestLoggerHandler.*'
导出日志。

SELECT count(1),n2 FROM requestlog GROUP BY n2
查询数据，找出其中为奇数的请求。

最终竟然真的找到了一个，而且有且只有一个

time thread level clazz n1 n2
23:26.449 [catalina-exec-19] INFO com.commons.log.RequestLoggerHandler [1406449_454_770] [25216485580601]

查看时间点，也确实与案发时间对的上。为增加确定性，搜索该时间点之后线程catalina-exec-19的相关日志，发现在该时间点之后，就没有与此线程相关的日志了。由此，根据各线程的不在场证明可以基本确定嫌疑人为线程catalina-exec-19。

查看该条日志，得到请求信息，内容为：

20180110-08:23:26.449 [catalina-exec-19] INFO  com.commons.log.RequestLoggerHandler [1406449_454_770] [25216485580601] - [http]preHandle url: http://xxx.com/apply, user:{"userId":100000001111111, "userCode":"1111111","userName":"光闪"}, inParams: {"103009":[""],"docContent":["大区 年会"],"submitterId":["22222222"],"showHalfDay":["1"],"docDuration":["1.5"],"dateValid":["true"],"docDurationApplied":["0"],"docType":["103014"],"isBeijing":["false"],"remaining":["0"],"maxDayCount":[""],"days":["2.5"],"docStartTime":["2018-01-08 08:22:50"],"docEndTime":["2018-01-10 08:22:56"],"docStartTimeInterval":["2"],"docEndTimeInterval":["2"]}

推理破案

上次讲到最终定位到了犯罪嫌疑人，但是犯罪嫌疑人也不是吃素的，证据又不足以定罪，小光继续进行分析推理：

1. 嫌疑人拒不认罪

嫌疑人catalina-exec-19表示，没有凶器与行凶方式，证据是不充足的，不能进行逮捕。小光说，既然已知嫌疑人，以及凶器的一点线索，找到凶器只是时间问题，接着便埋头开始推理。

凶器的线索在日志中已经提供：请求地址是http://xxx.com/apply。同时该线程日志id为25216485580601。通过请求处理逻辑，以及调用过程中整个的日志信息，要想得到确切的问题点不会太难。

查看了代码才发现，上面想的还是有点简单了，这个接口的处理逻辑使用了模板模式，在模板模式中又嵌tao了模板模式…与25216485580601相关的日志有71条，多为DataPermissionInterceptor类的日志，该类拦截所有dao层调用。

同时可知，在最后一条日志打印出来之后，该线程就没有再打印日志了，既没有报错也没有终止，那么大概率是死循环到某处了。

2. 找出凶器

通过请求参数”docType”:["103014"]找到对应的处理类，又通过层层模拟调用，结合日志，最终确定了问题发生在这段代码之中

protected JsonDto analyzec(ApplyCommonContext context) {
    List<String> noworkDays = new ArrayList<>();
    try {
        noworkDays = detailService.getNoworkDays(userCode, docStartTime, docEndTime);
    } catch (SourceVerifyException e) {
        logger.warn("警告信息，userCode:{}, applyType:{}", context.getUserVo(), context.getDoc().getDocType());
    }
    List<UserDetail> listist = UserProcessUtil.partDocToDetails(context, noworkDays, deepExclude(context.getDoc().getDocType(), context));

第71条日志是在getNoworkDays方法中打印的，而在UserProcessUtil.partDocToDetails后面又肯定会有新的日志产生，那么问题就发生在getNoworkDays方法体内和UserProcessUtil.partDocToDetails方法体内。(中间还遇到了日志与调用过程不一致的情况，后发现是因为dao层有@Cacheable注解，导致dao层逻辑没有经过DataPermissionInterceptor拦截器)

大致浏览了一下getNoworkDays，发现其中并没有特殊的方法调用和循环，嫌疑对象指向了UserProcessUtil.partDocToDetails方法：

public static List<UserDetail> partDocToDetails(ApplyCommonContext context, List<String> excludeDays, boolean deepExclude) {
    Doc doc = context.getDoc();
    List<TimeVo> timeVoList = transferDayDoc(doc, context.getUserVo());
    return convertToDetails(doc, timeVoList, doc.getId(), excludeDays, deepExclude);
}

查看transferDayAttenceDoc方法，其中隐去简单调用方法：

private static List<TimeVo> transferDayDoc(Doc doc, UserVo userVo) {
    List<TimeVo> timeVoList = Lists.newArrayList();
    String startTime = DateUtil.formatDate(doc.getDocStartTime());
    String endTime = DateUtil.formatDate(doc.getDocEndTime());
    // 处理中间天
    List<String> desList = ServiceDateUtil.getBetweenDates(startTime, endTime);
    ...
    return timeVoList;
}

继续往下一层进，查看ServiceDateUtil.getBetweenDates(startTime, endTime)

public static List<String> getBetweenDates(String begin, String end) {
    SimpleDateFormat format = new SimpleDateFormat("yyyy-MM-dd");
    List<String> betweenList = new ArrayList<String>();
    try {
        Calendar startDay = Calendar.getInstance();
        startDay.setTime(format.parse(begin));
        startDay.add(Calendar.DATE, -1);

        while (true) {
            startDay.add(Calendar.DATE, 1);
            Date newDate = startDay.getTime();
            String newend = format.format(newDate);
            betweenList.add(newend);
            if (end.equals(newend)) {
                break;
            }
        }
    } catch (Exception e) {
        e.printStackTrace();
    }
    betweenList.remove(begin);
    betweenList.remove(end);
    return betweenList;
}

看到这段代码时，突然一道光穿透了小光的两耳(此处配名侦探柯南发现真相图)。下面那个while (true)非常可疑！

分析代码，循环终止条件是end.equals(newend)。newend则是startDay每次循环加一的结果，那么就是在某种情况下无法触发循环结束条件。

把请求中参数的”docStartTime”:["2018-01-08 08:22:50"],”docEndTime”:["2018-01-10 08:22:56"]作为参数传入方法调用后，直接死循环了…结果是因为判断条件是拿全部String做的equals。而newend是经过日期格式化的，只取日期那一部分的值，而end则不做任何变化，那么一个日期与一个日期时间，做字符串equals是肯定不会相等的，必然会死循环。

到这里，小光以为案件已破。但是仔细一想，这样的话岂不是所以进到这里的逻辑，都会直接触发死循环，这一点又解释不通。

查看调用该方法传入的参数，发现start和end其实是经过格式化的日期字符串

String startTime = DateUtil.formatDate(attenceDoc.getDocStartTime());
String endTime = DateUtil.formatDate(attenceDoc.getDocEndTime());

继续分析equals条件，当传入参数start大于传入参数end时，就永远不会触发结束条件。什么情况下会start大于end呢。

此时，又一道光闪过小光的眼前！DateFormat是线程不安全的，当多个线程使用同一个DateFormat时，有可能导致格式化后的结果不是自己想要的！看DateUtil.formatDate的代码

private static final DateFormat DEFAULT_DATE_FORMAT = new SimpleDateFormat("yyyy-MM-dd");
public static String formatDate(Date date) {
    return DEFAULT_DATE_FORMAT.format(date);
}

果然与猜想的一样，此处使用了一个静态的DEFAULT_DATE_FORMAT来格式化日期，当多线程操作时，会导致start变为其他线程正在操作的时间。若此时间正好比end大，那么就会触发死循环。关于DateFormat线程不安全，参考归档3.

再看死循环逻辑，往一个list中丢String对象，与最开始jmap结果也一致！

3. 还原作案手法

在多线程并发环境下，并发越高，上面的问题越容易重现。这也解释了之前到月底发生该问题的现象，月底考勤系统并发增加，问题出现概率增高。

通过构建多线程共用同一个DateFormat，开启500个线程同时Format日期2018.01.12，主线程调用两次Format，分别Format 2018.01.08和2018.01.10，之后作为参数传入getBetweenDates，尝试几次后，果然重现

public static void main(String[] args) {
    Date start = DateUtil.parseDate("2018.01.08");
    Date end = DateUtil.parseDate("2018.01.10");
    final Date other = DateUtil.parseDate("2018.01.12");
    for (int i = 0; i < 500; i++) {
        new Thread(() -> DateUtil.formatDate(other)).start();
    }
    ServiceDateUtil.getBetweenDates(DateUtil.formatDate(start), DateUtil.formatDate(end));
}

4. 真相大白

至此，凶器已被找到，证据确凿，嫌疑人也已无法狡辩，只得乖乖俯首认罪。而小光也说出了那就他早就想说的话：真相永远只有一个！

后记

思考上面问题出现的原因。

Util作者写了个方法，期望该方法的使用者，传入参数时，一定符合他的约定。

而使用者在使用该方法时，也都严格按照该约定进行传参。

但是中间杀出了个程咬金，多线程环境下结果的不确定性，最终导致了严重的堆内存泄漏问题。

案件已经侦破，那么各位针对上面的问题，有什么好的解决方法吗？当然直接换线程安全的日期格式化工具是非常有必要的，方法中做参数的必要性校验也是有必要的。

插曲

归档

  1. JVisualVM长时间无法连接、工具Attach失败的原因：

    首先要了解一下这些工具执行的原理，为何会报出Attach失败？

    这些工具的执行原理都是基于Sun公司的Attach API。通过com.sun.tools.attach.VirtualMachine类，调用attach(pid)方法，attach到目标JVM上。

    那么目标JVM又是怎么觉察到attach进来一个工具呢？通过线程Signal Dispatcher来实现。当attach时，会对目标线程发出一个信号量，该信号量交由该线程处理，信号量处理程序发现是attach信号，检测Attach Listener线程是否启动，如果没有启动则启动一个Attach Listener线程，attach的具体操作交由Attach Listener执行。

    attach到目标虚拟机后，真正逻辑的执行是靠Java Platform Debugger Architecture(JPDA)来进行的。

    所有真正的执行还是要依赖目标JVM的，所以当目标JVM堆内存不足，且长时间GC占用CPU时间片时，Attach是很难执行的。

    要想获取更相信的信息，请参考：

    • Java调试那点事
    • JPDA 体系概览
    • JVM Attach机制实现
  2. 结构化日志方式
    • 脚本语言：Python、Node.js
    • sed命令
    • awk命令
    • grep命令

参考脚本

with open('E:/logAnalysis/out.txt', 'w', encoding='UTF-8') as fo:
    with open('E:/logAnalysis/request.log',encoding='UTF-8') as f:
        for line in f:
            if line[0:8] != '20180110':
                continue
            time = line[12:21]
            line = line[22:].lstrip()
            thread = line[0:line.find(" ")]
            line = line[len(thread) + 1:].lstrip()
            level = line[0:line.find(" ")]
            line = line[len(level) + 1:].lstrip()
            clazz = line[0:line.find(" ")]
            line = line[len(clazz) + 1:].lstrip()
            n1 = line[0:line.find(" ")]
            line = line[len(n1) + 1:].lstrip()
            n2 = line[0:line.find(" ")]
            line = line[len(n2) + 1:].lstrip()
            content = line[2:].strip()
            request = 0 if content.find('[http]preHandle') >= 0 else 1
            fo.write("" + time + "^" + thread + "^" + level + "^" + clazz + "^" + n1 + "^" + n2 + "^" + str(request) + "\n")
  1. DateFormat线程不安全的原因

    说严禁点，其实是SimpleDateFormat的parse和format方法线程不安全。究其原因是因为其中使用了一个共享的calendar变量来进行日期与实时间的处理。在format时，先进行了一个calendar的setTime操作。这里就导致了多线程环境下，结果的不一致。

// Called from Format after creating a FieldDelegate
private StringBuffer format(Date date, StringBuffer toAppendTo,
                            FieldDelegate delegate) {
    // Convert input date to time field list
    calendar.setTime(date);
  1. 上面虽然引起了堆内存大量占用，但是并没有OOM，思考原因

上面说了堆内存被大量占用，且有个死循环一直分配内存。奇怪的是却一直没有报出OutOfMemmoryError。这里需要去了解一下抛出OutOfMemmoryError的时机，参考JVM源码分析之临门一脚的OutOfMemoryError完全解读。

个人猜测是因为，尝试分配内存时，发现内存不足，尝试进行GC，一次GC时间达到了半分钟。GC后，由于有其他线程可以释放一部分内存，又可以让死循环多分配点内存，最终持续进行分配与GC，始终达不到触发OOM错误的时机，故没有抛出OOM。

PS

第一次尝试这种写作风格，欢迎各位提出意见与建议。如果觉得文章不错，欢迎关注和点赞哈，您的支持是我最大的动力。本地还有一些存货，有机会的话我会继续写这个系列，希望大家支持~

相关文章

    暂无相关文章
相关栏目：

相关文章

用户点评