1、處理歸檔日志增加過快一例(2010-08-25 20:03:47) 轉載標簽： oracle歸檔日志增加過快分類： 原創(chuàng)文章 處理歸檔日志增加過快一例摘要       本文介紹了不久前作者是如何徹底解決一家醫(yī)院數據庫由于歸檔日志增長過快,導致磁盤剩余空間占滿，引起宕機全過程。通過本案例的描述,我們可以了解到當遇到數據庫宕機問題時，應該如何分析現(xiàn)象、找到問題關鍵、最終徹底解決該問題的一個總體思路，最后還應該深入思考該問題產生的原因，總結出避免以后再出現(xiàn)該問題的建議。關鍵字: ORACLE、歸檔日志、宕機、DML語句初步了解 &

2、#160;     早上一來到公司，XZH就告訴我接到CQ公司的有一個技術申請，大致情況為一家三甲醫(yī)院，采用Rac+Linux環(huán)境，啟用了歸檔模式，但是由于日志增長過快，我們的技術人員設雖然置自動刪除歸檔的任務，但是還是沒有避免磁盤空間被占滿，已經引起醫(yī)院2次全院無法使用，雖然CQ公司也安排多名技術人員去現(xiàn)場處理，但是醫(yī)院認為一直沒有解決徹底，因此信息主管對此意見較大，希望公司安排技術支持部現(xiàn)場徹底解決該問題。       通過申請描述，我大致了解到以下幾個關鍵點：  

3、60;    1.醫(yī)院啟用了歸檔，也做了定期自動刪除歸檔日志的任務。       2.由于歸檔日志增加過快，已經導致醫(yī)院2號節(jié)點宕機。       3.我們的技術人員去了幾次，都未徹底解決，用戶已經意見很大了。       這只是個初步情況，往往只能了解問題的大概，具體的問題產生的原因還是得到用戶那里去才能真正了解，于是立即出發(fā)，前往用戶處處理問題。現(xiàn)場分析問題  &

4、#160;    到達醫(yī)院，同系統(tǒng)管理員互相寒暄了幾句，了解大體情況是醫(yī)院昨天凌晨部分科室反映不能登錄導航臺，于是系統(tǒng)管理員深夜被叫到醫(yī)院，查看服務器發(fā)現(xiàn)數據庫已經宕機，檢查磁盤空間，發(fā)現(xiàn)其中一個節(jié)點的剩余空間為0，于是立即刪除部分過去的歸檔日志，重新啟動服務器，下面科室才能夠正常登錄，談話間不斷聽見系統(tǒng)管理員抱怨深夜到醫(yī)院是如何如何不情愿，看來意見是比較大。而且同樣的問題不久前才出現(xiàn)過一次，當時是中午，詢問同去的同事，了解到確實不久前也出現(xiàn)過一次同樣的情況，當時認為是歸檔日志的定期刪除保留的日志時間太長，當時保留的是30天的日志，后來改為保留5天的日志，心想不會

5、再出現(xiàn)該問題，沒想到還是無法避免。       接下來，該我們自己著手分析問題了，因為畢竟用戶描述的只是他的主觀判斷，而且真正要想了解到時發(fā)生的真實情況，看是應該看下Oracle的日志才能確認，這也是我們處理問題必須遵守的原則，首先看下該節(jié)點的alter.ora在出現(xiàn)問題時的錯誤記錄，部分記錄情況如下：Fri Jul 18 22:10:18 2010Errors in file /u01/app/oracle/admin/orcl/bdump/orcl2_arc1_13762.trc:ORA-19502: Message 19502

6、not found; No message file for product=RDBMS, facility=ORA; arguments: /u01/app/oracle/archive/2_24046_698868487.dbf 22529 512ORA-27072: Message 27072 not found; No message file for product=RDBMS, facility=ORALinux-x86_64 Error: 9: Bad file descriptorAdditional information: 4Additional information:

7、22529Additional information: 507392ORA-19502: Message 19502 not found; No message file for product=RDBMS, facility=ORA; arguments: /u01/app/oracle/archive/2_24046_698868487.dbf 22529 512Fri Jul 18 22:10:18 2010ARCH: Archival stopped, error occurred. Will continue retryingFri Jul 18 22:10:18 2010ORAC

8、LE Instance orcl2 - Archival Error       從日志記錄的時間可以看出，真正出問題應該是在22點多鐘，只是系統(tǒng)管理員凌晨才得到問題反饋，可以看出自己查看日志是多么的重要，不過從來錯誤的記錄看，確實是由于無法歸檔，導致該節(jié)點出現(xiàn)問題，這個判斷到是準確的。首先檢查了下日志的增長速度，發(fā)現(xiàn)每個節(jié)點平均每13分鐘就產生一個50M的歸檔日志，一天的歸檔日志就接近30G，而醫(yī)院的日志放在本地磁盤，磁盤剩余空間也就100多G，按照這種日志的增長速度，空間被日志撐爆也就理所當然了。但是以該院的規(guī)模和業(yè)務量來看，產生

