服务器

资料来源： http://t.cn/EI9JdBu

处理过在线问题的学生基本上会遇到系统突然变慢、CPU 100 % uff0c和Full GC次数过多的问题。 当然，这些问题最终引起的直观现象是系统运行缓慢，有大量的报警。 本文主要针对系统运行缓慢的问题，给出了对该问题进行故障诊断的思路，从而找出问题的代码，并提供解决该问题的思路。

对于联机系统突然变慢的问题，如果该问题导致联机系统不可用，则必须首先导出jstack和内存信息，然后重新启动系统以尽快确保系统的可用性。 这主要可能有两个原因。

代码中某个位置读取数据量大，系统内存耗尽，Full GC次数过多，系统变慢

代码中存在消耗CPU的操作，CPU过高，系统运行缓慢；

相比之下，这是最频繁出现的两个在线问题，导致系统无法直接使用。 还有其他一些情况，某些功能的运行会变慢，但系统不会变为不可用。

代码的某个地方有闭塞性的操作，其功能调用整体很费时间，但出现比较随机

某个线程由于某种原因进入等待状态，此时该功能无法整体使用，但无法再现；

非法使用锁会导致多个线程处于死锁状态，从而导致整个系统变慢。

关于这三种情况，只看CPU和系统内存的情况是看不到具体问题的。 因为这些是相对闭塞性的操作，CPU和系统内存的使用情况不高，但功能很慢。 让我们通过查看系统日志，一步一步地认识这些问题。

1 .全GC次数过多

这是最容易发生的情况，特别是新功能在线时。 在全GC较多的情况下，主要有以下两个特征。

所有在线多线程的CPU都超过了100%%uFF0C。 通过jstack命令，可以看到这些线程主要是垃圾回收线程

通过jstat命令监视GC的状况，可以看到Full GC的次数非常多，次数在增加。

首先，使用top命令确定系统CPU的使用率。 以下是系统CPU高度的示例。

top - 08:31:10 up 30 min，0 users，load average:0.73，0.58，0.34

KiB Mem: 2046460 total，1923864 used，122596 free，14388 buffers

KiB Swap: 1048572 total，0 used，1048572 free. 1192352 cached Mem

piduserprnivirtresshrs % CPU % memtimecommand

9 root 200255716028897615812 s 98.014.10:42.60 Java

如您所见，某个Java程序此时已达到98.8 %的CPU使用率uff0c。 此时，您可以复制进程id 9，并使用以下命令检查进程中每个线程的执行情况：

top-Hp9

此进程中的每个线程的行为如下：

top - 08:31:16 up 30 min，0 users，load average:0.75，0.59，0.35

Threads: 11 total，1 running，10 sleeping，0 stopped，0 zombie

%CPU(s ) 3.5 us、0.6 sy、0.0 ni、95.9 id、0.0 wa、0.0 hi、0.0 si、0.0 st

KiB Mem: 2046460 total，1924856 used，121604 free，14396 buffers

KiB Swap: 1048572 total，0 used，1048572 free. 1192532 cached Mem

piduserprnivirtresshrs % CPU % memtimecommand

10 root 200255716028982415872 r 79.314.20:41.49 Java

11 root 200255716028982415872 s 13.214.20:06.78 Java

在进程9的Java程序中，可以看到每个线程的CPU占用率。 然后，使用jstack命令确定线程id为10的线程占用CPU最多的原因。 请注意，在jsatck命令显示的结果中，所有线程id都转换为十六进制格式。 可以使用以下命令查看转换结果，也可以找到科学计算机进行转换。

root@a39de7e7934b:/#printf&amp； #039； %x\\\n&amp； #039； 10a

此处的打印结果表示线程在jstack中的显示格式为0xa。 jstack命令显示以下信息：

&amp； #039； main&amp； #039； #1prio=5os _ prio=0tid=0x 00007 f 8718009800 NID=0xb runnable [0x 00007 f 871 Fe 41000 ]

Java.lang.thread.state:runnable

atcom.ai baobei.chapter2. eg2.user demo.main ( user demo.Java:9 ) ) )。

&amp； #039； VMthread&amp； #039； OS _ prio=0tid=0x 00007 f 871806 e 000 NID=0xa runnable

