使用spotligh+sqltuning+loadrunner对数据库性能问题进行定位和分析

压力测试结果

测试场景描述

本次测试脚本所对应的操作一次为:启动应用->输入用户名及密码->选择品牌->登陆->选择销售管理->输入店代码->开始营业->输入数据并保存->结束营业->退出.
测试中设置并发用户的数量为20个并发用户,持续运行了10分钟时间,考虑到本次测试的目的在于发现系统存在的问题，而并非模拟真实的并发量，因此将脚本中的思考时间为0，即不计入思考时间。

测试数据

测试结果表明,完成整个过程平均时间为37.26秒,下图为在运行10分钟期间，整个过程的响应时间情况。

从统计结果中来看，其中登陆操作的平均响应时间为20.193显然是性能的主要瓶颈。它消耗了54%左右的时间。下面为具体的测试数据统计列表:

Results in Session:	C:/Documents and Settings/Administrator/Local Settings/Temp/res/res.lrr
Duration:	10 minutes and 37 seconds.

Statistics Summary

Maximum Running Vusers:

20

Transaction Summary

Transactions:

Total Passed: 31,613

Total Failed: 4

Total Stopped: 30

Average Response Time

Transaction Name	Minimum	Average	Maximum	Std. Deviation	90 Percent	Pass	Fail	Stop
Action_Transaction	9.968	37.26	80.983	8.483	45.605	323	1	17
输入销售记录	0.28	3.843	21.727	2.254	5.903	327	1	5
输入店号	0.125	2.067	5.187	0.745	2.819	340	0	1
输入用户名密码	0.062	1.082	4.891	0.693	1.859	341	0	0
登陆	3.94	20.193	42.489	6.214	27.085	341	0	0
退出	0	0	0.016	0.001	0	324	0	0
menuclick_salesdailyreport	0.078	1.316	3.139	0.467	1.906	341	0	0
up_query_authorities	0	0.049	0.405	0.076	0.187	341	0	0
up_query_brand	0	0.056	5.232	0.22	0.156	669	0	0
up_query_brandAuthCheck	0	0.042	0.467	0.051	0.062	341	0	0
up_query_brandCards	0	0.047	0.734	0.073	0.172	674	0	0
up_query_brandInfo	0	0.041	0.359	0.052	0.062	341	0	0
up_query_checkStyle	0	0.059	0.562	0.092	0.187	332	1	0
up_query_dateClosing	0	0.053	0.64	0.085	0.187	665	0	0
up_query_informBoards	0	0.054	0.545	0.06	0.094	682	0	0
up_query_mailBoxDts	0.031	0.3	1.09	0.158	0.484	341	0	0
up_query_notifications	0	0.042	0.766	0.072	0.047	341	0	0
up_query_programList	0.156	1.201	3.894	0.931	2.655	341	0	0
up_query_roleProgramControls	0	0.052	0.623	0.078	0.187	341	0	0
up_query_shop	0	0.09	0.374	0.075	0.219	341	0	0
up_query_shop_inout	0.016	0.106	0.654	0.099	0.234	328	0	0
up_query_shopEmployees	0	0.054	0.436	0.078	0.172	676	0	1
up_query_shopFees	0	0.054	0.732	0.086	0.187	1,338	0	1
up_query_shopSaleDts	0	0.071	0.872	0.106	0.203	1,323	0	1
up_query_shopSalesP	0	0.065	0.75	0.082	0.187	1,675	0	1
up_query_shopSettleConfirms	0	0.051	0.578	0.076	0.172	668	0	0
up_query_shopSettlements	0.953	8.925	15.337	3.764	12.974	341	0	0
up_query_subRoles	0	0.044	0.406	0.066	0.172	341	0	0
up_query_surveys	0	0.043	0.578	0.063	0.062	341	0	0
up_query_udfTabShopRunDays	0	0.046	1.172	0.09	0.125	664	0	1
up_query_users	0	0.114	0.95	0.114	0.25	341	0	0
up_query_weatherInfo	0	0.037	0.515	0.058	0.047	328	0	0
up_save_loginHistory	0	0.059	0.872	0.111	0.078	341	0	0
up_save_shopSaleDts	0	0.058	0.406	0.071	0.187	333	0	0
up_save_shopSales	0	0.074	0.593	0.1	0.219	666	0	0
up_save_shopSalesP	0	0.048	0.592	0.076	0.172	328	0	0
vuser_end_Transaction	0	0	0	0	0	20	0	0
vuser_init_Transaction	0.001	0.001	0.004	0.001	0.001	20	0	0
MercuryFetch_0	0	0.002	0.031	0.005	0.016	341	0	0
MercuryFetch_1	0	0.004	0.172	0.011	0.016	341	0	0
MercuryFetch_10	0	0.001	0.062	0.005	0	341	0	0
MercuryFetch_11	0	0	0.016	0.001	0	341	0	0
MercuryFetch_12	0	0.002	0.047	0.006	0.016	341	0	0
MercuryFetch_13	0	0	0.016	0.001	0	341	0	0
MercuryFetch_14	0	0.004	0.187	0.012	0.016	341	0	0
MercuryFetch_15	0	0.001	0.016	0.003	0	341	0	0
MercuryFetch_16	0	0	0.016	0.002	0	341	0	0
MercuryFetch_17	0	0	0.016	0.001	0	341	0	0
MercuryFetch_18	0	0.001	0.016	0.004	0	341	0	0
MercuryFetch_19	0	0	0.016	0.001	0	341	0	0
MercuryFetch_2	0	0.001	0.016	0.003	0	341	0	0
MercuryFetch_20	0	0	0.016	0.001	0	341	0	0
MercuryFetch_21	0	0.001	0.016	0.003	0	340	0	0
MercuryFetch_22	0	0.006	0.031	0.008	0.016	337	0	0
MercuryFetch_23	0	0.003	0.016	0.006	0.016	336	0	0
MercuryFetch_24	0	0.001	0.031	0.004	0	336	0	0
MercuryFetch_25	0	0.001	0.016	0.005	0	335	0	0
MercuryFetch_26	0.047	1.028	28.14	3.219	1.822	333	0	1
MercuryFetch_27	0	0.001	0.016	0.003	0	332	1	0
MercuryFetch_28	0	0	0.016	0.001	0	333	0	0
MercuryFetch_29	0	0.001	0.016	0.004	0	333	0	0
MercuryFetch_3	0	0.001	0.016	0.004	0.002	341	0	0
MercuryFetch_30	0	0.001	0.016	0.003	0	333	0	0
MercuryFetch_31	0	0.007	0.031	0.009	0.016	332	0	0
MercuryFetch_32	0.047	0.55	9.324	1.185	1.374	329	0	1
MercuryFetch_33	0	0	0.016	0.001	0	328	0	0
MercuryFetch_34	0	0.008	1.635	0.09	0.016	328	0	0
MercuryFetch_35	0	0.001	0.016	0.003	0	328	0	0
MercuryFetch_36	0	0	0.016	0.002	0	328	0	0
MercuryFetch_37	0	0	0.016	0.002	0	324	0	0
MercuryFetch_38	0.062	0.648	26.478	2.342	1.199	324	0	0
MercuryFetch_39	0	0.001	0.016	0.003	0	324	0	0
MercuryFetch_4	0.375	5.279	23.674	4.424	10.857	341	0	0
MercuryFetch_5	0	0.003	0.047	0.007	0.016	341	0	0
MercuryFetch_6	0	0.008	0.062	0.009	0.016	341	0	0
MercuryFetch_7	0	0.007	0.062	0.009	0.016	341	0	0
MercuryFetch_8	0	0.001	0.016	0.003	0	341	0	0
MercuryFetch_9	0	0	0.016	0.002	0	341	0	0

