一个在多线程中使用 java.util.logging.Logger 类时应注意的问题

0.1 背景

前段时间开始写一个 gdflbd（generate datasets for learning big data，生成用于学习大数据的数据集）工具：GitHub 地址

其中使用了 java.util.logging.Logger 类来输出生成的日志文件，在多线程环境中使用该类有一个需要注意的地方，记录如下：

测试环境为：

• i5-4210M
• 16G 内存
• Win10（21H2）
• openJDK_11+25

0.2 简单说一下开发过程

0.2.1 最开始的实现

对应 v0.1.00 版（这个 commit）

只是单纯实现功能，实际 JVM 资源占用非常感人

• 在生成 large 规模的 AppStartLog 日志的时候，即使添加 -Xms8G -Xmx8G -XX:SurvivorRatio=8 参数，依然 oom：

  • 1	java -Xms8G -Xmx8G -XX:SurvivorRatio=8 -jar gdflbd_0.1.00-jar-with-dependencies.jar "D:\gdflbd001\test0_large" AppStartLog large 2020-08-20 14

  • 

  • 大概跑了 14 个小时，JVM 君很努力地进行了 10562 次 Full GC 😂，依然没能挽救 oom 的命运

    • 事后观察生成的数据集大概只有 30% ～ 40% 的完成度

  • 甚至在好奇心的驱使下，调到 13G 一样 oom 😩

0.2.2 初步优化：减少 static 方法的使用

对应 v0.1.01 版（这个 commit）

• 减少 static 方法的使用后，能顺利跑完 large 规模的任务了

  • 1	java -Xms8G -Xmx8G -XX:SurvivorRatio=8 -jar gdflbd_0.1.01-jar-with-dependencies.jar "D:\gdflbd001\test1_large" AppStartLog large 2020-08-20 14

  • 

  • 耗时：30.65 小时 😂，进行了 7845 次 Full GC ，幸存了下来

0.2.3 进一步优化：使用多线程

对应 v0.1.02 版（这个 commit）

使用多线程，大大提高了执行效率

• 执行 large 规模的任务

  • 由于后文所述的 java.util.logging.Logger 类的问题的特点，及其解决，进一步降低了资源占用，large 任务不添加 -Xms8G -Xmx8G -XX:SurvivorRatio=8 参数也能顺利完成了：

  • 1	java -jar gdflbd_0.1.02-jar-with-dependencies.jar "D:\gdflbd001\test2_large" AppStartLog large 2020-08-20 14

  • 

  • 耗时：仅 1.63 小时 👏 ，而且只进行了 38 次 Full GC

• 执行 huge 规模的任务

  • 1	java -jar gdflbd_0.1.02-jar-with-dependencies.jar "D:\gdflbd001\test2_huge2" AppStartLog huge 2020-08-20 14

  • 

  • （不调整 JVM 执行参数）大概 8 个多小时，进行了 3189 次 Full GC ，不幸 oom

    • 事后观察生成的数据集大概有 90% 的完成度

  • 添加 -Xms8G -Xmx8G -XX:SurvivorRatio=8 参数后，顺利完成任务

  • 1	java -Xms8G -Xmx8G -XX:SurvivorRatio=8 -jar gdflbd_0.1.02-jar-with-dependencies.jar "D:\gdflbd001\test2_huge2" AppStartLog huge 2020-08-20 14

  • 

  • 耗时： 11 小时，只进行了 20 次 Full GC

0.3 java.util.logging.Logger 类在多线程环境中需要注意的问题

在使用多线程生成日志的开发过程，遇到个排查了很久的问题

1. 测试时，使用 break 打断循环，使每天只生成一条日志

   • 1	break; // 开发测试，每天只写一条

   • 结果跑出来的日志：

     • 有的日期有 1 条日志，这符合预期

     • 但也有的日期有不止 1 条日志，多的甚至有 5、6 条（测试时生成 8 天的日志）

     • 将所有日志放到一起，去重后，正好是 8 条日志

     • 同一天的日志文件中，不存在重复日志

2. 一开始就怀疑是多线程的问题

   • 尝试在可疑的地方加锁，都没有解决，甚至问题丝毫没有发生改变

3. 后来实属 “瞎猫碰到死老鼠”

   • 各处看代码的时候发现各个类中获取 Logger 对象的代码有点不规范

   • 1 2 3 4 5

     // 应该是这么用比较好 private final Logger logger = Logger.getLogger(this.getClass().getName()); // 但我在代码中直接使用了类名 private final Logger logger = Logger.getLogger(AppStartLogger.class.toString());

   • 并且到处拷贝代码，导致有的类名用错了

   • 当时对手头的问题毫无头绪（甚至回头复习了多线程的知识点），就 “顺手” 把这些地方都规范一下

4. 错中错

   • 不小心把这两个 Logger 实例改成一样的了

     • 

     • 第一个实例用于本类输出自身的日志信息，第二个实例是用于输出数据集日志的
     • 于是测试的时候就发现输出的 AppStartLog 中，混了这个类自身的日志进去
   • 这才意识到问题在 java.util.logging.Logger 类，而不在多线程

5. 问题的解决

   • 导致问题的原因是：

     • java.util.logging.Logger.getLogger(String name) 这个方法，不管在哪个类中调用，只要传入的 String name 参数相同，那么返回的 Logger 对象就是同一个实例

   • 解决方法

     • 使用线程名作为传入参数

       • 1	Logger loggerToFile = Logger.getLogger(this.threadName);

6. 意外收获

   • 回顾前面对 java.util.logging.Logger 类的使用，就是因为全程只使用了一个 Logger 实例，所以资源得不到释放
   • 现在是每个线程使用一个实例，跑完的线程的资源就能顺利释放
   • 也就是说还可以进一步优化：
     • 比如用 “线程名 + 时间戳（按 10 分钟取模之类）” 来实例化 Logger 对象
     • 那么每个 Logger 实例就只会存在 10 分钟（目前用线程名，是从线程启动到结束都是用这同一个实例，huge 任务一个线程大概要跑 5 小时）
     • 这样就可以进一步减少资源占用

0.4 总结

1. 各种 API、类库的使用，都有必要学习一下源码，了解其实现机制
2. 回头还得补一补设计模式的知识