记一次摸不着头脑的FullGC问题 （Thumbnails压缩图片占用巨大内存）

问题现象

首先用户反映，有数据不一致情况产生，为了查询什么原因导致的数据不一致问题，
扒拉出来日志看了一通，发现有个简单的查询耗时特别长，平时只要几ms返回结果的
确调用了200多s，查了各个服务的日志，发现并没有什么问题，把日志展开了看，发现
有5分钟时间，系统各种超时，各种错误，包括连接数据库超时，连接redis超时，等等
就考虑看一下GC日志，这一看不要紧，发现这5分钟时间GC日志刷了上千条FullGC，如下图所示：

回收前后内存变化不大，基本没回收掉内存，但还在不断的回收，因为使用的CMS内存回收器，超过最大内存的80%时会进行FullGC，所以JVM一直在傻傻的回收内存空间，应用程序几乎暂停。

好了，基本找到为什么会报错了，但是为什么会频繁的FullGC呢，这个问题又困扰了很久

思考可能是内存泄漏，或者是某个远程接口阻塞导致大量请求堆积，查看代码发现，代码中resttemplate设置的超时时间都是60s超时，而整个GC持续了5分钟，如果内存泄漏，内存会一直不回收，最终导致的结果是内存占满，OutOfMemoryError, 但是这个摸不着头脑的FullGC最终把内存回收掉了，所以应该不是内存泄漏导致的。
猜想可能是某个业务占用内存特别大，并且短时间内回收不掉。

查阅了好久的代码以及日志，最终定位到一段图片压缩的代码，原代码如下：

import net.coobird.thumbnailator.Thumbnails;
public class ImageProcessor {
	  /**
	   * 压缩图片 bytes -> bytes
	   * @param imageContent image bytes
	   * @param size 压缩尺寸
	   * @return resized bytes
	   * @throws IOException e
	   */
	static byte[] resize(byte[] imageContent, int size) throws IOException {
	
	    ByteArrayOutputStream out = new ByteArrayOutputStream();
	
	    Thumbnails.of(new ByteArrayInputStream(imageContent)).size(size, size).useExifOrientation(true).outputFormat(FileTypeUtil.JPG).toOutputStream(out);
	
	    return out.toByteArray();
	 }
}

最开始以为是ByteArrayOutputStream流没关闭造成的，查看了ByteArrayOutputStream的源码：

/**
     * Closing a <tt>ByteArrayOutputStream</tt> has no effect. The methods in
     * this class can be called after the stream has been closed without
     * generating an <tt>IOException</tt>.
     */
    public void close() throws IOException {
    }

close方法不做任何的操作，因为这个是纯内存操作的流，没有跟文件系统打交道，这个地方数据量不需要关闭，用完等待垃圾回收就可以了。
既然不是这里的问题，那我对这个方法做个测试吧，使用了如下的方法打印了内存占用情况：

private static void getFreeMemoryPercentage() {
    // 虚拟机级内存情况查询
    long vmFree = 0;
    long vmUse = 0;
    long vmTotal = 0;
    long vmMax = 0;
    int byteToMb = 1024 * 1024;
    Runtime rt = Runtime.getRuntime();
    vmTotal = rt.totalMemory() / byteToMb;
    vmFree = rt.freeMemory() / byteToMb;
    vmMax = rt.maxMemory() / byteToMb;
    vmUse = vmTotal - vmFree;
    System.out.println("JVM内存已用的空间为：" + vmUse + " MB");
    System.out.println("JVM内存的空闲空间为：" + vmFree + " MB");
    System.out.println("JVM总内存空间为：" + vmTotal + " MB");
    System.out.println("JVM总内存空间为：" + vmMax + " MB");

    System.out.println("======================================");
    // 操作系统级内存情况查询
    OperatingSystemMXBean osmxb = (OperatingSystemMXBean) ManagementFactory.getOperatingSystemMXBean();
    String os = System.getProperty("os.name");
    long physicalFree = osmxb.getFreePhysicalMemorySize() / byteToMb;
    long physicalTotal = osmxb.getTotalPhysicalMemorySize() / byteToMb;
    long physicalUse = physicalTotal - physicalFree;
    System.out.println("操作系统的版本：" + os);
    System.out.println("操作系统物理内存已用的空间为：" + physicalFree + " MB");
    System.out.println("操作系统物理内存的空闲空间为：" + physicalUse + " MB");
    System.out.println("操作系统总物理内存：" + physicalTotal + " MB");

    // 获得线程总数
    ThreadGroup parentThread;
    int totalThread = 0;
    for (parentThread = Thread.currentThread().getThreadGroup(); parentThread
        .getParent() != null; parentThread = parentThread.getParent()) {
      totalThread = parentThread.activeCount();
    }
    System.out.println("获得线程总数:" + totalThread);

  }

main方法如下：

   public static void main(String[] args) throws IOException {
    byte[] b = Files.readAllBytes(Paths.get("C:\\Users\\zhangwb\\Desktop\\微信图片_20200717174522.png"));
    getFreeMemoryPercentage();
    System.out.println("压缩前大小：" + b.length);
    byte[] a = resize(b, 1920);
    getFreeMemoryPercentage();
    System.out.println("压缩后大小：" + a.length);

  }