瓶颈分析

从上述的详细结果列表中可以看出，其中存储过程up_query_shopSettlements的平均响应时间为8.925，是执行时间最长的存储过程，up_query_programList的平均响应时间为1.201秒,其他的存储过程所消耗的时间均不在秒这一数量级上,同时MercuryFetch_4的平均响应时间为5.279秒,它的含义是得到存储过程up_query_programList执行结果的时间为5.279秒,显然这也是一个较为明显的瓶颈.

性能监控及故障定位—使用spotlight

在进行压力测试的同时，使用了quest公司的spotlight, performance analysis，以及sql tuning 对性能问题产生的原因进行了跟踪和分析，一下是具体的分析结果和数据。

内存及缓冲区

从spotlight的对在压力测试进行过程中的监控结果来看，系统在运行过程中，SQL执行时候的数据缓冲区以及存储过程缓冲区命中率均较高，几乎达到100%，同时从SQL Memory以及物理磁盘的动态交互图上也对这一点也可以进行印证，SQL Servers数据库在压力测试过程中几乎不从物理磁盘上读取数据,说明在测试过程中所读取的数据都可以直接从cache中获得,进而说明数据库的内存配置是充足和高效的.下图为数据库内存配置的具体监控结果:

从总可以看出内存的使用状况稳定,缓冲区命中率很高,几乎达到100%,数据可以直接从缓存中获得,效率很高.

