事务处理不当,线上接口又双叒内存泄漏了!(附图解问题全过程)

情景

项目上线了一个接口,先灰度一台机器观察调用情况;
接口不断的调用,过了一段时间,发现机器上的接口调用开始报OOM异常
当天就是上线deadline了,刺激。。

q1.jpg

发现问题

第一步,使用jps命令获取出问题jvm进程的进程ID

使用jps -l -m获取到当前jvm进程的pid,通过上述命令获取到了服务的进程号:427726 (此处假设为这个)

q2.png

jps命令

jps(JVM Process Status Tool):显示指定系统内所有的HotSpot虚拟机进程
jps -l -m : 参数-l列出机器上所有jvm进程,-m显示出JVM启动时传递给main()的参数

第二步,使用jstat观察jvm状态,发现问题

因为是OOM异常,所以我们首先重启机器观察了JVM的运行情况;

我们使用jstat -gc pid time命令观察GC,发现GC在YGC后,GC掉的内存并不多,每次YGC后都有一部分内存未回收,导致在多次YGC后回收不掉的内存被挪到堆的old区,old满了之后FGC发现也是回收不掉;
这里基本可以确定是内存泄漏的问题了,下面我们有简单看了下机器的cpu、内存、磁盘状态

jstat命令:

jstat(JVM statistics Monitoring)是用于监视虚拟机运行时状态信息的命令,它可以显示出虚拟机进程中的类装载、内存、垃圾收集、JIT编译等运行数据。
jstat -gc pid time : -gc 监控jvm的gc信息,pid 监控的jvm进程id,time每个多少毫秒刷新一次
jstat -gccause pid time : -gccause 监控gc信息并显示上次gc原因,pid 监控的jvm进程id,time每个多少毫秒刷新一次
jstat -class pid time: -class 监控jvm的类加载信息,pid 监控的jvm进程id,time每个多少毫秒刷新一次

在这里先简单说一下,堆的GC:

在GC开始的时候,对象只会存在于Eden区和名为“From”的Survivor区,Survivor区“To”是空的。紧接着进行GC,Eden区中所有存活的对象都会被复制到“To”,而在“From”区中,仍存活的对象会根据他们的年龄值来决定去向。

年龄达到一定值(年龄阈值,可以通过-XX:MaxTenuringThreshold来设置)的对象会被移动到年老代中,没有达到阈值的对象会被复制到“To”区域。经过这次GC后,Eden区和From区已经被清空。这个时候,“From”和“To”会交换他们的角色,也就是新的“To”就是上次GC前的“From”,新的“From”就是上次GC前的“To”。不管怎样,都会保证名为To的Survivor区域是空的,minor GC会一直重复这样的过程。

第三步,观察机器状态,确认问题

使用top -p pid获取进程的cpu和内存使用率;查看RES 和 %CPU %MEM三个指标:

q3.png

在这里先简单说一下,top命令展示的内容:

VIRT:virtual memory usage 虚拟内存
1、进程“需要的”虚拟内存大小,包括进程使用的库、代码、数据等
2、假如进程申请100m的内存,但实际只使用了10m,那么它会增长100m,而不是实际的使用量

RES:resident memory usage 常驻内存
1、进程当前使用的内存大小,但不包括swap out
2、包含其他进程的共享
3、如果申请100m的内存,实际使用10m,它只增长10m,与VIRT相反
4、关于库占用内存的情况,它只统计加载的库文件所占内存大小

SHR:shared memory 共享内存
1、除了自身进程的共享内存,也包括其他进程的共享内存
2、虽然进程只使用了几个共享库的函数,但它包含了整个共享库的大小
3、计算某个进程所占的物理内存大小公式:RES – SHR
4、swap out后,它将会降下来

DATA
1、数据占用的内存。如果top没有显示,按f键可以显示出来。
2、真正的该程序要求的数据空间,是真正在运行中要使用的。

ps : 如果程序占用实存比较多,说明程序申请内存多,实际使用的空间也多。
如果程序占用虚存比较多,说明程序申请来很多空间,但是没有使用。

发现机器的自身状态不存在问题, so毋庸置疑,发现问题了,典型的内存泄漏。。

第四步,使用jmap获取jvm进程dump文件

我们使用jmap -dump:format=b,file=dump_file_name pid 命令,将当前机器的jvm的状态dump下来或缺的一份dump文件,用做下面的分析

jmap命令:

jmap(JVM Memory Map)命令用于生成heap dump文件,还可以查询finalize执行队列、Java堆和永久代的详细信息,如当前使用率、当前使用的是哪种收集器等。
jmap -dump:format=b,file=dump_file_name pid : file=指定输出数据文件名, pid jvm进程号

接下来,回滚灰度的机器,开始解决问题=.=

解决问题

第一步,dump文件分析

在这里,我们分析dump文件,使用的Jprofiler软件,就是下面这个东东:

q4.png

具体的使用方法,在这就不再赘述了,下面将dump文件导入到Jprofiler中:
选择Heap Walker 中的Current Object Set,这里面显示的是当前的类的占用资源,从占用空间从大到小排序;

q5.png

从上图中,没有观察出什么问题,我们点击Biggest Objects,查看哪个对象的占用的内存高:

q6.png

从上图中,我们发现org.janusgraph.graphdb.database.StandardJanusGraph这个对象居然占用了高达724M的内存! 看来内存泄漏八九不离十就是这个对象的问题了!
再点开看看 ,如下图,可以发现是一个openTransactions的类型为ConcurrentHashMap的数据结构:

