性能分析系列--小命令保证大性能

最近在工作中经常和性能压测工作打交道,积累了一些性能分析经验,我觉得这些经验对每一个开发者都有帮助的,能开发出性能高的代码也是我们的最终目标。


由易到难,我们逐步介绍不同命令的用法和好处,这些命令是如何帮助我们开发人员进行性能分析的。


一、开发者的自测利器-Hprof命令

1、示例演示


例子程序:


/**

* PROJECT_NAME: test

* DATE:         16/7/22

* CREATE BY:    chao.cheng

**/

public class HProfTest {

   public void slowMethod() {

       try {

           Thread.sleep(1000);

       } catch (Exception e) {

           e.printStackTrace();

       }

   }


   public void slowerMethod() {

       try {

           Thread.sleep(10000);

       } catch (Exception e) {

           e.printStackTrace();

       }

   }


   public static void main(String[] args) {

       HProfTest test = new HProfTest();

       test.slowerMethod();

       test.slowMethod();

   }

}

注:这是一段测试代码通过sleep方法进行延时,在程序运行过程中很慢,我想知道到底是哪段程序影响的整体性能呢?


我在这个java程序中,加了如下运行参数:


-agentlib:hprof=cpu=times,interval=10

/*

times:java函数的执行时间

hprof=cpu是针对cpu统计时间

interval=10 采样10次

*/

再次运行这段程序显示如下图:



Paste_Image.png


这时候还发现在工程目录里面,多了一个文本文件java.hprof.txt,如下图所示:



Paste_Image.png


内容如下:


CPU TIME (ms) BEGIN (total = 11542) Fri Jul 22 11:00:34 2016

rank   self  accum   count trace method

  1 86.65% 86.65%       1 303422 com.test.HProfTest.slowerMethod

  2  8.66% 95.31%       1 303423 com.test.HProfTest.slowMethod

  3  0.25% 95.56%      36 300745 java.util.zip.ZipFile.

  4  0.20% 95.76%      36 300434 java.lang.String.equals

  5  0.13% 95.89%      14 301138 java.net.URLStreamHandler.parseURL

  6  0.11% 96.01%       6 301339 java.net.URLClassLoader$1.run

  7  0.10% 96.10%      14 301124 java.lang.String.

  8  0.09% 96.19%    3407 300355 java.lang.String.charAt

  9  0.08% 96.27%      36 300443 java.io.UnixFileSystem.normalize

注:通过上面内容可以看到,哪个类的方法执行时间长,耗费了cpu时间,一目了然,方便我们快速定位问题。


2、命令的具体讲解

hprof不是独立的监控工具,它只是一个java agent工具,它可以用在监控Java应用程序在运行时的CPU信息和堆内容,使用java -agentlib:hprof=help命令可以查看hprof的使用文档。



Paste_Image.png

通过上图可以看到这个工具非常强大,可以统计的东西很多,上面的例子统计的是cpu时间,同样我们还可以统计内存占用的dump信息。

如:-agentlib:hprof=heap,format=b,file=/test.hprof


这个hprof小工具,非常方便我们在用JUnit自测代码的时候结合使用,既可以解决业务上的BUG,又能够在一定程序上解决可发现的性能问题,非常实用。


二、性能排查工具-pidstat

1、示例演示

例子程序:


/**

* PROJECT_NAME: test

* DATE:         16/7/22

* CREATE BY:    chao.cheng

**/

public class PidstatTest {

   public static class PidstatTask implements  Runnable {

       public void run() {

           while(true) {

               double value = Math.random() * Math.random();

           }

       }

   }


   public static class LazyTask implements Runnable {

       public void run() {

           try {

               while (true) {

                   Thread.sleep(1000);

               }

           } catch (Exception e) {

               e.printStackTrace();

           }

       }

   }


   public static void main(String[] args) {

       new Thread(new PidstatTask()).start();

       new Thread(new LazyTask()).start();

       new Thread(new LazyTask()).start();

   }

}

注:这是一段测试用的java程序,将其运行起来。


在命令行输入:


pidstat -p 843 1 3 -u -t

/*

-u:代表对cpu使用率的监控

参数1 3:表示每秒采样一次,一共三次

-t:将监控级别细化到线程

*/

运行命令显示如下图所示:



Paste_Image.png


注:其实中TID就是线程ID,%usr表示用户线程使用率,从图中可以看到855这个线程占用cpu非常的高。


再输入如下命令:


jstack -l 843 > /tmp/testlog.txt

查看testlog.txt显示如下部分内容:



Paste_Image.png


注:我们关注的是日志文件的NID这个字段,它对应的就是我们上面说的TID,NID是TID的16进制表示,将上面的十进制855转换成十六进制为357,在日志中进行搜索看到如下内容:


"Thread-0" prio=10 tid=0x00007f7d90103800 nid=0x357 runnable [0x00007f7d943d5000]

  java.lang.Thread.State: RUNNABLE

   at PidstatTest$PidstatTask.run(PidstatTest.java:13)

   at java.lang.Thread.run(Thread.java:722)


  Locked ownable synchronizers:

   - None

