分类 Java 相关 下的文章

perf-map-agent 使用步骤

  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 install build-essential
    sudo apt install gcc
    sudo apt install g++
  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.

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

为什么Java CMS GC 使用单线程做 Full GC?

虽然今天 CMS GC 已经不被推荐, 可是还经常被用来和G1 GC 做对比. 其中导致CMS 不被推荐的重要原因是: CMS 的full GC 是单线程的, 在如今多核统治天下的情况下, 单线程的 full GC 肯定比多线程的 full GC 慢很多.

CMS 什么情况下会产生full GC

  1. 并发模式失败(concurrent mode failures) 老年代并发回收的速度跟不上年轻代晋升的速度;
  2. 碎片化, 老年代虽然有足够的空间, 可是都是碎片化的, 没有一个连续的可容纳的空间;
  3. 元数据区(metaspace)/老年代没有空间;
  4. 明确的 System.gc() 或 Runtime.gc() 调用

为什么不把 parallel old 的算法引入CMS, 使之可以多线程

二者的数据结构不一样, 如果引入需要大量修改

为什么不重新为了 CMS 写一个多线程的 full gc?

据说开发工程师把更多的时间都用去写 G1 了, 并且 G1 各方面的期望都比CMS 好, 没有必要再写要给给CMS.

其它

google 内部有一个CMS 的老年代GC 实现, 并且曾经尝试patch到openJDK, 不过最后没有做到:
http://openjdk.java.net/jeps/8130200

最好还是用G1

记录一次奇怪的 CPU profiling 问题

