2020年9月

JDK attach API

从 JDK 1.6 开始, Sun 引入了 attach API, 可以 attach 到目标 Java 进程, 这样就可以和目标 JVM 通信, 建立通信之后, 你可以让目标进程加载某些 agent 代码, 这样你就可以和目标进程进行信息交换了.

最简单的代码就在 API 文档里: https://docs.oracle.com/javase/8/docs/jdk/api/attach/spec/index.html
要使用 attach API, 需要引入 jdk lib 目录下的 tools.jar, 因为里面包含包: com.sun.tools.attach.*.

一旦获得 VirtualMachine, 最简单可以获得目标进程的系统属性. 其他的都是通过让目标进程加载 agent 来获得. agent 分为两类: 一类是通过 java.lang.instrument API 写的 Java agent. 另外一类是通过 Native 代码 JVM TI (The agent must be written in native code) 写的 agent.

有人封装的 attach API: https://github.com/gridkit/jvm-attach
比如有人做的工具: https://github.com/aragozin/jvm-tools

如何写 Java Agent : https://docs.oracle.com/javase/8/docs/api/index.html?java/lang/instrument/package-summary.html
如何写基于 JVMTI 的 agent: https://www.oracle.com/technical-resources/articles/javase/jvmti.html

我写的使用 Attach API 和 Instrument API 的agent: https://github.com/manecocomph/myJavaAgent

其它相关概念:
JPDA (Java™ Platform Debugger Architecture), JVM TI, JDWP(Java Debug Wire Protocol), JDI(Java Debug Interface), Java Agent, HPROF agent, HPROF format, BCI (Byte Code Injection), Instrument API, Java Attach API, AsyncGetCallTrace.

JDI API: https://docs.oracle.com/javase/6/docs/jdk/api/jpda/jdi/index.html
使用 JDI 获得一个类的所有实例对象: https://docs.oracle.com/javase/6/docs/jdk/api/jpda/jdi/com/sun/jdi/ReferenceType.html#instances(long)

诊断由于多线程同步写日志竞争引起的上游应用超时

有开发人员抱怨说, 他的应用在某个数据中心有很多超时的错误, 怀疑是不是网络有问题.

SRE 查看了超时的请求, 又查看了提供该服务的应用, 发现在服务提供方有规律的收到大量请求, 一旦请求数量达到一定程度, 它的延时就会增加很多, 如下图:
traffic.png

首先, 我们确定这是跟流量相关的, 一旦流量增加到某个值, 它的 CPU 使用率, GC overhead, latency, 和 忙碌的线程数都同步的增加.

那么最简单的解决方式就是: 加机器. 云计算让加机器变得非常容易.
如果不加机器, 让请求变的更平均, 也是一种方案.

那么有没有可能对服务提供方的代码进行仅仅优化, 就可以满足要求的方式呢?
首先, 我们仔细查看了服务提供方应用的日志, 根据日志, 发现很多情况下, 如果对比流量低的时候, 在某行日志之后总是有大约 1s 的间隔, 这 1s 花费在那里了? 是有好多代码在执行? 还是花费在 I/O 请求上面? 还是花费在 CPU 执行上面?

一开始, 我们怀疑在请求大量增加的情况下, 是不是某些线程池里面的线程不够用了, 先是加了线程池数量, 观察一段时间后, 发现没有效果.
之后, 我们也意识到, 如果是等待线程池, 它的 CPU 不会增加太多, 而我们的观察到的情况是如果流量增加, CPU 使用率增加很多. 那么据此推测, 当流量增加的时候, 有大量的 CPU 消耗.
我们查看了应用的本地日志, 发现该应用大概 1 分钟写 15M 日志. 日志文件里很多线程交叉写的日志, 日志间隔在 1ms 以下, 所以推测, 这里会形成大量的多线程锁竞争.

这些大量的日志都是 warn 级别, 如果我们减少这种 warn 级别, 或者关掉 warn 级别的日志, 会不会有大量提升? 于是, 最简单的办法, 我们修改了日志的级别为 error 级别, 经过一段时间观察, 效果很明显. 于是确定了问题所在.

对于这种问题, 推荐的解决办法是:

  1. 去掉不需要的日志打印;
  2. 设置正确的日志级别;
  3. 把日志改成异步日志, 如 log4j 2.0 异步日志 或者其他异步日志;