锁

下面我们对可能造成数据库性能效率问题的令一个问题,数据库锁进行分析和诊断.

在测试过程中,我们发现数据库在特定时刻的锁数量可能会达到一个较大的数值,如下面的截图中,抓取到的锁数量达到4000多个:

但spotlight并没有产生报警,对这些锁进行进一步的分析可以得到这些锁没有造成数据库的等待以及更为严重的死锁现象的发生.

从上图中可以看到,系统中锁的数量在峰值时可以达到几千的水平,但是从锁等待上来看,确几乎没有因为这些锁而产生等待,如下:

从上图可以看出每秒中产生的锁等待数量极少,而对锁等待的时间进行监控发现,对于这些锁事务锁需要等待的时间仅为几个毫秒.如下图
:

这说明系统运行过程中的锁并不是系统性能瓶颈产生的原因.在对锁的具体内容进行分析后,也印证了这一点,发现系统在运行过程中产生的基本上都是共享锁,而不是对性能影响严重的排它锁,更没有死锁的产生,下图是对锁具体信息的统计结果:

数据库IO

系统中存在的一个较为明显的问题是,在20个并发用户的情况下,数据库的逻辑读数量巨大,从下面的实时截图中可以看出,SQL Server每秒中需要从缓冲区中读取160000个页面的数据,而SQLServer每个页面的大小为8K,这就是说SQL Server 每秒从缓冲区中读取的数据量为:
1280M即1G左右的数据量,而同时向数据库写的数据量极少,在几个到0之间浮动,现在每秒中产生如此巨大的逻辑读是比较严重的问题.

从一个阶段的统计视图中可以看到系统的逻辑读基本维持在100000页面/秒左右,也就是说数据库的逻辑读在20个并发用户的情况下基本维持在每秒800M的读取量上.,如下图
:

通过spotlight的分析结果可以基本定位出来系统的逻辑读处于一个不正常的状态,而其他的运行指标的统计结果表明基本正常.

性能监控及故障定位—使用performance anlysis

在进行压力测试过程中,使用了performance analysis对数据库的长期运行趋势进行分析和统计,并记录存储过程的执行效率.

监控系统负载

Performance analysis 可以对系统的负载进行分析,下图为在压力测试过程中数据库服务器的负载情况.

从图示中可以看出,系统的磁盘,网络,锁 ,栓,日志,Cache等情况均教正常,只是CPU的利用率偏高,并因而产生了较多的CPU等待现象的发生.而内存虽然使用了92%,这是由于数据库配置了较多的内存,倒是系统内存消耗较多,这并不会引发任何的不正常,因此在该服务器仅作为数据库服务器来使用,因此预留8%的时间给其他应用是足够的,这样可以也可以最大的发挥数据库的处理能力.

监控存储过程性能

从上图中同样可以发现存储过程up_query_shopSettlements的执行消耗了大量的时间,通过performance analysis可以对存储过程的时间进行分解,并得到其消耗的时间是由于具体的什么原因组成的(CPU使用,ＣＰＵ等待,内存等待,锁等待,栓等待,日志等待,网络等待),从分析结果中来看存储过程up_query_shopSettlements的时间中不包含锁,栓,日志等等待时间,这与spotlight的分析结果相一致.它所消耗的时间是由CPU使用,以及CPU等待组成的.

下图是存储过程up_query_ProgramList的监控结果:

性能监控及故障定位—使用SQLTuning

下面使用sql tuning对存在问题的存储过程进行分析:

从loadrunner得到的结果中我们可以知道问题最为严重的存储过程为: up_query_shopSettlements,使用quest的工具对这个存储过程的执行规划以及IO情况进行详细的分析.

在SQLTuning中运行这个存储过程,得到该存储过程的执行规划,发现其中的4个索引查询几乎占据了系统的全部时间,如下图:

但是可以发现,四个最消耗时间的查询均使用了索引,而且为速度最快的seek方式,说明查询均使用效率较高的索引的seek方式直接定位到数据.下面对该存储过程使用的IO进行分析:

