线上java程序CPU占用过高问题排查

2024-05-23 23:58
文章标签 java 问题 程序 线上 cpu 排查 占用 过高

本文主要是介绍线上java程序CPU占用过高问题排查，希望对大家解决编程问题提供一定的参考价值，需要的开发者们随着小编来一起学习吧！

简要

工作中负责的有一个项目是使用iReport+JasperReport实现的一个打印系统。最近这个线上程序经常无响应，重启后恢复正常，但是时不时还是会出现类似的问题。
最后发现是JasperReport的一个问题。有个JasperReport的转换任务内存占用特别高，当新对象需要分配内存时就会内存不够了，于是GC线程就不断GC，占用CPU。
导致系统CPU占用超高。
下面说下问题排查的一个思路步骤

基本环境

  • tomcat 7
  • JDK 7
  • Linux

问题定位

查看后台异常

通过查看系统的后台日志，发现各个请求都正常，没有异常抛出。于是考虑系统状况

查看系统状况

top 命令查看CPU、内存等使用情况

[root@DEV-L002323 ~]# top
top - 14:52:54 up 514 days,  7:00,  8 users,  load average: 2.85, 1.35, 1.62
Tasks: 147 total,   1 running, 146 sleeping,   0 stopped,   0 zombie
Cpu(s): 57.6%us,  6.3%sy,  0.0%ni,  9.2%id, 26.2%wa,  0.0%hi,  0.0%si,  0.7%st
Mem:   3922928k total,  3794232k used,   128696k free,   403112k buffers
Swap:  4194296k total,    65388k used,  4128908k free,  1492204k cachedPID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                     6764 root      20   0 2428m 1.1g  11m S 190.0 28.3  36:38.55 java                                                                       1161 root      20   0     0    0    0 D  0.3  0.0  32:43.06 flush-253:0                                                                 1512 root      20   0 14684 4188  488 S  0.3  0.1   0:16.12 sec_agent                                                                   1 root      20   0 19356  652  436 S  0.0  0.0   0:16.64 init                                                                        2 root      20   0     0    0    0 S  0.0  0.0   0:00.05 kthreadd                                                                    3 root      RT   0     0    0    0 S  0.0  0.0   1:49.34 migration/0                                                                 4 root      20   0     0    0    0 S  0.0  0.0  17:46.61 ksoftirqd/0                                                                 5 root      RT   0     0    0    0 S  0.0  0.0   0:00.00 migration/0                                                                 6 root      RT   0     0    0    0 S  0.0  0.0   2:02.78 watchdog/0                                                                  7 root      RT   0     0    0    0 S  0.0  0.0   1:46.79 migration/1

从top命令的结果发现。pid为6764的java进程CPU利用持续占用过高,达到了190%。内存占用率为28.3%。

定位问题线程

使用ps -mp pid -o THREAD,tid,time命令查看该进程的线程情况，发现该进程的两个线程占用率很高

[root@DEV-L002323 ~]# ps -mp 6764 -o THREAD,tid,time
USER     %CPU PRI SCNT WCHAN  USER SYSTEM   TID     TIME
root     71.7   -    - -         -      -     - 00:36:52
root      0.0  19    - futex_    -      -  6764 00:00:00
root      0.0  19    - poll_s    -      -  6765 00:00:01
root     44.6  19    - futex_    -      -  6766 00:23:32
root     44.6  19    - futex_    -      -  6767 00:23:32
root      1.2  19    - futex_    -      -  6768 00:00:38
root      0.0  19    - futex_    -      -  6769 00:00:00
root      0.0  19    - futex_    -      -  6770 00:00:01
root      0.0  19    - futex_    -      -  6771 00:00:00

从上面可以看出6766和6767两个线程占用CPU大约有半个小时，每个线程的CPU利用率约为45%。接下来需要查看对应线程的问题堆栈
下面就看看6766这个问题线程的堆栈

查看问题线程堆栈

将线程id转换为16进制
[root@DEV-L002323 ~]#  printf "%x\n" 6766
1a6e
jstack查看线程堆栈信息

jstack命令打印线程堆栈信息，命令格式：jstack pid |grep tid

