分类 Troubleshooting 相关 下的文章

记录一次tcp连接持续断掉的排查过程

有人上报说他们的 app 连接另外一个微服务的时候, 连接经常断掉, 不知道什么原因.

查看网络方面的监控, 网络一切安好.

查看日志, 看到一些异常信息: java.nio.channels.ClosedByInterruptException. 顺着这个信息, 我们找到了根本原因.

  1. 既然是 java.nio.channels.ClosedByInterruptException, 那么我们可以用 btrace 查看为什么这个异常被创建, 得到结果如下:

    java.nio.channels.ClosedByInterruptException.<init>(ClosedByInterruptException.java:51)
    java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:202)
    sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:477)
    com.tianxiaohui.java.BufferedWriteChannel.flush(BufferedWriteChannel.java:281)
    com.tianxiaohui.java.BufferedWriteChannel.write(BufferedWriteChannel.java:223)
    com.tianxiaohui.java.BaseClient.sendBytesActual(BaseClient.java:339)
    com.tianxiaohui.java.BaseClient.sendBytesOverChannel(BaseClient.java:203)
    ...
    rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
    rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
    rx.Observable.unsafeSubscribe(Observable.java:10327) 
    rx.internal.operators.OperatorSubscribeOn$SubscribeOnSubscriber.call(OperatorSubscribeOn.java:100)
    rx.xinternal.schedulers.CachedThreadScheduler$EventLoopWorker$1.call(CachedThreadScheduler.java:230)
    rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:55)
    ...
     java.lang.Thread.run(Thread.java:748)
  2. 既然是 interrupt 异常, 那么就一定有其它线程给这个线程发 interrupt, 于是通过下面的 btrace 代码, 我们就能找到发 interrupt 的线程

    import org.openjdk.btrace.core.annotations.*;
    import static org.openjdk.btrace.core.BTraceUtils.*;
    
    import org.openjdk.btrace.core.BTraceUtils.Strings;
    
    @BTrace
    public class ThreadInterruptTrace {
    
      @OnMethod( clazz="/java\\.nio\\.channels\\.ClosedByInterruptException/", method="<init>" )
      public static void createException() {
          println(Strings.strcat(name(currentThread()), " --- get ClosedByInterruptException "));
          println(jstackStr());
      }
    
      @OnMethod( clazz="/java\\.lang\\.Thread1/", method="/interrupt/" )
      public static void t1r(@ProbeClassName String probeClass, @Self Thread self) {
          if (Strings.startsWith(name(self), "RxIoScheduler")) {
              println(Strings.strcat(Strings.strcat(name(currentThread()), " try to interrupt ->  "), str(self)));
                println(jstackStr());
            }
        }
    }
  3. 找到发 interrupt 的线程, 那么就去看代码, 找了发生 interrupt 的原因, 最终原因是下面的代码. 每次 create 一个 Observable 都要新起一个线程池做为 scheduler, 其实不需要. 到时每次新建一个 scheduler 线程池导致创建太多线程池, 消耗大量内存, 之后又自动销毁. 然后这些 scheduler 销毁的时候, 还要通知 I/O 线程(这里的 I/O 线程池用的默认的), 也就是给 I/O 线程发一个 interrupt. 最终导致了我们看到的问题.

    Observable.create(new Observable.OnSubscribe<List<T>>() {
      @Override
      public void call(Subscriber<? super List<T>> subscriber) {
               //some code here
          }
      }).}).observeOn(Schedulers.newThread())
           .subscribeOn(Schedulers.io())
           .timeout(threadTimeout, TimeUnit.MILLISECONDS);
    

记录一次线上 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 程序.

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

记录一次奇怪的 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 看不到)