记一次定位js内存泄漏

by chainhelen

来源

线上有个升级服务，隔一两个月时间内存会慢慢上涨到服务器内存80%以上，单进程内存到500M左右

原因一直不明确

heapdump

首先压测无果，初步猜测应该是压测量级或者特殊情况触发不够

就想着添加一下代码，等出现情况时，dump线上进程的内存

添加heapdump库，准备随时dump内存，但是由于内存过大，不能设置定时器，否则很可能影响性能

所以采用添加在路由里，等到情况复现时，手动触发 

var heapdump = require('heapdump');  
...
router.get('/profiler', function(req, res, next) {  
  let query = req.query
  // 做token验证
  if('xxxxxxxxxxxxx' === query.token) {
    heapdump.writeSnapshot(path.join('/var/', '/log/', (new Date()).toString() + '.heapsnapshot'))
    res.send('ok')
    return
  }
  next()
})

注意：heapdump 是编译安装的，依赖gcc5.0以上特性，并且编译环境的node版本跟线上的node版本必须一致

分析heapsnapshot

某次运维事故，触发升级服务再次发生内存泄漏，我迅速dump内存文件，拖回本地，用开发者工具load

Memory -> Profiles -> load

如下图，第一份48.3M是当天正常状态下dump的内存，第二份348M是内存泄漏状态下dump的内存

对比发现，Promise对象大量未释放，还有EventEmiter对象未释放

具体跟业务相关就不提了

简化问题

接下来我们简化问题，看一下什么导致内存泄漏的

代码里有一段是为了解决，相同请求[AB....Z]大量并发过来时，只需要其中一个A请求去查数据库，然后缓存，其他请求[B....Z]去缓存里读取

那么这些"其他请求"[B....Z]，都监听这A完成缓存这件事，用的是事件监听once，主要希望[B....Z]请求在完成回调过后，能把这个事件监听删除掉

[B.....Z]事件监听once注册发生在一个new Promise的exec函数里面

问题来了，A在异步取数据出现了一个异常，而且是事先未预料到的异常，而且是在promise对象的下一层调用throw出来的

伪代码如下 

var cacheQueue = new EventEmitter();  
var cacheBusy = {};  
cacheQueue.setMaxListeners(500)  
.on('ready', function (key) {
    cacheBusy[key] = false;
    this.emit(`ready_${key}`);
})
.on('busy', function (key) {
    cacheBusy[key] = true;
});
cacheQueue.isBusy = function (key) {  
    return cacheBusy[key] === true;
}

var cacheQueue = new EventEmitter();  
var cacheBusy = {};  
cacheQueue.setMaxListeners(500)  
.on('ready', function (key) {
    cacheBusy[key] = false;
    this.emit(`ready_${key}`);
})
.on('busy', function (key) {
    cacheBusy[key] = true;
});

cacheQueue.isBusy = function (key) {  
    return cacheBusy[key] === true;
}

function updateCache(key,rpcFunc){  
    var that = this;
    return new Promise(function (resolve,reject) {
        if(cacheQueue.isBusy(key)){
            cacheQueue.once(`ready_${key}`, function () {
                resolve(that._readCache(key));
            });
        }else{
            cacheQueue.emit('busy',key);
            var retry = 3;
            ... // rpcHandler 有reject处理
            rpcFunc(rpcHandler);
        }
    })
}

setMaxListener

虽然setMaxListener有这个设置，但是不代表它超出这个设置不生效 

//nodejs /lib/events.js 源码 
function _addListener(target, type, listener, prepend) {  
     ...
    // Check for listener leak
    if (!existing.warned) {
      m = $getMaxListeners(target);
      if (m && m > 0 && existing.length > m) {
        existing.warned = true;
        // No error code for this since it is a Warning
        const w = new Error('Possible EventEmitter memory leak detected. ' +
                            `${existing.length} ${String(type)} listeners ` +
                            'added. Use emitter.setMaxListeners() to ' +
                            'increase limit');
        w.name = 'MaxListenersExceededWarning';
        w.emitter = target;
        w.type = type;
        w.count = existing.length;
        process.emitWarning(w);
      }
    }
  }

  return target;
}

可以看见超过setMaxListener设置数目，默认只警告一次

promise状态

通常情况下，如果promise一直处于pedding状态，内存是不会被释放的

也就是说上面rpcFunc内部不小心出错了，抛出异常了，而且是异步的，那么这个promise一直处于pedding状态

测试了一下，上面pedding状态的promise也是有可能被清除的

主要是cacheQueue一直引用这resolve，导致这个promise没有被释放

来个测试数据 

第一组，同步抛异常 

> var b = new Promise(() => {throw new Error('w')})

VM317:1 Uncaught (in promise) Error: w  
    at Promise (<anonymous>:1:34)
    at new Promise (<anonymous>)
    at <anonymous>:1:9

> b
Promise {<rejected>: Error: w  
    at Promise (<anonymous>:1:34)
    at new Promise (<anonymous>)
    at <anonymous>:1:9}


第二组，异步抛异常

> var b = new Promise(() => {setTimeout( () => {throw new Error('w')}, 1000)})
VM257:1 Uncaught Error: w  
    at setTimeout (<anonymous>:1:53)
setTimeout @ VM257:1  
setTimeout (async)  
Promise @ VM257:1  
(anonymous) @ VM257:1

> b
Promise {<pending>}

错误掩藏

为什么这个错误隐藏的这么旧都没被发现，因为rpc这个函数抛异常是由于远程调用超时造成的，整个错误不停地往外抛出，但是会在最外层被express路由捕捉到，这样我们在看到log，会以为这个错误是rpc中promise catch捕捉打印出来的；慢慢地超时错误越来越多，最终内存涨上来；