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

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

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

解决chrome extensions - Tabbed Postman - REST Client 无法导入问题

虽然 Postman 早就出了 Chrome Apps版本, 不过因为积累了很多老版本 Tabbed Postman 的例子, 大多数时间还是使用老版本的 Postman, 张这样:
postman.png

有次重装电脑, 把老版本里面的数据导出来, 然后想导入到新系统的 chrome的 Tabbed Postman 里面去, 不过每次都显示: it works, 却从来没有导入成功过, 原因在于 某段 JavaScript 出错, 今天为了使用某个数据, 只能手工 fix 这个 bug 了.

  1. 找到 Tabbed Postman Extension 的代码地址 (你可能要替换掉最后一部分):

    ~/Library/Application\ Support/Google/Chrome/Default/Extensions/coohjcphdfgbiolnekdpbcijmhambjff
  2. 把上面的整个文件夹复制到 ~/Download 目录下
  3. 修改 0.8.4.19_0/js/request.js (前面是我使用的 Tabbed Postman 的版本号), 修改的函数是: importCollectionData.

      importCollectionData:function (coll) {
    for (let i = 0; i < coll.collections.length; i++) {
      let collection = coll.collections[i];
      pm.indexedDB.addCollection(collection, function (c) {
          var message = {
              name:collection.name,
              action:"added"
          };
      
          $('.modal-import-alerts').append(Handlebars.templates.message_collection_added(message));
      
          var requests = [];
      
          var ordered = false;
          if ("order" in collection) {
              ordered = true;
          }
      console.log(collection);
          for (var i = 0; i < collection.requests.length; i++) {
              var request = collection.requests[i];
              request.collectionId = collection.id;
      
                /*Handling rawModeData */
              if(request.hasOwnProperty("rawModeData")) {
                  request.data = request.rawModeData;
              }  
      
      
              var newId = guid();
      
              if (ordered) {
                  var currentId = request.id;
                  var loc = _.indexOf(collection["order"], currentId);
                  collection["order"][loc] = newId;
              }
      
              request.id = newId;
      
              if ("responses" in request) {
                  var j, count;
                  for (j = 0, count = request["responses"].length; j < count; j++) {
                      request["responses"][j].id = guid();
                      request["responses"][j].collectionRequestId = newId;                        
                  }
              }
      
              pm.indexedDB.addCollectionRequest(request, function (req) {});
              requests.push(request);
          }
      
          pm.indexedDB.updateCollection(collection, function() {});
          
          collection.requests = requests;
          pm.collections.render(collection);
      });
    }
      },
  4. 然后在 Chrome Extensions 里面选择 Load unpacked, 选择刚才修改的版本, 就可以导入了.

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

JVM 的 "VM Thread" 线程

最近在帮一个同事看一个 Java 应用为什么会被经常重启的时候, 定位到 Java 应用中一个线程经常以 CPU 使用率100%的方式出现在 htop 的头部, 它是什么线程, 为什么会导致一个 CPU 100%? 这引起了我的兴趣.

相关背景及症状表现

这个应用程序运行中一个有8个 CPU 的 VM 上面, 经常看到该应用程序已最低13%的使用率运行, 有时候CPU 使用率会突然升到100%, 不过大多数会以13%或稍高来运行. 从 htop 的结果可以看到, 主要一个是一个线程导致一个 CPU 100% 运行:
cpu1.png

上面的截图中 25179 是 Java 进程ID, 25201 是占用一个 CPU core 的 Java 线程. 从 Thread dump 或者 Linux 的 proc 文件系统可以看到该线程的名字:

appUser@appHost:$ cat /proc/25179/task/25201/status
Name:    VM Thread
State:    R (running)
Tgid:    25179
Ngid:    0
Pid:    25201
PPid:    1626
TracerPid:    0

从上面的 shell 输出中可以看到, 该线程名字是 "VM Thread", 它经常单独占用一个 CPU core, 并且导致它100%.

VM Thread 做什么的?

"VM Thread" 是 JVM 自身启动的一个线程, 它主要用来协调其它线程达到安全点(Safepoint). 需要达到安全点的线程主要有: Stop the world 的 GC, 做 thread dump, 线程挂起以及偏向锁的撤销.
一般在 Thread dump 中, 它的表现为下面的样子, 没有线程栈信息:

"VM Thread" os_prio=0 tid=0x00007f5a212dc000 nid=0x1ad8d runnable

同时, 在 Thread dump 中, 有很多线程虽然当时不需要锁同步, 却能看到很多线程在 BLOCKED 状态, 如下:


"MyThreadPool-2" #77 daemon prio=5 os_prio=0 tid=0x00007f597a01c000 nid=0x1ae5e waiting for monitor entry [0x00007f591558a000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at com.sun.org.apache.xml.internal.dtm.ref.DTMManagerDefault.<init>(DTMManagerDefault.java:96)
    at com.sun.org.apache.xalan.internal.xsltc.dom.XSLTCDTMManager.<init>(XSLTCDTMManager.java:68)
    at com.sun.org.apache.xalan.internal.xsltc.dom.XSLTCDTMManager.newInstance(XSLTCDTMManager.java:78)

为什么这里出现 VM Thread 占用这么多 CPU

原因是这个程序因为内存泄漏, heap 几乎用光, 使用 jstat 命令看到, 每隔大约3s左右, 就有一次新的 full GC, 而CMS 的 full GC 只有单线程在工作, 所以只有一个 CPU core 在忙.

Refer:

  1. https://blog.jamesdbloom.com/JVMInternals.html
  2. http://hg.openjdk.java.net/jdk9/jdk9/hotspot/file/385668275400/src/share/vm/gc/cms/concurrentMarkSweepGeneration.cpp