分类 Java 相关 下的文章

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 异步日志 或者其他异步日志;

诊断不正确的 JSONArray 引起的死循环导致 CPU 使用率高

最近有个应用经常 CPU 使用率经常非常高, 一旦升上去, 很难再下来, 除非进行重启. 使用 htop 观察, 出现 CPU 使用率高的并不是一个线程. 然后使用 async-profiler 查看, 发现代码很像死循环, 99%以上的栈都被 JSONArray 初始化占用了:
jsonArray.png

看上去一个很正常的 JSONArray 初始化为什么会占用这么多 CPU 时间呢? 难道是处理的业务较多? 一开始开发人员认为最近的促销导致业务量暴涨导致的. 其实做一个 heap dump 很快发现了事情的元凶.

我们的这段代码是这么写的(这里只是展示基本含义, 没做其它验证):

String str = "some string";
if (str.startWith("[")) {
   new org.codehaus.jettison.json.JSONArray(str);
} else {
   //something else
}

问题就出现在这个 str, 如果它的格式有问题, 不是真正的数组, 那么就会出现问题, 比如下面的代码:

       public static void main(String[] args) {
        String str = "[*/*A25] **";
        try {
            System.out.println("start");
            System.out.println(new JSONArray(str));
            System.out.println("end");
        } catch (JSONException e) {
            e.printStackTrace();
        }
    }

如果 debug 上面的代码, 就会发现出现了死循环, 线程再也无法退出. stuck 在了 JSONTokener L179 ~ 188 -> next() -> back() -> next(). 一直 next(), back().

于是给这个 lib 提了一个 issue: https://github.com/jettison-json/jettison/issues/36

JVM Heap dump 相关知识

最近在研究 JVM heap 相关的东西, 把相关的内容整理在这里

  1. 什么是 HPROF
    HPROF 是 Heap and CPU Profiling Agent 的工具, 是通过使用 JVM TI 的接口实现的 agent, 它在 JDK 里面是用来展示如何使用 JVM TI 的小工具. 同时它也是 Hotspot JVM 产生的 heap dump 的文件格式. HPROF 的格式参考下面. https://docs.oracle.com/javase/8/docs/technotes/samples/hprof.html. 使用以下命令, 查看帮助

    java -agentlib:hprof=help
    HPROF: Heap and CPU Profiling Agent (JVMTI Demonstration Code)
    
    hprof usage: java -agentlib:hprof=[help]|[<option>=<value>, ...]
    
    Option Name and Value  Description                    Default
    ---------------------  -----------                    -------
    heap=dump|sites|all    heap profiling                 all
    cpu=samples|times|old  CPU usage                      off
    monitor=y|n            monitor contention             n
    format=a|b             text(txt) or binary output     a
    file=<file>            write data to file             java.hprof[{.txt}]
    net=<host>:<port>      send data over a socket        off
    depth=<size>           stack trace depth              4
    interval=<ms>          sample interval in ms          10
    cutoff=<value>         output cutoff point            0.0001
    lineno=y|n             line number in traces?         y
    thread=y|n             thread in traces?              n
    doe=y|n                dump on exit?                  y
    msa=y|n                Solaris micro state accounting n
    force=y|n              force output to <file>         y
    verbose=y|n            print messages about dumps     y
  2. 什么是 JVM TI
    JVM TI 是 JDK 5 开始, 取代早期(JDK 4 及以前) JVM 提供的 DI (Debug Interface) 和 PI (Profiling Interface) 的统一接口. 参考
  3. HPROF 文件里面都可以有啥?
    CPU profiling 的数据, 一般以 stack trace sample 的形式存在; Heap 内存分配的信息; 以及锁竞争的信息.

参考:

  1. JDK 自带文档 demo/jvmti/hprof/src/manual.html
  2. http://www.brendangregg.com/blog/2014-06-09/java-cpu-sampling-using-hprof.html