2007年10月30日 #

一次支持日志

故障现象:

测试一段时间后应用无响应,连接池不能放大,jvm crash,日志报对象分配失败

 

问题诊断:

第一个阶段是websphere问题

到现场之后,回放脚本测试几分钟,应用开始无法响应,后台也没有异常,update jdk之后,系统能正常响应了,但是发现新的问题,db2连接池始终无法放大,最大只能到30,而且系统也会抛OOM,导致系统异常推出,从系统日志看,是因为应用中的大对象分配导致的(2M大小)

期间,关于连接池无法放大问题想了很多办法,包括修改db2 maxappls,maxagents这些参数,更新数据库驱动,而且确定不是db2的问题(在创建30之后,我们依然可以通过其他方式连接到db2,说明db2的连接限制确实放大了),当然我们productdatasource这个池子大小我已经放大到100了。

中间还发现测试脚本没有正常启动流程,排查后发现是loadrunner的问题,用我机器上的lr录制正常(错误代码提示是字段长度限制,莫名其妙)。

关于jvm crach我们也调整了heap设置:-xms256m,-xmx1536m

但是问题依然存在。后面我们重新安装了应用,所有的设置采用缺省配置,没有打任何补丁,系统这个时候竟然可以正常跑了,只是响应很慢,而且时间曲线一直往上抛(测试一段时间系统无响应)

查了一下配置,发现productdatasource的缺省设置竟然就是30,这个时候基本判断是之前的websphere的设置修改没有生效

重新修改jvm和连接池配置,这时候系统正常,数据连接也达到83个,然后开始测试大并发量

 

阶段二就是调整数据库配置

1、第一个是db2 default buffer pool,缺省配置buffer才4m,这个一定要注意修改

2、第二个是db2的lock数量,在缺省基础上好像放大了100倍

3、sort heap,排序区(防止排序溢出)

这些调整都要通过db2的状态来调整,可以通过get snapshot指令来获得数据库状态,buffer不够会出现大量的逻辑读,lock不够会抛lock溢出(会导致锁升级),sort heap不够会提示排序溢出(这时候排序会在硬盘做)

 

回头看看这次支持:

1、websphere配置修改不生效,我后面仔细想了想,这个websphere很多公司用可能大家都乱改了一通,另一问题是我们的使用习惯,websphere强烈不建议用kill直接杀进程方式停服务器,websphere不但是一个java进程,还有很多的附属进程,直接kill也很容易导致websphere不正常

2、jvm crach问题,这个我建议大家看看这篇文档http://www-1.ibm.com/support/docview.wss?rs=180&context=SSEQTP&q1=fragmentation

&uid=swg21176363&loc=en_US&cs=utf-8&lang=en

如何去定位jvm问题,首先看nativerr.log日志,如果出现OOM,这里会有记录,当发现OOM的时候,可以打开jvm的verbosegc,分析verbosegc和jvm dump file,上面文档里提到一个很重要的东西就是pinned对象,这也是ibm为啥不建议设置ms=mx的原因。

posted @ 2007-10-30 13:09 tacy lee 阅读(130) | 评论 (0)编辑 收藏

捕获DB2 sql的执行快照

先建立一个监控器

db2 "create event monitor SQLCOST for statements write to file '/home/db2inst1'"

再设置事务状态为打开

db2 "set event monitor SQLCOST state=1"

注:1为打开,0为关闭,收集数据之后,记得关闭你的监控器,否则。。。

跑你的测试后,在你的/home/db2inst1目录下会生成一些evm文件

用下面指令获取诊断信息:

db2evmon -db eos51 -evm SQLCOST>sqlcost1.txt

完成之后删除你的监控器

db2 "drop event monitor SQLCOST"

生成的采样例子,从下面的例子中,你可以清除的看到SQL执行的时间,CPU消耗情况,排序是否溢出,BufferPool的使用情况,根据这些信息,SQL的执行效率一目了然:

26) Statement Event ...

Appl Handle: 336

Appl Id: C0A80421.O905.0ABDA5065446

Appl Seq number: 0657

Record is the result of a flush: FALSE

-------------------------------------------

Type : Dynamic

Operation: Execute

Section : 7

Creator : NULLID

Package : SYSSN300

Consistency Token : SYSLVL01

Package Version ID :

Cursor : SQL_CURSN300C7

Cursor was blocking: FALSE

Text : update WFProcessInst set relateData=? where processInstID= ?

-------------------------------------------

Start Time: 04/25/2007 14:57:19.402248

Stop Time: 04/25/2007 14:57:19.409622

Exec Time: 0.007374 seconds

Number of Agents created: 1

User CPU: 0.000000 seconds

System CPU: 0.000000 seconds    [licl1]

Fetch Count: 0

Sorts: 0

Total sort time: 0

Sort overflows: 0    [licl2]

Rows read: 1

Rows written: 1

Internal rows deleted: 0

Internal rows updated: 0

Internal rows inserted: 0

Bufferpool data logical reads: 9

Bufferpool data physical reads: 0

Bufferpool temporary data logical reads: 0

Bufferpool temporary data physical reads: 0

Bufferpool index logical reads: 3

Bufferpool index physical reads: 0

Bufferpool temporary index logical reads: 0

Bufferpool temporary index physical reads: 0    [licl3]

SQLCA:

sqlcode: 0

sqlstate: 00000


[licl1]SQL执行时间和CPU消耗情况

[licl2]SQL的排序情况,可以看到这个SQL没有排序,当然也没有排序溢出

[licl3]Bufferpool的使用情况,逻辑读和物理读的对比

del.icio.us Tags: , ,

posted @ 2007-10-30 12:59 tacy lee 阅读(147) | 评论 (0)编辑 收藏