Trace檔案過量生成問題解決

 

隨著Oracle技術本身的不斷髮展，“自動化”和“智慧化”的資料庫時代已經來臨。無論是運維管理、開發除錯，傳統DBA們的工作內容都已經發生了很大變化。一些諸如記憶體池劃分調整、歸檔日誌管理等功能，都已經被Oracle自動或者半自動的特性所解決。對新一代DBA而言，保持不斷學習的精神，接受新問題，發現屬於自己的一片新天地，才是當務之急。

今天，和一個朋友解決了一個運維環境問題。筆者感覺很有意思，記錄下來，供需要的朋友不時之需。

 

1、問題說明

 

今天，一個朋友從QQ上提出問題，說在測試環境的一臺10gR2庫，近期突然生成很多Trace Dump檔案。每個檔案大小在4-5M，頻率每分鐘若干次。幾天之內佔用了上百G的空間，刪除無用檔案之後依然產生。

Oracle Trace檔案從本質上是Oracle前後臺程式在特殊的情景下，例如開啟跟蹤模式、執行異常，自動向檔案系統中輸出的診斷檔案。Trace檔案通常以trc結尾，包含程式環境資訊、執行過程和故障點輸出。對Oracle官方和管理人員而言，Trace檔案是診斷的重要依據。

正常執行情況下，每臺資料庫都會生成一些trc檔案，每個檔案大小在幾k左右，是不會產生朋友遇到的問題的。

之後，朋友將資料庫alert log和一個trace檔案樣本發給筆者。Trace檔案大小在4M左右，明顯超過正常大小。之所以還要alert log，是因為Oracle在生成trace檔案時候，通常對應alert log中有相應記錄。

 

2、問題分析

 

朋友的資料庫環境是Oracle 10gR2，具體版本是10.2.0.3.0.。從alert log中，可以發現是一個標準的Windows資料庫環境。

 

 

System parameters with non-default values:

  processes                = 150

  sga_target               = 612368384

  control_files            = D:\ORADATA\ORACLE10\CONTROL01.CTL, D:\ORADATA\ORACLE10\CONTROL02.CTL, D:\ORADATA\ORACLE10\CONTROL03.CTL

  db_block_size            = 8192

  compatible               = 10.2.0.3.0

  db_file_multiblock_read_count= 16

  db_recovery_file_dest    = D:\oracle\product\10.2.0\flash_recovery_area

  db_recovery_file_dest_size= 2147483648

  undo_management          = AUTO

  undo_tablespace          = UNDOTBS1

  remote_login_passwordfile= EXCLUSIVE

 

 

在alert log中，我們果然發現了很多異常點。從若干天之前，就不斷報錯異常。

 

 

Wed Jan 21 12:49:10 2015

db_recovery_file_dest_size of 2048 MB is 0.00% used. This is a

user-specified limit on the amount of space that will be used by this

database for recovery-related files, and does not reflect the amount of

space available in the underlying filesystem or ASM diskgroup.

Wed Jan 21 12:49:11 2015

Completed: alter database open

Wed Jan 21 12:49:22 2015

Errors in file d:\oracle\product\10.2.0\admin\oracle10\bdump\oracle10_j002_2524.trc:

 

Wed Jan 21 12:49:28 2015

Errors in file d:\oracle\product\10.2.0\admin\oracle10\bdump\oracle10_j000_2516.trc:

 

Wed Jan 21 12:49:34 2015

Errors in file d:\oracle\product\10.2.0\admin\oracle10\bdump\oracle10_j003_3752.trc:

 

Wed Jan 21 12:49:35 2015

Errors in file d:\oracle\product\10.2.0\admin\oracle10\bdump\oracle10_j002_2524.trc:

ORA-12012: 自動執行作業 26 出錯

ORA-08102: 未找到索引關鍵字, 物件號 239, 檔案 1, 塊 1674 (2)

 

 

之後，每隔約5秒鐘，就生成一個trace檔案，對應內容相同。

 

 

Mon Mar 23 09:30:52 2015

Errors in file d:\oracle\product\10.2.0\admin\oracle10\bdump\oracle10_j002_4348.trc:

ORA-12012: 自動執行作業 26 出錯

ORA-08102: 未找到索引關鍵字, 物件號 239, 檔案 1, 塊 1674 (2)

 

Mon Mar 23 09:30:55 2015

Errors in file d:\oracle\product\10.2.0\admin\oracle10\bdump\oracle10_j001_1376.trc:

ORA-12012: 自動執行作業 4 出錯

ORA-08102: 未找到索引關鍵字, 物件號 239, 檔案 1, 塊 1674 (2)

 

Mon Mar 23 09:30:56 2015

Errors in file d:\oracle\product\10.2.0\admin\oracle10\bdump\oracle10_j001_1376.trc:

ORA-12012: 自動執行作業 4 出錯

ORA-08102: 未找到索引關鍵字, 物件號 239, 檔案 1, 塊 1674 (2)

 

 

