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

摘要: 小光是一名私家侦探,是小光侦探事务所的负责人。这天,他正在事务所中喝茶,突然接到警官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是很难执行的。

    要想获取更相信的信息,请参考:

  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

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



相关文章

发表评论

Comment form

(*) 表示必填项

3 条评论

  1. capozio 说道:

    一般的XXXFormat都不是线程安全的,用ThreadLocal可以解决

    Thumb up 0 Thumb down 0

  2. callmezx 说道:

    非常好

    Thumb up 0 Thumb down 0

  3. HelloWorld 说道:

    不错.赞

    Thumb up 0 Thumb down 0

跳到底部
返回顶部