大量redo生成的問題原因及改進(r6筆記第50天)
接著上次分享的關於資料庫無法登入的原因http://blog.itpub.net/23718752/viewspace-1791089/ 其實最終還是因為在短期內生成了大量的redo,造成了頻繁的日誌切換，導致歸檔佔用了大量的空間，最後無法登入，從這個層面來說，我們可以做一些工作來儘可能長時間的保留近期的歸檔，但是我們還可以換一個思路，那就是看看到底是什麼操作生成了大量的redo,能不能試著減少redo的生成量。 一般來說，這個問題有點傻，日誌肯定是記錄儘可能完整的資訊，這是做資料恢復的基礎，我們還是不要過早下結論，先來分析一下再來做決定。 檢視資料庫的redo切換頻率，在近幾天內的redo切換頻率極高，對於一個OLTP的系統來說是很非常高的負載，這種頻繁的日誌切換我也只在資料遷移的一些場景中碰到過。
但是奇怪的是檢視資料庫的DB time，卻發現這個值其實並不高，看起來似乎有些矛盾，從這一點來看資料庫內的資料變化頻率其實並不是很高。
BEGIN_SNAP END_SNAP SNAPDATE DURATION_MINS DBTIME ---------- ---------- ----------------------- ---------- 82560 82561 05 Sep 2015 00:00 30 26 82561 82562 05 Sep 2015 00:30 30 26 82562 82563 05 Sep 2015 01:00 29 29 82563 82564 05 Sep 2015 01:30 30 27 82564 82565 05 Sep 2015 02:00 30 23 82565 82566 05 Sep 2015 02:30 30 23 82566 82567 05 Sep 2015 03:00 30 20 82567 82568 05 Sep 2015 03:30 30 22 82568 82569 05 Sep 2015 04:00 30 20 82569 82570 05 Sep 2015 04:30 30 25 82570 82571 05 Sep 2015 05:00 30 23 82571 82572 05 Sep 2015 05:30 30 27 82572 82573 05 Sep 2015 06:00 30 40 82573 82574 05 Sep 2015 06:30 30 26 82574 82575 05 Sep 2015 07:00 30 28 82575 82576 05 Sep 2015 07:30 30 34 82576 82577 05 Sep 2015 08:00 29 40 82577 82578 05 Sep 2015 08:30 30 37 82578 82579 05 Sep 2015 09:00 30 40 82579 82580 05 Sep 2015 09:30 30 38 82580 82581 05 Sep 2015 10:00 30 41 82581 82582 05 Sep 2015 10:30 30 40 82582 82583 05 Sep 2015 11:00 30 37 82583 82584 05 Sep 2015 11:30 30 39 82584 82585 05 Sep 2015 12:00 30 41 82585 82586 05 Sep 2015 12:30 30 34 82586 82587 05 Sep 2015 13:00 30 53 82587 82588 05 Sep 2015 13:30 30 82 82588 82589 05 Sep 2015 14:00 30 74 82589 82590 05 Sep 2015 14:30 30 45
對於這種情況，我們還是抓取一個awr報告來看看。 在awr報告中，可以看到瓶頸還是主要在DB CPU和IOsh
Top 5 Timed Foreground Events
Event |
Waits |
Time(s) |
Avg wait (ms) |
% DB time |
Wait Class |
|---|---|---|---|---|---|
DB CPU |
2,184 |
68.89 |
|||
db file parallel read |
6,096 |
413 |
68 |
13.02 |
User I/O |
log file sync |
65,199 |
363 |
6 |
11.47 |
Commit |
db file sequential read |
46,038 |
172 |
4 |
5.43 |
User I/O |
direct path read |
415,685 |
46 |
0 |
1.47 |
User I/O |
檢視時間模型，可以看到DB CPU和sql相關的影響各佔了主要的比例。 看到這，自己還是有些犯嘀咕，柑橘這個問題還是有些奇怪，能夠關注的一個重點就是sql語句了，但是top 1的sql語句還是有些奇怪。
Elapsed Time (s) |
Executions |
Elapsed Time per Exec (s) |
%Total |
%CPU |
%IO |
SQL Id |
SQL Module |
SQL Text |
|---|---|---|---|---|---|---|---|---|
931.73 |
14,409 |
0.06 |
29.39 |
99.77 |
0.00 |
c95g9rc1hw48j |
JDBC Thin Client |
update sync_id set ma... |
這條語句執行頻率極高，語句也很簡單，但是CPU消耗卻很高，初步懷疑是走了全表掃描。 語句如下： update sync_id set max_id = :1 where sync_id_type = :2 簡單檢視執行計劃，發現確實是走了全表掃描，如果碰到這個問題，第一感覺是需要走索引，沒有索引可以建個索引，但是當我看到sql by Executions這個部分時，自己感覺到問題其實不是那麼簡單。 可以看到第2個語句其實就是剛剛提到的top 1的sql，對應的指標還是很不尋常的，一次執行處理的行數近5000度行，執行了1萬多次，處理的資料行數近8千萬。
Executions |
Rows Processed |
Rows per Exec |
Elapsed Time (s) |
%CPU |
%IO |
SQL Id |
SQL Module |
SQL Text |
|---|---|---|---|---|---|---|---|---|
14,684 |
14,684 |
1.00 |
3.39 |
94.7 |
.7 |
98kzt71wqz5qg |
JDBC Thin Client |
update sus_log set failed_c... |
14,409 |
78,329,332 |
5,436.14 |
931.73 |
99.8 |
0 |
c95g9rc1hw48j |
JDBC Thin Client |
update sync_id set ma... |
但是檢視這個表，發現數據其實就1萬多條，所以這是一個明顯的問題。 我們來進一步分析一下，一個小表1萬多的資料，每次更新能夠更新5000多行，可以斷定資料的分散式是不均勻的。因為這個表結構非常簡單，就兩個欄位，所以分析問題還是很好定位的。 簡單查看了一下資料情況，發現數據主要分佈在兩個type列值上，基本上佔用了99.99%以上的資料 SQL> select max_id,count(*)from SYNC_ID where SYNC_ID_TYPE='SYNC_LOG_ID' group by max_id; MAX_ID COUNT(*) ---------- ---------- 38 5558 SQL> select max_id,count(*)from SYNC_ID where SYNC_ID_TYPE=SYNC_TEST2_LOG_ID' group by max_id; MAX_ID COUNT(*) ---------- ---------- 108 5577 從資料的分佈情況可以看到，其實表中存在了大量的冗餘資料，而且表中沒有索引欄位和其它約束，在每次更新的時候本來更新一個欄位值，結果會修改5000多行資料的值，如果執行頻繁，短時間內就會頻繁生成大量的redo,從目前的sql執行情況來看，這條語句應該是造成redo頻繁切換的主要原因了。 但是這個環境還是需要做一些確認和溝通之後才能夠變更的，目前的也只是建議，我們在這個基礎上還是可以簡單地測試一下的。 測試的思路其實很簡單，就是把這個表裡的資料給匯出來，放到其它測試環境中，做頻繁的update，然後檢視歸檔的頻率即可。 然後刪除冗餘的資料，再做頻繁的update,然後檢視歸檔的頻率就可以比較出來。 把資料匯入到另外一個測試環境中。 然後使用下面的語句進行頻繁更新即可，先更新一百萬次，中間可以隨時中斷。
function test_update
{
sqlplus test/test <<eof
update sync_id set max_id = 38 where sync_id_type = 'SYNC_LOG_ID';
commit;
EOF
}</eof
for i in {1..1000000}
do
test_update
done
在測試開始的時候
Redo Switch times per hour 2015-Sep-05 16:02:55
MON DA 00 01 02 03 04 05 06 07 08 09 10 11 12 13 14 15 16 17 18 19 20 21 22 23
--- -- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ----
09 05 0 0 0 0 0 0 0 1 0 0 1 0 0 0 0 1 0 0 0 0 0 0 0 0
運行了不到3分鐘，日誌切換就達到了14次，還是很能夠說明問題的。
Redo Switch times per hour 2015-Sep-05 16:05:20
MON DA 00 01 02 03 04 05 06 07 08 09 10 11 12 13 14 15 16 17 18 19 20 21 22 23
--- -- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ----
09 05 0 0 0 0 0 0 0 1 0 0 1 0 0 0 0 2 14 0 0 0 0 0 0 0
然後我們使用update的方式來驗證一下。
Redo Switch times per hour 2015-Sep-05 16:08:04
MON DA 00 01 02 03 04 05 06 07 08 09 10 11 12 13 14 15 16 17 18 19 20 21 22 23
--- -- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ----
09 05 0 0 0 0 0 0 0 1 0 0 1 0 0 0 0 2 14 0 0 0 0 0 0 0
又過了4分鐘，日誌一次都沒有切換，這就足以說明了我們的推論是正確的。
Redo Switch times per hour 2015-Sep-05 16:12:47
MON DA 00 01 02 03 04 05 06 07 08 09 10 11 12 13 14 15 16 17 18 19 20 21 22 23
--- -- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ----
09 05 0 0 0 0 0 0 0 1 0 0 1 0 0 0 0 2 14 0 0 0 0 0 0 0
剩下的就是做進一步的確認和在正式環境部署了。
當然在清楚了冗餘資料之後，建立索引的優勢就沒有那麼大了。