频繁full gc cpu 100%

CPU高与FullGC故障排查

最新推荐文章于 2025-03-04 09:00:07 发布

原创最新推荐文章于 2025-03-04 09:00:07 发布 · 901 阅读

2 ·

CC 4.0 BY-SA版权

本文通过top命令发现CPU占用率异常，深入分析发现与日志打印及大对象处理有关，涉及线程堆栈、GC内存使用及慢查询问题，最终定位到大对象打印引起的资源消耗与GC机制故障。

top

top命令查看后，发现cpu占用比较高，对应的pid是205494

top -Hp 205494

查看对应进程下，是哪些线程占用的cpu比较高，发现pid为205599

printf "%x\n" 205599

把对应的pid转成16进制便于查看,得到3231f

jstack 205494 > mylog.txt

查看线程Java堆栈信息，猜测可能和cpu占用高和full gc可能和打印日志有关

-l 长列表. 打印关于锁的附加信息,例如属于java.util.concurrent 的 ownable synchronizers列表.
-F 当’jstack [-l] pid’没有相应的时候强制打印栈信息
-m 打印java和native c/c++框架的所有栈信息.

"pool-2-thread-1" #25 daemon prio=5 os_prio=0 tid=0x00007f529ca29800 nid=0x3231f runnable [0x00007f530c2be000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.String.getBytes(String.java:906)
	at org.apache.thrift.protocol.TBinaryProtocol.writeString(TBinaryProtocol.java:185)
	at com.meituan.scribe.thrift.LogEntry$LogEntryStandardScheme.write(LogEntry.java:430)
	at com.meituan.scribe.thrift.LogEntry$LogEntryStandardScheme.write(LogEntry.java:380)
	at com.meituan.scribe.thrift.LogEntry.write(LogEntry.java:327)
	at com.meituan.scribe.thrift.MTLog$Log_args$Log_argsStandardScheme.write(MTLog.java:517)
	at com.meituan.scribe.thrift.MTLog$Log_args$Log_argsStandardScheme.write(MTLog.java:465)
	at com.meituan.scribe.thrift.MTLog$Log_args.write(MTLog.java:420)
	at org.apache.thrift.TServiceClient.sendBase(TServiceClient.java:63)
	at com.meituan.scribe.thrift.MTLog$Client.send_Log(MTLog.java:74)
	at com.meituan.scribe.thrift.MTLog$Client.Log(MTLog.java:66)
	at org.apache.logging.log4j.scribe.appender.ScribeAppender.sendLogEntry(ScribeAppender.java:385)
	- locked <0x000000072191b168> (a org.apache.logging.log4j.scribe.appender.ScribeAppender)
	at org.apache.logging.log4j.scribe.appender.ScribeAppender.access$300(ScribeAppender.java:58)
	at org.apache.logging.log4j.scribe.appender.ScribeAppender$FlushLogEntry.run(ScribeAppender.java:438)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)


"pool-2-thread-1" #25 daemon prio=5 os_prio=0 tid=0x00007f529ca29800 nid=0x3231f runnable [0x00007f530c2be000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.cs.UTF_8$Encoder.encode(UTF_8.java:742)
	at java.lang.StringCoding$StringEncoder.encode(StringCoding.java:304)
	at java.lang.StringCoding.encode(StringCoding.java:344)
	at java.lang.String.getBytes(String.java:906)
	at org.apache.thrift.protocol.TBinaryProtocol.writeString(TBinaryProtocol.java:185)
	at com.meituan.scribe.thrift.LogEntry$LogEntryStandardScheme.write(LogEntry.java:430)
	at com.meituan.scribe.thrift.LogEntry$LogEntryStandardScheme.write(LogEntry.java:380)
	at com.meituan.scribe.thrift.LogEntry.write(LogEntry.java:327)
	at com.meituan.scribe.thrift.MTLog$Log_args$Log_argsStandardScheme.write(MTLog.java:517)
	at com.meituan.scribe.thrift.MTLog$Log_args$Log_argsStandardScheme.write(MTLog.java:465)
	at com.meituan.scribe.thrift.MTLog$Log_args.write(MTLog.java:420)
	at org.apache.thrift.TServiceClient.sendBase(TServiceClient.java:63)
	at com.meituan.scribe.thrift.MTLog$Client.send_Log(MTLog.java:74)
	at com.meituan.scribe.thrift.MTLog$Client.Log(MTLog.java:66)
	at org.apache.logging.log4j.scribe.appender.ScribeAppender.sendLogEntry(ScribeAppender.java:385)
	- locked <0x000000072191bc40> (a org.apache.logging.log4j.scribe.appender.ScribeAppender)
	at org.apache.logging.log4j.scribe.appender.ScribeAppender.access$300(ScribeAppender.java:58)
	at org.apache.logging.log4j.scribe.appender.ScribeAppender$FlushLogEntry.run(ScribeAppender.java:438)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
	- <0x0000000721809a98> (a java.util.concurrent.ThreadPoolExecutor$Worker)


