EOS系统性能分析工具_-_使用说明.doc

primeton technologies, ltd. 上海普元信息技术有限责任公司上海普元信息技术有限责任公司 eos 系统性能分析工具系统性能分析工具 使用说明使用说明 no part of this document may be reproduced, stored in any electronic retrieval system, or transmitted in any form or by any means, mechanical, photocopying, recording, otherwise, without the written permission of the copyright owner. copyright 2006 by primeton technologies, ltd. all rights reserved. eos 系统性能分析工具使用说明 /第 2 页 共 29 页 文档修订记录文档修订记录 序号序号版本号版本号修订日期修订日期修订概述修订概述修订人修订人审批人审批人备注备注 10.12007-06-10创建林锋 20.22007-09-06功能侧重分析 系统性能，而 不是分析系统 问题 林锋 30.32007-10-12支持 eos5.3林锋 40.42008-03-07修改分析结果 样式 增加查看单个 请求功能 林锋 eos 系统性能分析工具使用说明 /第 3 页 共 29 页 规范及约定规范及约定 1.【规范及约定】的内容仅仅是对本文档编写的规范和约定进行描述，文档编 写人员必须严格按照本规范和约定进行编写，在文档正式发布时删除该部分 内容； 2.文档内容采用“首行缩进、小四号字体、1.5 倍行距”的格式，选中段落文本 使用快捷键【ctrl+alt+4】可以进行格式化（直接选中蓝色的说明文字即可） ； 3.必须填写“文档修订控制记录” ； 4.文档目录必须更新为最新的，与实际内容相对应； 5.模版中每部分内容的下面的蓝色字体是对这块内容的说明，编写文档时选中 这段文字，使用【ctrl+alt+4】快捷键即可格式化成要求的字体； eos 系统性能分析工具使用说明 /第 4 页 共 29 页 目目 录录 1文档摘要文档摘要.6 1.1文档分类.6 1.2关键字/tag.6 1.2.1摘要6 1.3作者、协作者及评审人员.6 1.4定义、首字母缩写词及缩略语.6 2使用说明使用说明.7 2.1适用环境.7 2.2useraccessmonitor日志7 2.2.1日志开关7 2.2.2日志内容8 2.3使用工具.9 2.3.1打开工具9 2.3.2导入日志文件10 2.3.3性能分析13 设置分析范围及输出结果.13 分析日志.14 分析结果说明.15 .1全局统计数据.15 .2访问量分析图.16 .3活动用户量分析图.16 .4空闲内存变化分析图.17 .5功能列表.17 .6用户列表.18 .7未执行完的请求.18 .8超过指定执行时间的请求.19 如何利用工具分析问题.19 .1分析系统整体运行效率.19 .2分析系统内存泄漏.21 .3分析系统内存短时间内被耗光的现象.22 .4预判系统用户量增涨后内存是否足够使用.25 .5分析系统需要优化的功能.27 2.3.4查看单个请求27 eos 系统性能分析工具使用说明 /第 5 页 共 29 页 eos 系统性能分析工具使用说明 /第 6 页 共 29 页 1 文档摘要文档摘要 1.1 文档分类文档分类 1.2 关键字关键字/tag 1.2.1 摘要摘要 本工具通过分析 eos server 记录的用户请求记录信息（useraccessmonitor.log） ， 可以监控系统日常运行情况，诊断系统是否健康运转。该工具是 eos 系统后期运行维 护最重要的手段。 1.3 作者、协作者及评审人员作者、协作者及评审人员 林锋 1.4 定义、首字母缩写词及缩略语定义、首字母缩写词及缩略语 eos 系统性能分析工具使用说明 /第 7 页 共 29 页 2 使用说明使用说明 2.1 适用环境适用环境 windows 环境 jdk1.4.2 以上版本 eos3.5eos5.3 版本 2.2 useraccessmonitor 日志日志 性能分析工具是通过分析 eos server 记录的 useraccessmonitor 日志来得到系统 的性能分析报告的。 useraccessmonitor.log 是 eos 一个重要的日志。记录的是每个展现逻辑的开始调 用和结束调用，通过此日志文件可以检查展现逻辑是否成功执行、执行了多长时间、 执行之间的内存变化等等。 因为每个请求记录两条日志，记录的日志信息量不大，所以不会对系统的性能带 来什么影响。 2.2.1 日志开关日志开关 在 eos5.2 之前的版本不提供通过页面来修改配置，需要手工修改配置文件。 jboss 环境：环境： 修改 jboss-3.2.5serverdefaultconflog4j.xml 文件： eos 系统性能分析工具使用说明 /第 8 页 共 29 页 . weblogic、was 环境：环境： 修改 eos_home/config/ perties 文件： log4j.logger.defaultappid.useraccessmonitor=debug,uam log4j.appender.uam.layout.conversionpattern=%d- %m$%n log4j.appender.uam.layout=org.apache.log4j.patternlayout log4j.appender.uam.maxfilesize=8096kb log4j.appender.uam.maxbackupindex=10 log4j.appender.uam.file=$eos_home/logs/useraccessmonitor.log log4j.appender.uam=org.apache.log4j.rollingfileappender 将日志级别配置为 debug 则记录 useraccessmonitor 日志。 另外注意日志文件存在路径默认是在 eos_home/logs/目录下。 建议将日志文件大小配置 8096kb，保留 10 个备份文件，这样便于对系统长期的 分析监控。 2.2.2 日志内容日志内容 useraccessmonitro.log 中记录的是开始调用和结束调用展现逻辑是的日志，所以 eos 系统性能分析工具使用说明 /第 9 页 共 29 页 正常的日志应该是成双成对的。如下面的两条日志记录： 2005-06-22 11:35:04,023- b 1119411295568 sysadmin p bnom.pr_automat a.bnom_p_showempmain 66650112 25788232 success$ 2005-06-22 11:35:18,684- e 1119411295568 sysadmin p bnom.pr_automat a.bnom_p_showempmain 66650112 13912400 success$ 下面以第一条日志为例进行说明： 列列值值说明说明 12005-06-22 11:35:04,023记录日志的时间点 2b该日志为开始调用时的记录，结束调用为“e” 31119411295568请求编号，唯一。用它来定位日志中开始结束调用记录 4sysadmin调用展现逻辑的用户名 5p展现逻辑层的调用。目前版本只支持到展现逻辑层 6bnom.pr_automata.bno m_p_showempmain 调用的展现逻辑名 766650112eos server 启动时实时的 jvm 内存大小，单位为 byte 825788232当前 jvm 内存大小，单位为 byte 9success执行成功 2.3 使用工具使用工具 2.3.1 打开工具打开工具 首先需要说明的是，工具是使用 java 编写的，需要操作系统中安装 jdk 才能运行。 如果操作系统的环境变量中已经配置了 java_home，那么执行目录下的 uamtool.bat 文件即可启动工具。 如果没有配置 java_home，需要修改 uamtool.bat 文件指定 java_home。 有时因为 jdk 版本的问题，操作系统环境变量中配置的 java_home 不一定支 持工具的正常运行，所以建议还是修改 uamtool.bat 指定 java_home。 工具启动后，界面如下图所示： eos 系统性能分析工具使用说明 /第 10 页 共 29 页 如上图所示，首先需要选择日志文件（即 useraccessmonitor 日志文件） ，再指定 分析的范围和分析输出结果文件，然后就可以开始分析了。 2.3.2 导入日志文件导入日志文件 前面提及过，性能分析工具是通过分析 eos 系统记录的 useraccessmonitor 日志 来得到性能分析结果的。那么，首先就得选择需要分析的日志文件。 如上图所示，点击【导入日志文件】按钮来选择日志文件。未选择日志文件之前， 【导入日志文件】按钮右边有“未选择”的提示。 eos 系统性能分析工具使用说明 /第 11 页 共 29 页 日志文件是可以多选的，选择需要分析的日志文件后打开。如下图所示： 打开选择的日志文件后，会先对日志文件做初步的分析，得到每个日志文件中记 录的日志开始和结束时间。如下图所示： 因为日志文件是用 log4j 记录，如果在取日志文件时刚才 log4j 正在备份日志文件， 那么有可能会漏取或者取得重复的日志文件。 所以要注意检查一下每个日志文件的开始时间应当大于或等于上一个日志文件的 eos 系统性能分析工具使用说明 /第 12 页 共 29 页 结束时间，并且相差不大。 关闭选择日志文件的窗口后，在主界面可以看到【选择】按钮右边显示了选择了 几个日志文件的信息。如下图所示： 点击链接还可以再打开选择日志文件窗口来查看已选择的日志文件。 eos 系统性能分析工具使用说明 /第 13 页 共 29 页 2.3.3 性能分析性能分析 设置分析范围及输出结果设置分析范围及输出结果 日期：日期：分析某一天的系统运行情况，可选择的日期是根据日志的最大最小日期决 定的。 时间段：时间段：分析某一天某时间段内的系统运行情况。 时间点间隔：时间点间隔：取间隔时间内的访问量、活动用户量、空闲内存平均值，以图表的 方式展示在时间段中变化。可选择 1、3、5、10、20 分钟。 列出执行时间超过指定时间的请求：列出执行时间超过指定时间的请求：在这里指定您认为可以承受请求最长的执行 时间，超过此时间的请求将被记录。 分析结果输出：分析结果输出：分析结果输出到一个 excel 文件。注意，如果指定的文件已存在， eos 系统性能分析工具使用说明 /第 14 页 共 29 页 那么要求文件必须是关闭的。默认将指定的分析日期为文件名。 分析日志分析日志 选择了日志文件，并设置了分析范围及输出结果后，点击【开始分析】按钮即可 开始分析。 分析的过程中可以看到分析日志。分析成功结束后，可以立即打开分析结果文件 查看分析结果： 分析结果文件： eos 系统性能分析工具使用说明 /第 15 页 共 29 页 分析结果说明分析结果说明 .1全局统计数据全局统计数据 通过全局统计数据表格底下的链接可以查看其它统计分析数据： eos 系统性能分析工具使用说明 /第 16 页 共 29 页 .2访问量分析图访问量分析图 *访问量是指在间隔时间中的系统接收到的请求数 通过该图表数据，可以很清晰地看到系统在一个时间段内接收到请求的情况。 .3活动用户量分析图活动用户量分析图 *活动用户量是指在间隔时间中发出请求的用户数 通过该图表数据，可以很清晰地看到系统在一个时间段内用户访问系统的情况。 eos 系统性能分析工具使用说明 /第 17 页 共 29 页 .4空闲内存变化分析图空闲内存变化分析图 *空闲内存是间隔时间内记录的各个点的内存平均数 通过该图表数据，可以很清晰地看到系统在一个时间段内 jvm 空闲内存的变化 情况。 .5功能列表功能列表 eos 系统性能分析工具使用说明 /第 18 页 共 29 页 记录了时间段内所有访问的功能，并且统计了访问的次数，以及最短、最长、平 均的执行时间。 对于每个功能，会统计所以执行时间超过指定时间的请求，以及所占百分比。由 此可以判断这功能是否普遍执行时间超长。 另外还可以对分析结果重新排序。 .6用户列表用户列表 记录了时间段内所有访问系统的用户，并且统计了访问的次数，以及最早、最晚 在线的执行时间。 同样还可以对分析结果重新排序。 .7未执行完的请求未执行完的请求 记录了时间段内未执行结束的请求。当然，因为指定了时间段，有可能执行结束 是在时间段之外。 eos 系统性能分析工具使用说明 /第 19 页 共 29 页 .8超过指定执行时间的请求超过指定执行时间的请求 列出了所有执行时间超过指定时间的请求。 如何利用工具分析问题如何利用工具分析问题 .1分析系统整体运行效率分析系统整体运行效率 用户使用系统时，一般只是根据从页面点击，到结果返回的时间来判断系统运行 效率。但影响系统效率的环节很多，那么如何来判断 eos server 的后台运行效率呢？ 我们可以从功能和请求两个方面来分析。 从功能方面分析：从功能方面分析： 1、我们先到分析结果的统计数据中看看时间段内用户所访问过的功能数： eos 系统性能分析工具使用说明 /第 20 页 共 29 页 2、我们假设功能平均执行时间小于 5 秒是可以接受的，那么可以看到慢于 5 秒的 功能占总的功能的比例是多少来判断总体功能执行效率如何： 3、还可以到功能列表中按平均执行时间降序排列一下看更详细的数据： 从请求方面分析：从请求方面分析： eos 系统性能分析工具使用说明 /第 21 页 共 29 页 1、我们先到分析结果的统计数据中看看时间段内用户所访问过的请求数： 2、我们假设请求执行时间小于 5 秒是可以接受的，那么可以看到慢于 5 秒的请求 占总的请求数的比例是多少来判断总体功能执行效率如何： 3、还可以到执行时间超长的请求列表中看更详细的数据： .2分析系统内存泄漏分析系统内存泄漏 在 java 中，内存泄漏就是存在一些被分配的对象，这些对象有下面两个特点： 1、这些对象是有被引用的，即在有向树形图中，存在树枝通路可以与其相连； eos 系统性能分析工具使用说明 /第 22 页 共 29 页 2、这些对象是无用的，即程序以后不会再使用这些对象。 如果对象满足这两个条件，这些对象就可以判定为 java 中的内存泄漏。这些对象 是不会被做垃圾回收的，然而它却占用着内存。 我们来看一个内存使用率比较高的分析图： 空闲内存变化分析图 0 200000000 400000000 600000000 800000000 1000000000 12:00 12:25 12:50 13:15 13:40 14:05 14:30 14:55 15:20 15:45 16:10 16:35 17:00 17:25 17:50 18:15 18:40 19:05 19:30 19:55 20:20 20:45 从上图我们可以看到，系统有时会差不多将内存耗尽，好象有大量内存被占用着 无法回收。但最终内存还是回收到跟初始一样的水平，这就说明系统没有存在不可回 收的内存，不存在内存泄漏的可能。 如果在系统长时间地运行过程中，特别是到系统没有或者很少被使用时，空闲内 存还是无法回到初始水平，那么说明系统有可能存在内存泄漏了。 .3分析系统内存短时间内被耗光的现象分析系统内存短时间内被耗光的现象 我们来看看下面的一个分析图： 内存变化分析图 0 200000000 400000000 600000000 800000000 1000000000 09:05 09:25 09:45 10:05 10:25 10:45 11:05 11:25 11:45 12:05 12:25 12:45 13:05 13:25 13:45 14:05 14:25 14:45 15:05 15:25 15:45 16:05 从上图中很明显地看到空闲内存在很短的时间内突然降到最低点，并且最终没有 回到正常水平。在出现这种情况下，系统可能进程不会 down 掉，但已经无法响应任 何页面请求了，同时会在系统目录下生成 dump 堆栈文件和 javacore 文件。 空闲内存跌 落到低谷 但最终内存还是能回收 eos 系统性能分析工具使用说明 /第 23 页 共 29 页 导致这种现象的最常见的可能就是：某些功能在某些特定的情况下执行，会占用 大量的内存，并且是未执行完的，这一点是显而易见的，只有功能一直在执行，jvm 才无法将功能所占用内存回收。 下面通过一个例子来说明分析这种情况，所使用到的分析结果文件请参看文档 分析结果样例_内存泄漏.xls 。 1、检查日志中记录的最大内存是否有一个扩大的过程检查日志中记录的最大内存是否有一个扩大的过程 (此步骤要求 jvm 的最小、最大内存不要设置成一样。) 打开分析结果文件的工作表【5)执行时间超过 5 秒的请求】 ，可以看到如下的信息： 我们要关注的是最大内存这一列。 需要说明的是，这里记录的最大内存并不是指 jvm 设置的最大内存。jvm 设置 的最大内存是指 jvm 可使用的最大内存，而此处的记录最大内存是 jvm 某个时间点 的所占用的最大内存。服务器启动时，jvm 的所占用的最大内存即是 jvm 所设置的 最小内存，当 jvm 内存不足时，那么 jvm 就会再次扩大所占用的内存，直到达到 jvm 所设置的最大内存。 所以，虽然系统中设置的最大内存是 2g，但在这里记录的最大内存一开始只是系 统设置的最小内存 512m。 往下查看记录的日志信息，可以看到在很长的一段时间内记录的最大内存还是 500 多兆。 然后到 67 行如下图所示的位置： eos 系统性能分析工具使用说明 /第 24 页 共 29 页 在这里可以看到最大内存有一个很明显的扩大过程： 537m808m949m1472m1730m2033m2148m。这个过程在 9 分钟左右。 2、检查最大内存扩大过程中执行时间长的功能检查最大内存扩大过程中执行时间长的功能 我们可以发现在最大内存扩大的过程中只有 两个功能执行时间比较长： wfwebcomp.prworkitemmgr.showworkitemform （以下简称 showworkitemform）和 arms_rf_censorapp.pr.prtormplat（以下简称 prtormplat） ， 那么当然最有可能是这两个功能占用了很多的内存。 首先看一下功能开始执行和执行结束时记录的最大内存。功能 prtormplat 执行 时有三次内存扩大 537m808m、808m949m、1472m1730m，而功能 prtormplat 只有一次 949m1472m。那么当然功能 prtormplat 可能性更大一些。 然后再看一下功能开始执行和执行结束时记录的空闲内存。可以看到空闲内存都 有大幅度地下降，这是自然的。 3、检查未执行完的功能检查未执行完的功能 我们知道，一个请求未执行完，那么该请求所使用的内存当然是不会被回收的。 eos 系统性能分析工具使用说明 /第 25 页 共 29 页 根据这一点到【未执行完功能】列表查看记录的未执行完的功能，这些功能导致内存 耗光的可能性最大。 从以上列表可以看到有两个 prtormplat 功能的请求未执行完，16:11:11 第一个请 求开始执行时，空闲内存为 140 多兆，而 16:11:18 第二个请求开始执行时，空闲内存 只有 50 兆。其它的未执行完的功能请求开始执行时，空闲内存已经很小了，说明主要 是因为内存不足导致它未能执行完，而不是这些功能占用了过多的内存。 4、分析功能代码什么情况下会占用过多内存分析功能代码什么情况下会占用过多内存 什么情况下功能会占用过多内存呢？自然是做查询的时候查询了过多的数据。 分析功能代码时，有以下几个关键步骤： 1、找出功能里比如 bl_queryentityall、bl_runquerysql 等查询全部符合条件数 据的查询操作； 2、确认查询操作查询的表中的数据量有多少，特别要关注对数据量大的表的操作； 3、分析什么情况下有可能查询出过多的数据。注意不要从正常业务处理去分析， 不要管业务上不可能查出过多的数据。你要分析的是什么情况下会查出过多的数据， 比如不可能为空的查询条件什么情况下会变成空的了。 .4预判系统用户量增涨后内存是否足够使用预判系统用户量增涨后内存是否足够使用 例如下图是系统在用户量增涨之前的用户及空闲内存的分析图： eos 系统性能分析工具使用说明 /第 26 页 共 29 页 活动用户量分析图 0 20 40 60 80 100 120 12:00 12:25 12:50 13:15 13:40 14:05 14:30 14:55 15:20 15