分类 Java 相关 下的文章

如何找到 JVM 里面的 native C 代码

比如 java.lang.Thread.java 里面定义了定义了一些 native 代码, 那么如何找到这些 native 代码呢? 使用 google search 对应的 .c 文件:
thread.c site:openjdk.java.net

又比如: sun.nio.ch.FileDispatcherImpl.java 里面定义了一些 native 代码, 那么只要 search:
FileDispatcherImpl.c site:openjdk.java.net
就可以了.

记录一次线上 connection reset 排查

有开发人员发现他们的应用程序经常报一个空指针的错误, 他们自己查不出来是啥原因, 就报给了网络团队, 因为在这个空指针前面, 打了一行日志, 说接收回应数据为空(Response is empty), 他们认为网络时不时有问题.

  1. 找到对应的代码, 发现有人写了一段这样的代码:

    try {
      //access another service
      Response rsps = callAnotherService();
    } catch (Exception e) {
      logErr("Response is empty", e.getMessage);
    }
    return rsps;
  2. 上面这段代码中, 捕获异常, 只是打印了日志, 没有做错误处理, 这时候返回的 rsps 肯定为 null, 就可能导致上层调用者空指针异常. 通常我们需要封装之前的 Exception, 如果没有封装, 那么最好打印之前异常的错误栈到日志中, 这样方便排查问题出在哪一行. 另外这里有个特殊的地方, logErr() 方法的第二个参数并没有打印到日志中, 而是做了其它用途, 导致开发人员最后只看到 "Response is empty", 没看到具体出错原因.
  3. 对这行代码改造之后, 我们看到了出错栈和具体原因: connection reset by peer. 就是连接被断掉了.
  4. 于是做 tcpdump, 发现对于这种情况基本是客户端发出请求后, 服务端就 reset 了连接;
  5. 由于中间使用了 LB, 复制 LB 的同事在 LB 上双向抓包, 说是服务端主动 reset 连接;
  6. 于是在服务端抓包, 确实发现有时候服务端在收到请求后主动 reset 连接;
  7. 观察服务端的情况, 发现有些发来的请求服务端已经在处理了, 等处理完发现连接已经被 reset, 有些根本没进入服务端进行处理. 其它观察到的一些情况

    1. 服务端是异步 IO, 所以有些线程负责建立连接, 负责数据的读取写入, 有些负责业务处理;
    2. 服务端并没有发现特殊的线程 interrupt 的情况(这种情况很容易造成 IO 连接中断);
    3. 服务端在处理的时候, 又使用了 @suspended AsyncResponse. 基本是 Tomcat server 线程处理了 token 验证, 之后就留给线程池处理了.
  8. 通过 perf 过滤操作系统层面的 tcp:reset, 确实发现一些从tomcat 端口 reset 的连接, 可是由于是没有java 代码的栈, 所以看不出为什么要 reset;
  9. 于是对 java 进程添加 -XX:+PreserveFramePointer, 生成符号表文件, 成功看到部分 java 栈. 可是由于另外一些还是热度不够, 看到的代码仍然是翻译过来的, 所以看到的都是 Interpreter:
    interpreter.png
  10. 不过通过async-profiler 持续抓包, 终于捕获类似一个 java 栈:
    close_reset.png
  11. 通过 2 个栈相结合, 能看到导致 reset 的原因是: 代码中出了某种问题, 要 close 连接, close 的时候, 发现正常 close 的条件没达到, 比如还有没读的数据, 只能直接 reset;
  12. 导致 close 的代码段是:
    close.png

到底是什么情况导致 cancelledKey() close, 未完待续

perf-map-agent 使用步骤