本文记录了一次奇怪的线上线程相关问题的案例.

  1. 先是看到 CPU 稍微有点高
    cpu.png
  2. 大概看了下, 发现这个机器没做啥耗 CPU 的操作, 大多数都是网络请求, 于是做 CPU profiling, 于是出现了下面奇怪的方法调用
    sched_yield.png
    首先, 看上去这个不像 Java 的方法, 于是推断是 JVM 里面调用的系统 native 方法. 其次, 去 google 了一把, 这是系统的一个方法, 它的意图就是让出 CPU, 让其它 CPU 去执行. 可是为什么要频繁让出呢? 为什么占用这么多 CPU 资源呢? 另外, 搜了一下有没有人遇到过类似问题, 并没有发现.
  3. 是不是 Native 代码调用, 那些 native 代码调用了它? 于是从系统层面针对这个 Java 进程的这个方法调用, 又专门做了一次 CPU profiling, 看到下面的火焰图:
    native.png
  4. 从上的火焰图看, 貌似有个叫 WrapperJarAppMa 的方法调用了 __sched_yield 方法. 于是去 google 了一下这个关键字, 相当失望:
    google.png
    不过注意 google 给的提示! 后面再说.
  5. 正常的推理已经不能解决问题, 于是开始归纳总结. 发现如下模式:

    1. 这个应用分配了 174G 内存, 分配了 24 个 CPU, 资源相当丰富
      cpuMem.png
    2. 这个应用的 heap 给了 154G, heap 常规占用在 75G 左右, 空闲也非常多;
    3. 这个应用占用这么多 heap 是因为内存加载了非常多的缓存, 系统启动就加载, 加载完要十几分钟, 然后再接收流量;
      可是从上面的这些模式, 并么有推断出什么.
  6. 于是又回到已知的关键字 "__sched_yeild" 和 "WrapperJarAppMa". 想到 AsyncProfiler 其实可以根据线程做火焰图, 于是又根据线程做了火焰图, 看到如下:
    flameWithThread.png
    两边都是业务线程, 中间只有 2 层方法的都是我们看到的上面 "WrapperJarAppMa" 调用 "__sched_yeild", 所以, 中间从下数第二层红色的都是"WrapperJarAppMa", 第三层都是"__sched_yeild". 虽然这次也只能看到上面已经看到的 2 个关键字, 可是从于业务线程对比, 可以明显看出来: "WrapperJarAppMa" 是线程名字, 因为绿色的业务线程那边, 第二层也是线程名字.
  7. 于是通过 pstree 去查看线程的结构关系, 发现确实如此:
    wrappThread.png
  8. 可是代码里面从来没有看到这个线程的关键字, 这个线程从那里来的? 为什么这么多? 于是打算到 log 文件里面查一吧, 确实发现了这个线程(原来真正的线程名字叫 "WrapperJarAppMain" 其它地方只是字长的省略):
    log.png
  9. 这个时候在拿这个线程名字去 google, 就发现了线程出处, 原来在我们付费使用的商业软件 Java Service Wrapper 里面. 因为是付费软件, 在 maven 里面没有发现它的踪影, 于是从生产环境下载一个正在使用的 wrapper.jar. 反编译后重要找到了这个线程的出处:
    wrapperJarApp.png
  10. 为什么会有这么多 "WrapperJarAppMa" 线程一直存活, 并且一直 sched_yeild 呢? 想看看这些线程到底在做什么? 是不是在上面的 while 循环里面出不来了? 于是做了一个 54G 的 heap dump, 然后压缩到38G 下载到本地去做 heap 分析, 竟然没有看到这些线程:
    wrapperThreadHeap.png
  11. 于是怀疑在做 heap dump 过程中这些线程已经死掉了, 于是重新去查看了这些线程, 发现线程还好好的活着:
    threadAgain.png
  12. 这次还注意到, 在 heap dump 里面线程共计277个, 可是使用 pstree 能看到383个, 考虑到系统正在运行中, 有好多线程可能在变动中, 但是也不能差别这么多. 仔细观察, 发现类似这样的线程都没有出现在 heap dump 中
    g1.png
  13. 类似这样的线程有:

    1. {C2 CompilerThre}(123318)
    2. {G1 Main Marker}(123296)
    3. {G1 Marker#X}(123297)
    4. {G1 Refine#XX}(123295)
    5. {GC Thread#XX}(123247)
    6. {VM Periodic Tas}(123322)
    7. {VM Thread}(123313)
    8. {WrapperJarAppMa}(130114)
    9. {default-microme}(123384)
    10. {java}(123246)
  14. 可以看到这些线程的数量也不少:
    total.png
  15. 在生产环境看到这个问题之后, 去测试环境看了一下, 有如下总结:

    1. 测试环境在 CPU profiling 中并没有看到 __sched_yeild 被调用;
    2. 测试环境 也有 WrapperJarAppMa 线程;
    3. WrapperJarAppMa 总数与当前物理机的 CPU 合数一致, 除了一个正常结束的 WrapperJarAppMa 线程, 剩下 (CPU 核总数 - 1) 个这样的线程;
    4. 这些后来不死的线程, 在 heap 中看不到, 类似JDK 某些自带的线程;
    5. 这些线程的名字完全复制第一个线程的名字, 可是看不到创建的地方.
  16. 改动 WrapperJarApp 的源码, 在生产新线程的地方加了日志, 改了线程的名字, 发现日志中该方法只有一次被调用

    long i = System.currentTimeMillis() % 10;
    Thread mainThread = new Thread(this, i + "-WrapperJarAM");
    Thread.dumpStack();
  17. 如今的问题:

    1. 这些后来是怎么创建出来的?
    2. 为什么生产环境他们一直在运行, 可是在测试环境 profiling 中看不到运行;
    3. 另外发现 Wrapper-Connection 线程的优先级是 10, 怀疑这些不死的线程优先级也是 10
  18. 终于看到这些线程在干嘛

    1. 怀疑这些线程不是 Java 代码创建 (拦截Thread.start() 不到, 并且没有出现在 thread dump), 于是做了一个 core dump;
    2. 使用 gdb 从 core dump 可以看到线程正在运行的栈
      coreBt.png
    3. 果然在对应的目录找到了对应的共享库文件, 于是去查该项目的git 工程, 也找到了对应的共享库;
  19. 找到调用 JNI 共享库的代码 - 从项目源代码中找到了相应的代码, 如下:

    private static final String PATH = "/home/supra/work/test/blas/netlib-blas-dist/src/main/resources/linux-x86_64";
    private static final String[] NETLIB_LIBS = {
              "libquadmath.so.0", "libgfortran.so.3", "libopenblas.so.0", "libblas.so.3", "liblapack.so.3" };
    
    public static void main(String[] args) throws IOException {
      for (String lib : NETLIB_LIBS) {
        System.load(new File(PATH + "/" + lib).getAbsolutePath());
        NativeLibrary.getInstance(lib);
      }
    
      NativeSystemBLAS blas = new NativeSystemBLAS();
      double prod = blas.ddot(4, new double[] { 1.0, 1.0, 1.0, 1.0 }, 1, new double[] { 1.0, 0.0, 1.0, 0.0 }, 1);
      if (prod != 2.0) {
        throw new IllegalArgumentException("BLAS sanity test failed. Expected 2.0. Got: " + prod);
      }
    
      System.out.println("done");
      try {
        Thread.currentThread().sleep(1000000);
      } catch (InterruptedException e) {
        e.printStackTrace();
      }
    }
  20. 为什么会创建 (cpu count - 1) 个线程?

    1. 我们找到了这个共享库的源码, 结合 core dump 中看到的栈, 找出了创建这些线程的源代码行. 这里使用了 CPU 个数去创建 blas server 的服务线程数.
      https://github.com/xianyi/OpenBLAS/blob/974acb39ff86121a5a94be4853f58bd728b56b81/driver/others/blas_server.c#L639
    2. 下面的 blas_thread_server 方法就是 blas server 要执行的 routine. 我们通过 gdb 看到的代码, 就是这个里面的代码
  21. 为了进一步验证我们的想法, 下载了 https://github.com/xianyi/OpenBLAS 的代码, 在本地 Linux 上面重新编译包含符号的共享库, 这次, 我们看到这些线程在哪行代码运行:
    bt_thread.png

到此为止, 我们终于搞明白了这些线程哪来的?这些线程数目和 CPU 个数的关系. 其它一些相关的话题:

  1. blas 和 openBlas 应该是人工智能相关的算法类库;
  2. 其实 WrapperJarApp 里面设置的线程优先级在 Linux 上面其实没啥用.
  3. C 代码 (通过 pthread_create 创建的线程, 在Java 的 thread dump 看不到)