V2EX = way to explore
V2EX 是一个关于分享和探索的地方
现在注册
已注册用户请  登录
Geekerstar
V2EX  ›  Java

SpringBoot 程序运行中突然中止, JVM 退出

  •  
  •   Geekerstar · 28 天前 · 2750 次点击

    程序退出后,生成了一个 hs_err_pid1301132.log 文件,前面的内容如下,可以根据这个判断出是什么原因导致的吗?

    A fatal error has been detected by the Java Runtime Environment:

    SIGSEGV (0xb) at pc=0x000072ca636529ce, pid=1301132, tid=0x000072c7af5ff640

    JRE version: Java(TM) SE Runtime Environment (8.0_371) (build 1.8.0_371-b11)

    Java VM: Java HotSpot(TM) 64-Bit Server VM (25.371-b11 mixed mode linux-amd64 compressed oops)

    Problematic frame:

    J 39882 C2 sun.nio.ch.IOUtil.write(Ljava/io/FileDescriptor;[Ljava/nio/ByteBuffer;IILsun/nio/ch/NativeDispatcher;)J (509 bytes) @ 0x000072ca636529ce [0x000072ca636528a0+0x12e]

    Failed to write core dump. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again

    If you would like to submit a bug report, please visit:

    http://bugreport.java.com/bugreport/crash.jsp

    第 1 条附言  ·  27 天前
    程序有大量的 CPU 和 IO 操作。

    这个是当时的监控截图,大概是 8:53 停掉的。
    https://imgse.com/i/pAGLDy9
    https://imgse.com/i/pAGLBQJ
    第 2 条附言  ·  27 天前
    操作系统是 ubuntu ,检查 syslog 日志,发现一个信息,不知道是否有关联:
    1 、程序最后一行 info 日志时间是,2024-10-09 08:52:57.251 ,无错误日志。
    2 、检查 Syslog 日志,发现同一秒有下面的日志:
    Oct 9 08:52:57 lenovo-07 systemd[1]: session-2106.scope: Deactivated successfully.
    Oct 9 08:52:57 lenovo-07 systemd[1]: session-2106.scope: Consumed 2w 1d 21h 28min 5.200s CPU time.
    48 条回复    2024-10-11 08:57:42 +08:00
    jiom
        1
    jiom  
       27 天前
    ulimit -a 看看系统有没有做参数优化
    dx123
        2
    dx123  
       27 天前
    看看你的 JVM 参数和配置呢
    iyiluo
        3
    iyiluo  
       27 天前
    jvm 没配置 core dump ,这点日志看不出什么。看谷歌结果貌似是 netty 报的错,检查一下代码或者加 core dump 参数后等复现吧
    Geekerstar
        4
    Geekerstar  
    OP
       27 天前
    @jiom 没有优化过:
    real-time non-blocking time (microseconds, -R) unlimited
    core file size (blocks, -c) 0
    data seg size (kbytes, -d) unlimited
    scheduling priority (-e) 0
    file size (blocks, -f) unlimited
    pending signals (-i) 513419
    max locked memory (kbytes, -l) 16438992
    max memory size (kbytes, -m) unlimited
    open files (-n) 1024
    pipe size (512 bytes, -p) 8
    POSIX message queues (bytes, -q) 819200
    real-time priority (-r) 0
    stack size (kbytes, -s) 8192
    cpu time (seconds, -t) unlimited
    max user processes (-u) 513419
    virtual memory (kbytes, -v) unlimited
    file locks (-x) unlimited
    Geekerstar
        5
    Geekerstar  
    OP
       27 天前
    @dx123 -Xmx2048m -Xms2048m -XX:+UseG1GC 没有做其他的优化
    Geekerstar
        6
    Geekerstar  
    OP
       27 天前
    @iyiluo 好的,感谢
    serverKnignt
        7
    serverKnignt  
       27 天前
    是不是被 Linux kill 了?
    serverKnignt
        8
    serverKnignt  
       27 天前
    @serverKnignt 可以看下日志,cat /var/log/messages | egrep -T -C10 Kill
    ZZ74
        9
    ZZ74  
       27 天前   ❤️ 1
    jvm 退出最常见的就是内存不够了,要么是堆内存,要么是堆外内存。 结合 ByteBuffer 和 SIGSEGV ,堆外可能性最大。具体的得描述下你的程序是干嘛的,以及更多 log
    Geekerstar
        10
    Geekerstar  
    OP
       27 天前
    @iyiluo 我的错误和这个很像,难道真的是 Netty 的问题? https://github.com/netty/netty/issues/4206
    Geekerstar
        11
    Geekerstar  
    OP
       27 天前
    @serverKnignt #7 应该不是,查了系统日志没发现啥问题
    Geekerstar
        12
    Geekerstar  
    OP
       27 天前
    @ZZ74 我从监控平台看了下内存那些都很正常的呢? https://imgse.com/i/pAGLDy9
    https://imgse.com/i/pAGLBQJ 程序有大量的 IO 和 CPU 操作,用的 undertow 框架。
    willbetter
        13
    willbetter  
       27 天前
    可能是磁盘空间不足或者是打开的文件数据过多了
    ZZ74
        14
    ZZ74  
       27 天前
    @Geekerstar 你贴的 gihub 的例子就是 memory 问题啊,而且人家也给出了 netty 配置。
    hs_err_pid1301132.log 文件内容远不止于此,github 上面就详细多了,能看到 oom 报错还有
    Event: 984.476 GC heap before
    ParOldGen total 2796544K, used 2796216K
    object space 2796544K, 99% used

    你那个监控中的 45 到 9 点那一下 memory 的异常大量分配很值得怀疑,之后没数据了,持续 full GC 崩溃了导致没数据了吧
    Geekerstar
        15
    Geekerstar  
    OP
       27 天前
    @ZZ74 #14 大佬能否帮忙分析一下呢?实在找不到问题了,这是几张完整的监控截图。大概八点四五十的时候用户开始使用的,之后没数据是因为 JVM 退出了。
    https://imgse.com/i/pAJpwrD
    https://imgse.com/i/pAJp0qe
    https://imgse.com/i/pAJpdKO

    这是 hs_err_pid1301132.log 文件
    pan 点 baidu 点 com/s/1hZ5Fb8Nir458vSiS14XY-Q 提取码: cgpp
    D3EP
        16
    D3EP  
       27 天前
    程序有手动控制 Netty ByteBuf 的逻辑吗?之前接手过一个 RPC 框架,在一些业务场景下出现类似的 Segment Fault ,发现是在某个地方释放了 ByteBuf ,但后面又往里写数据最终 core 掉了。
    Geekerstar
        17
    Geekerstar  
    OP
       27 天前
    @D3EP 没有哦,我们程序有 websocket 推送,而且 web 框架是用的 undertow ,好像底层有 netty ,但是没有直接在业务代码里操作 netty
    Geekerstar
        18
    Geekerstar  
    OP
       27 天前
    @willbetter 磁盘还有几个 T ,文件句柄看日志也正常范围
    julyclyde
        19
    julyclyde  
       27 天前
    @jiom ulimit 只对“当前 shell”有效。查看别的进程的 limit 需要看/proc
    ZZ74
        20
    ZZ74  
       27 天前
    SEGV_MAPERR 错误,崩溃前平凡 FGC ,但是内存能下来,看起来有临时大对象。AbstractFramedChannel.flushSenders()的时候崩了。
    我不知道 undertow 用的堆内还是堆外。有可能是因为 ByteBuf 大小有限 把 java 大对象写入 ByteBuf 时导致的。也不排除 16 楼说的。
    你可以结合你的系统特点看看。看起来是个物联网数据采集系统不知道 flushSenders 是在给设备发数据还是提供查询。
    Geekerstar
        21
    Geekerstar  
    OP
       27 天前
    @ZZ74 #20 感谢大佬,AbstractFramedChannel.flushSenders()应该是 undertow 底层推送 ws 的时候调用的,系统中有 websocket 推送,数据量和频次很高,快的话几毫秒一次。但是据说出问题那会儿没有停留在有 ws 推送的页面。flushSenders 是给 web 客户端发送数据。
    Geekerstar
        22
    Geekerstar  
    OP
       27 天前
    @ZZ74 #20 查了一下,Undertow 使用 Java NIO ( non-blocking I/O )来处理 WebSocket 和 HTTP 连接。NIO 会使用 ByteBuffer ,其中包括堆外内存( Direct ByteBuffer )。有可能和这个有关系么?
    Solace202
        23
    Solace202  
       27 天前
    肯定是代码写的有问题,建议把最新版本和上次版本之间提交的代码 review 下,对于循环、查库 留意下,大概率是内存不够直接挂了
    hideon
        24
    hideon  
       27 天前
    有没有 heapdump? 看起来崩溃前存在频繁 GC 和对象生成, 结合使用 ws, 是不是瞬时连接增大导致的?
    Geekerstar
        25
    Geekerstar  
    OP
       27 天前
    @hideon 没有手动 dump ,因为当时 JVM 直接挂了。也没有自动生成 Dump 文件。您说的这个 ws 瞬间连接增大有一定道理,但是我们这个是内网使用,不会有很多人同时使用。以前有过 OOM ,是因为 ws 连接一直没释放,导致后端有引用在无法回收部分垃圾。但是目前已经加了五分钟自动断开重连 ws 的机制了。ws 推送的频次和数据量确实很高。毫秒级的。
    Geekerstar
        26
    Geekerstar  
    OP
       27 天前
    操作系统是 ubuntu ,检查 syslog 日志,发现一个信息,不知道是否有关联:
    1 、程序最后一行 info 日志时间是,2024-10-09 08:52:57.251 ,无错误日志。
    2 、检查 Syslog 日志,发现同一秒有下面的日志:
    Oct 9 08:52:57 lenovo-07 systemd[1]: session-2106.scope: Deactivated successfully.
    Oct 9 08:52:57 lenovo-07 systemd[1]: session-2106.scope: Consumed 2w 1d 21h 28min 5.200s CPU time.
    hrapunzel
        27
    hrapunzel  
       27 天前
    可能是堆外内存爆了
    ZZ74
        28
    ZZ74  
       27 天前
    @Geekerstar 很可能啊,发送的是序列化后的 java 对象还是文件?一般来说 java 代码写入超过 byebuff 大小只会有 runtime 异常,但如果直接是文件的话就不一定了。比如发送时文件大小比之前分配好 bytebuff 时大了导致越界。
    另外 XNIO-1 I/O-6" [_thread_in_Java 其他都是_thread_in_native 有一定并发可能
    Geekerstar
        29
    Geekerstar  
    OP
       27 天前
    @hrapunzel 这个服务器 128g ,目前只用了十多 G
    Geekerstar
        30
    Geekerstar  
    OP
       27 天前
    @ZZ74 #28 我们发送的是 JSON 的字符串,不是文件。您最后一句话是啥意思呢?是指可能是因为并发导致的吗
    ZZ74
        31
    ZZ74  
       27 天前
    @Geekerstar XNIO-1 I/O-x 这种线程理解没错的话 应该都是给 web 客户端发送数据的吧?
    你可以比较下是不是每次崩 ,那个线程都是_thread_in_Java ,如果是的话考虑下大字符串 毕竟这个线程还没执行 native 代码。
    因为你说你们没有操作 byebuff 那也有可能 undertow 高并发有 bug ,导致操作了正在被其他执行 native 代码的 byebuff 被这个线程用到了。
    cyningxu
        32
    cyningxu  
       27 天前 via Android   ❤️ 1
    太深奥了不懂,但还是每层楼都看完了,真的很喜欢这种氛围,大家一起帮忙解决问题,已经很久没在中文互联网看到这种场景了,现在大多都是冷嘲热讽。
    hrapunzel
        33
    hrapunzel  
       27 天前
    @Geekerstar #29 堆外内存默认是 -Xmx 的大小, -XX:MaxDirectMemorySize 用这个参数指定一下
    Geekerstar
        34
    Geekerstar  
    OP
       27 天前
    @hrapunzel #33 好的,我试一下,堆外内存默认 xmx 一样的 2g ,感觉 2g 应该够用了。我查了一下:如果 JVM 试图分配堆外内存(例如通过 ByteBuffer.allocateDirect()分配直接内存),但操作系统的内存资源已经耗尽,JVM 通常不会直接触发 SIGSEGV ,而是抛出 java.lang.OutOfMemoryError: Direct buffer memory 。JVM 本身一般不会直接因为堆外内存不足触发 SIGSEGV ,但如果程序使用了 JNI 、本地库或者使用了不安全的操作(例如 Unsafe 类),在处理内存时可能会导致 SIGSEGV
    Geekerstar
        35
    Geekerstar  
    OP
       27 天前
    @cyningxu 是的,非常感谢大家,我也喜欢这种氛围。
    suwu
        36
    suwu  
       27 天前
    @cyningxu +1 ,没有 dump 我就不会分析了。。。
    xuanbg
        37
    xuanbg  
       27 天前
    JVM 退出的话基本就是内存不足造成的,怕是接收到什么大数据,把分配给 JVM 的内存撑爆了
    D3EP
        38
    D3EP  
       27 天前
    @Geekerstar #17 作为在互联网公司中间件团队的我只能说,没准儿是 undertow 或者 JDK 有 bug 。
    LeegoYih
        39
    LeegoYih  
       27 天前
    遇到过有个生成图形验证码服务被 OOM Killer 杀过一次,没有 dump
    jarvison
        40
    jarvison  
       26 天前
    太深奥了不懂,但还是每层楼都看完了,真的很喜欢这种氛围,大家一起帮忙解决问题,已经很久没在中文互联网看到这种场景了,现在大多都是冷嘲热讽。
    julyclyde
        41
    julyclyde  
       26 天前
    @Geekerstar session deactivated 啊?你在 shell 里手工启动的 java ??
    Geekerstar
        42
    Geekerstar  
    OP
       26 天前
    @julyclyde #41 有启动脚本,我昨天也怀疑是不是在 shell 里手动启动的服务,但是和这个日期匹配不上。2w 1d 21h 28min 5.200 。这个日期要长于我们上次发版的日期。
    spkingr
        43
    spkingr  
       26 天前
    楼主解决了吗?
    可能是一个小问题,也可能是一个大问题,github 上那个问题居然是 epoll 的原因,太离谱了。
    所以,有没有可能是使用了其他第三方库导致?加载了一些什么大对象,大的类型导致元空间放不下,建议把问题代码发给 AI 问下看有没有什么线索。
    Geekerstar
        44
    Geekerstar  
    OP
       26 天前
    @spkingr 目前感觉大概率和 websocket 有关,排查了系统发现这种线程“XNIO-1 I/O-6” 只有在 websocket 断开连接的时候会使用。有可能是 websocket 断开连接的时候,有用到 undertow 和底层的 netty 的相关操作导致的。我怀疑是前端先建立某个连接,然后持续了很久,后端因为什么原因这个连接断开了,前端再发起断开连接请求,就导致这个问题。
    Geekerstar
        45
    Geekerstar  
    OP
       26 天前
    @julyclyde #41 我顺着你的这个思路查了一下,应该是找到为啥提示 session deactivated 的原因了。9.23 日让客户改一下启动脚本,加一下打印 GC 日志的参数,结果客户把最后一句去掉了 > /dev/null 2>&1 & ,这个会导致持续将日志写到 nohup.out 里。
    julyclyde
        46
    julyclyde  
       26 天前
    @Geekerstar 如果是从 shell 里启动的话,那还真是受 ulimit 影响(不过,是这个脚本启动之前的 ulimit ,而不是你另外开一个 shell 查看的 ulimit ,即使这俩值相同,也是两码事)

    后台服务,不应该在 user.slice 下启动;应该在 system.slice 下启动
    spkingr
        47
    spkingr  
       26 天前 via Android
    @Geekerstar 这个 bug 后面重现了吗?如果重现,能不能禁用前端的 ws 再试试运行一段时间?最好是本地复现就好搞
    Geekerstar
        48
    Geekerstar  
    OP
       26 天前
    @spkingr #47 目前为止没有复现,只出现了一次。要是能复现的话就能找到原因了。
    关于   ·   帮助文档   ·   博客   ·   API   ·   FAQ   ·   实用小工具   ·   5816 人在线   最高记录 6679   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 34ms · UTC 02:50 · PVG 10:50 · LAX 18:50 · JFK 21:50
    Developed with CodeLauncher
    ♥ Do have faith in what you're doing.