java

关注公众号 jb51net

关闭
首页 > 软件编程 > java > Java服务不可用

Java服务不可用问题排查和解决

作者：BeerBear

作为一名 java 开发者,经常会遇到服务不可用的问题排查,导致问题的原因可能是多种多样的,但是在预先不知道是什么原因导致的服务不可用的时候,通用的排查手段和流程是相似的,故本文给大家介绍了Java服务不可用问题排查方法和解决,需要的朋友可以参考下

前言

作为一名 java 开发者，经常会遇到服务不可用的问题排查。导致问题的原因可能是多种多样的，但是在预先不知道是什么原因导致的服务不可用的时候，通用的排查手段和流程是相似的。

在具体的一些排查方式中涉及到linux的shell命令的使用，但平常又很少用到，导致每次要用到了，都要去重新去搜索。

所以本篇文章记录一下通用的排查方式，并且尽可能得将其流程化，从而方便后续的排查，节省时间成本。

随着一次次的问题排查，经验会更加丰富，排查方式也会不断优化和进步，也能够对JVM和系统资源等方面的知识进一步了解。这篇文章不会写完了之后就封存不动了，而是会持续得更新。

接下来就进入排查流程，并逐一介绍每个流程中要做的事情，

观察监控

问题排查必须要建立在有监控和日志的基础上，否则都没法入手问题调查。观察系统资源和JVM的监控，基本上能够快速找到服务不可用的直接原因和不可用的时间点。

如果连监控都没有，那么首先要做的事情就是应该给Java服务和所在的服务器加上监控。

从监控中我们往往能够看出以下几方面导致服务不可用的原因：

JVM 监控

首先要查看的就是JVM的内存，下面是一个包含一些JVM内存指标的监控截图。

从这张图中可以很好的看出JVM堆内存和非堆内存的情况。最常关注的就是：

如果以上的内存实际占用随着时间不断增加，最终临近相对应的最大值时（used >> max），基本就可以确认是因为内存占用过多导致的服务不可用了。

需要注意的是，不同的虚拟机和垃圾回收对于以上的内存空间的划分不同，但问题的思考上是一致的，即究竟哪块内存占用超出了预设的值。

如果确实发现了内存占用的异常，那么就应该先去看日志记录中，在应用首次不可用那个时间点，是否出现了Out of memory的报错日志。这一步是为了确定我们基于监控直观获得的初步结论。下文中会介绍如何去查看这些日志。

其实这一步不做也可以，因为根据经验来看，如果直观得发现服务不可用的时刻的内存占用超出max的值，那么基本上就是发生了OOM。

接下来继续排查以下内容：

如果怀疑是第一点，那么就去重新设置JVM的资源分配即可；针对2、3点则需要进一步进行Dump 文件分析，后文中会进行介绍。

宿主机监控

如果JVM的监控并没有什么异常，这时候就应该去看看是不是宿主机的问题。一台宿主机上往往会部署很多服务或者运行很多进程，如果其他进程抢占了过多的资源（往往就是CPU、内存），也会导致服务不可用。

下图是一个通过Node Exporter来采集的系统资源的部分指标的截图：

通过这张图就是很清晰得看出是否是因为系统的资源不够用导致的问题。

解决这类问题，有三个方向上的解决方式：

通过日志确定是OOM

集中的日志收集系统

分布式应用部署的如今，基本上现在所有公司都有自己的日志收集系统，很少需要去机器上的log文件上查看日志了。开源常用的有：

在这些日志系统中，选择相应的时间段和Out of memory的关键字就能判断出是否出现了内存溢出。

机器上查看日志

一般有了日志系统后就不需要再到机器上查看日志了，但有一些日志可能需要单独输出。比如我们有时候需要查看GarbageCollection的情况。

想要将GC的情况输出到特定的日志文件中，可以使用下面的JVM启动参数：

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution -XX:+PrintHeapAtGC -XX:+PrintReferenceGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 -Xloggc:${SYSTEM_LOG_DIR}/gc-%t.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=14 -XX:GCLogFileSize=100M

先介绍一下这些参数的作用：

-XX:+PrintGCDetails

记录详细的 GC 日志，包括每次垃圾回收的类型（如 Minor GC、Major GC）、内存分代的使用情况（年轻代、老年代等）、回收前后内存的变化等信息。

-XX:+PrintGCDateStamps

为每条 GC 日志添加时间戳。

-XX:+PrintTenuringDistribution

打印每次垃圾回收时晋升年龄分布（Tenuring Distribution），记录哪些对象从年轻代（Eden 区）晋升到老年代，以及晋升的条件（如对象的存活年龄）。

-XX:+PrintHeapAtGC

在每次 GC 开始和结束时，打印详细的堆内存使用情况。

-XX:+PrintReferenceGC

打印对软引用（SoftReference）、弱引用（WeakReference）、虚引用（PhantomReference）对象的回收信息。

-XX:+PrintGCApplicationStoppedTime

记录应用程序因为 GC 停顿的时间。

-XX:+PrintSafepointStatistics

打印 JVM 安全点（Safepoint）相关的统计信息。安全点是 JVM 停止所有应用线程以执行特定任务（如 GC）的点。输出包括进入安全点的时间、原因以及线程的暂停时间等

-XX:PrintSafepointStatisticsCount=<n>

定义打印的安全点统计的次数，如果设置为 1，表示每次达到安全点时打印统计信息。

-Xloggc:<file>

指定 GC 日志输出的文件路径

-XX:+UseGCLogFileRotation

开启 GC 日志文件轮转功能，当日志文件达到指定大小时，会生成一个新文件，而不是覆盖原文件。

-XX:NumberOfGCLogFiles=<n>