此处的VM Thread行的末尾将显示nid=0xa。 这里nid是操作系统线程id的意思。 VM Thread是垃圾回收的线程。 在这里，基本上可以确认，目前系统缓慢的原因主要是垃圾回收过于频繁，GC的停止时间长。 可以通过以下命令确认GC的状况。

root@8d36124607a0://# jtat-GC util 9100010 s0 S1 eomccsygcygctfgcfgctgct 0.000.000.0075.0759.0959.6032590.91965177.7158.6350.000.60

这里FGC是指Full GC的数量，这里达到了6793，可以看出在持续增加。 这进一步证实了由于内存溢出导致的系统延迟。 那么，现在我们已经检查了内存溢出，如何确定什么对象导致了内存溢出呢？ 这可以通过dump内存日志，在eclipse的mat工具中进行确认。 以下是其对象树结构：

通过mat工具分析的结果，基本上判断内存中主要是哪些对象占用了内存，然后找出该对象的创建位置进行处理即可。 这里主要以PrintStream最多，但可以看到内存消耗为12.2%%u3002。 这意味着，这还不足以引起大量的Full GC。 在这种情况下，必须考虑出现在代码或第三方依赖的包中的System.gc )调用。 通过查看从dump内存中获得的文件，可以判断这一点，因为它会打印GC的原因。

[fullGC(system.GC ) ][tenured:262546k-262546k ) 349568k]、0.0014879 secs ] 262546 k-262546 k ( 506816 k )和[metet real=0.01 secs ] [分配故障( GC ) ( def new:2795 k-0k ( 157248 k ) )。 0.0012949secs(265342k-402k ) 506816k )、[ metaspace:3109 k-3109 k ] 1056768 k ]和0.0014699secs ) times:user=0.009

例如，这里的第一个GC是由System.gc ( ) )的显示调用引起的，而第二个GC是由JVM主动发起的。 总之，全GC次数过多主要有以下两个原因。

如果代码一次获取大量对象并导致内存溢出，则可以使用eclipse的mat工具查看内存中有多少对象

虽然内存不太被占用，但是Full GC的次数很多。 在这种情况下，显示的System.gc )调用可能会导致GC次数过多。 这可以通过添加-XX: DisableExplicitGC来禁用JVM对显示GC的响应。

2. CPU太高

正如前面第一点所述，处理器过高可能是因为系统经常执行完全GC，导致系统速度变慢。 我们平时很乐意通过费时的计算遇到CPU过高的情况，这时的表示方法与上述非常相似。 首先，通过top命令检查当前哪些进程消耗了过多的CPU，并获取进程id。 然后，在top-Hppid中，检查该进程中哪个线程的CPU太高。 一般超过80%%u5C31比较高，80%%u5DE6右比较合理。 这样可以获得占用大量CPU的线程id。 然后，使用此线程id的十六进制表示形式在jstack日志中显示当前线程特定的堆栈信息。

在此，您可以区分CPU过高的原因是Full GC次数过多，还是代码中存在耗时的计算。 如果Full GC过多，则jstack中的线程信息将是线程，如VM Thread，但如果代码中存在耗时的计算，则可以获取线程的具体堆栈信息。 以下代码包含耗时的计算和过高的CPU线程信息。

如您所见，当请求UserController时，线程的CPU始终位于100%%u3002中，因为此Controller进行了耗时的调用。 根据堆栈信息，可以直接定位到UserController的34行，以查看代码中的具体原因是否计算量如此之大。

3 .不定期发生的接口费时现象

在这种情况下，典型的例子是访问我们的某个接口总是需要2~3s。 这是一个比较麻烦的案例。 因为一般来说，CPU的消耗量很少，内存的消耗量也不高。 这意味着，通过上述两种方法进行故障排除并不能解决此问题。 另外，由于不定期地发生这样的接口花费时间的问题，即使通过jstack命令得到线程访问的堆栈信息，也无法判断具体哪个线程是正在执行花费时间的操作的线程。

对于不定期出现的接口时间非常大的问题，我们的定位思路基本上如下。 首先，找到该接口，用压力测量工具提高访问力。 如果那个接口中的某个地方很费时间的话，因为我们的访问频率非常高，所以大部分的线程最终会在那个块点被屏蔽。 这样，通过多个线程具有相同的堆栈日志，我们基本上可以在那个接口中寻找花费时间的代码的位置。 以下代码包含通过耗时的阻塞操作从压力测量工具获得的线程堆栈日志