执行这个方法打印出来的日志如下：

JVM内存已用的空间为：22 MB
JVM内存的空闲空间为：223 MB
JVM总内存空间为：245 MB
JVM总内存空间为：3616 MB
======================================
操作系统的版本：Windows 10
操作系统物理内存已用的空间为：2538 MB
操作系统物理内存的空闲空间为：13730 MB
操作系统总物理内存：16268 MB
获得线程总数:2
压缩前大小：11398750
JVM内存已用的空间为：423 MB
JVM内存的空闲空间为：228 MB
JVM总内存空间为：651 MB
JVM总内存空间为：3616 MB
======================================
操作系统的版本：Windows 10
操作系统物理内存已用的空间为：2640 MB
操作系统物理内存的空闲空间为：13628 MB
操作系统总物理内存：16268 MB
获得线程总数:2
压缩后大小：255408

可以看到读出来的数据内存占用22M，图片压缩后JVM内存飙升到423M，多了将近20倍！！
图片压缩后大小小了不少，但是内存却多了这么多，这个可能是导致内存飙升，并且一直FullGC的真正元凶。

终于找到问题了，那如何解决呢

替换掉图片压缩的方法，改用GraphicsMagick处理图片，修改完之后的代码如下：

import java.io.IOException;
import java.nio.file.Files;
import java.nio.file.Path;
import lombok.extern.slf4j.Slf4j;
import org.apache.commons.lang3.math.NumberUtils;
import org.im4java.core.ConvertCmd;
import org.im4java.core.IMOperation;

/**
 * @author prague
 * @description 使用GraphicsMagick处理图片
 */
@Slf4j
public class GmImageProcessor {

  /**
   * 临时文件前缀-原始文件
   */
  public static final String SOURCE_PREFIX = "imgCut";
  /**
   * 临时文件前缀-转换文件
   */
  public static final String TARGET_PREFIX = "imgCutResult";
  /**
   * 所有输出文件都指定为JPEG
   */
  private static final String TARGET_IMG_SUFFIX = ".jpg";
  public static byte[] resize(byte[] imageContent, int size) throws IOException {

    Path sourcePath = null;
    Path targetPath = null;

    try {

      sourcePath = loadFile(imageContent);
      IMOperation op = new IMOperation();

      targetPath = Files.createTempFile(TARGET_PREFIX, TARGET_IMG_SUFFIX);

      op.size(size, size);
      op.addImage(sourcePath.toAbsolutePath().toString());
      op.resize(size, size, ">");
      op.p_profile("*");
      op.addImage(targetPath.toAbsolutePath().toString());

      log.debug("输出文件路径：{}", targetPath);

      ConvertCmd convertCmd = new ConvertCmd(true);
      convertCmd.run(op);

      return Files.readAllBytes(targetPath);
    } catch (Exception e) {
      log.error("压缩图片异常", e);
    } finally {
      deleteFile(sourcePath);
      deleteFile(targetPath);
    }

    return null;
  }

  /**
   * 旋转图
   *
   * @param degree 逆时针
   */
  static byte[] rotateImage(byte[] imageContent, int degree) {
    Path sourcePath = null;
    Path targetPath = null;
    try {
      sourcePath = loadFile(imageContent);
      IMOperation op = new IMOperation();
      //2020-07-28 16:13:06 add by gaotx 兼容瑞琪逆时针度数
      op.rotate((double) degree);
      op.addImage(sourcePath.toAbsolutePath().toString());
      targetPath = Files.createTempFile("imgCutResult", TARGET_IMG_SUFFIX);
      log.debug("输出文件路径：{}", targetPath);
      op.addImage(targetPath.toAbsolutePath().toString());
      ConvertCmd cmd = new ConvertCmd(true);
      log.debug(op.toString());
      cmd.run(op);
      return Files.readAllBytes(targetPath);
    } catch (Exception e) {
      BusiExceptionUtils.marshException(e);
    } finally {
      deleteFile(sourcePath);
      deleteFile(targetPath);
    }
    return null;
  }

  /**
   * 把一张大图切成多张小图，期间要保持源文件，完成后删除源文件， 每次切图完成后，删除临时目标文件
   */
  static byte[] cut(Path sourcePath, int startX, int startY, int endX, int endY, int degree) {

    Path outPath = null;
    try {
      IMOperation op = new IMOperation();
      op.addImage(sourcePath.toAbsolutePath().toString());
      int width = NumberUtils.max(endX - startX, 0);
      int height = NumberUtils.max(endY - startY, 0);
      op.crop(width, height, startX, startY);
      if (degree != 0) {
        //2020-07-28 16:13:06 add by gaotx 兼容瑞琪逆时针度数
        op.rotate((double) degree);
      }
      outPath = Files.createTempFile(TARGET_PREFIX, FileTypeUtil.JPG);
      log.debug("输出文件路径：{}", outPath);
      op.addImage(outPath.toAbsolutePath().toString());
      ConvertCmd convert = new ConvertCmd(true);
      log.debug(op.toString());
      convert.run(op);
      return Files.readAllBytes(outPath);
    } catch (Exception e) {
    	// TODO 处理异常
    } finally {
      deleteFile(outPath);
    }
    return null;
  }


