诊断 mimepull.jar 导致的大量临时文件不能释放的问题

某天某个应用程序的某些服务器突然大量抛出下面异常:

msg=Error executing HystrixCommand 'xxxClient', failureType = COMMAND_EXCEPTION, rootcause=SocketException: Too many open files&st=com.sun.jersey.api.client.ClientHandlerException: java.net.SocketException: Too many open files

很明显, 这个应用打开了太多的文件句柄, 没有关闭. 为了缓解问题, 重启服务器临时解决. 到底哪里出了问题呢? 为什么最近才开始有这种错误? 我们一步步找出事故的原因.

- 阅读剩余部分 -

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

  1. 1
  2. 2
  3. 3
  4. 4
  5. ...
  6. 77