1. 背景
排序服务新上线一个DPP(Determinantal Point Process)重排算法逻辑，基于DJL(Deep Java Library)实现的, DJL目前提供了MXNet,、PyTorch和TensorFlow的实现，通过调用JNI或者JNA来调用相应的底层操作。
新重排算法上线之服务调用方每隔一段时间就会出现超时报错，每个一段时间还会出现OOM，这是之前从来没有的情况，因此开始了JVM排查之路。
排序服务是部署在K8S集群上，配置是8C16G，使用的JDK11的ZGC。
2 排查之路
2.1 NDManager
- 监控显示18点30左右，排序服务调用方有超时报错。查看接口的平均响应时间，确实有尖峰（因为排序服务被多个服务调用，所以截取的是服务调用方展示的接口平均耗时曲线）。
- 查看CPU利用率发现 18:30 确实有提升，但是CPU throttled time还好。说明响应时间升高跟CPU throttled没有关系，再结合OOM怀疑跟内存泄露有关（废话，都OOM了，肯定是跟内存泄露有关系了，但是响应时间升高是有很多因素引起的，还要排除CPU throttled的影响）。
- 怀疑内存泄露第一时间查看堆的使用情况和GC情况(频率与耗时)，但是18:30 左右都是正常的。
- 问题暂时陷入了僵局， 忽然发现18:30左右的超时报错大部分都跟某一台机器有关，查看stdout日志，发现 18:31:27 Tomcat被重启了，同样09:20:34、12:22:34 Tomcat都被kill然后重启。这样CPU利用率在这几个时间点彪高也能解释了。
- 排查的过程中意外发现Direct BufferPool使用率随着时间逐渐增加。每次重启之后骤降，过一段时间又增加。堆内的使用情况又正常， 怀疑跟堆外内存有关。
- 堆外内存主要包括：DirectByteBuffer分配的内存，JNI里分配的内存，线程栈分配占用的系统内存，jvm本身运行过程分配的内存，codeCache，java 8里还包括metaspace元数据空间。而且之前也提到了新上线基于DJL的DPP重排逻辑，会有大量使用JNI。因为对JNI不熟悉，只是简单了解过其机制，且堆外的内存特别难以排查，所以试着查看代码看看有没有什么发现。DPP的主要代码如下所示（省略部分代码和参数）：
private void dppRank ( ) {
DPPModel dppModel = new DPPModel(itemCount, topK);
List<Integer> resDPP = dppModel.dppSW(/* 参数省略 */);
}
public class DPPModel {
private NDArray rankScore;
private NDArray kernelMatrix;
private NDManager manager = NDManager.newBaseManager();
// ... ...
}
这里使用的DJL的pytorch-engine:0.18.0，通过NDManger.create()创建NDArray，会调manager.attachInternal() 将创建的NDArray放到NDManager.resources中，以便统一管理。
public PtNDArray(PtNDManager manager, long handle) {
super(handle);
this.manager = manager;
this.ptNDArrayEx = new PtNDArrayEx(this);
manager.attachInternal(getUid(), this);
}
public synchronized void attachInternal(String resourceId, AutoCloseable resource) {
if (closed.get()) {
throw new IllegalStateException("NDManager has been closed already.");
}
tempResources.compute(
resourceId,
(key, tempResource) -> {
if (tempResource != null) {
// This state occurs when this manager (manA) tempAttaches a resource that
// is later
// tempAttached to another manager (manB)
// When manB is closed, it will use attach to return the resource to this
// (manA)
// In that case, it should stay as a tempResource in this (manA)
tempResource.detached = false;
} else {
resources.put(resourceId, resource);
}
return tempResource;
});
}
PtNDManager继承自BaseNDManager，实现AutoCloseable的close接口，会遍历resources调所有NDArray的close方法
public void close() {
if (!closed.getAndSet(true)) {
for (AutoCloseable closeable : resources.values()) {
try {
closeable.close();
} catch (Exception e) {
logger.error("Resource close failed.", e);
}
}
for (TempResource resource : tempResources.values()) {
resource.returnResource();
}
parent.detachInternal(uid);
resources.clear();
tempResources.clear();
}
}
查看PtNDManger的create 方法，会删除NDArray的内存。
@Override
public void close() {
Long pointer = handle.getAndSet(null);
if (pointer != null) {
JniUtils.deleteNDArray(pointer);
}
manager.detachInternal(getUid());
dataRef = null;
查到这里可以肯定是因为DJL的使用不当引起的， 可以通过try-with-resource方式使用NDManager，使用后会自动释放资源。
try (NDManager manager = NDManager.newBaseManager(Device.cpu())) {
NDArray rankScore = manager.create(rankScoreArray);
}
修改后，重新发布后，可以发现 BufferPool direct used 使用正常。
2.2 NDManager自身bug
但是故事到这里还没有结束，本以为调整使用方式就万事大吉了，但是上线一段时间后系统仍然报OOM、Tomcat也被重启，只是频率比之前低了很多，又开始漫长的排查之路。
- 查看gc.log，发现确实有内存泄露，如下图所示，只是被之前误用的问题掩盖起来了。这里介绍一个网站https://gceasy.io/ 可以分析GC日志，发现GC后的堆使用情况一直是增加的。 同时Mem RSS使用量也是不断增加的。
- 查看堆内存dump
使用Memory Analyzer (MAT)查看堆内存使用情况，直方图如下所示，其中：
- Retained Heap（深堆）代表对象本身和对象关联的对象占用的内存；
- Shallow Heap（浅堆）代表对象本身占用的内存。
其中有大量的PtNDManager，远超正常使用。通过list objects- with incoming referencs 查看， 发现被PtNDManager$SystemManager的resources引用。
每个一段时间执行一下jmap -histo:live 也可以发现PtNDManager一直增加。
- 继续查看DJL源码
NDManager.newBaseManager()创建PtNDManager源码如下所示, 会调用PtNDManager$SystemManager的attachUncappedInternal将创建的PtNDManager挂载到resoures里。
PtNDManager manager = new PtNDManager(this, device);
attachUncappedInternal(manager.uid, manager);
return manager;
resources.put(resourceId, resource);
当PtNDManager执行close方法时，会调用parent的detachInternal方法，parent是PtNDManager$SystemManager， PtNDManager$SystemManager的detachInternal什么都没干
public void close() {
if (!closed.getAndSet(true)) {
// ignore some code
parent.detachInternal(uid);
resources.clear();
tempResources.clear();
}
}
@Override
public void detachInternal(String resourceId) {}
查看pytorch-engine的0.17.0的源码就正常多了，使用之后也没有问题，于是去DJL的github怒提issue： https://github.com/deepjavalibrary/djl/issues/1886
总结
此次内存泄露有两个原因：
- DJL使用不当，NDManager创建之后没有关闭，导致相应的NDArray和JNI内存都没有被回收；
- DJL自身bug， NDManager即使执行了close，但是还是被引用，导致自身无法被回收。
虽然排查之后再进行复盘，根据各种现象，顺理成章就排查了问题的根源。 但是一开始排查时，毫无头绪，各种细节充斥其中，有些是原因，有些是结果， 比如最开始怀疑是CPU彪高导致响应时间变长，但其实是因为OOM导致tomcat 重启导致的CPU彪高。只能不停地假设，然后根据现象验证假设，最终定位问题。
总结内存泄露的排查流程如下：
- 首先要熟悉JVM、包括垃圾收集器的原理，这样才能有的放矢；
- 借助一些工具，事半功倍：本文涉及到有graphana、cat、mat、jmap 等，每个工具都有自身的功能，帮忙定位一些问题；
- 结合理论与工具，抓住线索，不停地去怀疑、假设，然后验证自己的假设；
- 剩下的就是交给时间，本次排查也耗时好久，开始走了很多的弯路，但是硬刚到底最终会发现问题根源。
经过此次排查，对很多东西的理解和工具的使用更上一层楼。
最后想说一下DJL，虽然本文的内存泄露与DJL有关，但是不得不说DJL是一个难得的JAVA 机器学习工具包，可以在Java中开发及应用原生的机器学习和深度学习模型，同时简化了深度学习开发的难度。通过DJL提供的直观的、高级的API，Java开发人员可以训练自己的模型，或者利用数据科学家用Python预先训练好的模型来进行推理。如果恰好是对学习深度学习感兴趣的Java开发者，那么DJL无疑将是开始深度学习应用的一个最好的起点。
