使用隱含Trace引數診斷Oracle Data Pump故障

realkid4發表於2013-09-14

Data Pump資料泵是Oracle10g開始推出的,用於取代傳統exp/imp工具的資料備份還原元件。經過若干版本的演進和修改,Data Pump已經非常成熟,逐漸被越來越多的DBA和運維人員接受。

 

相對於傳統的exp/impData Pump有很多優勢,也變得更加複雜。資料泵一個最顯著的特點就是Server-Side執行。Exp/Imp是執行在客戶端上面的小工具,雖然使用方便,但是需要處理資料來源端和目標端各自伺服器和客戶端四個版本的差異相容問題。這就是為什麼網路上很多朋友都在糾結如何處理Exp/Imp的版本差異。而且,執行在客戶端上的Exp/Imp受網路影響很大,一旦操作時間較長網路不穩定,操作過程可能就以失敗告終。同時,exp/imp還存在很多效能、穩定性和特性支援上的不足。

 

 

Data Pump資料泵是執行在服務端,直接就減少了版本問題出現的可能。即使存在版本問題,使用version引數也可以進行有效的控制。此外單獨的作業執行,可以避免出現意外中斷的情況。

 

 

儘管如此,我們還是經常會遇到Data Pump的故障和問題,很多時候僅僅藉助提示資訊不能做到完全的診斷。這個時候,我們可以考慮使用Data Pump的隱藏引數Trace來生成跟蹤檔案,逐步排查錯誤。

 

1、  Data Pump工作原理和環境準備

 

Data Pump工作原理有兩個特點:作業排程,多程式配合協作。Oracle中,Data Pump是作為一個特定的Job來進行處理的,可以進行Job作業的啟動、終止、暫停,而且更重要的是Dump作業的工作過程是獨立於外部使用者的。也就是說,使用者不需要和Exp/Imp一樣“死盯著”介面,也不需要使用nohup &後臺作業化,就可以實現自動的後臺操作。

 

在工作中,Data Pump是一個多程式配合的工作。我們從工作日誌上就可以看到,每個Data Pump作業在建立的時候,會自動建立一個作業表,其中記錄操作過程。Job工作的時候有兩類Process程式工作,一個是master control process,負責整體過程協調,Work Process池管理,任務分配。實際進行匯入匯出的是Work process,如果設定了parallel引數,就會有多個Work Process進行資料工作。

 

Data Pump的診斷本質上就是對各種Process行為的跟蹤。Oracle提供了一個Trace的隱含引數,來幫助我們實現這個目標。

 

首先,我們準備一下Data Pump工作環境。開始需要準備Directory物件。

 

 

[root@SimpleLinux /]# ls -l | grep dumpdata

drwxr-xr-x   2 root   root      4096 Sep 11 09:01 dumpdata

[root@SimpleLinux /]# chown -R oracle:oinstall dumpdata/

[root@SimpleLinux /]# ls -l | grep dumpdata

drwxr-xr-x   2 oracle oinstall  4096 Sep 11 09:01 dumpdata

 

--建立directory物件

SQL> select * from v$version where rownum<2;

 

BANNER

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

Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - Producti

 

SQL> create directory dumpdir as '/dumpdata';

Directory created

 

 

2、隱含引數Trace

 

Trace引數是Data Pump隱含內部使用的一個引數。使用方法和其他資料泵引數相同,但是使用取值需要有一些注意之處。下面是我們實驗的Trace命令。

 

 

[oracle@SimpleLinux dumpdata]$ expdp \"/ as sysdba\" directory=dumpdir schemas=scott dumpfile=scott_dump.dmp parallel=2 trace=480300

 

Export: Release 11.2.0.3.0 - Production on Wed Sep 11 09:45:07 2013

 

 

Trace並不像其他跟蹤過程相同,使用y/n的引數,開啟或者關閉。Data PumpTrace引數是一個7位十六進位制組成的數字串。不同的數字串表示不同的跟蹤物件方法。7位十六進位制數字分為兩個部分,前三個數字表示特定的資料泵元件,後四位使用0300就可以。

 

根據Oracle MOS中提供資訊資料,Trace字元遵守如下設定規則:

 

ü  不要輸入超過7位長度;