&amp； #039； http-nio-8007-exec-2&amp； #039； # 29 daemon prio=5os _ prio=31 tid=0x 0007 FD 08 CB 26000 NID=0x 9603 waiting on condition [0x 007 fd08，CB 26000 NID=0x 9603 waiting

Java.lang.thread.state:timed _ waiting ( sleeping ) )。

at Java.lang.thread.sleep ( native method )

at Java.lang.thread.sleep ( thread.Java:340 ) )。

at Java.util.concurrent.time unit.sleep ( time unit.Java:386 ) )。

atcom.ai baobei.user.controller.user controller.detail ( user controller.Java:18 ) )。

&amp； #039； http-nio-8007-exec-3&amp； #039； # 30 daemon prio=5os _ prio=31 tid=0x 0007 FD 08 CB 27000 NID=0x 6203 waiting on condition [0x 0007 ] (0x 0000 ) NID=0x 6203 waitid

Java.lang.thread.state:timed _ waiting ( sleeping ) )。

at Java.lang.thread.sleep ( native method )

at Java.lang.thread.sleep ( thread.Java:340 ) )。

at Java.util.concurrent.time unit.sleep ( time unit.Java:386 ) )。

atcom.ai baobei.user.controller.user controller.detail ( user controller.Java:18 ) )。

&amp； #039； http-nio-8008-exec-4&amp； #039； # 31 daemon prio=5os _ prio=31 tid=0x 0007 FD 08 d 0f a 000 NID=0x 6403 waiting on condition [0x 007 FD 08 d 0f a 000 NID=0x 6403 waiting on

Java.lang.thread.state:timed _ waiting ( sleeping ) )。

at Java.lang.thread.sleep ( native method )

at Java.lang.thread.sleep ( thread.Java:340 ) )。

at Java.util.concurrent.time unit.sleep ( time unit.Java:386 ) )。

atcom.ai baobei.user.controller.user controller.detail ( user controller.Java:18 ) )。

从上面的日志中可以看到，此处有多个线程被阻止在UserController的第18行中，表明这是一个阻塞点，也就是接口变慢的原因。

4 .某个线程进入等待状态

对于这种情况，虽然这是比较少见的情况，但由于有可能发生，且具有一定的“不可重复性”，因此在排查时非常难以发现。 笔者以前遇到过这种情况。 具体情况是，使用CountDownLatch时，需要在每个并行任务完成后调用主线程来执行。 我们曾通过CountDownLatch控制多个线程的连接，并导出用户的gmail邮箱数据。 其中一个线程已连接到用户的邮箱，但连接被服务器挂起，并且该线程正在等待来自服务器的响应。 最终，我们的主线程和剩下的几个线程都将进入等待状态。

关于这样的问题，看过jstack日志的读者应该都知道。 通常，在线上的大多数线程都处于TIMED_WAITING状态，但出现问题的线程却处于相同的状态。 这很容易混淆我们的判断。 解决这个问题的想法主要有：

使用grep查找jstack日志中所有处于TIMED_WAITING状态的线程，并将其导出为类似a1.log的文件。 以下是导出的日志文件的示例。

&amp； #039； attach监听器& amp； #039； # 13 daemon prio=9os _ prio=31 tid=0x 0000007 Fe 690064000 NID=0xd 07 waiting on condition [0x 0000000000 ] 12 prio=5os _ prio #039； thread-0&amp； #039； # 11 prio=5os _ prio=31 tid=0x 00007 Fe 690065000 NID=0x5a 03 waiting on condition [0x 00070003 a d4000 ] & amp； #039； C1compilerthread3&amp； #039； #9daemon prio=9os _ prio=31 tid=0x 00007 Fe 68 c 00 a 000 NID=0xa 903 waiting on condition [0x 0000000000 ]

稍等片刻，例如，在10s下，再次grep jstack日志并将其导出到另一个文件，如a2.log。 结果如下。

&amp； #039； destroyJavaVM&amp； #039； # 12 prio=5os _ prio=31 tid=0x 00007 Fe 690066000 NID=0x 2603 waiting on condition [0x 0000000000 ] & amp； #039； ttroy 11 prio=5os _ prio=31 tid=0x 00007 Fe 690065000 NID=0x5a 03 waiting on condition [0x 00070003 a d4000 ] & amp； #039； vmperiodictaskthread