使用 asyncProfiler 能捕获 Java 的栈, 使用 perf 能捕获操作系统栈, 由于 JVM 使用自己单独的虚拟机, 所以不能同时访问 2 部分栈. Netflix 的教程(https://netflixtechblog.com/java-in-flames-e763b3d32166), 能捕获 2 个在一起的栈. 需要做 2 件事情:

  1. 对 Java 进程添加 -XX:+PreserveFramePointer flag
  2. 生成 Java 进程的 符号表文件. 下面就是关于如何产生符号表文件的教程.

下面是详细教程:

  1. clone 或者下载最新版本 https://github.com/jvm-profiling-tools/perf-map-agent

    curl -vvv 'https://github.com/jvm-profiling-tools/perf-map-agent/archive/refs/heads/master.zip' --output perf-map-agent.zip
    
    # or
    git clone https://github.com/jvm-profiling-tools/perf-map-agent.git
  2. 设置 JAVA_HOME 环境变量

    export JAVA_HOME=/home/supra/work/tools/ebayjdk/jdk11/jdk
  3. 编译

    cmake .
    make
  4. 产生 perf-<pid>.map

    ./bin/create-java-perf-map.sh $(pgrep java)
    # 到 /tmp 目录查看对应的 perf-<pid>.map 是不是存在了

更多实用工具在 bin 目录

可能遇到问题:

  1. 如果遇到下面:

    -- The C compiler identification is GNU 7.5.0
    -- The CXX compiler identification is unknown
    -- Check for working C compiler: /usr/bin/cc
    -- Check for working C compiler: /usr/bin/cc -- broken
    CMake Error at /usr/share/cmake-3.10/Modules/CMakeTestCCompiler.cmake:52 (message):
      The C compiler
    
        "/usr/bin/cc"
    
      is not able to compile a simple test program.
    
      It fails with the following output:

    则安装编译工具

    sudo apt-get cmake
    sudo apt-get install build-essential
  2. 如果遇到下面:

    Sorry, user xxx is not allowed to execute '/yyyy/bin/java -cp /home/xxx/perf-map-agent-master/bin/../out/attach-main.jar:/yyyy/lib/tools.jar net.virtualvoid.perf.AttachOnce 23545 ' as xxx on hostzzzz.txh.com.

    那么我们可以到 perf-map-agent-master/out/ 目录下去执行这个命令就好了, 不是执行 create-java-perf-map.sh.

  3. 关于要如何使用 root 的, 查看 Netflix 的那个文档
  4. 创建 perf-<pid>.map 要使用 java 应用启动相同的用户名, 因为 java 应用的 agent 要使用同样的用户才能访问对应的 java 程序.

Linux 上的 Java 线程优先级

最近看了一篇关于 Java 在 Linux 上设置线程优先级的文章, 受益良多. 原来写了这么多年 Java 代码, 线程优先级在 Linux 上竟然是默认竟然是无效的. 这个网站可能在国内无法访问:
Thread Priority in Linux and Java

大致意思是:
Java 有个 Flag 是: -XX:ThreadPriorityPolicy. 它的值默认是 0, 还有另外一个值是 1. 对着 2 个值的解释是:

0 : Normal.
    VM chooses priorities that are appropriate for normal
    applications. On Solaris NORM_PRIORITY and above are mapped
    to normal native priority. Java priorities below
    NORM_PRIORITY map to lower native priority values. On
    Windows applications are allowed to use higher native
    priorities. However, with ThreadPriorityPolicy=0, VM will
    not use the highest possible native priority,
    THREAD_PRIORITY_TIME_CRITICAL, as it may interfere with
    system threads. On Linux thread priorities are ignored
    because the OS does not support static priority in
    SCHED_OTHER scheduling class which is the only choice for
    non-root, non-realtime applications.
1 : Aggressive.
    Java thread priorities map over to the entire range of
    native thread priorities. Higher Java thread priorities map
    to higher native thread priorities. This policy should be
    used with care, as sometimes it can cause performance
    degradation in the application and/or the entire system. On
    Linux this policy requires root privilege.

所以, 要想 Java 的优先级在 Linux 上生效, 要这么做(既要 sudo 又要设置 flag):

sudo java -XX:ThreadPriorityPolicy=1 ThreadPrioTest

就能看到下面的优先级输出:

supra@suprabox:~$ ps -l -m  -p $(pgrep java)
F S   UID   PID  PPID  C PRI  NI ADDR SZ WCHAN  TTY          TIME CMD
4 -     0 30388 30387 99   -   - - 2033328 -    pts/2    00:03:00 java
1 S     0     -     - 62  84   4 -     - -      -        00:00:14 -
1 S     0     -     - 66  83   3 -     - -      -        00:00:15 -
1 S     0     -     - 68  82   2 -     - -      -        00:00:15 -
1 S     0     -     - 74  81   1 -     - -      -        00:00:17 -
1 S     0     -     - 78  80   0 -     - -      -        00:00:17 -
1 S     0     -     - 76  79  -1 -     - -      -        00:00:17 -
1 S     0     -     - 79  78  -2 -     - -      -        00:00:18 -
1 S     0     -     - 85  77  -3 -     - -      -        00:00:19 -
1 S     0     -     - 88  76  -4 -     - -      -        00:00:20 -
1 S     0     -     - 90  75  -5 -     - -      -        00:00:20 -

上面的测试文件内容:

import java.lang.management.ManagementFactory;
import java.lang.management.ThreadInfo;
import java.lang.management.ThreadMXBean;
import java.util.Random;

public class ThreadPrioTest {

    public static void main(String[] args) throws InterruptedException {
        Runnable runnable = new Runnable() {
            public void run() {
                StringBuffer sb = new StringBuffer("");
                while (true) {
                    Random r = new Random();
                    sb.append(r.nextDouble());
                    sb.setLength(300);
                    sb.trimToSize();
                }
            }
        };
        
        for (int i = 0; i < 10; i++) {
            Thread t = new Thread(runnable, "ThreadTest_ " + i);
            t.setPriority(i+1);
            t.start();
        }
        
        ThreadMXBean threadMxBean = ManagementFactory.getThreadMXBean();
        ThreadInfo[] threadInfos = threadMxBean.dumpAllThreads(false, false);
        String name = null;
        for (int i = 0; i < 1000; i++) {
            System.out.println();
            for (ThreadInfo info : threadInfos) {
                name = info.getThreadName();
                if (name.contains("ThreadTest")) {
                    System.out.println(name + " " + threadMxBean.getThreadCpuTime(info.getThreadId()));
                }
            }
            
            Thread.sleep(30000);
        }
        
    }    
}

运行的结果(可以看到占用时间的差别):

supra@suprabox$ sudo java -XX:ThreadPriorityPolicy=1 ThreadPrioTest

ThreadTest_ 0 31115073
ThreadTest_ 1 88458982
ThreadTest_ 2 57653703
ThreadTest_ 3 47742366
ThreadTest_ 4 87852759
ThreadTest_ 5 81910285
ThreadTest_ 6 87854949
ThreadTest_ 7 74596281
ThreadTest_ 8 73344747
ThreadTest_ 9 79761175

   ...
ThreadTest_ 0 94775603625
ThreadTest_ 1 100380714690
ThreadTest_ 2 100932887535
ThreadTest_ 3 108438013681
ThreadTest_ 4 113013836327
ThreadTest_ 5 118102801890
ThreadTest_ 6 121683982580
ThreadTest_ 7 127791024493
ThreadTest_ 8 130891651909
ThreadTest_ 9 134574994529

如果你是在一个有大于 10 个 CPU 核的机器上跑这个测试, 可能结果并不是这样, 因为他们又足够的 CPU, 所以各个优先级的线程使用 CPU 差别不是很大. 所以线程优先级只有在 CPU 不够用的机器上才比较明显.

另外 java 里面关于线程优先级的 flags:

supra@suprabox:~$ java -XX:+PrintFlagsFinal -version | grep riori
     intx CompilerThreadPriority                   = -1                                        {product} {default}
     intx JavaPriority10_To_OSPriority             = -1                                        {product} {default}
     intx JavaPriority1_To_OSPriority              = -1                                        {product} {default}
     intx JavaPriority2_To_OSPriority              = -1                                        {product} {default}
     intx JavaPriority3_To_OSPriority              = -1                                        {product} {default}
     intx JavaPriority4_To_OSPriority              = -1                                        {product} {default}
     intx JavaPriority5_To_OSPriority              = -1                                        {product} {default}
     intx JavaPriority6_To_OSPriority              = -1                                        {product} {default}
     intx JavaPriority7_To_OSPriority              = -1                                        {product} {default}
     intx JavaPriority8_To_OSPriority              = -1                                        {product} {default}
     intx JavaPriority9_To_OSPriority              = -1                                        {product} {default}
     intx ThreadPriorityPolicy                     = 0                                         {product} {default}
     bool ThreadPriorityVerbose                    = false                                     {product} {default}
     bool UseThreadPriorities                      = true                                   {pd product} {default}
     intx VMThreadPriority                         = -1                                        {product} {default}
openjdk version "11.0.11" 2021-04-20
OpenJDK Runtime Environment (build 11.0.11+9-Ubuntu-0ubuntu2.18.04)
OpenJDK 64-Bit Server VM (build 11.0.11+9-Ubuntu-0ubuntu2.18.04, mixed mode, sharing)

关于之前 Java 里面关于那个 flag 的 bug:
http://www.akshaal.info/2008/04/javas-thread-priorities-in-linux.html
关于 Java 线程优先级的另外一个问答:
https://stackoverflow.com/questions/46936170/cassandra-and-java-9-threadprioritypolicy-42-is-outside-the-allowed-range

Java 如何简单的诊断 https (SSL/TLS) 请求

如果你能控制整个 Java 应用的启动, 那么你可以很简单的加SSL/TLS 的 debug 参数去打印等多的信息. 比如:

java -Djavax.net.debug=all myApp
java -Djavax.net.debug=ss:plaintext myApp 

想查看更多可以用的参数: 必须找一个 App, 不能使用常见的 java -Djavax.net.debug=help -version

java -Djavax.net.debug=help myApp

一个访问百度首页的 (-Djavax.net.debug=ss:plaintext) 的输出:

javax.net.ssl|DEBUG|01|main|2021-08-06 07:43:20.943 PDT|SSLCipher.java:1769|Plaintext before ENCRYPTION (
  0000: 47 45 54 20 2F 20 48 54   54 50 2F 31 2E 30 0A 0A  GET / HTTP/1.0..
)
javax.net.ssl|DEBUG|01|main|2021-08-06 07:43:21.233 PDT|SSLCipher.java:1671|Plaintext after DECRYPTION (
  0000: 48 54 54 50 2F 31 2E 30   20 35 30 30 20 49 6E 74  HTTP/1.0 500 Int
  0010: 65 72 6E 61 6C 20 53 65   72 76 65 72 20 45 72 72  ernal Server Err
  0020: 6F 72 0D 0A 43 6F 6E 74   65 6E 74 2D 4C 65 6E 67  or..Content-Leng
  0030: 74 68 3A 20 30 0D 0A 43   6F 6E 74 65 6E 74 2D 54  th: 0..Content-T
  0040: 79 70 65 3A 20 74 65 78   74 2F 70 6C 61 69 6E 3B  ype: text/plain;
  0050: 20 63 68 61 72 73 65 74   3D 75 74 66 2D 38 0D 0A   charset=utf-8..
  0060: 44 61 74 65 3A 20 46 72   69 2C 20 30 36 20 41 75  Date: Fri, 06 Au
  0070: 67 20 32 30 32 31 20 31   34 3A 34 33 3A 32 31 20  g 2021 14:43:21 
  0080: 47 4D 54 0D 0A 53 65 72   76 65 72 3A 20 62 66 65  GMT..Server: bfe
  0090: 0D 0A 0D 0A                                        ....
)

更多信息参考:

  1. https://docs.oracle.com/javase/7/docs/technotes/guides/security/jsse/ReadDebug.html
  2. https://docs.oracle.com/javase/7/docs/technotes/guides/security/jsse/JSSERefGuide.html#Debug
  3. https://access.redhat.com/solutions/973783