ü  不需要使用0X指定十六進位制字元;

ü  不能將十六進位制字元轉化為數字取值;

ü  如果7位字元以0開頭,可以省略0

ü  輸入字元大小寫不敏感;

 

各個元件分別使用不同的三位十六進位制數字代表。如下片段所示:

 

 

-- Summary of Data Pump trace levels:
-- ==================================

  Trace   DM   DW  ORA  Lines
  level  trc  trc  trc     in
  (hex) file file file  trace                                         Purpose
------- ---- ---- ---- ------ -----------------------------------------------
  10300    x    x    x  SHDW: To trace the Shadow process (API) (expdp/impdp)
  20300    x    x    x  KUPV: To trace Fixed table
  40300    x    x    x  'div' To trace Process services
  80300    x            KUPM: To trace Master Control Process (MCP)      (DM)
 100300    x    x       KUPF: To trace File Manager
 200300    x    x    x  KUPC: To trace Queue services
 400300         x       KUPW: To trace Worker process(es)                (DW)
 800300         x       KUPD: To trace Data Package
1000300         x       META. To trace Metadata Package
--- +
1FF0300    x    x    x  'all' To trace all components          (full tracing)

 

 

如果需要同時跟蹤多個元件,需要將目標元件的hex值進行累加,後面四位的300相同。

 

目標Dump作業生成的Trace檔案,同其他Trace檔案沒有什麼本質差異。預設都是在BACKGROUP_DUMP_DEST目錄。但是注意,Data PumpTrace過程,會生成多個Trace檔案,而且定位需要知道dmdwProcess ID資訊。

 

筆者建議的一種方法是,如果系統業務不是非常繁忙,可以將目錄上的Trctrm檔案暫時儲存在其他的地方。再進行Trace作業,此時生成的檔案就可以明顯看出是哪些。

 

對於跟蹤的Trace取值,Oracle建議使用480300就可以應對大部分的情況。480300會跟蹤Oracle Dump作業的Master Control ProcessMCP)和Work Process作為初始化跟蹤的過程,480300基本就夠用了。

 

3Expdp Trace過程

 

我們先從資料匯出ExpdpTrace,匯出一個案例。首先清理一下Trace File目錄。

 

 

[oracle@SimpleLinux trace]$ rm *.trc

[oracle@SimpleLinux trace]$ rm *.trm

[oracle@SimpleLinux trace]$ ls -l

total 92

-rw-r----- 1 oracle oinstall 86384 Sep 11 09:37 alert_ora11g.log

 

 

呼叫命令,以兩個並行度的方法進行匯出動作。

 

 

[oracle@SimpleLinux dumpdata]$ expdp \"/ as sysdba\" directory=dumpdir schemas=scott dumpfile=scott_dump.dmp parallel=2 trace=480300

 

Export: Release 11.2.0.3.0 - Production on Wed Sep 11 09:45:07 2013

 

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

 

Connected to: Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - Production

With the Partitioning, OLAP, Data Mining and Real Application Testing options

Starting "SYS"."SYS_EXPORT_SCHEMA_01":  "/******** AS SYSDBA" directory=dumpdir schemas=scott dumpfile=scott_dump.dmp parallel=2 trace=480300

Estimate in progress using BLOCKS method...

Processing object type SCHEMA_EXPORT/TABLE/TABLE_DATA

Total estimation using BLOCKS method: 32.18 MB

Processing object type SCHEMA_EXPORT/USER

. . exported "SCOTT"."T_MASTER":"P1"                     42.43 KB     982 rows

Processing object type SCHEMA_EXPORT/SYSTEM_GRANT

Processing object type SCHEMA_EXPORT/ROLE_GRANT

