RPC client OOM - RPC client 内存泄露

原因简述

• 公司的rpc框架是内部开发并维护的
• RPC server timeout时不回复机制使得client端大量请求对象一直存活而不被销毁（内存泄露），造成client端内存耗尽

现象及分析过程

• 7.25(周四)晚某web卡死，发现是gc频繁所致，运维重启后服务正常

• 7.26(周五)对该web增加gc监控，对gc.time.max，gc.tenuredUsed.percent, gc.throughput做监控

• 7.29(周一)发现tenuredUsed.percent从上周五的40%升至50%. 找运维取jmap并用mat进行分析, 发现一个可疑的约900m的大对象odis.rpc2.RpcClient$ConnectionImpl(old区约4.5g)，其中积存了大量的Call对象（运行三天多后约16*1000=1.6万个）. 该RpcClient为向rpc server请求的RpcClient

• 查看odis.rpc2.RpcClient$ConnectionImpl相关code，分析pendingCalls进行put和remove的相关逻辑, 可知：client端的call对象们在完成send后会被put进pendingCalls里wait. 再通过一个后台线程向server读取各个call的结果, 该线程读到某个call的返回时就将该call从pendingCalls里remove

    odis.rpc2.RpcClient$ConnectionImpl部分代码: 
  
    @Override
    public void sendParam(Call call) throws RpcException {
        boolean error = true;
        try {
            pendingCalls.put(call.id, call);                    // yinxj: 将call请求放入map中
            // check closed after put to pendingCalls. if we check closed first, 
            // we may: 
            // 1. we check closed, it is false.
            // 2. connection is closed, all pendingCalls are discard.
            // 3. we put our call in pendingCalls and wait.
            // 4. we wait forever if we do not have a timeout.
            if (closed) {
                throw new RpcException("connection already closed");
            }
    ...
  
    @Override
    public void run() {
        try {
            while (running) {
                lastActiveTime = System.currentTimeMillis();
                int id;
                try {
                    id = in.readInt();
                } catch (SocketTimeoutException e) {
                    continue;
                }
                Call call = pendingCalls.remove(id);                    // yinxj: 将对应的call从map中remove. 注意：此为唯一进行remove的逻辑, 若读不到call.id则该call将不会被remove
                if (call == null) {
                    LOG.severe("Unknown call ID received: " + id
                            + ". This is usually because readFields and "
                            + "writeFields is not match, or RpcServer and "
                            + "RpcClient has different writable implements");
                    continue;
                }
    ...
  

• jmap中odis.rpc2.RpcClient$ConnectionImpl中有众多的Call对象是因为其未被remove所致, 进一步可推断出是server端没有将call的请求回写导致call对象未从pendingCalls里remove. 与rpc相应开发人员确认: rpc server在处理某个请求时如果发现超时，就会直接结束该请求而不回复, 因此导致了pendingCalls的内存泄漏

解决办法

• 建议增加一后台线程去遍历pendingCalls，移除已timeout的无用calls -- 与rpc开发人员确认，会提一个issue进行fix
• 提升的rpc client的性能(超时情况较严重)

QA

    Q: 日志里向rpc server请求的timeout数量每天约有4-5万，服务运行近4天，约为10-20w，但对应pendingCalls里的数量只有1.6w，二者的不一致性如何解释？
    A: pendingCalls中未remove的call仅为rpc server发现超时后未回复的请求, server在回写过程中才超时的call是会被remove掉的, 所以pendingCalls中的数量要小于总timeout的数量

    Q: 为何这个问题之前一直没有被发现？
    A: 原因大概有三个方面. 一是其他rpc server的timeout比例应该没有这么高, 因此pendingCalls里未被remove的对象不会太多; 二是我们的call对象较大(其中一个参数为500个url的数组), 参数占用空间较小的call对象造成的内存开销较小不易被发现; 三是我们的服务运行了一个多月后才内存耗尽的, 而之前上线较为频繁, 很少有运行这么长的时间

    Q: 测试过程中为什么也没发现这个问题？
    A: 我们曾模拟一些异常环境（如rpc server卡死不响应请求)做测试，但此bug复现的环境则需要rpc server所在的机器有较大负载(忙不过来而超时较多)，但亦能有一定的工作能力(能接收请求)而不是直接卡死(无法接收请求)，这样的环境不是很好模拟。我们之后会多考虑这样的风险

经验教训

• 运维：服务卡死时 如果知道是内存耗尽所致 最好取一下jmap再重启服务：jmap -dump:file=mem.dump <pid>, 以便更快的定位问题
• 测试：压力测试时需要深入了解各服务的实现原理，考虑并设计不同的异常环境进行测试，这样才能更好的规避风险
• 测试：在进行压力测试一段时间后，可以用jmap来取得内存dump并用mat来分析其中大小 top N 的对象, 排查异常的情况