再開啟trace檔案，檔名稱為：oracle10_j000_5820。Jxxx通常為Oracle的自動作業Job後臺程式，自動按照執行的規則後臺執行。其中，包括了報錯功能點：

 

 

*** 2015-03-23 09:30:38.468

ksedmp: internal or fatal error

Current SQL statement for this session:

update sys.job$ set failures=0, this_date=null, flag=:1, last_date=:2,  next_date = greatest(:3, sysdate),  total=total+(sysdate-nvl(this_date,sysdate)) where job=:4

 

 

執行job$修改操作時候，發出的錯誤資訊。

診斷的依據中，“物件239，檔案1，塊1674（2）”是很好的入手點。從提示資訊看，似乎這個物件遇到了壞塊情況。檔案1是system表空間，應該是Oracle內部物件。

由於筆者不能實際操作問題庫，所以找到了類似的環境進行簡單檢查。

 

 

SQL> select * from v$version;

 

BANNER

----------------------------------------------------------------

Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - Prod

PL/SQL Release 10.2.0.3.0 - Production

CORE  10.2.0.3.0    Production

 

TNS for 32-bit Windows: Version 10.2.0.3.0 - Production

NLSRTL Version 10.2.0.3.0 – Production

 

 

找到object_id=239物件。

 

 

SQL> select object_name, object_type, status from dba_objects where object_id=239;

 

OBJECT_NAME          OBJECT_TYPE         STATUS

-------------------- ------------------- -------

I_JOB_NEXT           INDEX               VALID

 

 

報錯物件是一個索引物件，對應的段結構。

 

 

SQL> select SEGMENT_TYPE, TABLESPACE_NAME, HEADER_FILE, HEADER_BLOCK, BLOCKS, EXTENTS from dba_segments where segment_name='I_JOB_NEXT';

 

SEGMENT_TYPE       TABLESPACE_NAME      HEADER_FILE HEADER_BLOCK     BLOCKS    EXTENTS

------------------ -------------------- ----------- ------------ ---------- ----------

INDEX              SYSTEM                         1         1673          8          1

 

 

對應的索引段結構很小，只有一個extents，合計八個資料塊。注意：頭塊編號為1673。報錯塊號為1674，是段頭塊後面第一個資料塊。

熟悉Oracle段結構的朋友一定知道，索引段後第一個資料塊就是索引樹的根節點塊。報錯資訊很可能是出現了索引段損壞的情況。

 

3、問題修復

 

在Oracle中，壞塊是很難處理的一種故障。從官方角度，壞塊的來源有兩個：一個是軟硬體儲存之間的不相容，另一個是Oracle內部Bug。處理壞塊的手段有很多，落實到這個案例中，索引段壞塊是比較好處理的一種。

最簡單的處理策略是嘗試rebuild索引，讓資料庫重新整理結構。模擬操作：

 

 

SQL> alter index I_JOB_NEXT rebuild;

Index altered

 

 

讓朋友在環境上進行測試，發現執行成功，索引狀態也是valid。但是問題依然存在，trace檔案還會生成。

索要最新的alert log之後，發現報錯資訊變化。

 

 

Mon Mar 23 10:15:35 2015

Errors in file d:\oracle\product\10.2.0\admin\oracle10\bdump\oracle10_j002_6932.trc:

ORA-00604: 遞迴 SQL 級別 1 出現錯誤

ORA-08102: 未找到索引關鍵字, 物件號 239, 檔案 1, 塊 65946 (2)

ORA-12012: 自動執行作業 26 出錯

ORA-08102: 未找到索引關鍵字, 物件號 239, 檔案 1, 塊 65946 (2)

 

Mon Mar 23 10:15:37 2015

Errors in file d:\oracle\product\10.2.0\admin\oracle10\bdump\oracle10_j001_7056.trc:

ORA-00604: 遞迴 SQL 級別 1 出現錯誤

ORA-08102: 未找到索引關鍵字, 物件號 239, 檔案 1, 塊 65946 (2)

ORA-12012: 自動執行作業 4 出錯

ORA-08102: 未找到索引關鍵字, 物件號 239, 檔案 1, 塊 65946 (2)

 

 

注意，報錯內容發生了變化。塊號變化到了system表空間另一個位置。說明：rebuild操作生效，修改了index的結構，但是錯誤依然存在。

筆者的一種猜想是：也許rebuild操作並不能直觀反映資料表的資料情況，而報錯問題是在索引資料和表段資料的不一致。嘗試解決方法：drop後重新create索引物件。

 

 

SQL> drop index i_job_next;

Index dropped

 

SQL> create index i_job_next on job$ (next_date);

Index created

 

 

之後，問題解決。

 

4、結論

 

相對於各種複雜問題，今天這個問題相對比較單純簡單。但是這個問題告訴我們教訓。首先，問題處理要從核心線索入手，層層深入，最後定位問題。其次，對於一些想當然的概念，如rebuild，要更加深層次理解含義，更詳細的分析。