java程序启动时cpu和负载高探索

这两天协助运维定位1个监控程序CPU占用率达到150%的问题,过程曲折,结论简单,很有意思:)

首先我们来看一下cpu高时候截图:

可以看到红色框中的监控程序CPU占用率都很高,但其实这些监控程序的实现很简单:发送1个http请求,收到响应后简单判断一下响应码,然后打印监控结果,打印完成就退出了。每次监控都会重新由daemon程序拉起运行。

这么简单的业务占用这么高的cpu,怎么感觉都不太可能,于是拿到监控程序的源码开始定位。

第一个想到的是VisualVm、JConsole等工具,但由于程序很快就运行完成了,这两个工具都还没有连接上就结束了,而且拿到的数据也没法看出具体是什么原因导致cpu高,尝试了一下就放弃了。

第二个尝试是用strace去跟踪程序的调用,结果摘录如下(省略很多):

17572 14:08:43.485878 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.486132 clock_gettime(CLOCK_REALTIME, {1423721323, 486165000}) = 0
17572 14:08:43.486204 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9949000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.496964 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.497142 clock_gettime(CLOCK_REALTIME, {1423721323, 497169000}) = 0
17572 14:08:43.497236 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9935000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.507896 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.508164 clock_gettime(CLOCK_REALTIME, {1423721323, 508201000}) = 0
17572 14:08:43.508240 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9945000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.518960 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.519140 clock_gettime(CLOCK_REALTIME, {1423721323, 519168000}) = 0
17572 14:08:43.519236 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9934000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.529882 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.530144 clock_gettime(CLOCK_REALTIME, {1423721323, 530177000}) = 0
17572 14:08:43.530216 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9946000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.540951 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.541129 clock_gettime(CLOCK_REALTIME, {1423721323, 541157000}) = 0
17572 14:08:43.541222 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9935000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.551872 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.552127 clock_gettime(CLOCK_REALTIME, {1423721323, 552159000}) = 0
17572 14:08:43.552199 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9949000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.562857 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.563029 clock_gettime(CLOCK_REALTIME, {1423721323, 563056000}) = 0
17572 14:08:43.563119 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9936000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.573913 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.574159 clock_gettime(CLOCK_REALTIME, {1423721323, 574214000}) = 0
17572 14:08:43.574253 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9925000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.584885 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.585055 clock_gettime(CLOCK_REALTIME, {1423721323, 585081000}) = 0
17572 14:08:43.585147 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9936000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.595900 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.596170 clock_gettime(CLOCK_REALTIME, {1423721323, 596206000}) = 0
17572 14:08:43.596245 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9947000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.606960 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.607139 clock_gettime(CLOCK_REALTIME, {1423721323, 607167000}) = 0
17572 14:08:43.607232 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9935000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.617875 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.618119 clock_gettime(CLOCK_REALTIME, {1423721323, 618209000}) = 0
17572 14:08:43.618249 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9890000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.628960 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.629140 clock_gettime(CLOCK_REALTIME, {1423721323, 629168000}) = 0
17572 14:08:43.629231 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9935000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.639865 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.640134 clock_gettime(CLOCK_REALTIME, {1423721323, 640167000}) = 0
17572 14:08:43.640206 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9946000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.650868 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.651139 unlink("/tmp/hsperfdata_gamedata/17559") = 0
17572 14:08:43.651324 exit_group(0)     = ?   

怎么那么多futex,google一查“futex connection time out”,嘿,还真有很多结果,最典型的就是leap second,中文翻译为“闰秒”,但仔细一看,上一次闰秒发生是2012年06月份,现在都2015年了,而且天天cpu都高,应该不是这个问题

工具指望不上,只好看代码,代码看了后怀疑几个地方:

1)CountDownLatch:因为这个最有可能用到futex了,但实际想了想和验证了一下,这个东东不可能导致cpu这么高,真有这个问题,这东东完全就没法用了

2)多线程:看了代码,没有几个线程,而且业务就是一发一收,不可能多线程导致的

问题陷入僵局,怎么办呢? 只好用终极大招了:分段注释!

1)注释响应处理的代码 —— 不行,cpu占用100%

2)注释发送请求的代码 —— 还是不行,,cpu占用100%

这不坑爹嘛,请求都不发,响应也没有了,你咋还这么慢?

3)干脆注释所有代码, 只在main里面打印Hello world —— 还是不行,,cpu占用100%

这下就蛋疼了,没有任何业务,你cpu还高,这不坑我嘛

4)自己写个Hello world —— 咦,这次可以了,cpu占用2%

咋回事,同样都是打印Hello world,为啥cpu差别那么大?

左思右想,突然灵光一闪:难道是和jvm加载类文件有关 ?

jvm在启动的时候会装载并连接所有除反射以外的类,而class文件是二进制的文件,需要从磁盘加载到内存然后解析,这种解析是很耗费cpu的,那么class文件越多,cpu耗费就越高,这正好解释了为什么同样输出Hello world,不同程序cpu占用率差别很大。

