分类 有趣的 bug 下的文章

多线程情况下不正确的编码引起的内存泄漏

那年冬天, 新上线了一个处理在线消息的应用, 这个应用上线没多久, 就被发现有内存泄漏的问题. 从verbose GC log 来看, 是内存 heap 被用光了. 于是进一步做了一个 heap dump, 发现里面有个 ConcurrentHashMap 占用了大部分 heap 还不释放. 看上去是这个 ConcurrentHashMap 引起的问题.

这个 ConcurrentHashMap 是这么定义的:

Map<Runnable, ScheduledFuture<?>> futures = new ConcurrentHashMap<>();

它的 key 是一个将要执行的 task, value 是一个已经被 scheduled 的 Future 对象. 仔细观察这个 futures 里面的 ScheduledFuture 元素, 发现里面有一大部分全部都是已经被执行过的(通过Future对象的 status 字段可以判断它当前的状态), 不过按照代码的思路, 如果被执行过之后, 它就会被从这个 futures 里面移除, 可是这里却有大量应该被移除, 却没有被移除的 ScheduledFuture 对象.

代码稍微有点复杂, 那个类大概1千行左右代码. 不过这里我们只把跟问题相关的代码描述一下, 另外加了一个main函数做测试, 代码如下:

public class TaskProcessor {
    
    private TaskProcessor(){};
    private static final TaskProcessor instance = new TaskProcessor();
    public static TaskProcessor getInstance() {//单例
        return instance;
    }
    
    private static final ScheduledExecutorService ses = Executors.newScheduledThreadPool(3);
    private static final Map<Runnable, ScheduledFuture<?>> futures = new ConcurrentHashMap<>();
    
    public void submitTask(Runnable task, int latency) {//提交任务, 并且放入 map
        futures.put(task, ses.schedule(new TaskProcessor.Request(task), latency, TimeUnit.MILLISECONDS));
    }
    
    @PreDestroy
    public void shutdown() {//善后
        ses.shutdown();
    }
    
    /**
     *  internal class wrapper a Runnable 封装任务
     */
    private final class Request implements Runnable {
        
        private final Runnable runnable;

        private Request(final Runnable runnable) { this.runnable = runnable;}
        
        public void run() {//真正执行之前先移除
            ScheduledFuture<?> future = futures.remove(runnable);//remove the task from futures queue
            if (null == future) {
                System.out.println("running in a task");
            }
        }
    }
    
