故障处理：troubleshooting high buffer gets in insert into … values …
我们的文章会在微信公众号IT民工的龙马人生和博客网站( www.htz.pw )同步更新 ，欢迎关注收藏，也欢迎大家转载，但是请在文章开始地方标注文章出处，谢谢！
由于博客中有大量代码，通过页面浏览效果更佳。
本文转自朋友的真实案例分享。
troubleshooting high buffer gets in insert into … values …
本案例客户是exadata，11.2.0.4版本，故障现象是很多平时一条非常简单的insert语句，会消耗了大量逻辑读。应用性能严重下降。
以sql_id：gcwv8p1fhdq5y为例
sql为insert into xxx values(XXX,XXX,XXX…)
该sql历史执行消耗为：
Execs LIO PIO CPU Elapsed
===== === === === =======
13,380,181 54,315,104,439 35,415,040 3,709,587.09 7,822,300.39
Per-Plan Execution Statistics Over Time
Avg Avg
Plan Snapshot Avg Rows Avg LIO Avg PIO CPU (secs) Elapsed (secs)
Hash Value Time INSTANCE_NUMBER Execs Per Exec Per Exec Per Exec Per Exec Per Exec
---------- ------------ --------------- -------- ------------------- ------------------- ------------------- ------------------- -------------------
0 15-NOV 04:00 1 45,396 0.98 32.85 0.85 0.00 0.00
15-NOV 05:00 1 263 0.98 43.07 1.31 0.00 0.01
15-NOV 06:00 1 46,487 0.99 33.08 1.28 0.00 0.00
15-NOV 07:00 1 49,998 0.98 33.14 1.18 0.00 0.00
15-NOV 08:00 1 60,315 0.97 33.38 1.25 0.00 0.00
15-NOV 09:00 1 66,830 0.99 33.47 1.20 0.00 0.00
15-NOV 10:00 1 69,444 0.99 33.07 1.10 0.00 0.00
15-NOV 11:00 1 68,093 0.98 33.08 1.28 0.00 0.00
15-NOV 12:00 1 67,742 0.99 33.26 1.30 0.00 0.00
15-NOV 13:00 1 65,145 0.99 33.31 1.78 0.00 0.00
15-NOV 14:00 1 67,342 0.99 33.01 1.76 0.00 0.00
15-NOV 15:00 1 68,911 0.99 32.98 1.76 0.00 0.00
15-NOV 16:00 1 70,164 0.99 33.02 1.76 0.00 0.00
15-NOV 17:00 1 71,330 0.99 33.22 1.75 0.00 0.00
15-NOV 18:00 1 65,323 0.99 33.48 2.00 0.00 0.00
15-NOV 19:00 1 64,115 0.99 33.10 1.98 0.00 0.00
15-NOV 19:00 2 44,502 1.00 34.16 1.84 0.00 0.00
15-NOV 20:00 1 61,588 0.99 33.32 1.99 0.00 0.00
15-NOV 21:00 1 61,381 0.99 33.33 2.03 0.00 0.00
15-NOV 22:00 1 65,744 0.99 33.43 2.06 0.00 0.00
15-NOV 23:00 1 58,918 0.99 33.09 2.12 0.00 0.00
16-NOV 00:00 1 76,843 0.99 27.58 0.11 0.00 0.00
16-NOV 01:00 1 66,925 0.99 33.59 0.27 0.00 0.00
16-NOV 02:00 1 83,400 0.98 33.73 0.33 0.00 0.00
16-NOV 02:59 1 74,856 0.99 33.98 0.62 0.00 0.00
16-NOV 04:00 1 68,930 0.99 33.32 0.74 0.00 0.00
16-NOV 05:00 2 382 1.00 32.98 1.21 0.00 0.00
16-NOV 05:00 1 458 0.98 39.14 1.21 0.00 0.01
16-NOV 06:00 2 41,818 1.00 33.56 1.21 0.00 0.00
16-NOV 06:00 1 54,686 0.99 33.18 1.26 0.00 0.00
16-NOV 07:00 1 61,275 0.99 33.18 1.16 0.00 0.00
16-NOV 07:00 2 41,817 1.00 33.67 1.16 0.00 0.00
16-NOV 08:00 1 69,710 0.98 33.37 1.15 0.00 0.00
16-NOV 09:00 1 70,784 0.99 33.23 1.15 0.00 0.00
16-NOV 10:00 1 76,177 0.99 33.04 1.64 0.00 0.00
16-NOV 11:00 1 76,369 0.99 33.11 1.52 0.00 0.00
16-NOV 12:00 1 76,806 0.99 33.37 1.70 0.00 0.00
16-NOV 13:00 1 81,768 0.99 33.17 1.69 0.00 0.00
16-NOV 14:00 1 85,599 0.99 33.22 1.64 0.00 0.00
16-NOV 15:00 1 81,204 0.99 33.26 1.67 0.00 0.00
16-NOV 16:00 1 83,322 0.99 33.33 1.79 0.00 0.00
16-NOV 17:00 1 85,418 0.98 33.14 1.73 0.00 0.00
16-NOV 18:00 1 36,410 0.99 27,633.41 5.08 2.45 5.49 <<<<<
16-NOV 18:00 2 33,332 1.00 19,376.40 5.71 1.91 3.78
16-NOV 19:00 2 50,064 1.00 13,713.77 8.81 2.03 4.63
16-NOV 19:00 1 35,535 0.99 47,756.96 9.46 4.44 10.61
16-NOV 20:00 1 27,949 0.99 52,272.56 41.94 3.97 6.96
16-NOV 20:00 2 53,479 0.99 0.00 6.29 1.09 1.69
16-NOV 21:00 1 49,896 0.99 0.00 3.73 2.00 3.17
16-NOV 21:00 2 29,409 1.00 430.01 5.20 2.12 2.75
16-NOV 22:00 2 12,981 0.98 41,086.04 15.62 5.28 9.47
16-NOV 22:00 1 36,640 0.99 4,902.41 46.31 3.43 8.08
16-NOV 23:00 2 17,020 0.99 146,861.55 9.35 1.97 3.61
16-NOV 23:00 1 44,648 0.99 31,295.57 34.07 1.62 2.90
17-NOV 00:00 1 22,612 0.99 55,897.26 9.23 4.01 8.77
17-NOV 00:00 2 40,059 0.98 0.00 5.39 1.36 2.93
17-NOV 01:00 2 25,935 0.98 87,856.31 17.00 0.40 0.54
17-NOV 01:00 1 89,672 0.99 7,669.73 0.94 0.23 0.28
17-NOV 02:00 2 26,005 1.00 0.00 1.50 0.19 0.24
17-NOV 02:00 1 80,526 0.99 0.00 0.85 0.21 0.26
17-NOV 03:00 1 67,907 0.99 0.00 1.87 0.16 0.23
17-NOV 03:00 2 33,695 1.00 71,044.72 3.06 0.29 0.39
17-NOV 04:00 1 65,799 0.99 0.00 2.75 0.50 0.61
17-NOV 04:00 2 18,725 0.98 23,310.63 12.45 0.96 1.36
17-NOV 05:00 1 22,702 0.99 81,274.17 16.71 3.93 5.44
17-NOV 05:00 2 11,586 0.99 0.66 20.76 2.60 3.57
17-NOV 06:00 1 54,276 0.99 33.22 1.09 0.00 0.00
17-NOV 06:00 2 24,660 1.00 33.44 1.23 0.00 0.00
17-NOV 07:00 1 56,152 0.98 32.89 1.39 0.00 0.00
17-NOV 08:00 1 60,410 0.97 33.11 1.59 0.00 0.00
17-NOV 09:00 2 12,895 1.00 99,298.68 9.55 1.92 3.71
17-NOV 09:00 1 20,664 0.99 77,236.22 10.92 1.36 2.42
17-NOV 10:00 1 56,935 0.99 16,582.96 3.35 0.83 1.40
17-NOV 10:00 2 25,459 0.99 12.06 4.59 1.44 2.69
17-NOV 11:00 1 75,261 0.99 33.25 1.48 0.00 0.00
17-NOV 12:00 1 69,754 0.99 33.20 1.73 0.00 0.00
17-NOV 13:00 1 69,707 0.99 33.16 1.79 0.00 0.00
17-NOV 14:00 1 73,647 0.99 33.02 1.70 0.00 0.00
17-NOV 15:00 1 72,567 0.99 33.26 1.79 0.00 0.00
17-NOV 16:00 1 87,512 0.99 33.25 1.87 0.00 0.00
17-NOV 17:00 1 84,382 0.99 33.27 1.86 0.00 0.00
17-NOV 18:00 1 84,219 0.99 33.37 2.09 0.00 0.00
17-NOV 19:00 1 54,877 0.99 2,568.54 5.51 1.13 2.43
17-NOV 19:00 2 31,188 1.00 13,338.01 8.11 1.37 2.55
17-NOV 20:00 2 17,498 0.99 204,632.21 19.86 7.97 14.53
17-NOV 20:00 1 11,772 0.98 134,229.15 17.83 15.30 39.63
17-NOV 21:00 2 30,800 0.99 6,145.28 17.51 4.05 9.73
17-NOV 21:00 1 14,982 0.98 91,575.35 34.80 12.05 37.02
17-NOV 22:00 2 2,205 0.98 0.00 37.19 16.69 44.47
17-NOV 21:59 1 1,392 0.94 442,739.64 34.52 32.47 119.56
17-NOV 22:14 1 6,599 0.96 0.00 39.99 19.11 57.64
17-NOV 22:14 2 16,574 0.98 25,482.72 21.21 5.40 11.58
17-NOV 23:00 1 36,251 0.99 0.00 10.71 3.65 8.42
17-NOV 23:00 2 14,982 0.99 152,533.89 26.28 4.95 8.98
18-NOV 00:00 1 19,041 0.99 92,379.50 21.48 6.72 11.65
18-NOV 00:00 2 9,854 0.99 154,224.37 33.44 5.08 7.37
18-NOV 01:00 2 744 0.98 2,853,039.65 272.57 25.28 31.72
18-NOV 01:00 1 68,056 1.00 9,013.49 5.80 0.93 1.30
18-NOV 02:00 2 916 0.99 600,847.27 16.21 2.51 3.06
18-NOV 02:00 1 119,607 0.99 2,613.11 1.02 0.15 0.20
18-NOV 03:00 2 1,026 0.98 7.29 49.64 6.19 8.13
18-NOV 03:00 1 117,650 0.99 0.00 0.62 0.19 0.29
18-NOV 04:00 2 14,185 1.00 211,853.87 25.93 6.58 10.41
18-NOV 04:00 1 21,548 0.99 174,800.64 18.26 7.56 15.02
18-NOV 05:00 1 4,658 0.94 396,001.34 117.96 37.79 110.04
18-NOV 05:00 2 8,124 0.98 170,945.39 80.86 13.84 31.89
18-NOV 06:00 1 93,960 1.00 3,121.78 0.71 0.01 0.02
18-NOV 06:00 2 1,314 1.00 115,183.44 49.00 0.48 0.61
18-NOV 07:00 2 278 0.94 4,086,062.82 204.54 15.72 20.20
18-NOV 07:00 1 28,062 1.00 36,707.77 6.69 0.68 0.93
18-NOV 08:00 1 29,772 1.00 181.33 3.09 0.51 0.66
18-NOV 08:00 2 258 1.00 3,819,536.15 45.25 15.03 18.63
可以看到该sql性能非常不稳定，正常情况下几十个逻辑读即可，但是异常时段每次执行逻辑读非常高。如果我碰到这个case，第一感觉可能是存在大事务或者并发事务，由于data blocks consistent reads – undo records applied过高，导致逻辑读异常增加。但是通常对于这条insert的一个block中的情况，不可能逻辑读增长到如此程度。或者是触发器？
SQL> select owner,trigger_name,table_name from dba_triggers where table_name='TFA_ALARM_ACT';
no rows selected
通过异常时段的awr发现，有一条删除recyclebin$的sql的逻辑读，占据了awr snap逻辑读的90%，并且执行次数和单次执行的逻辑读都很高。
delete from RecycleBin$ where bo=:1
该sql是清除回收站的sql，当表空间除开回收站的free空间不足时，会触发该sql去回收回收站对象占用的空间。那么问题就比较清楚了，很可能就是insert的时候表空间不足，并且回收站占用空间过大，触发了递归了该sql，回收recyclebin，并且递归sql的逻辑读应该也算在了insert sql的逻辑读上，所以我们看到insert的逻辑读如此之高。
Execs LIO PIO CPU Elapsed
===== === === === =======
6,812,062 50,267,538,233 10,416,376 2,455,756.04 4,956,904.22
Summary Execution Statistics Over Time of SQL_ID:b52m6vduutr8j
Avg Avg
Snapshot Avg Rows Avg LIO Avg PIO CPU (secs) Elapsed (secs)
Time INSTANCE_NUMBER Execs Per Exec Per Exec Per Exec Per Exec Per Exec
------------ --------------- -------- ------------------- ------------------- ------------------- ------------------- -------------------
16-NOV 12:00 1 2,058 0.35 90,876.92 12.99 0.27 0.27
16-NOV 12:00 2 450 0.15 91,078.82 0.00 0.28 0.28
16-NOV 13:00 1 1,483 0.42 91,104.69 0.15 0.28 0.28
16-NOV 13:00 2 888 0.29 91,011.18 0.00 0.28 0.28
16-NOV 14:00 1 1,496 0.41 91,014.69 0.01 0.27 0.27
16-NOV 14:00 2 1,319 0.18 90,941.15 0.00 0.29 0.29
16-NOV 15:00 1 1,037 0.57 91,259.33 0.47 0.28 0.28
16-NOV 15:00 2 1,095 0.21 91,079.43 0.00 0.30 0.30
16-NOV 16:00 1 367 0.73 91,085.14 0.01 0.29 0.30
16-NOV 16:00 2 1,764 0.29 90,488.30 25.85 0.29 0.30
16-NOV 17:00 1 1,125 0.39 91,221.01 0.01 0.27 0.27
16-NOV 17:00 2 1,702 0.22 90,929.74 0.02 0.29 0.29
16-NOV 18:00 2 112,235 0.01 11,394.69 0.72 0.35 0.60
16-NOV 18:00 1 159,825 0.00 8,200.66 0.52 0.39 0.86
16-NOV 19:00 1 300,218 0.00 2,197.06 0.66 0.37 0.87
16-NOV 19:00 2 186,744 0.01 0.00 1.21 0.35 0.70
16-NOV 20:00 1 226,914 0.01 0.00 3.18 0.35 0.59
16-NOV 20:00 2 88,764 0.02 0.00 1.75 0.33 0.46
16-NOV 21:00 2 95,967 0.02 597.85 0.56 0.33 0.38
16-NOV 21:00 1 197,939 0.00 1,701.41 0.36 0.35 0.55
16-NOV 22:00 2 107,305 0.01 8,839.62 0.99 0.35 0.53
16-NOV 22:00 1 242,637 0.00 0.00 5.27 0.37 0.80
16-NOV 23:00 2 55,205 0.02 11,429.16 1.53 0.36 0.60
16-NOV 23:00 1 128,425 0.01 22,644.41 6.72 0.36 0.61
17-NOV 00:00 2 90,179 0.01 0.00 1.49 0.36 0.67
17-NOV 00:00 1 165,560 0.01 0.00 0.74 0.37 0.81
17-NOV 01:00 2 16,670 0.04 89,853.02 17.19 0.34 0.44
17-NOV 01:00 1 31,514 0.05 92,014.78 0.39 0.29 0.32
17-NOV 02:00 2 10,659 0.04 90,329.35 0.56 0.31 0.34
17-NOV 02:00 1 27,684 0.08 0.00 0.64 0.28 0.31
17-NOV 03:00 1 19,277 0.06 93,007.84 3.19 0.30 0.38
17-NOV 03:00 2 19,741 0.02 0.00 2.43 0.32 0.38
17-NOV 04:00 2 46,440 0.02 0.00 3.57 0.32 0.43
17-NOV 04:00 1 52,820 0.06 11,044.13 1.16 0.29 0.33
17-NOV 05:00 1 163,112 0.01 0.00 1.03 0.32 0.42
17-NOV 05:00 2 65,164 0.02 24,299.51 1.86 0.31 0.40
17-NOV 06:00 2 18,879 0.08 0.00 1.11 0.30 0.35
17-NOV 06:00 1 91,912 0.02 0.00 0.52 0.33 0.42
17-NOV 07:00 1 2,841 0.36 90,991.08 8.25 0.26 0.27
17-NOV 08:00 1 1,133 0.34 90,959.12 0.01 0.27 0.27
17-NOV 08:00 2 292 0.06 91,077.71 0.00 0.28 0.28
17-NOV 09:00 2 49,286 0.01 2,256.05 1.42 0.36 0.68<<<<
17-NOV 09:00 1 45,759 0.02 0.00 2.88 0.35 0.56
17-NOV 10:00 2 72,029 0.01 29,373.33 0.70 0.35 0.66
17-NOV 10:00 1 76,768 0.03 33,478.30 0.71 0.34 0.53<<<<
17-NOV 11:00 1 962 0.47 91,098.62 18.01 0.27 0.28
17-NOV 12:00 1 264 0.52 91,083.06 0.02 0.28 0.28
17-NOV 13:00 1 304 0.64 91,084.48 0.03 0.28 0.29
17-NOV 14:00 1 361 0.47 91,082.94 0.02 0.27 0.27
17-NOV 16:00 2 1,907 0.22 91,054.87 12.62 0.29 0.30
17-NOV 16:00 1 1,442 0.37 91,154.80 0.01 0.29 0.29
17-NOV 17:00 2 1,664 0.19 91,238.62 0.02 0.30 0.30
17-NOV 17:00 1 743 0.48 91,205.23 0.01 0.28 0.28
17-NOV 18:00 2 443 0.48 91,082.50 0.01 0.27 0.28
17-NOV 19:00 1 115,267 0.00 13,414.72 1.08 0.37 0.77<<<<<
17-NOV 19:00 2 71,196 0.01 28,965.26 1.88 0.34 0.60
17-NOV 20:00 1 320,847 0.00 7,627.59 0.43 0.40 1.00
17-NOV 20:00 2 240,198 0.01 5.04 0.88 0.34 0.57
17-NOV 21:00 2 219,392 0.01 0.00 1.57 0.36 0.77
17-NOV 21:00 1 308,486 0.00 0.00 1.17 0.41 1.24
17-NOV 21:59 1 77,813 0.00 33,034.00 0.40 0.40 1.47
17-NOV 22:00 2 53,058 0.01 9,294.22 1.12 0.37 0.92
17-NOV 22:14 2 144,273 0.01 0.00 1.63 0.35 0.67
17-NOV 22:14 1 221,411 0.00 0.00 0.82 0.40 1.19
17-NOV 23:00 1 247,058 0.00 1,387.63 0.95 0.38 0.83
17-NOV 23:00 2 120,079 0.02 18,354.85 2.05 0.35 0.56
18-NOV 00:00 2 78,057 0.03 0.00 2.87 0.35 0.47
18-NOV 00:00 1 250,600 0.00 3,532.16 1.09 0.35 0.59
18-NOV 01:00 1 117,582 0.02 0.00 1.24 0.30 0.38
18-NOV 01:00 2 31,214 0.03 0.00 2.85 0.32 0.38
18-NOV 02:00 2 6,091 0.12 91,599.30 6.27 0.28 0.32
18-NOV 02:00 1 31,710 0.05 91,229.94 0.54 0.29 0.35
18-NOV 03:00 2 11,228 0.09 91,329.35 3.07 0.29 0.35
18-NOV 03:00 1 44,298 0.02 89,853.18 0.49 0.33 0.49
18-NOV 04:00 2 134,051 0.02 0.00 1.73 0.34 0.51
18-NOV 04:00 1 318,089 0.00 0.00 0.88 0.37 0.72
18-NOV 05:00 1 294,244 0.00 997.39 1.33 0.42 1.22
18-NOV 05:00 2 197,673 0.01 1,679.84 2.31 0.36 0.74
18-NOV 06:00 2 976 0.06 91,665.72 2.67 0.30 0.35
18-NOV 06:00 1 66,407 0.02 24,292.01 1.92 0.38 0.80
18-NOV 07:00 1 40,087 0.07 0.00 1.66 0.29 0.35
18-NOV 07:00 2 13,510 0.09 91,197.58 2.65 0.29 0.33
18-NOV 08:00 1 33,641 0.06 0.00 0.88 0.29 0.33
18-NOV 08:00 2 7,240 0.08 91,123.94 0.73 0.28 0.33
18-NOV 09:00 1 2,996 0.16 91,050.79 0.01 0.27 0.27
18-NOV 10:00 1 519 0.33 91,081.06 0.02 0.28 0.28
可以看到delete recyclebin$的sql性能也比较差，单词执行9w多逻辑读。并且执行次数非常多，其实从执行次数也可以看出，回收站每个对象占用的空间其实比较小，但是对象很多。清理一个对象并不能支撑多久。recyclebin$的segment大小撑到了700多M。查看该执行计划发现还是一个全表扫描。。。
Plan hash value: 716146596
------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
------------------------------------------------------------------------------------------
| 0 | DELETE STATEMENT | | | | 611 (100)| |
| 1 | DELETE | RECYCLEBIN$ | | | | |
| 2 | TABLE ACCESS STORAGE FULL| RECYCLEBIN$ | 1 | 19 | 611 (1)| 00:00:08 |
------------------------------------------------------------------------------------------
一看这个sql就知道统计信息也是错的，那么大的逻辑读，cost才611。。。
create table recyclebin$
(
obj# number not null, /* original object number */
owner# number not null, /* owner user number */
original_name varchar2(32), /* Original Object Name */
operation number not null, /* Operation carried out */
/* 0 -> DROP */
/* 1 -> TRUNCATE (not supported) */
type# number not null, /* object type (see KQD.H) */
ts# number, /* tablespace number */
file# number, /* segment header file number */
block# number, /* segment header block number */
droptime date, /* time when object was dropped */
dropscn number, /* SCN of Tx which caused the drop */
partition_name varchar2(32), /* Name of the partition dropped */
/* NULL otherwise */
flags number, /* flags for undrop processing */
related number not null, /* obj one level up in heirarchy */
bo number not null, /* base object */
purgeobj number not null, /* obj to purge when purging this */
base_ts# number, /* Base objects Tablespace number */
base_owner# number, /* Base objects owner number */
space number, /* number of blocks used by the object */
con# number, /* con#, if index is due to constraint */
spare1 number,
spare2 number,
spare3 number
)
/
create index recyclebin$_obj on recyclebin$(obj#)
/
create index recyclebin$_ts on recyclebin$(ts#)
/
create index recyclebin$_owner on recyclebin$(owner#)
/
delete的where条件是bo(base object)，并且该列是没有索引的。这个可能是oracle设计缺陷。没有想到recyclebin$会被撑到那么大？
解决方法：
create index RecycleBin$_bo on RecycleBin$(bo);
exec dbms_stats.gather_table_stats(ownname=>'SYS',tabname=>'RecycleBin$', cascade=>TRUE);
为了避免此类故障再次发生，建议：
如果可以关闭recyclebin
如果非要开启，那么需要监控recyclebin$里的对象占用的空间占据dba_free_space中的比例，如果比例过高，就要在低峰期的手动清理回收站。
------------------作者介绍-----------------------
姓名：黄廷忠
现就职：Oracle中国高级服务团队
曾就职：OceanBase、云和恩墨、东方龙马等
电话、微信、QQ：18081072613
个人博客: (http://www.htz.pw)
CSDN地址: (https://blog.csdn.net/wwwhtzpw)
博客园地址: (https://www.cnblogs.com/www-htz-pw)
提供ORACLE技术支持(系统优化，故障处理，安装升级，数据恢复等） TEL:18081072613，微信、QQ同手机号。
浙公网安备 33010602011771号