以此可以推断出有性能瓶颈的程序点。


2、pidstat具体命令详解

pidstat是一个功能非常强大的性能监测工具,他是Sysstat的组件之一,可以从http://sebastien.godard.pagesperso-orange.fr/download.html 进行下载,下载后可以通过./configure等命令进行安装,这个命令的强大之处在于不仅可以监控进程的性能情况,也可以监控线程的性能情况。


pidstat监控cpu常用显示字段内容如下:


1、PID - 被监控的任务的进程号

2、%usr - 当在用户层执行(应用程序)时这个任务的cpu使用率,和 nice 优先级无关。注意这个字段计算的cpu时间不包括在虚拟处理器中花去的时间。

3、%system - 这个任务在系统层使用时的cpu使用率。

4、%guest - 任务花费在虚拟机上的cpu使用率(运行在虚拟处理器)。

5、%CPU - 任务总的cpu使用率。在SMP环境(多处理器)中,如果在命令行中输入-I参数的话,cpu使用率会除以你的cpu数量。

6、CPU - 正在运行这个任务的处理器编号。

7、Command - 这个任务的命令名称。

pidstat监控io常用的字段显示内容如下:


1、kB_rd/s - 任务从硬盘上的读取速度(kb)

2、kB_wr/s - 任务向硬盘中的写入速度(kb)

3、kB_ccwr/s - 任务写入磁盘被取消的速率(kb)

三、一个内存溢出案例分析

1、内存溢出现象

系统共有8台服务器,每次随机只有一台服务器报java.lang.OutOfMemoryError: GC overhead limit exceeded错误,然后接着就报内存溢出错误java.lang.OutOfMemoryError: Java heap space。


2、理论支撑

我们先解释一下什么是GC overhead limit exceeded错误。


GC overhead limt exceed检查是Hotspot VM 1.6定义的一个策略,通过统计GC时间来预测是否要OOM了,提前抛出异常,防止OOM发生。Sun 官方对此的定义是:“并行/并发回收器在GC回收时间过长时会抛出OutOfMemroyError。过长的定义是,超过98%的时间用来做GC并且回收了不到2%的堆内存。用来避免内存过小造成应用不能正常工作。


可以看到当堆中的对象无法被收回的时候,就提前遇警报出这样的错误,此时内存并没有溢出,这个特性在JDK中是默认添加的。


3、DUMP文件分析

将dump文件导入VisualVM工具中,如下图所示:



Paste_Image.png

通过上图可以看出类结构图中,最占用内存的是char[],LinkedHashMap和String三项。但是这三项的实例数并没有占满,看样子不会内存溢出,怎么才能具体分析呢?原因就在于GC overhead limt exceed,这个错并不会在内存真正溢出才会报,所以通过dump文件,我们只能自己去判断分析,哪些项有可能会造成溢出,我们进入char[]项具体来看,会发现里面有很多hessian的url字符被缓存,通过排除程序可以看到由于底层中间件程序为了提高“性能”,将每次调用的url都缓存起来,不用每次都生成,但没有相应缓存释放操作,于是造成了大量字符对象长期持有从而报错,在此就不截图来具体看代码,涉及一些公司信息。


4、问题解决方案


可以添加JVM的启动参数来去掉提前报警限制:-XX:-UseGCOverheadLimit,于其让应用每次都提前报警,还不如让暴风雨来的更猛些,直接内存溢出,因为服务器是集群,其中一台挂掉不会影响线上正常交易,同时也方便我们通过日志来排错。


通过排查程序,检查系统是否有使用大内存的代码不释放或死循环。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 205,132评论 6 478
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 87,802评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 151,566评论 0 338
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,858评论 1 277
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,867评论 5 368
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,695评论 1 282
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,064评论 3 399
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,705评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 42,915评论 1 300
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,677评论 2 323
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,796评论 1 333
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,432评论 4 322
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,041评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,992评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,223评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,185评论 2 352
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,535评论 2 343

推荐阅读更多精彩内容

  • 最近在工作中经常和性能压测工作打交道,积累了一些性能分析经验,我觉得这些经验对每一个开发者都有帮助的,能开发出性能...
    小程故事多阅读 2,767评论 9 36
  • 1. Java基础部分 基础部分的顺序:基本语法,类相关的语法,内部类的语法,继承相关的语法,异常的语法,线程的语...
    子非鱼_t_阅读 31,577评论 18 399
  • Spring Cloud为开发人员提供了快速构建分布式系统中一些常见模式的工具(例如配置管理,服务发现,断路器,智...
    卡卡罗2017阅读 134,598评论 18 139
  • 一 、java虚拟机底层结构详解 我们知道,一个JVM实例的行为不光是它自己的事,还涉及到它的子系统、存储区域、...
    葡萄喃喃呓语阅读 1,472评论 0 4
  • 才饮山涧水,又食荷塘鱼,。千里玉带奔腾,大浪滔天驻。无惧群岚阻隔,胜似腾云驾雾,一朝破川蜀。子在川上曰:逝者如...
    一舟洲阅读 327评论 0 1