1. 客户环境
操作系统:HP
数据库版本:Oracle Database 10.2.0.5
2. 问题描述
用户数据库系统2015年3月19日1点到2015年3月19日1点22分,数据库响应非常缓慢。
3. 数据库检查
3.1 查询1点至2点每分钟的数据库事物数量
点击(此处)折叠或打开
- select to_char(SAMPLE_TIME, 'yyyy-mm-dd hh24:mi'), count(*)
- from dba_hist_active_sess_history
- where snap_id >= 34592
- and snap_id <= 34593
- group by to_char(SAMPLE_TIME, 'yyyy-mm-dd hh24:mi')
- order by 1;
-
- 2015-03-18 23:59 7
- 2015-03-19 00:00 72
- 2015-03-19 00:01 161
- 2015-03-19 00:02 79
- 2015-03-19 00:03 78
- 2015-03-19 00:04 79
- 2015-03-19 00:05 105
- 2015-03-19 00:06 69
- 2015-03-19 00:07 74
- 2015-03-19 00:08 71
- 2015-03-19 00:09 75
- 2015-03-19 00:10 81
- 2015-03-19 00:11 158
- 2015-03-19 00:12 87
- 2015-03-19 00:13 69
- 2015-03-19 00:14 61
- 2015-03-19 00:15 64
- 2015-03-19 00:16 77
- 2015-03-19 00:17 67
- 2015-03-19 00:18 74
- 2015-03-19 00:19 90
- 2015-03-19 00:20 84
- 2015-03-19 00:21 106
- 2015-03-19 00:22 84
- 2015-03-19 00:23 79
- 2015-03-19 00:24 71
- 2015-03-19 00:25 120
- 2015-03-19 00:26 68
- 2015-03-19 00:27 96
- 2015-03-19 00:28 71
- 2015-03-19 00:29 67
- 2015-03-19 00:30 77
- 2015-03-19 00:31 75
- 2015-03-19 00:32 53
- 2015-03-19 00:33 72
- 2015-03-19 00:34 69
- 2015-03-19 00:35 88
- 2015-03-19 00:36 86
- 2015-03-19 00:37 98
- 2015-03-19 00:38 76
- 2015-03-19 00:39 83
- 2015-03-19 00:40 82
- 2015-03-19 00:41 108
- 2015-03-19 00:42 59
- 2015-03-19 00:43 65
- 2015-03-19 00:44 63
- 2015-03-19 00:45 49
- 2015-03-19 00:46 56
- 2015-03-19 00:47 114
- 2015-03-19 00:48 71
- 2015-03-19 00:49 89
- 2015-03-19 00:50 97
- 2015-03-19 00:51 55
- 2015-03-19 00:52 76
- 2015-03-19 00:53 80
- 2015-03-19 00:54 66
- 2015-03-19 00:55 89
- 2015-03-19 00:56 106
- 2015-03-19 00:57 75
- 2015-03-19 00:58 101
- 2015-03-19 00:59 99
- 2015-03-19 01:00 313
- 2015-03-19 01:01 296
- 2015-03-19 01:02 381
- 2015-03-19 01:03 496
- 2015-03-19 01:04 713
- 2015-03-19 01:05 929
- 2015-03-19 01:06 1074
- 2015-03-19 01:07 1146
- 2015-03-19 01:08 1317
- 2015-03-19 01:09 1399
- 2015-03-19 01:10 1649
- 2015-03-19 01:11 1827
- 2015-03-19 01:12 2031
- 2015-03-19 01:13 2133
- 2015-03-19 01:14 2281
- 2015-03-19 01:15 2421
- 2015-03-19 01:16 2117
- 2015-03-19 01:17 2637
- 2015-03-19 01:18 2880
- 2015-03-19 01:19 3072
- 2015-03-19 01:20 3203
- 2015-03-19 01:21 3319
- 2015-03-19 01:22 1746
- 2015-03-19 01:23 140
- 2015-03-19 01:24 170
- 2015-03-19 01:25 122
- 2015-03-19 01:26 97
- 2015-03-19 01:27 104
- 2015-03-19 01:28 133
- 2015-03-19 01:29 100
- 2015-03-19 01:30 119
- 2015-03-19 01:31 109
- 2015-03-19 01:32 93
- 2015-03-19 01:33 122
- 2015-03-19 01:34 95
- 2015-03-19 01:35 111
- 2015-03-19 01:36 96
- 2015-03-19 01:37 131
- 2015-03-19 01:38 261
- 2015-03-19 01:39 302
- 2015-03-19 01:40 293
- 2015-03-19 01:41 182
- 2015-03-19 01:42 101
- 2015-03-19 01:43 100
- 2015-03-19 01:44 105
- 2015-03-19 01:45 327
- 2015-03-19 01:46 108
- 2015-03-19 01:47 111
- 2015-03-19 01:48 104
- 2015-03-19 01:49 118
- 2015-03-19 01:50 118
- 2015-03-19 01:51 86
- 2015-03-19 01:52 119
- 2015-03-19 01:53 102
- 2015-03-19 01:54 119
- 2015-03-19 01:55 88
- 2015-03-19 01:56 109
- 2015-03-19 01:57 87
- 2015-03-19 01:58 80
- 2015-03-19 01:59 73
分析: 2015-03-19 01:00 至 2015-03-19 01:22 发生等待次数较多SQL_ID
3.2 进一步分析1点至1点22分等待事件
点击(此处)折叠或打开
- select * from (select sql_id,event, count(*) cnt
- from dba_hist_active_sess_history
- where snap_id >= 34592
- and snap_id <= 34593
- and to_char(SAMPLE_TIME, 'yyyy-mm-dd hh24:mi')>'2015-03-19 01:00'
- and to_char(SAMPLE_TIME, 'yyyy-mm-dd hh24:mi')<'2015-03-19 01:22'
- group by sql_id,event
- order by 3 desc) where rownum<30;
-
- SQL_ID EVENT CNT
- ------------- ---------------------------------------------------------------- ----------
- 0ggty2d2d96qn enq: TX - row lock contention 14319
- fkjwrr2ax004g latch: cache buffers chains 8851
- fkjwrr2ax004g gc buffer busy 7076
- fkjwrr2ax004g wait list latch free 735
- fkjwrr2ax004g latch: row cache objects 587
- fkjwrr2ax004g 224
- log file sync 210
- Backup: sbtwrite2 167
- 123
- 7g3xvq43j0rns 86
- log file parallel write 72
- 79t4hx5nx9bu6 db file sequential read 68
- grwfx6xbcnh39 55
- SQL*Net message from dblink 42
- 520mkxqpf15q8 38
- 1u209u2t2d7fd db file scattered read 36
- 7xbdhjbn3x96q 35
- d7g1p6925bps5 db file scattered read 30
- 2m7w0gv9v0hpb 28
- fkjwrr2ax004g buffer busy waits 27
- 55hk4qa068nku 24
- 1t5mrg4njz5jj 23
- cursor: pin S 20
- 520mkxqpf15q8 cursor: pin S 14
- bqju3yc59quzb 14
- fkjwrr2ax004g gc current block 2-way 14
- 1nwwqwc0qay94 enq: TX - row lock contention 14
- 3j66afaz3n3s9 gc current block 2-way 14
- dgkwa1zp9fxwk SQL*Net message from dblink 13
分析: 等待事件较高sql为0ggty2d2d96qn(select for update)/ fkjwrr2ax004g(insert into porthistory)
3.3 进一步分析awr报告
点击(此处)折叠或打开
- Sql_id 79t4hx5nx9bu6
- DELETE FROM PORTHISTORY WHERE TIMEKEY < TO_CHAR(TRUNC(SYSDATE) - 120, 'YYYYMMDDHH24MISS')
分析: 单次执行时间1307.13秒,接近22分钟
3.4 抓取执行计划分析
点击(此处)折叠或打开
- SQL> select * from table(dbms_xplan.display_awr('79t4hx5nx9bu6'));
-
- PLAN_TABLE_OUTPUT
- --------------------------------------------------------------------------------------------
- SQL_ID 79t4hx5nx9bu6
- --------------------
- DELETE FROM PORTHISTORY WHERE TIMEKEY < TO_CHAR(TRUNC(SYSDATE) - 120,
- 'YYYYMMDDHH24MISS')
-
- Plan hash value: 1650323717
- ---------------------------------------------------------------------------------
- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
- ---------------------------------------------------------------------------------
- | 0 | DELETE STATEMENT | | | | 85528 (100)| |
- | 1 | DELETE | PORTHISTORY | | | | |
- | 2 | INDEX SKIP SCAN| PORTHISTORY_PK | 426K | 13M | 85528 (1)| 00:17:07 |
- ---------------------------------------------------------------------------------
-
- SQL_ID 79t4hx5nx9bu6
- --------------------
- DELETE FROM PORTHISTORY WHERE TIMEKEY < TO_CHAR(TRUNC(SYSDATE) - 120,
- 'YYYYMMDDHH24MISS')
-
- Plan hash value: 3989602834
-
- ----------------------------------------------------------------------------------
- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
- ----------------------------------------------------------------------------------
- | 0 | DELETE STATEMENT | | | | 49551 (100)| |
- | 1 | DELETE | PORTHISTORY | | | | |
- | 2 | INDEX FULL SCAN | PORTHISTORY_PK | 568K | 17M | 49551 (1)| 00:09:55 |
- ----------------------------------------------------------------------------------
-
- 30 rows selected.
分析: 有多个版本执行计划
3.5 查看sql执行计划版本变化时间
点击(此处)折叠或打开
- select sql_id,plan_hash_value,to_char(timestamp,\'yyyy-mm-dd hh24:mi:ss\') from dba_hist_sql_plan where sql_id=\'79t4hx5nx9bu6\'
-
- 79t4hx5nx9bu6 1650323717 2015-02-14 17:38:45
- 79t4hx5nx9bu6 1650323717 2015-02-14 17:38:45
- 79t4hx5nx9bu6 1650323717 2015-02-14 17:38:45
- 79t4hx5nx9bu6 3989602834 2015-02-15 16:39:31
- 79t4hx5nx9bu6 3989602834 2015-02-15 16:39:31
- 79t4hx5nx9bu6 3989602834 2015-02-15 16:39:31
分析: sql执行计划最新版本为3989602834
4. 操作过程
4.1分析所用到索引
点击(此处)折叠或打开
- SQL> analyze index fabadm.porthistory_pk validate structure;
-
- Index analyzed.
-
- SQL> select t.name,
- 2 t.lf_rows, --number of leaf rows (values in the index)
- 3 t.lf_blks,
- 4 t.del_lf_rows, --number of deleted leaf rows in the index
- 5 (t.del_lf_rows / t.lf_rows)*100 ratio
- 6 from index_stats t
- 7 where t.name=\'PORTHISTORY_PK\';
-
- NAME LF_ROWS LF_BLKS DEL_LF_ROWS RATIO
- ------------------------------ ---------- ---------- ----------- ----------
- PORTHISTORY_PK 18031455 251171 51533 .285795018
分析: 索引不存在碎片化
4.1 重新收集统计信息,保证执行计划准确性
点击(此处)折叠或打开
- BEGIN
- DBMS_STATS.GATHER_TABLE_STATS(ownname => 'FABADM',
- tabname => 'PORTHISTORY',
- estimate_percent => 60,
- method_opt => 'for all columns size repeat',
- no_invalidate => FALSE,
- degree => 4,
- granularity => 'ALL',
- cascade => TRUE);
- END;
- /
5. 总结
1. 分析
1点至2点每分钟的等待事件,主要在01:00 至 01:22 产生大量等待
2 2、进一步分析,查询1点至1点22产生等待sql_id为0ggty2d2d96qn/ fkjwrr2ax004g
3、了解业务进一步分析,首先select for update锁定数据,inert 到porthistory并成功提交后释放锁
4. 综合awr分析可能由于delete删除造成此次响应较慢问题, SQL_ID: 79t4hx5nx9bu6 DELETE FROM PORTHISTORY WHERE TIMEKEY < TO_CHAR(TRUNC(SYSDATE) - 120,'YYYYMMDDHH24MISS'),执行时间为1307秒,正好接近22分钟,也就是业务缓慢时间段
已经对表收集统计信息,并把索引rebuild
来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/29990276/viewspace-1471380/,如需转载,请注明出处,否则将追究法律责任。
转载于:http://blog.itpub.net/29990276/viewspace-1471380/