[root@DEV-L002323 ~]# jstack 6764 | grep 1a6e
"GC task thread#0 (ParallelGC)" prio=10 tid=0x00007ffeb8016800 nid=0x1a6e runnable
"GC task thread#0 (ParallelGC)" prio=10 tid=0x00007ffeb8016800 nid=0x1a6e runnable 
"GC task thread#1 (ParallelGC)" prio=10 tid=0x00007ffeb8016800 nid=0x1a6e runnable  
"VM Periodic Task Thread" prio=10 tid=0x00007ffeb8016800 nid=0x3700 waiting on condition JNI global references: 496

从上面可以看书，这些都是GC的线程。那么可以推断，很有可能就是内存不够导致GC不断执行。接下来我们就需要查看
gc 内存的情况

jstat查看进程内存状况

命令: jstat -gcutil

[root@DEV-L002323 bin]# jstat -gcutil 6764 2000 10S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT   0.00   0.00  100.00 100.00  97.74   1863   33.937   310  453.788  487.7260.00   0.00  100.00 100.00  97.74   1863   33.937   310  453.788  487.7260.00   0.00  100.00 100.00  97.74   1863   33.937   310  453.788  487.7260.00   0.00  100.00 100.00  97.74   1863   33.937   310  453.788  487.7260.00   0.00  100.00 100.00  97.74   1863   33.937   310  453.788  487.7260.00   0.00  100.00 100.00  97.74   1863   33.937   310  453.788  487.7260.00   0.00  100.00 100.00  97.74   1863   33.937   310  453.788  487.7260.00   0.00  100.00 100.00  97.74   1863   33.937   310  453.788  487.7260.00   0.00  100.00 100.00  97.74   1863   33.937   310  453.788  487.7260.00   0.00  100.00 100.00  97.74   1863   33.937   310  453.788  487.726

可以看出内存的年轻代和年老带的利用率都达到了惊人的100%。FGC的次数也特别多，并且在不断飙升。可以推断出
程序肯定是在哪里的实现有问题，需要重点查看大对象或者异常多的对象信息。此时可以生成headdump文件拿到本地来分析

jstack 和 jmap 分析进程堆栈和内存状况

使用jmap命令导出heapdump文件，然后拿到本地使用jvisualvm.exe分析。

命令: jmap [option] vmid
jmap -dump:format=b,file=dump.bin 6764

命令: jstack [option] vmid
jstack -l 6764 >> jstack.out

从heapdump文件中定位到程序中的工作现场，和内存状况，如下：
线程:

