本案例来自北区同事的分享，客户是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中的比例，如果比例过高，就要在低峰期的手动清理回收站。
over！
发表回复