Oracle 11g - Export / import Datapump : Activer des traces dans les logs

Qui ne c'est jamais demandé pourquoi la durée d'un export Full datapump passe du simple au double voir pire, du jour au lendemain ?

Dans le blog de Laurent, il y a un article sur Oracle 12c R1, où des options sont possibles pour réaliser des exports / imports avec des traces et métriques (voir ici ) mais cela est également valable en 11G.

En effet, via les deux paramètres TRACE et METRICS, il est possible d'affiner nos diagnostiques, de trouver des réponses voir même des solutions, alors c'est parti !

/home/oracle[ORCL]:expdp user/pass dumpfile=datapump:exptest.dmp logfile=datapump:exptest.log schemas='MYSCHEMA' full=n trace=1FF0300 metrics=Y 

Export: Release 11.2.0.3.0 - Production on Jeu. Oct. 2 15:19:49 2014
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.

Connecté à : Oracle Database 11g Release 11.2.0.3.0 - 64bit Production
With the Real Application Clusters and Automatic Storage Management options 
Démarrage de "EXPDBA"."SYS_EXPORT_SCHEMA_03" : expdba/******** dumpfile=datapump:exptest.dmp logfile=datapump:exptest.log 
schemas=MYSCHEMA full=n trace=1FF0300 metrics=Y 
Estimation en cours à l'aide de la méthode BLOCKS ... 
Traitement du type d'objet SCHEMA_EXPORT/TABLE/TABLE_DATA 
Estimation totale à l'aide le la méthode BLOCKS : 208.1 MB
Traitement du type d'objet SCHEMA_EXPORT/USER
1 USER objets terminés en 0 secondes 
Traitement du type d'objet SCHEMA_EXPORT/SYSTEM_GRANT 
5 SYSTEM_GRANT objets terminés en 0 secondes 
Traitement du type d'objet SCHEMA_EXPORT/ROLE_GRANT 
4 ROLE_GRANT objets terminés en 0 secondes 
Traitement du type d'objet SCHEMA_EXPORT/DEFAULT_ROLE 
1 DEFAULT_ROLE objets terminés en 1 secondes 
Traitement du type d'objet SCHEMA_EXPORT/TABLESPACE_QUOTA 
1 TABLESPACE_QUOTA objets terminés en 2 secondes 
Traitement du type d'objet SCHEMA_EXPORT/PRE_SCHEMA/PROCACT_SCHEMA 
1 PROCACT_SCHEMA objets terminés en 8 secondes 
Traitement du type d'objet SCHEMA_EXPORT/TABLE/TABLE 
33 TABLE objets terminés en 2 secondes 
Traitement du type d'objet SCHEMA_EXPORT/TABLE/GRANT/OWNER_GRANT/OBJECT_GRANT 
1 OBJECT_GRANT objets terminés en 1 secondes 
Traitement du type d'objet SCHEMA_EXPORT/PACKAGE/PACKAGE_SPEC 
1 PACKAGE objets terminés en 2 secondes 
Traitement du type d'objet SCHEMA_EXPORT/PROCEDURE/PROCEDURE 
1 PROCEDURE objets terminés en 0 secondes 
Traitement du type d'objet SCHEMA_EXPORT/PACKAGE/COMPILE_PACKAGE/PACKAGE_SPEC/ALTER_PACKAGE_SPEC 
1 ALTER_PACKAGE_SPEC objets terminés en 0 secondes 
Traitement du type d'objet SCHEMA_EXPORT/PROCEDURE/ALTER_PROCEDURE 
1 ALTER_PROCEDURE objets terminés en 0 secondes 
Traitement du type d'objet SCHEMA_EXPORT/TABLE/INDEX/INDEX 
13 INDEX objets terminés en 4 secondes 
Traitement du type d'objet SCHEMA_EXPORT/TABLE/CONSTRAINT/CONSTRAINT 
1 CONSTRAINT objets terminés en 0 secondes 
Traitement du type d'objet SCHEMA_EXPORT/TABLE/INDEX/STATISTICS/INDEX_STATISTICS 
13 INDEX_STATISTICS objets terminés en 0 secondes 
Traitement du type d'objet SCHEMA_EXPORT/PACKAGE/PACKAGE_BODY 
1 PACKAGE_BODY objets terminés en 1 secondes 
Traitement du type d'objet SCHEMA_EXPORT/TABLE/CONSTRAINT/REF_CONSTRAINT 
3 REF_CONSTRAINT objets terminés en 5 secondes 
Traitement du type d'objet SCHEMA_EXPORT/EVENT/TRIGGER 
1 TRIGGER objets terminés en 0 secondes 
Traitement du type d'objet SCHEMA_EXPORT/TABLE/STATISTICS/TABLE_STATISTICS 
33 TABLE_STATISTICS objets terminés en 12 secondes 
Traitement du type d'objet SCHEMA_EXPORT/JOB 
14 JOB objets terminés en 1 secondes . . 
export : "MYSCHEMA"."TBL0" 120.7 MB 2400663 lignes . .
export : "MYSCHEMA"."TBL1" 22.74 MB 381140 lignes 
Table maître "EXPDBA"."SYS_EXPORT_SCHEMA_03" chargée/déchargée avec succès 
*****************************************************************************
L'ensemble de fichiers de vidage de EXPDBA.SYS_EXPORT_SCHEMA_03 est : /ora/export/exptest.dmp 
L'exécution du travail "EXPDBA"."SYS_EXPORT_SCHEMA_03" a abouti à 15:22:26

Dans cet exemple j'ai paramétré une full trace mais il est possible d'affiner via les codes ci dessous :

10300 SHDW: To trace the Shadow process
20300 KUPV: To trace Fixed table
40300 'div' To trace Process services
80300 KUPM: To trace Master Control Process
100300 KUPF: To trace File Manager
200300 KUPC: To trace Queue services
400300 KUPW: To trace Worker process(es)
800300 KUPD: To trace Data Package
1000300 META: To trace Metadata Package
1FF0300 'all' To trace all components, full tracing

Note : L'option METRICS dans cet exemple n'est pas obligatoire, mais pratique car elle permet d'avoir des informations liées au nombre d'objets ainsi qu'à la durée d’exécution de chaque étapes.

Mais revenons à la trace qui a été précédemment paramétrée car dans cet exemple (Trace = 1FF0300), trois fichiers traces ont été crées et sont disponibles dans la home directory d'ADRCI.

Allons donc y jeter un oeil, en récupérant avant tout l'emplacement de la HOME ADRCI :

SQL> select value from v$diag_info where NAME='Diag Trace';

VALUE 
--------------------------------------
/oracle/admin/diag/diag/rdbms/ORCL/ORCL/trace

Les traces sont de la forme :

SID_dm_process_id.trc -- Data Pump Master Control Processes files
SID_dw_process_id.trc -- Data Pump Worker Process trace files
SID_ora_process_id.trc -- Data Pump Shadow Process trace files

Prenons l'exemple de la trace du Worker process ci dessus (à mon sens le plus utile dans les analyses) :

/home/oracle[ORCL]: cat /oracle/admin/diag/diag/rdbms/ORCL/ORCL/trace/ORCL_dw_9382.trc

KUPC:15:25:01.957: Added agent KUPC$A_1_152501651115000 
KUPC:15:25:01.957: to queue SYS.KUPC$C_1_20141002152459 
KUPW:15:25:01.959: 0: KUPP$PROC.WHATS_MY_ID called. 
KUPW:15:25:01.959: 1: KUPP$PROC.WHATS_MY_ID returned. 
KUPW:15:25:01.960: 1: worker max message number: 1000 
KUPW:15:25:01.961: 1: Full cluster access allowed 
KUPW:15:25:01.962: 1: Original job start time: 14-OCT. -02 03:25:00 PM 
$KUPW:15:25:01.964: 1: Seqno 63 is SCHEMA_EXPORT/TABLE/TABLE_DATA 
KUPW:15:25:01.964: 1: Seqno 243 is SCHEMA_EXPORT/TABLE/INDEX/TABLE_DATA 
KUPW:15:25:01.964: 1: KUPP$PROC.WHATS_MY_NAME called. 
KUPW:15:25:01.964: 1: KUPP$PROC.WHATS_MY_NAME returned. Process name: DW00 
KUPW:15:25:01.964: 1: KUPV$FT_INT.GET_INSTANCE_ID called. 
KUPW:15:25:01.969: 1: KUPV$FT_INT.GET_INSTANCE_ID returned. Instance name: SRV1:MYBASE
KUPV:15:25:01.970: Has Privs test for Operation: EXPORT, Caller type: 3 
KUPV:15:25:01.970: Linkname: , Product: 4 
KUPW:15:25:01.972: 1: ALTER SESSION ENABLE RESUMABLE called. 
KUPW:15:25:01.972: 1: ALTER SESSION ENABLE RESUMABLE returned. 
KUPW:15:25:01.973: 1: KUPF$FILE.INIT called. 
SHDW:15:25:01.973: *** DATAPUMP_JOB call *** 
KUPF:15:25:01.985: In INIT_CB 
KUPF:15:25:01.986: dump file version: 769 
KUPF:15:25:01.986: dviDmpCaps1: 98559 
KUPF:15:25:01.986: dviDmpCaps1: 98543 
KUPF:15:25:01.986: dviDmpCaps1: 98511 
KUPF:15:25:01.986: dviDmpCaps1: 98447 
KUPF:15:25:01.986: dump file block size: 4096 
KUPF:15:25:01.986: metadata buffer size: 131072 
KUPF:15:25:01.986: table data buffer size: 262144 
KUPF:15:25:01.986: min phy block size: 512 
KUPF:15:25:01.986: max phy block size: 32768 
KUPF:15:25:01.986: metadata compression: 1 
KUPF:15:25:01.986: tabldata compression: 0 
KUPF:15:25:01.986: metadata encryption: 0 
KUPF:15:25:01.986: tabldata encryption: 0 
KUPF:15:25:01.986: column encryption: 0 
KUPF:15:25:01.986: job version: 11.02.00.00.00 .... .... 
KUPW:15:25:01.996: 1: Master table : "EXPDBA"."SYS_EXPORT_SCHEMA_03" 
KUPW:15:25:01.996: 1: Metadata job mode : SCHEMA_EXPORT 
KUPW:15:25:01.996: 1: Debug enable : TRUE 
KUPW:15:25:01.996: 1: Profile enable : FALSE 
KUPW:15:25:01.996: 1: Transportable enable : FALSE 
KUPW:15:25:01.996: 1: Metrics enable : TRUE 
KUPW:15:25:01.996: 1: db version : 11.2.0.3.0 
KUPW:15:25:01.996: 1: job version : 11.2.0.0.0 
KUPW:15:25:01.996: 1: service name : 
KUPW:15:25:01.996: 1: Current Edition : ORA$BASE 
KUPW:15:25:01.996: 1: Job Edition : 
KUPW:15:25:01.996: 1: Abort Step : 0 
KUPW:15:25:01.996: 1: Access Method : DIRECT_PATH 
KUPW:15:25:01.996: 1: Data Options : 0 
KUPW:15:25:01.996: 1: Dumper directory : 
KUPW:15:25:01.996: 1: Master only : FALSE 
KUPW:15:25:01.996: 1: Data Only : FALSE 
KUPW:15:25:01.996: 1: Metadata Only : FALSE 
KUPW:15:25:01.996: 1: Estimate : BLOCKS 
KUPW:15:25:01.996: 1: Data error logging table : 
KUPW:15:25:01.996: 1: Remote Link : 
KUPW:15:25:01.996: 1: Dumpfile present : TRUE 
KUPW:15:25:01.996: 1: Table Exists Action : 
KUPW:15:25:01.996: 1: Partition Options : NONE 
KUPW:15:25:01.996: 1: Tablespace Datafile Count: 0 
KUPW:15:25:01.996: 1: Metadata Filter Index : 1 Count : 8 
KUPW:15:25:01.996: 1: 1 Name - INCLUDE_USER 
KUPW:15:25:01.996: 1: Value - TRUE 
KUPW:15:25:01.996: 1: Object Name - SCHEMA_EXPORT 
KUPW:15:25:01.996: 1: 2 Name - SCHEMA_EXPR 
KUPW:15:25:01.996: 1: Value - IN ('MYSCHEMA') 
KUPW:15:25:01.996: 1: 3 Name - ORDERED 
KUPW:15:25:01.996: 1: Value - FALSE 
KUPW:15:25:01.996: 1: Object - TABLE_DATA 
KUPW:15:25:01.996: 1: 4 Name - NO_XML 
KUPW:15:25:01.997: 1: Value - TRUE 
KUPW:15:25:01.997: 1: Object - XMLSCHEMA/EXP_XMLSCHEMA 
KUPW:15:25:01.997: 1: 5 Name - XML_OUTOFLINE 
KUPW:15:25:01.997: 1: Value - FALSE 
KUPW:15:25:01.997: 1: Object - TABLE/TABLE_DATA 
KUPW:15:25:01.997: 1: 6 Name - XDB_GENERATED 
KUPW:15:25:01.997: 1: Value - FALSE 
KUPW:15:25:01.997: 1: Object - TABLE/TRIGGER 
KUPW:15:25:01.997: 1: 7 Name - XDB_GENERATED 
KUPW:15:25:01.997: 1: Value - FALSE 
KUPW:15:25:01.997: 1: Object - TABLE/RLS_POLICY 
KUPW:15:25:01.997: 1: 8 Name - PRIVILEGED_USER

A la première lecture, c'est un peu brut de fonderie il faut l'admettre. Certaines informations peuvent néanmoins nous aider et nous aiguiller dans la direction d'une note Oracle, ou encore pour ouvrir un SR au support avec des informations plus précises dans l'objectif (par exemple) d'identifier un bug, et ainsi bénéficier d'un fix.

A adapter en fonction des contextes d'études, mais qui peut s'avérer pratique pour pointer du doigt la cause de notre export si long !

@+

Micka