"Thread-21" daemon prio=5 tid=85 WAITINGat java.lang.Object.wait(Native Method)at java.lang.Object.wait(Object.java:503)at net.sf.jasperreports.engine.fill.AbstractThreadSubreportRunner.waitResult(AbstractThreadSubreportRunner.java:81)Local Variable: net.sf.jasperreports.engine.fill.ThreadExecutorSubreportRunner#2at net.sf.jasperreports.engine.fill.AbstractThreadSubreportRunner.start(AbstractThreadSubreportRunner.java:53)at net.sf.jasperreports.engine.fill.JRFillSubreport.prepare(JRFillSubreport.java:758)at net.sf.jasperreports.engine.fill.JRFillElementContainer.prepareElements(JRFillElementContainer.java:331)Local Variable: net.sf.jasperreports.engine.fill.JRFillSubreport#3at net.sf.jasperreports.engine.fill.JRFillBand.fill(JRFillBand.java:384)at net.sf.jasperreports.engine.fill.JRFillBand.fill(JRFillBand.java:358)at net.sf.jasperreports.engine.fill.JRVerticalFiller.fillBandNoOverflow(JRVerticalFiller.java:458)Local Variable: net.sf.jasperreports.engine.fill.JRFillBand#3at net.sf.jasperreports.engine.fill.JRVerticalFiller.fillPageHeader(JRVerticalFiller.java:421)at net.sf.jasperreports.engine.fill.JRVerticalFiller.fillPageBreak(JRVerticalFiller.java:1954)at net.sf.jasperreports.engine.fill.JRVerticalFiller.fillColumnBreak(JRVerticalFiller.java:1981)at net.sf.jasperreports.engine.fill.JRVerticalFiller.fillDetail(JRVerticalFiller.java:754)Local Variable: net.sf.jasperreports.engine.fill.JRFillBand[]#1Local Variable: net.sf.jasperreports.engine.fill.JRFillBand#2at net.sf.jasperreports.engine.fill.JRVerticalFiller.fillReportStart(JRVerticalFiller.java:288)at net.sf.jasperreports.engine.fill.JRVerticalFiller.fillReport(JRVerticalFiller.java:151)at net.sf.jasperreports.engine.fill.JRBaseFiller.fill(JRBaseFiller.java:939)at net.sf.jasperreports.engine.fill.JRFiller.fill(JRFiller.java:152)Local Variable: net.sf.jasperreports.engine.util.LocalJasperReportsContext#1Local Variable: net.sf.jasperreports.engine.fill.JRVerticalFiller#1at net.sf.jasperreports.engine.JasperFillManager.fill(JasperFillManager.java:464)at net.sf.jasperreports.engine.JasperFillManager.fill(JasperFillManager.java:300)Local Variable: java.io.File#135Local Variable: net.sf.jasperreports.engine.JasperFillManager#1Local Variable: net.sf.jasperreports.engine.JasperReport#1at net.sf.jasperreports.engine.JasperFillManager.fillReport(JasperFillManager.java:757)at com.pingan.icore.print.asyntask.jasper.AysnJasPdfConvertorThread.fill(AysnJasPdfConvertorThread.java:110)Local Variable: java.lang.String#57815Local Variable: java.lang.String#55498Local Variable: java.util.HashMap#1682Local Variable: java.lang.String#57807Local Variable: java.lang.String#57809at com.pingan.icore.print.asyntask.jasper.AysnJasPdfConvertorThread.run(AysnJasPdfConvertorThread.java:223)Local Variable: java.io.File#139Local Variable: java.io.File#138Local Variable: java.io.File#137Local Variable: java.io.File#136Local Variable: com.pingan.icore.print.asyntask.jasper.AysnJasPdfConvertorThread#1at java.lang.Thread.run(Thread.java:722)

内存:
发现这个net.sf.jasperreports.engine.fill.JRTemplatePrintText类的实例特别多，实例占了33.2%，大小占了58.1%

结论

到这里可以判断出是JasperReport在转换时对对象的创建和使用不当造成的。然而解决该问题并没有什么特别好的方式，除非去改源码或者换一个报表工具
根据上面的情况google了下别人是否遇到过类似的问题，然后定位到如下两个网址:

  • http://community.jaspersoft.com/jasperreports-library/issues/4151
  • http://community.jaspersoft.com/wiki/isprintwhendetailoverflowstrue-can-cause-report-render-indefinitely

可以看出新版的jasperreports依然会有该问题。只能通过取消勾选 **‘Print When Detail Overflows’**的选项来避免该问题
同时使jasperreport的virtualizer(Virtualizes data to the filesystem. When this object is finalized, it removes the swap files it makes. The virtualized objects have references to this object, so finalization does not occur until this object and the objects using it are only weakly referenced.)
来优化jasperreport的内存使用，减轻症状。
下面给出个使用demo:

  • http://www.massapi.com/source/sourceforge/17/71/1771543975/oreports-code/openreports/src/org/efs/openreports/util/ScheduledReportJob.java.html#158

问题解决并不算完美。遗憾

感想

总的来说，这次问题排查的过程，很多思路和想法都是来自于之前阅读的一本书《深入理解Java虚拟机：JVM高级特性与最佳实践》的第二版。其中对虚拟机性能监控与故障处理以及jvm内存等的介绍以及一些实战都是很有帮助的，想了解的可以去阅读下。

这篇关于线上java程序CPU占用过高问题排查的文章就介绍到这儿，希望我们推荐的文章对编程师们有所帮助！


http://www.chinasem.cn/article/996792。

相关文章

Java中流式并行操作parallelStream的原理和使用方法

Java中流式并行操作parallelStream的原理和使用方法

《Java中流式并行操作parallelStream的原理和使用方法》本文详细介绍了Java中的并行流（parallelStream）的原理、正确使用方法以及在实际业务中的应用案例,并指出在使用并行流... 目录Java中流式并行操作parallelStream0. 问题的产生1. 什么是parallelS
阅读更多...
Java中Redisson 的原理深度解析

Java中Redisson 的原理深度解析