重复步骤2，导出3到4个文件，然后比较导出的文件以找到一直存在于这些文件中的用户线程。 可以确认此线程基本上包含处于等待状态的有问题的线程。 因为一般的请求线程在20~30s秒后也不会进入待机状态。

故障排除的结果是，可以继续排除线程堆栈信息的故障。 如果线程本身必须处于等待状态，例如用户创建的线程池中的空闲线程，则该线程的堆栈信息不包含用户定义的类。 虽然可以排除所有这些，但是可以确保剩下的线程基本上是我们要找的有问题的线程。 根据该堆栈信息，可以知道具体位于哪个位置的代码正在等待该线程。

另外，在判断是否是用户线程时，可以通过线程开头的线程名称进行判断。 一般框架的线程名非常规范，所以可以根据线程名直接判断该线程是某个框架内的线程，这样的线程基本上可以被排除。 剩下的Thread-0 (例如上面的Thread-0 )和我们可以确定的定制线程名称，需要我们进行故障排除。

通过以上方法进行故障排除，您将会发现，基本上这里的Thread-0就是我们要找的线程。 通过查看堆栈信息，可以知道具体在哪个位置处于等待状态。 在以下示例中，线程在SyncTask的第8行等待。

&amp； #039； thread-0&amp； #039； # 11 prio=5os _ prio=31 tid=0x 00007 F9 de 08 c 7000 NID=0x 5603 waiting on condition [0x 00070001 f 89000 ] Java.0 at sun.misc.unsafe.park ( native method ) at Java.util.concurrent.locks.lock support.park ) lock support.lock a$main$0(Synctask.Java:8 ) atcom.ai baobei.chapter2. eg4.shap ter

5 .死锁

对于死锁，这基本上很容易理解，因为jstack有助于检查死锁并在日志中打印特定的死锁线程信息。 以下是发生死锁的jstack日志的示例。

正如您所看到的，jstack日志的底部直接分析了日志中存在的死锁以及每个死锁的线程堆栈信息。 这里，两个用户线程各自都在等待对方解锁，但所有被阻止的位置都在ConnectTask的第五行中。 此时，我们可以直接定位在那个位置进行代码分析，找出死锁的原因。

6 .总结

本文主要说明了在线可能出现的5种原因导致系统变慢的情况，详细分析了每种情况发生时的现象，并阐明了现象如何可以定位为导致系统变慢。 简单来说，进行在线日志分析时，主要分为以下几个步骤。

使用top命令检查CPU的状态，如果CPU较高，则使用top-Hppid命令检查当前进程的每个线程的执行情况，如果CPU发现线程过高，则将其线程id转换为十六进制表示形式，并在jstack日志中将其写入这里又分为两种情况

对于普通用户线程，它会根据该线程的堆栈信息来确定它运行的具体位置，并消耗CPU

如果线程是VMThread，请使用jstat-gcutilpidperiodtimes命令监视当前系统的GC状态，并使用jmapdump:format=b，file=filepathpid检查系统的当前内存数据导出后，将内存情况放入eclipse的mat工具进行分析，可以发现内存中主要占用的对象是哪些内存，并可以处理相关代码；

在top命令中发现CPU不高，系统的内存使用率也很低。 此时，可以认为是其他3种情况引起的问题。 具体来说，可以根据情况进行分析。

如果接口调用很费时间且不定期发生，可以按下探测器以提高拥塞点的发生频率，并通过jstack检查堆栈信息来查找拥塞点。

如果是某项功能突然停滞的情况，这种情况也无法再现。 在这种情况下，通过多次导出jstack日志，可以比较哪个用户线程一直在等待。 这些线程是有问题的线程

如果可以通过jstack检查死锁的状态，则可以检查导致死锁的两个线程的特定阻塞点以解决相应的问题。

本文主要提出了五种常见的导致在线功能下降的问题和排除思路。 当然，出现在线问题的形式多种多样，并不一定局限于这些情况。 如果能仔细分析出现这些问题的场景，就可以根据具体情况具体分析，解决相应的问题。

详情请访问云服务器、域名注册、虚拟主机的问题，请访问西部数码代理商官方网站： www.chenqinet.cn