(篇幅原因,有省略……

Processing object type SCHEMA_EXPORT/TABLE/CONSTRAINT/CONSTRAINT

Processing object type SCHEMA_EXPORT/TABLE/INDEX/STATISTICS/INDEX_STATISTICS

Processing object type SCHEMA_EXPORT/TABLE/CONSTRAINT/REF_CONSTRAINT

. . exported "SCOTT"."T_MASTER":"P2"                     88.69 KB    1859 rows

. . exported "SCOTT"."T_SLAVE":"P1"                      412.2 KB   11268 rows

. . exported "SCOTT"."T_SLAVE":"P2"                      975.7 KB   21120 rows

. . exported "SCOTT"."DEPT"                              5.929 KB       4 rows

. . exported "SCOTT"."EMP"                               8.562 KB      14 rows

. . exported "SCOTT"."SALGRADE"                          5.859 KB       5 rows

. . exported "SCOTT"."BONUS"                                 0 KB       0 rows

Master table "SYS"."SYS_EXPORT_SCHEMA_01" successfully loaded/unloaded

******************************************************************************

Dump file set for SYS.SYS_EXPORT_SCHEMA_01 is:

  /dumpdata/scott_dump.dmp

Job "SYS"."SYS_EXPORT_SCHEMA_01" successfully completed at 09:45:36

 

 

我們從日誌上能看出Parallel的一點不一樣,額外的T_MASTER.P1被提前匯出了。

 

新生成的Trace檔案目錄。

 

 

[oracle@SimpleLinux trace]$ ls -l

total 260

-rw-r----- 1 oracle oinstall 87421 Sep 11 09:45 alert_ora11g.log

-rw-r----- 1 oracle oinstall 40784 Sep 11 09:45 ora11g_dm00_3894.trc

-rw-r----- 1 oracle oinstall  1948 Sep 11 09:45 ora11g_dm00_3894.trm

-rw-r----- 1 oracle oinstall 73971 Sep 11 09:45 ora11g_dw00_3896.trc

-rw-r----- 1 oracle oinstall  1986 Sep 11 09:45 ora11g_dw00_3896.trm

-rw-r----- 1 oracle oinstall 27366 Sep 11 09:45 ora11g_dw01_3898.trc

-rw-r----- 1 oracle oinstall   982 Sep 11 09:45 ora11g_dw01_3898.trm

-rw-r----- 1 oracle oinstall  3016 Sep 11 09:45 ora11g_ora_3890.trc

-rw-r----- 1 oracle oinstall   209 Sep 11 09:45 ora11g_ora_3890.trm

 

 

Dmdw標註的就是MCPWork Process生成的Trace檔案。同時Parallel設定使得dw0001兩個。

 

在匯出過程中,我們可以看到兩個worker的會話資訊。

 

 

SQL> select * from dba_datapump_sessions;

 

OWNER_NAME          JOB_NAME     INST_ID SADDR    SESSION_TYPE

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

SYS     SYS_EXPORT_SCHEMA_01                    1 35EB0580 DBMS_DATAPUMP

SYS       SYS_EXPORT_SCHEMA_01                    1 35E95280 MASTER

SYS       SYS_EXPORT_SCHEMA_01                    1 35E8A480 WORKER

SYS       SYS_EXPORT_SCHEMA_01                    1 35E84D80 WORKER

 

 

此時我們可以從Trace檔案中,看到一些Data Pump工作的細節資訊。例如:在MCPTrace檔案中,我們看到一系列呼叫動作過程,如下片段:

 

--初始化匯出動作,整理檔案系統;

KUPM:09:45:08.720: ****IN DISPATCH at 35108, request type=1001

KUPM:09:45:08.721: Current user is: SYS

KUPM:09:45:08.721: hand := DBMS_DATAPUMP.OPEN ('EXPORT', 'SCHEMA', '', 'SYS_EXPORT_SCHEMA_01', '', '2');

KUPM:09:45:08.791: Resumable enabled

KUPM:09:45:08.799: Entered state: DEFINING

KUPM:09:45:08.799: initing file system

 

*** 2013-09-11 09:45:08.893

KUPM:09:45:08.893: ****OUT DISPATCH, request type=1001, response type =2041

 

--日誌寫入

KUPM:09:45:12.135: ****IN DISPATCH at 35112, request type=3031

KUPM:09:45:12.135: Current user is: SYS

KUPM:09:45:12.136: Log message received from worker DG,KUPC$C_1_20130911094507,KUPC$A_1_094510040559000,MCP,3,Y

KUPM:09:45:12.136: Processing object type SCHEMA_EXPORT/TABLE/TABLE_DATA

kwqberlst rqan->lascn_kwqiia > 0 block

kwqberlst rqan->lascn_kwqiia  4

kwqberlst ascn 986758 lascn 0

KUPM:09:45:12.137: ****OUT DISPATCH, request type=3031, response type =2041

 

 

Worker Process中,如下片段看出在匯出資料。

 

 

KUPW:09:45:12.153: 1:

KUPW:09:45:12.153: 1:

KUPW:09:45:12.153: 1: TABLE

KUPW:09:45:12.153: 1: SCOTT

KUPW:09:45:12.153: 1: DEPT

KUPW:09:45:12.154: 1: In procedure LOCATE_DATA_FILTERS

KUPW:09:45:12.154: 1: In function NEXT_PO_NUMBER

KUPW:09:45:12.161: 1: In procedure DETERMINE_METHOD_PARALLEL

KUPW:09:45:12.161: 1: flags mask: 0

KUPW:09:45:12.161: 1: dapi_possible_meth: 1

KUPW:09:45:12.161: 1: data_size: 65536

KUPW:09:45:12.161: 1: et_parallel: TRUE

KUPW:09:45:12.161: 1: object: TABLE_DATA:"SCOTT"."DEPT"

KUPW:09:45:12.164: 1: l_dapi_bit_mask: 7

KUPW:09:45:12.164: 1: l_client_bit_mask: 7

KUPW:09:45:12.164: 1: TABLE_DATA:"SCOTT"."DEPT" either, parallel: 1

KUPW:09:45:12.164: 1: In function GATHER_PARSE_ITEMS

KUPW:09:45:12.165: 1: In function CHECK_FOR_REMAP_NETWORK

KUPW:09:45:12.165: 1: Nothing to remap

KUPW:09:45:12.165: 1: In procedure BUILD_OBJECT_STRINGS

KUPW:09:45:12.165: 1: In DETERMINE_BASE_OBJECT_INFO

KUPW:09:45:12.165: 1: TABLE_DATA

KUPW:09:45:12.165: 1: SCOTT

KUPW:09:45:12.165: 1: EMP

 

 

4Impdp匯入過程

 

Trace過程中,我們也可以如10046跟蹤過程一樣,新增SQL跟蹤。Data Pump本質上工作還是一系列的SQL語句,很多時候的效能問題根源都是從SQL著手的。

 

切換到SQL跟蹤模式也比較簡單,一般是在Trace數值後面新增1。我們使用匯入過程進行實驗。

 

 

--處理之前

[root@SimpleLinux trace]# ls -l

total 4

-rw-r----- 1 oracle oinstall 552 Sep 11 10:49 alert_ora11g.log

 

[oracle@SimpleLinux dumpdata]$ impdp \"/ as sysdba\" directory=dumpdir dumpfile=scott_dump.dmp remap_schema=scott:test trace=480301 parallel=2

 

Import: Release 11.2.0.3.0 - Production on Wed Sep 11 10:50:14 2013

 

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

 

Connected to: Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - Production

With the Partitioning, OLAP, Data Mining and Real Application Testing options

Master table "SYS"."SYS_IMPORT_FULL_01" successfully loaded/unloaded

Starting "SYS"."SYS_IMPORT_FULL_01":  "/******** AS SYSDBA" directory=dumpdir dumpfile=scott_dump.dmp remap_schema=scott:test trace=480301 parallel=2

Processing object type SCHEMA_EXPORT/USER

Processing object type SCHEMA_EXPORT/SYSTEM_GRANT

Processing object type SCHEMA_EXPORT/ROLE_GRANT

Processing object type SCHEMA_EXPORT/DEFAULT_ROLE

Processing object type SCHEMA_EXPORT/PRE_SCHEMA/PROCACT_SCHEMA

Processing object type SCHEMA_EXPORT/TABLE/TABLE

Processing object type SCHEMA_EXPORT/TABLE/TABLE_DATA

. . imported "TEST"."T_MASTER":"P1"                      42.43 KB     982 rows

. . imported "TEST"."T_MASTER":"P2"                      88.69 KB    1859 rows

. . imported "TEST"."T_SLAVE":"P1"                       412.2 KB   11268 rows

. . imported "TEST"."T_SLAVE":"P2"                       975.7 KB   21120 rows

. . imported "TEST"."DEPT"                               5.929 KB       4 rows

. . imported "TEST"."EMP"                                8.562 KB      14 rows

. . imported "TEST"."SALGRADE"                           5.859 KB       5 rows

. . imported "TEST"."BONUS"                                  0 KB       0 rows

Processing object type SCHEMA_EXPORT/TABLE/COMMENT

Processing object type SCHEMA_EXPORT/TABLE/INDEX/INDEX

Processing object type SCHEMA_EXPORT/TABLE/CONSTRAINT/CONSTRAINT

Processing object type SCHEMA_EXPORT/TABLE/INDEX/STATISTICS/INDEX_STATISTICS

Processing object type SCHEMA_EXPORT/TABLE/CONSTRAINT/REF_CONSTRAINT

Job "SYS"."SYS_IMPORT_FULL_01" successfully completed at 10:50:24

 

 

檢視跟蹤目錄。

 

 

[root@SimpleLinux trace]# ls -l

total 7588

-rw-r----- 1 oracle oinstall     739 Sep 11 10:50 alert_ora11g.log

-rw-r----- 1 oracle oinstall 1916394 Sep 11 10:50 ora11g_dm00_4422.trc

-rw-r----- 1 oracle oinstall    9446 Sep 11 10:50 ora11g_dm00_4422.trm

-rw-r----- 1 oracle oinstall 2706475 Sep 11 10:50 ora11g_dw00_4424.trc

-rw-r----- 1 oracle oinstall   15560 Sep 11 10:50 ora11g_dw00_4424.trm

-rw-r----- 1 oracle oinstall 2977812 Sep 11 10:50 ora11g_ora_4420.trc

-rw-r----- 1 oracle oinstall   12266 Sep 11 10:50 ora11g_ora_4420.trm

-rw-r----- 1 oracle oinstall   29795 Sep 11 10:50 ora11g_p000_4426.trc

-rw-r----- 1 oracle oinstall     526 Sep 11 10:50 ora11g_p000_4426.trm

-rw-r----- 1 oracle oinstall   30109 Sep 11 10:50 ora11g_p001_4428.trc

-rw-r----- 1 oracle oinstall     524 Sep 11 10:50 ora11g_p001_4428.trm

-rw-r----- 1 oracle oinstall    8430 Sep 11 10:50 ora11g_p002_4430.trc

-rw-r----- 1 oracle oinstall     184 Sep 11 10:50 ora11g_p002_4430.trm

-rw-r----- 1 oracle oinstall    8432 Sep 11 10:50 ora11g_p003_4432.trc

-rw-r----- 1 oracle oinstall     204 Sep 11 10:50 ora11g_p003_4432.trm

 

 

目錄生成的Trace檔案,都是10046格式的Raw檔案。擷取片段如下:

 

 

=====================

PARSING IN CURSOR #13035136 len=51 dep=2 uid=0 ct=3 lid=0 tim=1378867817703043 hv=1523794037 ad='360b079c' sqlid='b1wc53ddd6h3p'

select audit$,options from procedure$ where obj#=:1

END OF STMT

PARSE #13035136:c=0,e=96,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=1637390370,tim=1378867817703039

EXEC #13035136:c=0,e=79,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=1637390370,tim=1378867817703178

FETCH #13035136:c=0,e=53,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=4,plh=1637390370,tim=1378867817703248

STAT #13035136 id=1 cnt=1 pid=0 pos=1 bj=221 p='TABLE ACCESS BY INDEX ROWID PROCEDURE$ (cr=3 pr=0 pw=0 time=53 us cost=2 size=47 card=1)'

STAT #13035136 id=2 cnt=1 pid=1 pos=1 bj=231 p='INDEX UNIQUE SCAN I_PROCEDURE1 (cr=2 pr=0 pw=0 time=24 us cost=1 size=0 card=1)'

CLOSE #13035136:c=0,e=7,dep=2,type=1,tim=1378867817703387

=====================

 

 

5、結論

 

Oracle Data Pump已經非常成熟,也越來越多被人們接受。Trace引數尤其存在的歷史背景,相信使用的機會越來越少。不過,作為研究內部機制的用途,還是比較有用的。

 

來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/17203031/viewspace-772718/,如需轉載,請註明出處,否則將追究法律責任。

相關文章