    public static void main(String[] args) {//做测试
        TaskProcessor processor = TaskProcessor.getInstance();
        
        for (int i = 0; i < 50000; i++) {//添加5万个任务
            Runnable r = new Runnable() {

                @Override
                public void run() {//做点打印的任务, 防止代码被优化掉
                    System.out.print("-");
                }
            };
            
            processor.submitTask(r, i % 2);//延迟要么0, 要么1
        }
        
        System.out.println(futures.size());//先打印一次队列长度
        
        try {
            Thread.sleep(8000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        System.out.println(futures.size());//8s之后在打印, 正常已经全部执行完
        
        try {
            Thread.sleep(8000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        System.out.println(futures.size());//再8s之后在打印, 正常已经全部执行完
        
        processor.shutdown();
    }
}

这段代码主要描述这么一个事情: 有任务来的时候, 把任务封装到一个 Request 里面, 然后把它 schedule 将来的某个时间去执行. schedule 动作同步返回一个 ScheduledFuture 实例, 为了统计或反映将要执行的task 数量, 把返回的 ScheduledFuture 实例放到了一个 futures 的ConcurrentHashMap 里面. 当真的要执行的时候, 再把它从 futures 这个map 里面移除. 看上去很简单的一个操作, 就是为了算一下在将要执行队列里面的任务, 加了一个这么 futures.

问题也出现在这个 futures 里面. 进一步对 heap 分析, 那些执行过的 ScheduledFuture, 已经都从 scheduler 内部的队列中移除了, 可是没有从这个futures Map 中移除.

仔细看一下这个代码, 如果说 schedule 一个task的时候, 把延迟设置成0或者非常短, 那么这个问题就很有可能出现. 写代码的人期望的顺序是:

ScheduledFuture future = ses.schedule(new TaskProcessor.Request(task), 0, TimeUnit.MILLISECONDS);  //添加将来任务 在schedule task的线程执行
futures.put(task, future);  //放入map, 在schedule task的线程执行
futures.remove(task) //在map中移除, 在scheduler的worker 执行

而实际执行的时间先后顺序可能是:

ScheduledFuture future = ses.schedule(new TaskProcessor.Request(task), 0, TimeUnit.MILLISECONDS);  //1 schedule task的线程执行
futures.remove(task) //3 在scheduler的worker 执行, 可是这里还没有加到Map
futures.put(task, future);  //2 schedule task的线程执行, 加到map

所以, 这个是没有考虑到多线程情况下, 代码同步可能引起的问题.

Java SimpleDateFormat 的格式化字符串里的Y

2017年元旦假期三天, 程序员小吴没有出去玩. 早上10点多了, 还在家睡懒觉. 突然电话响起,吵醒了半睡半醒的他. 他心想是推销还是贷款专员? 休假都被叫醒, 很是生气. 拿起手机, 发现竟然是公司打来的电话,顿时感觉不妙. 接通电话, 那头说有个紧急的site issue, 可能跟小吴的代码相关, 让他紧急上线看一下. 小吴一下子清醒了很多, 连忙登录VPN, 检查最新邮件, 确实发现有个问题, 跟自己几个月前上线的代码有关系.

这段代码巨简单, 就是取服务器当前的时间, 然后格式化一下, 显示在页面上. 同时,页面上有些数据统计信息, 会通过Ajax请求的方式去慢慢取,然后展示在页面. 去取的时候, 把本来展示在页面的这个格式化后的日期, 发给后台服务器. 问题就出现在, 本来这天是2017年12月31日, 可是页面上却显示的是 2018/12/31, 默认加了1年, 非常的奇怪.

小吴首先把线上已部署的代码的commit id 找到,然后把这个commit拉下来, 仔细检查了一番, 并没有发现什么情况. 这段代码已经在生产环境运行了8个多月, 之后一直没有人改过. 之前的测试以及线上从来没出现过问题, 真是奇了怪了. 小吴只好本地debug了一下, 发现本地能完美重现... 用当天的日期格式化一把, 格式化之后一直是2018年12月31日. 之前从来没有问题, 难道这天是啥好日子? 经过一番修改测试, 终于发现了问题:

public static void main(String[] args) {
    Calendar cal = Calendar.getInstance();
    cal.set(2017, 11, 29);
    SimpleDateFormat sdf0 = new SimpleDateFormat("YYYY/MM/dd");
    SimpleDateFormat sdf1 = new SimpleDateFormat("yyyy/MM/dd");
    Date date = null;
    for (int i = 0; i < 4; i++) {
        date = cal.getTime();
        System.out.println(sdf0.format(date));
        System.out.println(sdf1.format(date));
        cal.add(Calendar.DATE, 1);
    }
}

运行结果:

2017/12/29
2017/12/29
2017/12/30
2017/12/30
2018/12/31
2017/12/31
2018/01/01
2018/01/01

从上面代码片段及运行结果看, 只有2017年12月31日出问题了. 问题出现在格式化的时候, 使用是大写的Y还是小写的y. 那么根据官方文档, 差别是什么呢?

y: Year Year 如: 1996; 96
Y: Week year Year 如: 2009; 09

一个是year, 一个 week year. year 很好理解, 就是我们所说的年, 那么 week year 呢? week year的计算涉及到2个东西, 一个是: 一周的第一天是从周一开始算还是从周日开始算, 有的人/地方从周日开始算, 有的从周一开始算. 第二个是, 我们经常听说这是今年第几周, 试想如果一个week跨过1年, 那么这周算到那年里?
JDK 文档举的例子是: 1998年1月1日是周四.
如果我们设定一周的第一天是周一, 那么这周属于1998年的就有4天(周4,5,6,7), 属于1997年的只有3天, 那么这周算在1998年,这是1998年的第一周. 那么1997年12月29, 30, 31日的 week year 就是1998, 而不是1997了.
如果我们设定一周的第一天是周日, 那么这周属于1998年的就有3天(周4,5,6), 属于1997年的就有4天了. 那么这周算在1997年,这是1997年的最后一周,1998年的第一周从1月4号开始, 那么1998年,1月1,2.3号的 week year 就是1997了.

FirstDayOfWeek 是根据JDK所在的系统设置, 有个默认设置的.

所以这个问题, 只要改回正确的yyyy问题就解决了. 另外还发现有人误以为这是JDK的bug, 去提了bug: https://bugs.openjdk.java.net/browse/JDK-8194625

参考:
https://docs.oracle.com/javase/7/docs/api/java/text/SimpleDateFormat.html
https://docs.oracle.com/javase/9/docs/api/java/util/GregorianCalendar.html#week_year