设置 GC 日志文件的最大数量。超过此数量时，旧的日志文件会被自动删除，默认值是 10。

-XX:GCLogFileSize=<size>

设置单个 GC 日志文件的大小上限。这里设置为 100M，即日志文件超过 100MB 后会创建新的日志文件。

去log中找到那个时刻的gc情况，就能很好知道在垃圾回收中存在的问题。下面就是一次正常的GC情况的日志记录：

{Heap before GC invocations=410 (full 0):
 garbage-first heap   total 1402880K, used 1252020K [0x0000000080000000, 0x0000000080102ad0, 0x0000000100000000)
  region size 1024K, 822 young (841728K), 5 survivors (5120K)
 Metaspace       used 214892K, capacity 236788K, committed 237056K, reserved 337920K
  class space    used 26519K, capacity 30174K, committed 30208K, reserved 131072K
2025-01-07T15:49:31.806+0800: 7390.574: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 54001664 bytes, new threshold 15 (max 15)
- age   1:    1242448 bytes,    1242448 total
- age   2:     240440 bytes,    1482888 total
- age   3:     287160 bytes,    1770048 total
- age   4:      82880 bytes,    1852928 total
- age   5:      55912 bytes,    1908840 total
- age   6:      29800 bytes,    1938640 total
- age   7:      25160 bytes,    1963800 total
- age   8:     231416 bytes,    2195216 total
- age   9:      81152 bytes,    2276368 total
- age  10:     323552 bytes,    2599920 total
- age  11:     225480 bytes,    2825400 total
- age  12:      96504 bytes,    2921904 total
- age  13:      82944 bytes,    3004848 total
- age  14:     262752 bytes,    3267600 total
- age  15:      48672 bytes,    3316272 total
2025-01-07T15:49:31.833+0800: 7390.601: [SoftReference, 0 refs, 0.0000535 secs]2025-01-07T15:49:31.833+0800: 7390.601: [WeakReference, 162 refs, 0.0000281 secs]2025-01-07T15:49:31.834+0800: 7390.601: [FinalReference, 427 refs, 0.0017021 secs]2025-01-07T15:49:31.835+0800: 7390.603: [PhantomReference, 5 refs, 0 refs, 0.0000161 secs]2025-01-07T15:49:31.835+0800: 7390.603: [JNI Weak Reference, 0.0001040 secs], 0.0308174 secs]
   [Parallel Time: 26.4 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 7390574.6, Avg: 7390574.6, Max: 7390574.7, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 3.0, Avg: 3.7, Max: 4.4, Diff: 1.4, Sum: 14.8]
      [Update RS (ms): Min: 19.9, Avg: 20.5, Max: 21.0, Diff: 1.1, Sum: 82.2]
         [Processed Buffers: Min: 305, Avg: 327.5, Max: 345, Diff: 40, Sum: 1310]
      [Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.7]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 1.5, Avg: 1.8, Max: 2.0, Diff: 0.5, Sum: 7.2]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.2, Max: 2, Diff: 1, Sum: 5]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.2]
      [GC Worker Total (ms): Min: 26.2, Avg: 26.3, Max: 26.3, Diff: 0.1, Sum: 105.1]
      [GC Worker End (ms): Min: 7390600.9, Avg: 7390600.9, Max: 7390600.9, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 4.2 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 2.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.2 ms]
      [Free CSet: 0.7 ms]
   [Eden: 817.0M(817.0M)->0.0B(816.0M) Survivors: 5120.0K->6144.0K Heap: 1222.7M(1370.0M)->241.4M(1370.0M)]
Heap after GC invocations=411 (full 0):
 garbage-first heap   total 1402880K, used 247151K [0x0000000080000000, 0x0000000080102ad0, 0x0000000100000000)
  region size 1024K, 6 young (6144K), 6 survivors (6144K)
 	Metaspace       used 214892K, capacity 236788K, committed 237056K, reserved 337920K
  class space    used 26519K, capacity 30174K, committed 30208K, reserved 131072K
}
 [Times: user=0.11 sys=0.00, real=0.03 secs]

Dump 文件分析

如果怀疑或者确认了是OOM的问题，那么接下来就是查看究竟是哪些业务导致了OOM，这时候就需要去分析内存的详细信息了。

Dump 文件下载

如果发生了OOM，进程就会卡住，此时就应该登录到服务器上去立马把内存导出到文件中，从而进一步分析。

获取Java进程号

ps -ef | grep java

或

jps

dump 内存文件

jmap -dump:format=b,file=dumplog.hprof <pid>

-F选项用于强制执行堆转储，通常在目标进程（PID 6885）无响应或挂起时使用。如果进程已经完全挂起，jmap命令本身也可能卡住，因为它需要与目标JVM进行交互才能生成dump文件。

使用 VisualVM 查看下载的hprof文件

从中寻找异常（数量多、占用内存大）的对象，一般只要找到了异常的对象，就能知道是哪部分的代码出了问题。

常用的Linux shell命令

查看占用内存最多的进程

如果是系统内存异常，往往需要知道是哪个进程占用内存过多，挤占了JVM所需的内存。

ps -aux | sort -k4nr | head -10

其中k4表示按照内存排序，如果想通过cpu占用排序使用k3。

查看进程状态

ps -p <pid> -o stat

用于查看进程是否异常。

查看进程中占用时间片较长的线程

top -Hp <pid>

查看GC情况

jstat -gcutil <pid> 1000

每隔一秒（1000）来打印一下gc和JVM内存的情况。

到此这篇关于Java服务不可用问题排查和解决的文章就介绍到这了,更多相关Java服务不可用内容请搜索脚本之家以前的文章或继续浏览下面的相关文章希望大家以后多多支持脚本之家！

您可能感兴趣的文章:
阅读全文