"pool-2-thread-1" #25 daemon prio=5 os_prio=0 tid=0x00007f529ca29800 nid=0x3231f runnable [0x00007f530c2be000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.Throwable.getStackTraceDepth(Native Method)
	at java.lang.Throwable.getOurStackTrace(Throwable.java:824)
	- locked <0x00000006dc313928> (a org.apache.thrift.TApplicationException)
	at java.lang.Throwable.printStackTrace(Throwable.java:656)
	- locked <0x0000000721890738> (a java.io.PrintStream)
	at java.lang.Throwable.printStackTrace(Throwable.java:643)
	at java.lang.Throwable.printStackTrace(Throwable.java:634)
	at org.apache.logging.log4j.scribe.appender.ScribeAppender.sendLogEntry(ScribeAppender.java:402)
	- locked <0x000000072191ba08> (a org.apache.logging.log4j.scribe.appender.ScribeAppender)
	at org.apache.logging.log4j.scribe.appender.ScribeAppender.access$300(ScribeAppender.java:58)
	at org.apache.logging.log4j.scribe.appender.ScribeAppender$FlushLogEntry.run(ScribeAppender.java:438)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)


"pool-2-thread-1" #25 daemon prio=5 os_prio=0 tid=0x00007f529ca29800 nid=0x3231f runnable [0x00007f530c2be000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.cs.UTF_8$Encoder.encode(UTF_8.java:742)
	at java.lang.StringCoding$StringEncoder.encode(StringCoding.java:304)
	at java.lang.StringCoding.encode(StringCoding.java:344)
	at java.lang.String.getBytes(String.java:906)
	at org.apache.thrift.protocol.TBinaryProtocol.writeString(TBinaryProtocol.java:185)
	at com.meituan.scribe.thrift.LogEntry$LogEntryStandardScheme.write(LogEntry.java:430)
	at com.meituan.scribe.thrift.LogEntry$LogEntryStandardScheme.write(LogEntry.java:380)
	at com.meituan.scribe.thrift.LogEntry.write(LogEntry.java:327)
	at com.meituan.scribe.thrift.MTLog$Log_args$Log_argsStandardScheme.write(MTLog.java:517)
	at com.meituan.scribe.thrift.MTLog$Log_args$Log_argsStandardScheme.write(MTLog.java:465)
	at com.meituan.scribe.thrift.MTLog$Log_args.write(MTLog.java:420)
	at org.apache.thrift.TServiceClient.sendBase(TServiceClient.java:63)
	at com.meituan.scribe.thrift.MTLog$Client.send_Log(MTLog.java:74)
	at com.meituan.scribe.thrift.MTLog$Client.Log(MTLog.java:66)
	at org.apache.logging.log4j.scribe.appender.ScribeAppender.sendLogEntry(ScribeAppender.java:385)
	- locked <0x000000072191b070> (a org.apache.logging.log4j.scribe.appender.ScribeAppender)
	at org.apache.logging.log4j.scribe.appender.ScribeAppender.access$300(ScribeAppender.java:58)
	at org.apache.logging.log4j.scribe.appender.ScribeAppender$FlushLogEntry.run(ScribeAppender.java:438)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)

jstat -gcutil 205494 2000 20

每隔2s查看进程205494，下的gc内存使用情况，共查看20次。发现堆内存使用率最大到了60%，图片没有保留下来。

查看gc日志

发现新生代gc时空间担保机制一直失败，导致频繁full gc

jmap -dump:format=b,file=log205494.dump 205494

导出内存对象堆栈数据的dump文件，用jprofiler工具进行分析

结论：

大对象，是由于有个查询条件查询的数据量过大，产生慢查询，mysql耗时30多秒，有索引但是是索引范围查询。打印log时把该大对象整体全部打印所致，异步打印日志线程一直在运行没有完成，导致cpu过高，且大对象没有被回收，一直占用老年代内存。新生代进行回收时，由于老年代内存不足,空间担保机制失败所以一直进行full gc。