p2p-relay服务CPU高

发表于 分类于 ， 阅读次数：

一、背景

国内宇视p2p-relay服务CPU利用率一直很高，造成服务被liveness杀死，或者内置的P2P控件抢占不到CPU而崩溃。

img

P2P奔溃堆栈

1
2
3
4
5
6
7
2025-03-14 16:27:38.070 [34mINFO[0;39m [Thread-53990888] [CLoggerImpl.pFnLogFun: 45] [] - [p2p control] level: 3, message: [7f16197f0700][libcloud.c:7145]StartStream timeout. [50396A31-6769-5A37-5659-626251566B6A]
2025-03-14 16:27:38.071 [34mINFO[0;39m [Thread-53990889] [CLoggerImpl.pFnLogFun: 45] [] - [p2p control] level: 3, message: [7f16197f0700][libcloud.c:7573][ConnectPeerDone] iTaskType(2), iIsSUccess(0), pcPeerID(50396A31-6769-5A37-5659-626251566B6A), pcPeerIP(222.222.30.55), iPeerPort(29433).2025-03-14 16:27:38.078 [34mINFO[0;39m [http-nio-8998-exec-515] [CLoggerImpl.pFnLogFun: 45] [] - [p2p control] level: 3, message: [7f15f4dc4700][t2u_runner.c:265]Failed to call epoll wait, ret[0], errno[2]2025-03-14 16:27:38.079 [34mINFO[0;39m [http-nio-8998-exec-515] [CLoggerImpl.pFnLogFun: 45] [] - [p2p control] level: 6, message: [7f15f4dc4700][libcloud.c:5662]MTU probe.## A fatal error has been detected by the Java Runtime Environment:##  SIGSEGV (0xb) at pc=0x00007f161e0757f3, pid=1, tid=0x00007f15f4dc4700## JRE version: Java(TM) SE Runtime Environment (8.0_231-b11) (build 1.8.0_231-b11)# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.231-b11 mixed mode linux-amd64 compressed oops)# Problematic frame:# C  [libtunnel_new.so+0x607f3]  Libcloud_CreateT2URelation+0x313## Core dump written. Default location: //core or core.1## An error report file with more information is saved as:# //hs_err_pid1.log## If you would like to submit a bug report, please visit:#    http://bugreport.java.com/bugreport/crash.jsp# The crash happened outside the Java Virtual Machine in native code.# See problematic frame for where to report the bug.#
[error occurred during error reporting , id 0xb]
[error occurred during error reporting , id 0xb]
[error occurred during error reporting , id 0xb]
[error occurred during error reporting , id 0xb]
[error occurred during error reporting , id 0xb]

二、分析

  1. CPU高主要是pid为1的java进程占用的，也就是p2p-relay的服务

  2. 使用top -H，查看线程号为8/9/10/11的线程CPU使用率的特别高

    img

  3. jstack 1查看线程8/9/10/11对应着四个ParalLelGC并行垃圾回收器（CPU 4核会存在4个垃圾回收器线程）；
    垃圾回收器线程为什么会CPU高，说明有大量的对象在被创建/没有引用/被回收持续往复

    img

  4. 使用arthas的dashboard命令查看，young gc出现了289W次，持续了8小时（进程启动了25小时)，再次确认有大量的对象在被创建

    img

  5. 使用jstat -gc 1000 | awk ‘{print $6}’ 观察 Eden 分配速率，发现每隔几秒采集就有大量Eden对象创建（单位是kb）；也就是说时时刻刻有2.27G的对象产生
    大量对象产生说明业务中存在很大的并发的业务；结合p2p-relay流程，怀疑是接口/pr/device/p2p/invoke接口调用的频发；
    但是TOMCAT的http-nio线程并不多，说明请求量并没有很大

    img

  6. 重新梳理流程后，怀疑可能是P2P日志回调导致的问题

    img

    P2P日志需要java进程给P2P配置回调接口，P2P将日志回调给java进行打印

  7. 线上配置的P2P日志level是0，一般不会输出到日志中；
    但是回看这个业务，如果回调频繁，岂不是要创建大量的String对象（JNA 将原生代码（如 C/C++的 char*）传递的字符串转换为 Java 的 String）；为了确认日志回调的量，将level设置为8，在日志采集服务中发现P2P产生的日志是其他所有服务加起来的10倍+
    那问题基本确认就是这个造成的，将设置回调的函数注释掉，并重新部署

三、修改效果

修改后效果明显，CPU利用率下降到20%

b04caed56a1b9bf1e2cdc1d0555f1043

四、优化方向

建议P2P库优化方向：

P2P的日志level控制由P2P侧实现，云端下发日志的level；P2P库整理下日志，尽量减少日志，精简下。