9、這么多的日志肯定是不正常的，所以找到日志增長過快的原因，是解決問題的根本。       首先觀察下歸檔日志產生的頻率，我們取當天24小時產生日志的頻率數，如下圖：               發(fā)現(xiàn)除了在上午業(yè)務高峰期（89點），其他時間段沒有明顯的曲線變化，而且凌晨時分（07點）的日志也切換頻繁，這就肯定有問題，于是我生成今天2點3點的AWR報告進行分析，分析情況如下：  &#

10、160;     首先看該時間段的會話不多，只有60多個會話，除去系統(tǒng)自帶的幾個會話，真正應用ZLHIS的會話肯定不多，證明當時醫(yī)院的業(yè)務肯定不繁忙。        但是每秒鐘的處理事務卻有23.82,比很多三甲醫(yī)院業(yè)務高峰期的事務都要大，肯定有問題，進一步分析執(zhí)行sql：        發(fā)現(xiàn)即使在凌晨時分，居然也會如此頻繁的執(zhí)行大量的sql語句，其中涉及到update等DML語句，勢必會產生大量歸檔日志，從表名看，

11、應該是與體檢系統(tǒng)有直接關系，通過分析，發(fā)現(xiàn)是zl_體檢任務結果_Transation過程中的語句。該過程是實現(xiàn)把體檢病人的檢驗結果更新到體檢系統(tǒng)里面，我們程序有2種方式進行更新：       1.后臺每天晚上定時對全院未完成體檢的病人集中更新一次，通過調用zl_體檢任務結果_TransationAll實現(xiàn)，其中zl_體檢任務結果_TransationAll過程里面，又循環(huán)調用了zl_體檢任務結果_Transation過程。       2.是由操作人員在程序上操作，單獨更新某

12、一指定病人，只調用zl_體檢任務結果_Transation過程。       后一種情況肯定不會頻繁執(zhí)行該過程，目標鎖定在第一種，后臺作業(yè)方式，于是查看系統(tǒng)后臺作業(yè)，發(fā)現(xiàn)問題作業(yè)，如下：        該后臺作業(yè)中該過程的執(zhí)行頻率被調整3分鐘，通過對zl_體檢任務結果_TransationAll過程分析我們知道，只要體檢病人沒有完成體檢，都會對其檢驗結果進行更新，而該醫(yī)院當時正好進行大量體檢，有上千病人沒有完成體檢，每次執(zhí)行該過程，都會對這些病人進行更新，可想而知肯

13、定會產生大量日志，所以如此頻繁的執(zhí)行該過程，肯定是不現(xiàn)實的，定位了問題，接下來就該處理該問題。現(xiàn)場處理問題       詢問相關人員，了解到由于該院體檢科想實時得到體檢病人的檢驗結果，所以我們的同事按醫(yī)院的要求對作業(yè)執(zhí)行頻率進行了調整所致，說明了問題的嚴重性，經過和醫(yī)院協(xié)商，闡述利弊，得到醫(yī)院的同意，按醫(yī)院要求最后把該后臺作業(yè)修改為每天執(zhí)行2次，中午一次，晚上一次。處理方法如下：1. 1.        刪除原來的job由于知道job號為107，所以調用dbms_j

14、ob包刪除              exec dbms_job.remove(107);2. 2.        創(chuàng)建2個的job,一個是中午13點執(zhí)行，一個晚上執(zhí)行1點-1點的jobvariable job number;begin  sys.dbms_job.submit(job => :job,      

15、;                what => 'zl_體檢任務結果_TransationAll;',                      next_date => to_date('20-07-

16、2010 01:00:00', 'dd-mm-yyyy hh24:mi:ss'),                      interval => 'trunc(Sysdate)+1+01/24+00/(24*60)+00/(24*60*60)');  commit;end;/-13點的jobvariable job&#

17、160;number;begin  sys.dbms_job.submit(job => :job,                      what => 'zl_體檢任務結果_TransationAll;',           

18、60;          next_date => to_date('20-07-2010 13:00:00', 'dd-mm-yyyy hh24:mi:ss'),                      interval => 'trunc(S

19、ysdate)+1+13/24+00/(24*60)+00/(24*60*60)');  commit;end;/3. 3.        后續(xù)處理       通過上面的修改，馬上可以觀察到2個節(jié)點的日志產生速度明顯下降了，觀察了1個小時，才產生了1個歸檔日志，由于是在下午時分，本身醫(yī)院業(yè)務不是太忙，這種歸檔日志的產生速度應該是正常的。       然后，再對每個節(jié)點的備份和歸檔日志的刪除策略進行下檢查，1，2號機都改為每天晚上12點定時刪除30天前的歸檔日志，standby的機器由于空間比較大，調整為每天12點定時刪除60天前的歸檔日志，最后要求醫(yī)院近期觀察下日志的生成速度，經過醫(yī)院的確認，得到醫(yī)院的認可。（另：第二天，要求醫(yī)院提供日志切換的次數統(tǒng)計，如下圖，可以看到確實歸檔日志切換已經恢復正常，看到問題得到解決，醫(yī)院的管理員也相當高興。） 后續(xù)總結