Question:某客户的应用做过变更（短链变长链），现cpu利用率较之前有明显改善，参见附件中的awr报告。想咨询一下sql语句的执行时间，cpu Time等指标，是否会受到短链变长链影响，因为从awr报告看，性能有明显改善。
Load Profile
变更前:
| Per Second | Per Transaction | |
|---|---|---|
| Redo size: | 244,606.59 | 13,269.94 |
| Logical reads: | 5,964.59 | 323.58 |
| Block changes: | 1,278.41 | 69.35 |
| Physical reads: | 339.03 | 18.39 |
| Physical writes: | 35.30 | 1.92 |
| User calls: | 693.44 | 37.62 |
| Parses: | 241.46 | 13.10 |
| Hard parses: | 0.16 | 0.01 |
| Sorts: | 97.93 | 5.31 |
| Logons: | 16.05 | 0.87 |
| Executes: | 617.55 | 33.50 |
| Transactions: | 18.43 |
变更后:
| Per Second | Per Transaction | |
|---|---|---|
| Redo size: | 314,037.68 | 4,249.08 |
| Logical reads: | 7,939.19 | 107.42 |
| Block changes: | 1,629.35 | 22.05 |
| Physical reads: | 221.23 | 2.99 |
| Physical writes: | 41.85 | 0.57 |
| User calls: | 1,005.17 | 13.60 |
| Parses: | 76.15 | 1.03 |
| Hard parses: | 0.16 | 0.00 |
| Sorts: | 37.36 | 0.51 |
| Logons: | 0.36 | 0.00 |
| Executes: | 810.16 | 10.96 |
| Transactions: | 73.91 |
Top 5 Timed Events
变更前:
| Event | Waits | Time(s) | Avg Wait(ms) | % Total Call Time | Wait Class |
|---|---|---|---|---|---|
| CPU time | 2,430 | 68.6 | |||
| db file sequential read | 84,286 | 416 | 5 | 11.7 | User I/O |
| log file sync | 63,773 | 266 | 4 | 7.5 | Commit |
| db file scattered read | 74,972 | 235 | 3 | 6.6 | User I/O |
| enq: TX – row lock contention | 463 | 229 | 494 | 6.5 | Application |
变更后:
| Event | Waits | Time(s) | Avg Wait(ms) | % Total Call Time | Wait Class |
|---|---|---|---|---|---|
| CPU time | 1,661 | 74.0 | |||
| log file sync | 167,658 | 473 | 3 | 21.1 | Commit |
| db file sequential read | 91,101 | 411 | 5 | 18.3 | User I/O |
| wait for scn ack | 145,796 | 142 | 1 | 6.3 | Other |
| log file parallel write | 166,143 | 121 | 1 | 5.4 | System I/O |
Time Model Statistics
变更前:
| Statistic Name | Time (s) | % of DB Time |
|---|---|---|
| sql execute elapsed time | 2,603.73 | 73.47 |
| DB CPU | 2,430.37 | 68.58 |
| connection management call elapsed time | 511.90 | 14.45 |
| parse time elapsed | 163.60 | 4.62 |
| PL/SQL execution elapsed time | 84.88 | 2.40 |
| hard parse elapsed time | 27.08 | 0.76 |
| sequence load elapsed time | 17.88 | 0.50 |
| hard parse (sharing criteria) elapsed time | 0.01 | 0.00 |
| repeated bind elapsed time | 0.00 | 0.00 |
| DB time | 3,543.74 | |
| background elapsed time | 513.68 | |
| background cpu time | 351.72 |
变更后:
| Statistic Name | Time (s) | % of DB Time |
|---|---|---|
| DB CPU | 1,661.42 | 74.02 |
| sql execute elapsed time | 1,558.64 | 69.44 |
| PL/SQL execution elapsed time | 66.66 | 2.97 |
| parse time elapsed | 37.24 | 1.66 |
| hard parse elapsed time | 15.09 | 0.67 |
| connection management call elapsed time | 8.37 | 0.37 |
| sequence load elapsed time | 3.53 | 0.16 |
| PL/SQL compilation elapsed time | 0.49 | 0.02 |
| hard parse (sharing criteria) elapsed time | 0.08 | 0.00 |
| failed parse elapsed time | 0.08 | 0.00 |
| repeated bind elapsed time | 0.00 | 0.00 |
| DB time | 2,244.66 | |
| background elapsed time | 669.28 | |
| background cpu time | 382.82 |
性能分析:
从这2个awr报告对比来看修改为长连接后单位小时的CPU TIME与DB TIME均有所下降，CPU TIME从原来的2430s下降到1661s,降幅为769s。但分析2个报告中的每秒逻辑读可以发现修改为长连接后的逻辑读反而增加了。CPU TIME主要可以分为parse cpu,execute cpu和fetch cpu。短连接时一小时的parse time即解析时间为163s；另外因为短连接时每秒登录数达到16个，Oracle为建立连接(connection management call)耗时511s。
总结以下几点:
1.短连接情况下因为新建立的会话没有缓存游标信息，进而导致无法避免大量的软解析，解析消耗了163s的DB TIME。修改为长连接后解析数量明显减少，解析仅消耗37s的DB TIME。
2.短连接情况下每秒登录数达到16次，建立连接(connection)同样会消耗大量的CPU TIME，这里connection management call消耗了约500s的CPU TIME。修改为长连接后每秒Logons数为0.36，节约了大量无谓的CPU浪费。
3.改为长连接后Top SQL的平均每次逻辑读并未下降，部分Top SQL的执行次数还有所增加；可见通过减少不必要的解析和反复建立连接，系统的性能得到了释放
4.原短连接的AWR报告中显示该时段内出现行锁等待(row lock contention)共463次，总耗时为229s,该等待事件也是造成2个报告中DB TIME差异的一个因素。而长连接报告中则没有该等待出现，这可能是出于偶然，也可能是程序修改导致的。
Comment