背景介绍
业务介绍
在某学习APP浏览文章,客户端会将浏览的文章信息上传到服务端,服务端将浏览信息最终存储到HBase;
在某学习APP首页点击【我的】->【历史】,会展示用户浏览文章的历史记录。
技术介绍
服务端的服务是【阅读历史离线服务】,从metaq消费用户阅读文章的信息,解析、处理相关业务逻辑,最后存储到HBase。
问题现象
ECS监控
两台机器【xx-xxxx-xxx-xxx-xxx-xxx-6、xx-xxx-xxx-xxx-xxx-xxx-1】在早高峰的时候Load很高,CPU使用率正常。
metaq监控
造成消息消费的慢,每天早上都有大量消息堆积,导致用户看不到自己的阅读历史。
问题分析
基本情况
【阅读历史离线服务】共有x台ECS,每台ECS配置是8c16g。其中x台机器正常,2台机器不正常。
排查思路
找不同
分析不正常机器与正常机器有哪些差异:对比了【应用程序版本】、【应用程序配置】、【JVM配置参数】、【JDK版本】、【操作系统版本】,发现【JDK版本】不一致。
正常机器:
openjdk version "1.8.0_171" OpenJDK Runtime Environment (build 1.8.0_171-b10) OpenJDK 64-Bit Server VM (build 25.171-b10, mixed mode)
异常机器:
openjdk version "1.8.0_222" OpenJDK Runtime Environment (build 1.8.0_222-b10) OpenJDK 64-Bit Server VM (build 25.222-b10, mixed mode)
到此初步定位不同机器运行状态不一致的现象是由于【JDK版本】不一致造成的,所以将【问题机器的JDK版本】替换为【正常机器的JDK版本】问题就可以解决了。
定位问题代码
但是问题的根因还需要尝试排查一下,既然是【JDK版本】不一致造成的,那么会不会是【1.8.0_222】这个版本中有BUG,刚好我们写的程序触发了这个BUG?
所以接下来需要弄清楚程序运行过程中执行了哪些业务逻辑、这些业务逻辑涉及到了哪些JDK API,直接想到的工具是arthas profiler,下面是抓到的热点方法。
通过对比【异常机器】与【正常机器】的热点方法,发现Runtime.getRuntime().availableProcessors()很可疑:
业务相关代码:
CompletableFuture<Result> completableFuture = //业务逻辑,调用hbase-client中api completableFuture.whenCompleteAsync((result, t) -> { //业务逻辑处理 }, Pool.getSubmitPool()).exceptionally((t) -> { //业务逻辑处理 }).get();
CompletableFuture相关代码:
/** * Waits if necessary for this future to complete, and then * returns its result. * * @return the result value * @throws CancellationException if this future was cancelled * @throws ExecutionException if this future completed exceptionally * @throws InterruptedException if the current thread was interrupted * while waiting */ public T get() throws InterruptedException, ExecutionException { Object r; return reportGet((r = result) == null ? waitingGet(true) : r); } /** * Returns raw result after waiting, or null if interruptible and * interrupted. */ private Object waitingGet(boolean interruptible) { Signaller q = null; boolean queued = false; int spins = -1; Object r; while ((r = result) == null) { if (spins < 0) spins = (Runtime.getRuntime().availableProcessors() > 1) ? 1 << 8 : 0; // Use brief spin-wait on multiprocessors else if (spins > 0) { if (ThreadLocalRandom.nextSecondarySeed() >= 0) --spins; } else if (q == null) q = new Signaller(interruptible, 0L, 0L); else if (!queued) queued = tryPushStack(q); else if (interruptible && q.interruptControl < 0) { q.thread = null; cleanStack(); return null; } else if (q.thread != null && result == null) { try { ForkJoinPool.managedBlock(q); } catch (InterruptedException ie) { q.interruptControl = -1; } } } if (q != null) { q.thread = null; if (q.interruptControl < 0) { if (interruptible) r = null; // report interruption else Thread.currentThread().interrupt(); } } postComplete(); return r; }
猜测验证
public class Processors { public static void main(String []args) { int availableProcessors = Runtime.getRuntime().availableProcessors(); System.out.println("Available Processors: " + availableProcessors); for(int i = 0;i < availableProcessors;i++){ Thread t = new Thread(()-> { while (true){ try { int ps = Runtime.getRuntime().availableProcessors(); Thread.sleep(1L); }catch (Exception e){ e.printStackTrace(); } } }); t.start(); } } }
将验证代码在【JDK版本】为【1.8.0_222】的机器上运行,随即复现了线上问题。
定位根因
那么【1.8.0_222】与【1.8.0_171】版本在Runtime.getRuntime().availableProcessors()的实现上有什么差别呢?【1.8.0_222】增加了容器环境的逻辑,比【1.8.0_171】复杂了很多。
最后我们看看在https://bugs.openjdk.java.net/的解释吧。
总结:
Runtime.getRuntime().availableProcessors()在不同JDK版本上的实现是没有问题的,CompletableFuture.waitingGet在【1.8.0_222】版本上,没有测试到Runtime.getRuntime().availableProcessors()对性能的影响,导致了性能问题。
解决方法
openjdk在1.8.0_191~1.8.0_222之间的版本都存在问题,换成1.8.0_191之前,或1.8.0_232及以后的版本可以。
问题根因
CompletableFuture.get()的实现方式在一些jdk版本存在缺陷,
详情见:CompletableFuture should not call Runtime.availableProcessors on fast path