《Java中Redisson的原理深度解析》Redisson是一个高性能的Redis客户端,它通过将Redis数据结构映射为Java对象和分布式对象,实现了在Java应用中方便地使用Redis,本文... 目录前言一、核心设计理念二、核心架构与通信层1. 基于 Netty 的异步非阻塞通信2. 编解码器三、
阅读更多...
SpringBoot基于注解实现数据库字段回填的完整方案

SpringBoot基于注解实现数据库字段回填的完整方案

《SpringBoot基于注解实现数据库字段回填的完整方案》这篇文章主要为大家详细介绍了SpringBoot如何基于注解实现数据库字段回填的相关方法,文中的示例代码讲解详细,感兴趣的小伙伴可以了解... 目录数据库表pom.XMLRelationFieldRelationFieldMapping基础的一些代
阅读更多...
一篇文章彻底搞懂macOS如何决定java环境

一篇文章彻底搞懂macOS如何决定java环境

《一篇文章彻底搞懂macOS如何决定java环境》MacOS作为一个功能强大的操作系统,为开发者提供了丰富的开发工具和框架,下面：本文主要介绍macOS如何决定java环境的相关资料,文中通过代码... 目录方法一：使用 which命令方法二：使用 Java_home工具（Apple 官方推荐）那问题来了，
阅读更多...
Java HashMap的底层实现原理深度解析

Java HashMap的底层实现原理深度解析

《JavaHashMap的底层实现原理深度解析》HashMap基于数组+链表+红黑树结构,通过哈希算法和扩容机制优化性能,负载因子与树化阈值平衡效率,是Java开发必备的高效数据结构,本文给大家介绍... 目录一、概述：HashMap的宏观结构二、核心数据结构解析1. 数组（桶数组）2. 链表节点（Node
阅读更多...
Java AOP面向切面编程的概念和实现方式

Java AOP面向切面编程的概念和实现方式

《JavaAOP面向切面编程的概念和实现方式》AOP是面向切面编程,通过动态代理将横切关注点（如日志、事务）与核心业务逻辑分离,提升代码复用性和可维护性,本文给大家介绍JavaAOP面向切面编程的概... 目录一、AOP 是什么？二、AOP 的核心概念与实现方式核心概念实现方式三、Spring AOP 的关
阅读更多...
详解SpringBoot+Ehcache使用示例

详解SpringBoot+Ehcache使用示例

《详解SpringBoot+Ehcache使用示例》本文介绍了SpringBoot中配置Ehcache、自定义get/set方式,并实际使用缓存的过程,文中通过示例代码介绍的非常详细,对大家的学习或者... 目录摘要概念内存与磁盘持久化存储：配置灵活性：编码示例引入依赖：配置ehcache.XML文件：配置
阅读更多...
Java 虚拟线程的创建与使用深度解析

Java 虚拟线程的创建与使用深度解析

《Java虚拟线程的创建与使用深度解析》虚拟线程是Java19中以预览特性形式引入,Java21起正式发布的轻量级线程,本文给大家介绍Java虚拟线程的创建与使用,感兴趣的朋友一起看看吧... 目录一、虚拟线程简介1.1 什么是虚拟线程？1.2 为什么需要虚拟线程？二、虚拟线程与平台线程对比代码对比示例：三
阅读更多...
IDEA和GIT关于文件中LF和CRLF问题及解决

IDEA和GIT关于文件中LF和CRLF问题及解决

《IDEA和GIT关于文件中LF和CRLF问题及解决》文章总结：因IDEA默认使用CRLF换行符导致Shell脚本在Linux运行报错,需在编辑器和Git中统一为LF,通过调整Git的core.aut... 目录问题描述问题思考解决过程总结问题描述项目软件安装shell脚本上git仓库管理，但拉取后，上l
阅读更多...
Java中的.close()举例详解

Java中的.close()举例详解

《Java中的.close()举例详解》.close()方法只适用于通过window.open()打开的弹出窗口,对于浏览器的主窗口,如果没有得到用户允许是不能关闭的,：本文主要介绍Java中的.... 目录当你遇到以下三种情况时，一定要记得使用 .close()：用法作用举例如何判断代码中的 input
阅读更多...

Copyright China编程 23002807@qq.com

沪ICP备2023033072号-2