q7.png

第二步,源码查找定位代码

这到底是什么对象呢,去项目中查找一下,打开idea-打开项目-双击shift键-打开全局类查找-输入StandardJanusGraph,如下图:

q8.png

发现是我们项目使用的图数据库janusgraph的一个类,找到对应的数据结构:
类型定义:

private Set<StandardJanusGraphTx> openTransactions;

初始化为一个ConcurrentHashMap:

openTransactions = Collections.newSetFromMap(new 
ConcurrentHashMap<StandardJanusGraphTx, Boolean>(100, 
0.75f, 1));

观察上述代码,我们可以看到,里面的存储的StandardJanusGraphTx从字面意义上理解是janusgraph框架中的事务对象,下面往上追一下代码,看看什么时候会往这个Map中赋值:

// 找到执行openTransactions.add()的方法
    public StandardJanusGraphTx newTransaction(final TransactionConfiguration configuration) {
        if (!isOpen) ExceptionFactory.graphShutdown();
        try {
            StandardJanusGraphTx tx = new StandardJanusGraphTx(this, configuration);
            tx.setBackendTransaction(openBackendTransaction(tx));
            openTransactions.add(tx);  // 注意! 此处对上述的map对象进行了add
            return tx;
        } catch (BackendException e) {
            throw new JanusGraphException("Could not start new transaction", e);
        }
    }
 // 上述发现,是一个newTransaction,创建事务的一个方法,为确保起见,再往上跟找到调用上述方法的类:
   public JanusGraphTransaction start() {
        TransactionConfiguration immutable = new ImmutableTxCfg(isReadOnly, hasEnabledBatchLoading,
                assignIDsImmediately, preloadedData, forceIndexUsage, verifyExternalVertexExistence,
                verifyInternalVertexExistence, acquireLocks, verifyUniqueness,
                propertyPrefetching, singleThreaded, threadBound, getTimestampProvider(), userCommitTime,
                indexCacheWeight, getVertexCacheSize(), getDirtyVertexSize(),
                logIdentifier, restrictedPartitions, groupName,
                defaultSchemaMaker, customOptions);
        return graph.newTransaction(immutable);  // 注意!此处调用了上述的newTransaction方法
    }
 // 接着找上层调用,发现了最上层的方法
    public JanusGraphTransaction newTransaction() {
        return buildTransaction().start();  // 此处调用了上述的start方法
    } 

在我们对图数据库中图数据操作的过程中,采用的是手动创建事务的方式,在每次查询图数据库之前,我们都会调用类似于dataDao.begin()代码,
其中就是调用的public JanusGraphTransaction newTransaction()这个方法;

最后,我们简单的看下源码可以发现,从上述内存泄漏的map中去除数据的逻辑就是commit事务的接口,调用链如下:

    public void closeTransaction(StandardJanusGraphTx tx) {
        openTransactions.remove(tx); // 从map中删除StandardJanusGraphTx对象
    }
    
    private void releaseTransaction() {
        isOpen = false;
        graph.closeTransaction(this); // 调用上述closeTransaction方法
        vertexCache.close();
    }
    
   public synchronized void commit() {
        Preconditions.checkArgument(isOpen(), "The transaction has already been closed");
        boolean success = false;
        if (null != config.getGroupName()) {
            MetricManager.INSTANCE.getCounter(config.getGroupName(), "tx", "commit").inc();
        }
        try {
            if (hasModifications()) {
                graph.commit(addedRelations.getAll(), deletedRelations.values(), this);
            } else {
                txHandle.commit();  // 这个commit方法中释放事务也是调用releaseTransaction
            }
            success = true;
        } catch (Exception e) {
            try {
                txHandle.rollback();
            } catch (BackendException e1) {
                throw new JanusGraphException("Could not rollback after a failed commit", e);
            }
            throw new JanusGraphException("Could not commit transaction due to exception during persistence", e);
        } finally {
            releaseTransaction();  // // 调用releaseTransaction
            if (null != config.getGroupName() && !success) {
                MetricManager.INSTANCE.getCounter(config.getGroupName(), "tx", "commit.exceptions").inc();
            }
        }
    }
   

终于,我们找到了内存泄漏的根源所在:项目代码中存在调用了事务begin但是没有commit的代码!

第三步,修复问题验证

解决问题: 找到内存泄漏接口的代码,并发现了没有commit()的位置,try-catch-finally中添加上了commit()代码;

提交-部署-发布-灰度一台机器后观察内存泄漏的现象消失,GC回收正常;

内存泄漏问题解决,项目如期上线~

最后

大家,有没有遇到过内存泄漏的情况,欢迎在评论区说出你的故事=.=

写这篇文章耗费的时间超出了我的预料,预计2个小时写完,结果花了一下午的时间...

原创不易,如果大家有所收获,希望大家可以点赞评论支持一下~

也欢迎大家关注我的简书和微信搜索公众号[匠心Java]支持一下作者,作者定期分享工作中的所见所得~

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 206,126评论 6 481
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 88,254评论 2 382
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 152,445评论 0 341
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 55,185评论 1 278
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 64,178评论 5 371
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,970评论 1 284
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,276评论 3 399
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,927评论 0 259
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 43,400评论 1 300
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,883评论 2 323
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,997评论 1 333
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,646评论 4 322
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,213评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,204评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,423评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,423评论 2 352
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,722评论 2 345

推荐阅读更多精彩内容