  /**
   * bytes -> path
   *
   * @param imageContent bytes
   * @return path
   */
  static Path loadFile(byte[] imageContent) {
    Path sourcePath = null;
    String suffix = "." + bytes(imageContent);
    try {
      sourcePath = Files.createTempFile(SOURCE_PREFIX, suffix);
      log.debug("当前临时文件路径={}", sourcePath);
      Files.write(sourcePath, imageContent);
    } catch (IOException e) {
      log.error(e.getMessage(), e);
    }
    return sourcePath;
  }
/**
   * byte数组转换成16进制字符串
   */
  public static String bytes(byte[] src) {
    StringBuilder stringBuilder = new StringBuilder();
    if (src == null || src.length <= 0) {
      return null;
    }
    // 防止调用的时候没有进行截取前几位
    if (src.length > 4) {
      src = Arrays.copyOfRange(src, 0, 4);
    }

    for (byte b : src) {
      // 以十六进制（基数 16）无符号整数形式返回一个整数参数的字符串表示形式，并转换为大写
      String hv = Integer.toHexString(b & 0xFF).toUpperCase();
      if (hv.length() < 2) {
        stringBuilder.append(0);
      }
      stringBuilder.append(hv);
    }
    return getFileType(stringBuilder.toString());
  }

  /**
   * 根据文件路径获取文件头信息,因为根据文件的后缀名识别文件类型并不准确 424D--->BMP (bmp) ,  FFD8FF--->JPEG (jpg) , 89504E47---> PNG
   * (png)
   *
   * @return 文件头信息
   */
  public static String getFileType(String bytes) {
    if (bytes != null) {
      if (bytes.contains("FFD8FF")) {
        return "jpg";
      }
      if (bytes.contains("89504E47")) {
        return "png";
      }
      if (bytes.contains("424D")) {
        return "bmp";
      }
      if (bytes.contains("25504446")) {
        return "pdf";
      }
    }
    return null;
  }
  /**
   * 删除文件
   *
   * @param imagePath imagePath
   */
  static void deleteFile(Path imagePath) {
    try {
      if (imagePath != null) {
        Files.deleteIfExists(imagePath);
      }
      log.info("临时文件清理成功");
    } catch (IOException e) {
      log.error(e.getMessage(), e);
    }
  }

}

windows系统调试需要下载安装http://www.graphicsmagick.org/，linux环境请自行百度，并且在代码中设置path：
convertCmd.setSearchPath(“C:\Program Files\GraphicsMagick-1.3.35-Q16”);

否则调用会报找不到gm文件的异常
ok，我们对同样的图片进行同样大小的压缩，得出内存占用情况如下：

JVM内存已用的空间为：22 MB
JVM内存的空闲空间为：223 MB
JVM总内存空间为：245 MB
JVM总内存空间为：3616 MB
======================================
操作系统的版本：Windows 10
操作系统物理内存已用的空间为：2762 MB
操作系统物理内存的空闲空间为：13506 MB
操作系统总物理内存：16268 MB
获得线程总数:2
压缩前大小：11398750
14:16:10.583 [main] DEBUG com.yonyou.einvoice.common.util.image.GmImageProcessor - 当前临时文件路径=C:\Users\zhangwb\AppData\Local\Temp\imgCut742249801216682093.png
14:16:10.625 [main] DEBUG com.yonyou.einvoice.common.util.image.GmImageProcessor - 输出文件路径：C:\Users\zhangwb\AppData\Local\Temp\imgCutResult2449445347052121528.jpg
14:16:16.003 [main] INFO com.yonyou.einvoice.common.util.image.GmImageProcessor - 临时文件清理成功
14:16:16.004 [main] INFO com.yonyou.einvoice.common.util.image.GmImageProcessor - 临时文件清理成功
JVM内存已用的空间为：29 MB
JVM内存的空闲空间为：216 MB
JVM总内存空间为：245 MB
JVM总内存空间为：3616 MB
======================================
操作系统的版本：Windows 10
操作系统物理内存已用的空间为：2665 MB
操作系统物理内存的空闲空间为：13603 MB
操作系统总物理内存：16268 MB
获得线程总数:2
压缩后大小：209797

可以看出，图片压缩的更小了，JVM内存基本没有占用，堆外内存也基本没占用。

缺点：需要在服务器上安装插件，如果是私有部署比较麻烦，需要安装人员安装插件，否则图片压缩报错。

上线后就没再出现过内存占用暴增的情况了。

思考：你所看到的错误，并不一定是真正的错误，特别是超时的错误，有可能是其它原因导致的应用暂停，比如频繁的FullGC，比如，线程栈出现的死锁等问题。一定要找到真正的问题，并且经过自己验证过的，所有问题都不是凭空产生的，一定是有原因的，可以使用科学的知识解释的。