While importing a dump file, sometimes it takes too long and seems to be “hanging” and processing something unknown in the background, or queuing for something. As a DBA, you HAVE NOT wait “until it finishes”. You have to try to find out the solution.
Yesterday, while importing a metadata of a big database, the session hold and took hours to finish.
This is the command I run to import the dump file into the new database:
impdp system/oracle directory=mydir dumpfile=dump01.dmp exclude=tablespace, statistics parfile=param.ini METRICS=y
The session was hold in the following section:
Processing object type DATABASE_EXPORT/SCHEMA/CLUSTER/CLUSTER
Completed 1 CLUSTER objects in 0 seconds
Processing object type DATABASE_EXPORT/SCHEMA/CLUSTER/INDEX
Completed 1 INDEX objects in 0 seconds
Processing object type DATABASE_EXPORT/SCHEMA/TABLE/TABLE
Note: I suggest that we use undocumented METRICS=Y parameter to get information about the number of objects and the time it takes to process them into the log file
I waited shortly and was curious about the activities in the background, so decided to debug the Data Pump session and run the following query to get the SID and SERIAL number of the running data pump sessions. These values will be used to trace the session in the next step:
col username format a10
set linesize 150
col job_name format a20
col program format a25
SELECT TO_CHAR (SYSDATE, ‘YYYY-MM-DD HH24:MI:SS’) “DATE”,
s.program,
s.sid,
s.status,
s.username,
d.job_name,
p.spid,
s.serial#,
p.pid
FROM V$SESSION s, V$PROCESS p, DBA_DATAPUMP_SESSIONS d
WHERE p.addr = s.paddr AND s.saddr = d.saddr;
DATE PROGRAM SID STATUS USERNAME JOB_NAME SPID SERIAL# PID
——————- ————————- ———- ——– ———- ——————– ———— ———- ———-
2013-03-07 14:52:04 udi@TestDB02 (TNS V1-V3) 152 ACTIVE SYSTEM SYS_IMPORT_FULL_01 12143 36 17
2013-03-07 14:52:04 oracle@TestDB02 (DM00) 148 ACTIVE SYSTEM SYS_IMPORT_FULL_01 12147 3 19
2013-03-07 14:52:04 oracle@TestDB02 (DW01) 142 ACTIVE SYSTEM SYS_IMPORT_FULL_01 12149 15 20
Then I queried V$SESSION_WAIT view to get the waiting event:
SELECT w.sid, w.event, w.seconds_in_wait
FROM V$SESSION s, DBA_DATAPUMP_SESSIONS d, V$SESSION_WAIT w
WHERE s.saddr = d.saddr AND s.sid = w.sid;
SID EVENT SECONDS_IN_WAIT
———- —————————————————————- —————
142 control file sequential read 1
148 wait for unread message on broadcast channel 43
152 wait for unread message on broadcast channel 306
If you run the same query a number of times, you’ll see how the wait event changes:
To get detailed information I decided to debug the first session (SID = 142) and provided values of SID and SERIAL# columns to DBMS_SYSTEM.SET_EV procedure and started the trace:
SQL> EXECUTE SYS.DBMS_SYSTEM.SET_EV (142,15,10046,8,”);
Then I switched to udump folder and checked the file labeled “dbname_ora_PID” – “testdb_ora_12149”
-bash-4.2$ tail -f testdb_ora_12149.trc
WAIT #4: nam=’Data file init write’ ela= 3 count=4294967295 intr=32 timeout=2147483647 obj#=51780 tim=13410366772411
WAIT #4: nam=’control file sequential read’ ela= 21 file#=0 block#=1 blocks=1 obj#=51780 tim=13410366772623
WAIT #4: nam=’control file sequential read’ ela= 15 file#=1 block#=1 blocks=1 obj#=51780 tim=13410366772660
WAIT #4: nam=’control file sequential read’ ela= 15 file#=2 block#=1 blocks=1 obj#=51780 tim=13410366772695
WAIT #4: nam=’control file sequential read’ ela= 13 file#=0 block#=16 blocks=1 obj#=51780 tim=13410366772728
WAIT #4: nam=’control file sequential read’ ela= 13 file#=0 block#=18 blocks=1 obj#=51780 tim=13410366772760
WAIT #4: nam=’control file sequential read’ ela= 13 file#=0 block#=24 blocks=1 obj#=51780 tim=13410366772802
WAIT #4: nam=’db file sequential read’ ela= 12 file#=4 block#=1 blocks=1 obj#=51780 tim=13410366772834
WAIT #4: nam=’db file single write’ ela= 11313 file#=4 block#=1 blocks=1 obj#=51780 tim=13410366784170
WAIT #4: nam=’control file parallel write’ ela= 38910 files=3 block#=17 requests=3 obj#=51780 tim=13410366823104
WAIT #4: nam=’control file parallel write’ ela= 46532 files=3 block#=15 requests=3 obj#=51780 tim=13410366869661
WAIT #4: nam=’control file parallel write’ ela= 40258 files=3 block#=1 requests=3 obj#=51780 tim=13410366909955
WAIT #4: nam=’control file sequential read’ ela= 12 file#=0 block#=1 blocks=1 obj#=51780 tim=13410366909986
WAIT #4: nam=’rdbms ipc reply’ ela= 7016 from_process=5 timeout=21474836 p3=0 obj#=51780 tim=13410366917049
=====================
PARSING IN CURSOR #15 len=296 dep=3 uid=0 oct=6 lid=0 tim=13410366917452 hv=2379717279 ad=’de799c58′
update seg$ set type#=:4,blocks=:5,extents=:6,minexts=:7,maxexts=:8,extsize=:9,extpct=:10,user#=:11,iniexts=:12,lists=decode(:13, 65535, NULL, :13),groups=decode(:14, 65535, NULL, :14), cachehint=:15, hwmincr=:16, spare1=DECODE(:17,0,NULL,:17),scanhint=:18 where ts#=:1 and file#=:2 and block#=:3
END OF STMT
PARSE #15:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=3,tim=13410366917447
EXEC #15:c=0,e=337,p=0,cr=5,cu=1,mis=0,r=1,dep=3,og=3,tim=13410366918000
STAT #15 id=1 cnt=0 pid=0 pos=1 obj=0 op=’UPDATE SEG$ (cr=5 pr=0 pw=0 time=277 us)’
STAT #15 id=2 cnt=1 pid=1 pos=1 obj=14 op=’TABLE ACCESS CLUSTER SEG$ (cr=5 pr=0 pw=0 time=166 us)’
STAT #15 id=3 cnt=1 pid=2 pos=1 obj=9 op=’INDEX UNIQUE SCAN I_FILE#_BLOCK# (cr=2 pr=0 pw=0 time=31 us)’
By using tkprof I formatted content of the trace file into a readable output:
tkprof testdb_ora_12149.trc impdp_output.dat
And read the file:
insert into seg$ (file#,block#,type#,ts#,blocks,extents,minexts,maxexts,
extsize,extpct,user#,iniexts,lists,groups,cachehint,bitmapranges,hwmincr,
spare1, scanhint)
values
(:1,:2,:3,:4,:5,:6,:7,:8,:9,:10,:11,:12,:13,:14,:15,0,:16,DECODE(:17,0,NULL,
:17),:18)
call count cpu elapsed disk query current rows
——- —— ——– ———- ———- ———- ———- ———-
Parse 905 0.04 0.01 0 0 0 0
Execute 905 0.26 0.32 0 2756 6420 905
Fetch 0 0.00 0.00 0 0 0 0
——- —— ——– ———- ———- ———- ———- ———-
total 1810 0.30 0.34 0 2756 6420 905
Everything is fine. It’s importing the metadata into the database by inserting data to the seg$ (segments) table. I used tail command to get the output of the trace file and run the first query.
After a delay, I got “statement suspended, wait error to be cleared” message, checked alert.log file and found that the USERS tablespace is FULL
SQL> /
SID EVENT SECONDS_IN_WAIT
———- —————————————————————- —————
142 statement suspended, wait error to be cleared 20
148 wait for unread message on broadcast channel 905
152 wait for unread message on broadcast channel 246
SQL>
tail –f Alert.log file
statement in resumable session ‘SYSTEM.SYS_IMPORT_FULL_01.1’ was suspended due to
ORA-01658: unable to create INITIAL extent for segment in tablespace USERS
After adding some space to the USERS tablespace the message disappeared.
Then suddenly I begin receiving “data file init write” wait event. That was the main reasons why the import took much time.
The reason was that the AUTOEXTEND value of the datafile was set very low and Oracle was making too many calls to OS in order to add new extents
The output from the trace file was as follows:
WAIT #4: nam=’Data file init write’ ela= 3 count=4294967295 intr=32 timeout=2147483647 obj#=51780 tim=13410366772411
In order to define the tablespace which is the cause of this event, I got the object id from the trace file (obj#=51780) and checked obj$ table.
SELECT name
FROM OBJ$
WHERE obj# = 51780
Then using DBMS_METADATA.GET_DLL function I got the tablespace name of the object that couldn’t be imported
SELECT DBMS_METADATA.get_ddl (‘TABLE’, ‘TAB_TEST’, ‘USR01’) FROM DUAL
As the ‘Data file init write’ event directly relates to AUTOEXTEND and occurs while adding extents to the datafile, I checked AUTOEXTEND value of the datafiles. Their values were too small. I increased the AUTOEXTEND values and the event disappeared from the trace log and import job finished successfully.
Reference: Export/Import DataPump Parameter TRACE – How to Diagnose Oracle Data Pump [ID 286496.1]