从上图中看到,该存储过程对表shop_acc_receivables进行了大量的逻辑读,达到130000个页面,也就是说该存储过程仅运行一次从数据库的缓冲池中读了1G的数据量,并且对表的扫描次数达到65000次,这显然是一个不合理的值.

这里我们做了一个试验,如果对执行一条select * from shop_acc_receivables语句那么对IO的访问是:

从上图中可以看到运行一个全表查询,逻辑读的数量仅仅为100左右,显然上述存储过程的执行存在很不合理的地方.

而对另外一个问题存储过程(up_query_programList @sub_role_code='91'
)的分析,结果也类似.存储过程的时间消耗在通过索引进行的查询上:

而存储过程运行是进行了巨大的逻辑读:

优化试验及结果比对

下面我们对问题进行了仅一步的追踪,
存储过程:up_query_shopSettlements @typ='H',@brand_code='',"
"@branch_code='',@sales_date=?,根据输入的参数执行的SQL语句实际为:
select sum(isnull(a.invoice_amt,0)) amt

from(

select distinct a.brand_code,a.shop_code,a.yyyymm,a.settle_seq,a.invoice_amt

from shop_settlements a left outer join shop_acc_receivables b on a.brand_code = b.brand_code and a.shop_code = b.shop_code

and a.yyyymm = b.yyyymm and a.settle_seq = b.settle_seq and b.receive_date <= @sales_date

left outer join sales_orgs c on a.brand_code = c.brand_code and a.shop_code = c.shop_code

left outer join shop_settle_confirms d on a.brand_code = d.brand_code and a.shop_code = d.shop_code

and a.yyyymm = d.yyyymm and a.settle_seq = d.settle_seq

-- yleehb : 20070702

-- INNER JOIN authority_branches f ON e.branch_code = f.branch_code

-- AND f.user_id = 'yleehb'

-- LEFT OUTER JOIN view_all_shops e ON a.brand_code = e.brand_code AND a.shop_code = e.shop_code

-- INNER JOIN branch_offices g ON e.branch_code = g.branch_code AND sales_yn = 1

where a.brand_code like rtrim(ltrim(@brand_code))

and c.branch_code like rtrim(ltrim(@branch_code))

and a.yyyymm >='200601'

and dateadd(dd, 5, a.pre_receive_date) <= @sales_date

and b.settle_seq is null

and d.settle_seq is not null

) a

根据存储过程的执行逻辑,我们把@brand_code,@branch_code,@sales_date三个参数分别替换为’%’,’%’,以及’2007-07-02’,发现运行时候的IO数量急剧减少,进为数百,下降了3个数量级.经过进一步的分析,发现如果直接将存储过程中的参数@brand_code,@branch_code替换为’%”,而不是通过存储过程声明体中通过语句:

IF @brand_code = ''

SET @brand_code = '%'

IF @branch_code = ''

SET @branch_code = '%' 进行赋值,那么性能就会大幅度的提高.

为进行验证,在对该存储过程中的@typ='H’部门进行参数的直接赋值后,重新进行压力测试,发现该存储过程在20个并发用户的情况下,响应时间降为了:2.326秒,该存储过程在修改前后的响应时间图分别如下:

结论

在本次测试中，通过压力测试，发现了目前系统的瓶颈的位置所在，并使用了Quest Center for SQLServer的一系列工具进行了性能的监控以及性能故障的分析和定位。
通过结果的分析，我们得到目前系统中登陆是较为明显的性能瓶颈，通过对压力测试结果的分析，得到了存储过程up_query_shopSettlements，up_query_programList地执行是执行速度最慢的存储过程，而获取up_query_programList的结果集同样消耗了较多的时间。
通过监控和追踪工具发现，系统在内存，缓存，锁，Session等方面运行均正常，而在IO方面存在巨大的逻辑读写，而使用SQL Tuning分析工具同样证明了执行速度最慢的存储过程在运行过程中产生了大量的逻辑读，而这些逻辑读都是使用了索引，并非是索引的配置问题。在进一步的分析下，对up_query_shopSettlements进行了参数调用方式的修改后，在得到同样查询结果的情况下，逻辑读下降了3个数量级，响应时间也下降为原来的1/4，性能得到了提升。同时在测试过程中使用了Performance Analysis它可以监控到每个存储过程的执行情况,以及整个系统的负载情况。