7号接到同事电话说一个olap数据库,数据量大概3T,在跑脚本的时候truncate表非常慢,有的一个小时还没完成。查下等待事件发现很多的enq: TX - row lock contention事件
我试试命令一发起就在等待这个事件'enq: RO - fast object reuse' 然后很快又变成enq: TX - row lock contention
SQL> @session_wait
SEQ# SIDS SQL_HASH_VALUE USERNAME EVENT P1 P1RAW P2 P3 WAIT STATE SEC STATUS LOGON_TIME
---------- --------------- -------------- --------------- ------------------------------ ---------- ---------------- ---------- ---------- ---------- ------------------- ---------- -------- -----------
61275 232,13690 0 SYS Backup: sbtbackup 0 00 0 0 0 WAITING 6439 ACTIVE 06/20:03:46
53842 204,43688 647275908 AWPOPR db file sequential read 266 000000000000010A 821048 1 0 WAITING 1 ACTIVE 29/19:34:51
8671 251,30579 647275908 AWPOPR db file sequential read 266 000000000000010A 2535727 1 0 WAITING 0 ACTIVE 29/19:34:51
52934 168,57598 647275908 AWPOPR db file sequential read 266 000000000000010A 2533259 1 0 WAITING 0 ACTIVE 06/20:20:10
32991 206,38461 647275908 AWPOPR db file sequential read 266 000000000000010A 360791 1 0 WAITING 1 ACTIVE 06/22:30:40
55312 308,63502 647275908 AWPOPR db file sequential read 266 000000000000010A 2033288 1 0 WAITING 1 ACTIVE 06/23:59:40
23250 155,35338 647275908 AWPOPR db file sequential read 266 000000000000010A 2480900 1 0 WAITING 1 ACTIVE 07/00:05:46
37058 141,23338 829113447 AWPOPR db file sequential read 255 00000000000000FF 173045 1 0 WAITING 1 ACTIVE 06/20:40:10
60044 131,1196 2115648383 DCPPOPR db file sequential read 245 00000000000000F5 1594364 1 0 WAITING 0 ACTIVE 07/07:02:48
45453 196,26528 2563985644 AWPOPR db file sequential read 266 000000000000010A 1265517 1 0 WAITING 1 ACTIVE 29/19:33:30
41300 239,12487 2563985644 AWPOPR db file sequential read 266 000000000000010A 1214173 1 0 WAITING 1 ACTIVE 29/19:33:30
27403 127,24118 2563985644 AWPOPR db file sequential read 266 000000000000010A 2492427 1 0 WAITING 1 ACTIVE 06/21:20:10
45458 161,47381 3701837625 AWPOPR db file sequential read 259 0000000000000103 1525686 1 0 WAITING 0 ACTIVE 07/05:11:19
379 163,21087 2180602573 LIZHONGYUAN002 enq: RO - fast object reuse 1380909062 00000000524F0006 65701 1 0 WAITING 7 ACTIVE 07/06:33:17
17542 126,54811 1669410309 DBQUA enq: TX - contention 1415053316 0000000054580004 262176 12403957 0 WAITING 239 ACTIVE 07/03:00:00
25603 262,50636 829113447 AWPOPR enq: TX - row lock contention 1415053318 0000000054580006 1114116 4377148 0 WAITING 25472 ACTIVE 06/20:40:10
26491 375,18665 3701837625 AWPOPR enq: TX - row lock contention 1415053318 0000000054580006 2228247 1090731 0 WAITING 6178 ACTIVE 06/21:20:10
42884 180,16791 3701837625 AWPOPR enq: TX - row lock contention 1415053318 0000000054580006 2228247 1090731 0 WAITING 6178 ACTIVE 06/22:00:10
61626 351,10551 3701837625 AWPOPR enq: TX - row lock contention 1415053318 0000000054580006 2228247 1090731 0 WAITING 6178 ACTIVE 07/05:25:00
56220 157,7248 3701837625 AWPOPR enq: TX - row lock contention 1415053318 0000000054580006 2228247 1090731 0 WAITING 6178 ACTIVE 07/05:25:05
57943 197,62006 3701837625 AWPOPR enq: TX - row lock contention 1415053318 0000000054580006 2228247 1090731 0 WAITING 6178 ACTIVE 07/05:25:08
56362 252,34959 3701837625 AWPOPR enq: TX - row lock contention 1415053318 0000000054580006 2228247 1090731 0 WAITING 6178 ACTIVE 07/05:25:09
61399 348,40460 3701837625 AWPOPR enq: TX - row lock contention 1415053318 0000000054580006 2228247 1090731 0 WAITING 6178 ACTIVE 07/05:25:09
9 117,52307 0 SYS i/o slave wait 1.38350580 C0000000F81E4BD0 0 0 0 WAITING 10588 ACTIVE 06/20:03:01
10 218,46643 0 SYS i/o slave wait 1.38350580 C0000000EAFB33B0 0 0 0 WAITING 18657 ACTIVE 06/20:03:52
22152 231,27263 0 SYS imm op 1.38350580 C0000000F81CA218 0 0 0 WAITING 6440 ACTIVE 06/20:03:46
947 166,3242 506364182 DCPPOPR local write wait 53 0000000000000035 699785 0 0 WAITING 5 ACTIVE 07/06:56:52
931 124,30785 1677860569 DCPPOPR local write wait 238 00000000000000EE 101897 0 0 WAITING 2 ACTIVE 07/06:55:10
530 177,28915 4248312840 DCPPOPR local write wait 152 0000000000000098 724618 0 0 WAITING 5 ACTIVE 07/07:00:15
5574 360,2158 647275908 AWPOPR read by other session 266 000000000000010A 2533259 1 0 WAITING 0 ACTIVE 29/19:33:30
30 rows selected
SQL> @session_wait
SEQ# SIDS SQL_HASH_VALUE USERNAME EVENT P1 P1RAW P2 P3 WAIT STATE SEC STATUS LOGON_TIME
---------- --------------- -------------- --------------- ------------------------------ ---------- ---------------- ---------- ---------- ---------- ------------------- ---------- -------- -----------
61275 232,13690 0 SYS Backup: sbtbackup 0 00 0 0 0 WAITING 6469 ACTIVE 06/20:03:46
59315 204,43688 647275908 AWPOPR db file sequential read 266 000000000000010A 582916 1 0 WAITING 0 ACTIVE 29/19:34:51
58706 168,57598 647275908 AWPOPR db file sequential read 266 000000000000010A 1658986 1 0 WAITING 0 ACTIVE 06/20:20:10
60751 308,63502 647275908 AWPOPR db file sequential read 266 000000000000010A 625000 1 0 WAITING 0 ACTIVE 06/23:59:40
28536 155,35338 647275908 AWPOPR db file sequential read 266 000000000000010A 1291063 1 0 WAITING 0 ACTIVE 07/00:05:46
44926 141,23338 829113447 AWPOPR db file sequential read 115 0000000000000073 62004 1 0 WAITING 0 ACTIVE 06/20:40:10
5977 131,1196 2115648383 DCPPOPR db file sequential read 239 00000000000000EF 1503713 1 0 WAITING 0 ACTIVE 07/07:02:48
49435 196,26528 2563985644 AWPOPR db file sequential read 266 000000000000010A 1291437 1 0 WAITING 0 ACTIVE 29/19:33:30
31744 127,24118 2563985644 AWPOPR db file sequential read 266 000000000000010A 968780 1 0 WAITING 0 ACTIVE 06/21:20:10
53930 161,47381 3701837625 AWPOPR db file sequential read 256 0000000000000100 874606 1 0 WAITING 0 ACTIVE 07/05:11:19
17542 126,54811 1669410309 DBQUA enq: TX - contention 1415053316 0000000054580004 262176 12403957 0 WAITING 269 ACTIVE 07/03:00:00
25603 262,50636 829113447 AWPOPR enq: TX - row lock contention 1415053318 0000000054580006 1114116 4377148 0 WAITING 25502 ACTIVE 06/20:40:10
26491 375,18665 3701837625 AWPOPR enq: TX - row lock contention 1415053318 0000000054580006 2228247 1090731 0 WAITING 6208 ACTIVE 06/21:20:10
42884 180,16791 3701837625 AWPOPR enq: TX - row lock contention 1415053318 0000000054580006 2228247 1090731 0 WAITING 6208 ACTIVE 06/22:00:10
61626 351,10551 3701837625 AWPOPR enq: TX - row lock contention 1415053318 0000000054580006 2228247 1090731 0 WAITING 6208 ACTIVE 07/05:25:00
56220 157,7248 3701837625 AWPOPR enq: TX - row lock contention 1415053318 0000000054580006 2228247 1090731 0 WAITING 6208 ACTIVE 07/05:25:05
57943 197,62006 3701837625 AWPOPR enq: TX - row lock contention 1415053318 0000000054580006 2228247 1090731 0 WAITING 6208 ACTIVE 07/05:25:08
56362 252,34959 3701837625 AWPOPR enq: TX - row lock contention 1415053318 0000000054580006 2228247 1090731 0 WAITING 6208 ACTIVE 07/05:25:09
61399 348,40460 3701837625 AWPOPR enq: TX - row lock contention 1415053318 0000000054580006 2228247 1090731 0 WAITING 6208 ACTIVE 07/05:25:09
11338 360,2158 647275908 AWPOPR free buffer waits 258 0000000000000102 1099710 23 0 WAITING 0 ACTIVE 29/19:33:30
14299 251,30579 647275908 AWPOPR free buffer waits 255 00000000000000FF 981633 23 0 WAITING 0 ACTIVE 29/19:34:51
38508 206,38461 647275908 AWPOPR free buffer waits 259 0000000000000103 1697855 23 0 WAITING 0 ACTIVE 06/22:30:40
44995 239,12487 2563985644 AWPOPR free buffer waits 266 000000000000010A 2537838 23 0 WAITING 0 ACTIVE 29/19:33:30
34877 339,42201 3366597220 DCPPOPR free buffer waits 187 00000000000000BB 404488 23 0 WAITING 0 ACTIVE 07/06:43:21
9 117,52307 0 SYS i/o slave wait 1.38350580 C0000000F81E4BD0 0 0 0 WAITING 10618 ACTIVE 06/20:03:01
10 218,46643 0 SYS i/o slave wait 1.38350580 C0000000EAFB33B0 0 0 0 WAITING 18687 ACTIVE 06/20:03:52
22152 231,27263 0 SYS imm op 1.38350580 C0000000F81CA218 0 0 0 WAITING 6470 ACTIVE 06/20:03:46
960 166,3242 506364182 DCPPOPR local write wait 123 000000000000007B 737929 0 0 WAITING 1 ACTIVE 07/06:56:52
942 124,30785 1677860569 DCPPOPR local write wait 240 00000000000000F0 100618 0 0 WAITING 8 ACTIVE 07/06:55:10
392 163,21087 2180602573 LIZHONGYUAN002 local write wait 147 0000000000000093 748553 0 0 WAITING 3 ACTIVE 07/06:33:17
543 177,28915 4248312840 DCPPOPR local write wait 155 000000000000009B 718602 0 0 WAITING 3 ACTIVE 07/07:00:15
31 rows selected
SQL>
查下文档发现这个等待事件跟ckpt进程有关,检查所有redo发现都是active的手动checkpoint之后,redo都变成inactive,这两个等待就没了,数据库truncate也正常了
SQL> select * from v$log;
GROUP# THREAD# SEQUENCE# BYTES MEMBERS ARCHIVED STATUS FIRST_CHANGE# FIRST_TIME
---------- ---------- ---------- ---------- ---------- -------- ---------------- ------------- -----------
1 1 895398 157286400 1 YES ACTIVE 8403339048809 8/7/2010 7:
2 1 895402 157286400 1 YES ACTIVE 8403339118031 8/7/2010 7:
3 1 895403 157286400 1 YES ACTIVE 8403339135425 8/7/2010 7:
4 1 895404 157286400 1 YES ACTIVE 8403339153332 8/7/2010 7:
5 1 895405 157286400 1 YES ACTIVE 8403339170837 8/7/2010 7:
6 1 895409 157286400 1 NO CURRENT 8403339245209 8/7/2010 7:
7 1 895406 157286400 1 YES ACTIVE 8403339188372 8/7/2010 7:
8 1 895407 157286400 1 YES ACTIVE 8403339206298 8/7/2010 7:
9 1 895408 157286400 1 YES ACTIVE 8403339226345 8/7/2010 7:
10 1 895394 157286400 1 YES INACTIVE 8403338985252 8/7/2010 7:
11 1 895395 157286400 1 YES ACTIVE 8403339001243 8/7/2010 7:
12 1 895396 157286400 1 YES ACTIVE 8403339016879 8/7/2010 7:
13 1 895397 157286400 1 YES ACTIVE 8403339032606 8/7/2010 7:
14 1 895399 157286400 1 YES ACTIVE 8403339065860 8/7/2010 7:
15 1 895400 157286400 1 YES ACTIVE 8403339082549 8/7/2010 7:
16 1 895401 157286400 1 YES ACTIVE 8403339101354 8/7/2010 7:
16 rows selected
SQL> alter system checkpoint;
System altered
SQL> select * from v$log;
GROUP# THREAD# SEQUENCE# BYTES MEMBERS ARCHIVED STATUS FIRST_CHANGE# FIRST_TIME
---------- ---------- ---------- ---------- ---------- -------- ---------------- ------------- -----------
1 1 895398 157286400 1 YES INACTIVE 8403339048809 8/7/2010 7:
2 1 895402 157286400 1 YES INACTIVE 8403339118031 8/7/2010 7:
3 1 895403 157286400 1 YES INACTIVE 8403339135425 8/7/2010 7:
4 1 895404 157286400 1 YES INACTIVE 8403339153332 8/7/2010 7:
5 1 895405 157286400 1 YES INACTIVE 8403339170837 8/7/2010 7:
6 1 895409 157286400 1 YES INACTIVE 8403339245209 8/7/2010 7:
7 1 895406 157286400 1 YES INACTIVE 8403339188372 8/7/2010 7:
8 1 895407 157286400 1 YES INACTIVE 8403339206298 8/7/2010 7:
9 1 895408 157286400 1 YES INACTIVE 8403339226345 8/7/2010 7:
10 1 895410 157286400 1 YES ACTIVE 8403339261816 8/7/2010 7:
11 1 895411 157286400 1 NO CURRENT 8403339279588 8/7/2010 7:
12 1 895396 157286400 1 YES INACTIVE 8403339016879 8/7/2010 7:
13 1 895397 157286400 1 YES INACTIVE 8403339032606 8/7/2010 7:
14 1 895399 157286400 1 YES INACTIVE 8403339065860 8/7/2010 7:
15 1 895400 157286400 1 YES INACTIVE 8403339082549 8/7/2010 7:
16 1 895401 157286400 1 YES INACTIVE 8403339101354 8/7/2010 7:
16 rows selected
事后分析这应该是oracle 的增量检查点在作怪,由于晚上数据库中有大量大的事务,本来数据库应该在switch logfile的事后checkpoint,但是由于增量checkpoint的原因数据库一直没有完全刷新log buffer,造成log buffer满,redo都显示active状态。此时手动checkpoint,把高速缓存中的数据全部写入到磁盘。
有关检查点的相信信息请参考:http://space.itpub.net/15779287/viewspace-671350
来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/15779287/viewspace-671348/,如需转载,请注明出处,否则将追究法律责任。
转载于:http://blog.itpub.net/15779287/viewspace-671348/