这个推论正好也解释了之前遇到的另外一个线上项目的现象:每次启动后有大约1分钟左右系统的cpu和负载很高,过了1分钟后就恢复正常了。

【建议】

需要重复运行的监控类程序,如果用java写,最好不要做成每次都要重新启动,而是在程序里面循环或者定时运行;

如果一定要每次都要重新启动,频率又很频繁的话,建议用shell、python之类的来写,否则一台机器运行太多java类的工具程序,会导致cpu和负载飙升

转载请注明出处:http://blog.csdn.net/yunhua_lee/article/details/43765371

时间: 2024-07-29 06:51:36

java程序启动时cpu和负载高探索的相关文章

java程序 启动时参数

iEMP34:/opt/version/lktest/b030/jre/jre_linux/bin # ./java -classpath . SysInfo Exception in thread "main" java.lang.NoClassDefFoundError: org/hyperic/sigar/SigarException at java.lang.Class.getDeclaredMethods0(Native Method) at java.lang.Class.

Android应用程序启动时发生AndroidRuntime : ClassNotFoundException for Activity class的解决方法

在android应用程序启动时抛出下面异常导致启动失败:07-09 17:12:35.709: ERROR/AndroidRuntime(3866): Uncaught handler: thread main exiting due to uncaught exception 07-09 17:12:35.719: ERROR/AndroidRuntime(3866): java.lang.RuntimeException: Unable to instantiate activity Com

java程序启动参数-D是用来做什么的?

java程序启动参数 -D是用来做什么的呢?去查询了一下官方解释: Set a system property value. If value is a string that contains spaces, you must enclose the string in double quotes: java -Dfoo="some string" SomeClass 也就是说-D是用来在启动一个java程序时设置系统属性值的.如果该值是一个字符串且包含空格,那么需要包在一对双引号中

Java程序运行时的几个区域

Java运行时涉及到的区域 几个基本概念: 1.Java对象     2.Java方法    3.一个编译好的类,以class文件的形式出现 4.Java的本地方法   5.线程私有和线程共有 一.方法区(永久代) 和 堆(heap) 这两个区域是线程共有的,供所有线程使用.所以,对存放在这两个地方的资源进行操作时,如果是程序是多线程的,那么要考虑同步. 方法区存放的是类的类型信息.类的类型信息有,类的静态变量,其它从class文件中读取到的信息. 当用户访问一个类的静态方法或者类的静态变量,或

SpringBoot程序启动时执行初始化代码

因项目集成了Redis缓存部分数据,需要在程序启动时将数据加载到Redis中,即初始化数据到Redis. 在SpringBoot项目下,即在容器初始化完毕后执行我们自己的初始化代码. 第一步:创建实现ApplicationListener接口的类 package com.stone; import com.stone.service.IPermissionService; import org.springframework.context.ApplicationListener; import

iOS 应用程序启动时要做什么

当您的应用程序启动(无论是在前台或后台),使用您的应用程序委托application:willFinishLaunchingWithOptions:和application:didFinishLaunchingWithOptions:方法来执行以下操作: 检查启动选项字典的内容,了解有关启动应用程序的原因,并做出相应的响应. 初始化您的应用程序的关键数据结构. 准备您的应用程序的窗口和视图以供显示: 在启动时,系统会自动加载您的应用程序的main Storyboard加载初始视图控制器. app

如何在ASP.NET Core程序启动时运行异步任务(2)

原文:Running async tasks on app startup in ASP.NET Core (Part 2) 作者:Andrew Lock 译者:Lamond Lu 在我的上一篇博客中,我介绍了如何在ASP.NET Core应用程序启动时运行一些一次性异步任务.本篇博客将继续讨论上一篇的内容,如果你还没有读过,我建议你先读一下前一篇. 在本篇博客中,我将展示上一篇博文中提出的"在Program.cs中手动运行异步任务"的实现方法.该实现会使用一些简单的接口和类来封装应用

线上Java程序导致服务器CPU占用率过高的问题排除过程

博文转至:http://www.jianshu.com/p/3667157d63bb,博文更好效果看原版,转本博文的目的就算是个书签吧,需要时候可以定位原文学习 1.故障现象 客服同事反馈平台系统运行缓慢,网页卡顿严重,多次重启系统后问题依然存在,使用top命令查看服务器情况,发现CPU占用率过高. 2.CPU占用过高问题定位 2.1.定位问题进程 使用top命令查看资源占用情况,发现pid为14063的进程占用了大量的CPU资源,CPU占用率高达776.1%,内存占用率也达到了29.8% [[

记一次线上Java程序导致服务器CPU占用率过高的问题排除过程

https://blog.csdn.net/u013991521/article/details/52781423 1.故障现象 客服同事反馈平台系统运行缓慢,网页卡顿严重,多次重启系统后问题依然存在,使用top命令查看服务器情况,发现CPU占用率过高. 2.CPU占用过高问题定位 2.1.定位问题进程 使用top命令查看资源占用情况,发现pid为14063的进程占用了大量的CPU资源,CPU占用率高达776.1%,内存占用率也达到了29.8% [ylp@ylp-web-01 ~]$ top t