Oracle impdp running way too long
I'm trying to import a schema into an oracle instance, that's running in a docker container (hopefully this is not relevant).
I would like to apologize in advance for the long post, but I wanted to include all I have already checked.
The import quickly loads the tables, builds the indexes, but when it gets to the packages progress just stops.
The log output stops with these lines
Processing object type SCHEMA_EXPORT/VIEW/COMMENT
Processing object type SCHEMA_EXPORT/PACKAGE/PACKAGE_BODY
It appears to be stuck in process 273, "ALTER PACKAGE ..."
set linesize 200
select s.username, s.sid, s.process, s.status, t.command_type, t.sql_text
from v$session s
, v$sqltext t
where t.sql_id = s.sql_id
order by t.sql_id, t.piece
USERNAME SID PROCESS STATUS COMMAND_TYPE SQL_TEXT
------------------------------ ---------- ------------------------ -------- ------------ ----------------------------------------------------------------
SYS 192 266 ACTIVE 47 BEGIN :1 := sys.kupc$que_int.get_status(:2, :3); END;
SYS 195 699 ACTIVE 3 select s.username, s.sid, s.process, s.status, t.command_type, t
SYS 195 699 ACTIVE 3 .sql_text from v$session s , v$sqltext t where t.sql_id
SYS 195 699 ACTIVE 3 = s.sql_id order by t.sql_id, t.piece
SYS 7 273 ACTIVE 98 ALTER PACKAGE "XXX"."XXX_AQ_PUT" COMPILE BODY PLSQL_OPTIM
SYS 7 273 ACTIVE 98 IZE_LEVEL= 2 PLSQL_CODE_TYPE= INTERPRETED PLSQL_DEBUG=
SYS 7 273 ACTIVE 98 FALSE PLSCOPE_SETTINGS= 'IDENTIFIERS:NONE' REUSE SETTINGS TI
SYS 7 273 ACTIVE 98 MESTAMP '2015-06-02 13:31:03'
SYS 196 271 ACTIVE 47 BEGIN :1 := sys.kupc$que_int.receive(:2); END;
but "ps agxu" reveals that process 273 uses a lot of CPU
oracle 119 0.0 0.0 1782464 14724 ? Ss 10:56 0:01 ora_pmon_xxxdb
oracle 121 0.0 0.0 1780172 11276 ? Ss 10:56 0:02 ora_vktm_xxxdb
oracle 125 0.0 0.0 1780172 11216 ? Ss 10:56 0:00 ora_gen0_xxxdb
oracle 127 0.0 0.0 1780172 11228 ? Ss 10:56 0:00 ora_diag_xxxdb
oracle 129 0.0 0.0 1780172 19120 ? Ss 10:56 0:00 ora_dbrm_xxxdb
oracle 131 0.0 0.0 1780172 11504 ? Ss 10:56 0:00 ora_psp0_xxxdb
oracle 133 0.0 0.0 1780684 14884 ? Ss 10:56 0:04 ora_dia0_xxxdb
oracle 135 0.0 0.3 1780172 109800 ? Ss 10:56 0:00 ora_mman_xxxdb
oracle 137 0.0 1.3 1817344 439448 ? Ss 10:56 0:02 ora_dbw0_xxxdb
oracle 139 0.0 0.0 1796924 20736 ? Ss 10:56 0:01 ora_lgwr_xxxdb
oracle 141 0.0 0.0 1780684 29472 ? Ss 10:56 0:02 ora_ckpt_xxxdb
oracle 143 0.0 0.3 1786832 108004 ? Ss 10:56 0:01 ora_smon_xxxdb
oracle 145 0.0 0.0 1781708 20928 ? Ss 10:56 0:00 ora_reco_xxxdb
oracle 147 0.0 0.1 1786180 62136 ? Ss 10:56 0:01 ora_mmon_xxxdb
oracle 149 0.0 0.0 1780172 19240 ? Ss 10:56 0:00 ora_mmnl_xxxdb
oracle 151 0.0 0.0 1803680 11540 ? Ss 10:56 0:00 ora_d000_xxxdb
oracle 153 0.0 0.0 1781368 10352 ? Ss 10:56 0:00 ora_s000_xxxdb
oracle 163 0.0 0.0 1780172 13140 ? Ss 10:56 0:00 ora_qmnc_xxxdb
oracle 228 0.0 0.0 9508 1288 ? S 10:56 0:00 /bin/bash /home/oracle/bin/import-dump
oracle 243 0.0 0.1 1784780 56672 ? Ss 10:56 0:01 ora_cjq0_xxxdb
oracle 263 0.0 0.0 1783616 25872 ? Ss 10:56 0:00 ora_q001_xxxdb
oracle 266 0.0 0.0 64128 12920 ? S 10:57 0:00 impdp as sysdba' directory=data dumpfile=xxx_exp.dmp schemas=xxx version=11.1
oracle 267 0.0 0.3 1796312 115144 ? Ss 10:57 0:04 oraclexxxdb (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle 269 0.0 0.0 1780916 15944 ? Ss 10:57 0:00 ora_q002_xxxdb
oracle 271 0.0 0.3 1828020 117032 ? Ss 10:57 0:04 ora_dm00_xxxdb
oracle 273 98.1 3.9 1981864 1293136 ? Rs 10:57 216:44 ora_dw00_xxxdb
oracle 275 0.0 0.0 1790988 20540 ? Ss 10:57 0:01 ora_smco_xxxdb
oracle 277 0.0 0.0 1790920 28676 ? Ss 10:57 0:01 ora_w000_xxxdb
There is plenty of free diskspace, and the tablespaces can expand as seen from this report
set linesize 150
set pagesize 50
col "Tablespace" for a25
col "Used MB" for 99,999
col "Free MB" for 99,999
col "Total MB" for 99,999
col "Max MB" for 99,999
select df.tablespace_name "Tablespace"
, totalusedspace "Used MB"
, (df.totalspace - tu.totalusedspace) "Free MB"
, df.totalspace "Total MB"
, round(100 * ( (df.totalspace - tu.totalusedspace)/ df.totalspace)) "Pct. Free"
, MaxSpace "Max MB"
from (
select tablespace_name
, round(sum(bytes) / 1048576) TotalSpace
, round(sum(
case
when maxbytes = 0 then bytes
else maxbytes
end
) / 1024 / 1024) MaxSpace
from dba_data_files
group by tablespace_name
) df,
(
select round(sum(bytes)/(1024*1024)) totalusedspace
, tablespace_name
from dba_segments
group by tablespace_name
) tu
where df.tablespace_name = tu.tablespace_nam
Tablespace Used MB Free MB Total MB Pct. Free Max MB
------------------------- ------- ------- -------- ---------- -------
SYSAUX 455 25 480 5 32,768
UNDOTBS1 127 3 130 2 32,768
XXX_T_256K 50 2 52 4 32,768
XXX_T_8M 858 43 901 5 32,768
XXX_T_256M 11,664 642 12,306 5 65,536
USERS 0 5 5 100 32,768
SYSTEM 684 6 690 1 32,768
XXX_I_8M 584 29 613 5 32,768
XXX_I_256K 5 1 6 17 32,768
XXX_I_256M 34,496 1,772 36,268 5 65,536
There are no blocking locks
set lines 200
set pages 50
col object1 for a30
col object2 for a30
select l.*, o1.owner || '.' || o1.object_name object1, o2.owner || '.' || o2.object_name object2
from v$lock l
, dba_objects o1
, dba_objects o2
where o1.object_id = l.id1
and o2.object_id(+) = l.id2
ADDR KADDR SID TY ID1 ID2 LMODE REQUEST CTIME BLOCK OBJECT1 OBJECT2
---------------- ---------------- ---------- -- ---------- ---------- ---------- ---------- ---------- ---------- ------------------------------ ------------------------------
00000000BFC51AC8 00000000BFC51B20 7 TO 12697 1 3 0 11738 0 SYS.IMPDP_STATS .
00000000BFC50F50 00000000BFC50FA8 3 RS 25 1 2 0 12155 0 SYS.PROXY_ROLE_DATA$ .
00000000BFC519E0 00000000BFC51A38 66 TS 3 1 3 0 12155 0 SYS.I_OBJ# .
00000000BFC51910 00000000BFC51968 127 MR 201 0 4 0 12155 0 SYS.I_SQL$TEXT_HANDLE .
00000000BFC510F0 00000000BFC51148 7 AE 100 0 4 0 12087 0 SYS.ORA$BASE .
00000000BFC51360 00000000BFC513B8 192 AE 100 0 4 0 12092 0 SYS.ORA$BASE .
00000000BFC51430 00000000BFC51488 190 AE 100 0 4 0 12154 0 SYS.ORA$BASE .
00000000BFC51B98 00000000BFC51BF0 196 AE 100 0 4 0 12090 0 SYS.ORA$BASE .
00000000BFC51C68 00000000BFC51CC0 195 AE 100 0 4 0 180 0 SYS.ORA$BASE .
00000000BFC527E0 00000000BFC52838 127 MR 11 0 4 0 12093 0 SYS.I_USER# .
00000000BFC50DB0 00000000BFC50E08 3 XR 4 0 1 0 12159 0 SYS.TAB$ .
00000000BFC51840 00000000BFC51898 127 MR 4 0 4 0 12155 0 SYS.TAB$ .
00000000BFC516A0 00000000BFC516F8 127 MR 2 0 4 0 12155 0 SYS.C_OBJ# .
00000000BFC528B0 00000000BFC52908 127 MR 12 0 4 0 12093 0 SYS.FET$ .
00000000BFC52628 00000000BFC52680 127 MR 10 0 4 0 12093 0 SYS.C_USER# .
00000000BFC52558 00000000BFC525B0 127 MR 8 0 4 0 12093 0 SYS.C_FILE#_BLOCK# .
00000000BFC52218 00000000BFC52270 127 MR 5 0 4 0 12093 0 SYS.CLU$ .
00000000BFC522E8 00000000BFC52340 127 MR 6 0 4 0 12093 0 SYS.C_TS# .
00000000BFC52488 00000000BFC524E0 127 MR 7 0 4 0 12093 0 SYS.I_TS# .
00000000BFC523B8 00000000BFC52410 127 MR 9 0 4 0 12093 0 SYS.I_FILE#_BLOCK# .
00000000BFC51770 00000000BFC517C8 127 MR 3 0 4 0 12155 0 SYS.I_OBJ# .
Update:
Unfortunately I still can't see what's wrong.
The select from gv$session gave no rows.
Here is an excerpt of the output from gv$sql. It's sorted on last_load_time, so it should show a timeline of what has been going on. The ALTER PACKAGE is still marked active, but has only used 182 microseconds in three days, and as far as I can see there are no recursive SQL statements, the ALTER could be waiting on.
SQL> select elapsed_time/1000000 seconds, s.inst_id, s.sql_text, s.users_executing, s.cpu_time,
s.first_load_time, s.last_load_time
2 3 from gv$sql s
4 where users_executing > 0
5 union
select elapsed_time/1000000 seconds, s.inst_id, s.sql_text, s.users_executing, s.cpu_time,
s.first_load_time, s.last_load_time
6 7 8 from gv$sql s
9 where rownum < 50
10 order by last_load_time
11 /
SECONDS INST_ID SQL_TEXT USERS_EXECUTING CPU_TIME FIRST_LOAD_TIME LAST_LOAD_TIME
---------- ---------- -------------------------------------------------- --------------- ---------- ------------------- -------------------
.000293 1 LOCK TABLE FOR INDEX "XXX"."PK_YYYYYYYYYYYYYYYYYY 0 572 2016-04-08/11:02:09 2016-04-08/11:02:09
" IN EXCLUSIVE MODE NOWAIT
.000358 1 LOCK TABLE FOR INDEX "XXX"."IX_XXX_YYYYYYYYYYYYYY 0 2132 2016-04-08/11:02:38 2016-04-08/11:02:38
YYYYY" IN EXCLUSIVE MODE NOWAIT
.000349 1 LOCK TABLE FOR INDEX "XXX"."IX_XXX_DATA_02" IN EX 0 574 2016-04-08/11:03:06 2016-04-08/11:03:06
CLUSIVE MODE NOWAIT
.000402 1 INSERT INTO "SYS". "IMPDP_STATS" (TYPE,VERSION,FLA 0 289 2016-04-08/11:03:17 2016-04-08/11:03:17
GS,C1,C2,C3,C5,N1,N2,N3,N4,N5,N6,N7,N8,N9,N10,N11,
N12,D1,CL1) VALUES ('I',5,2,:B3 ,NULL,NULL,:B2 ,15
219,31,15219,1,1,2108,1,15219,NULL,NULL,NULL,NULL,
TO_DATE('2014-11-15 19:10:36',:B1 ),NULL)
.000405 1 INSERT INTO "SYS". "IMPDP_STATS" (TYPE,VERSION,FLA 0 0 2016-04-08/11:03:17 2016-04-08/11:03:17
GS,C1,C2,C3,C5,N1,N2,N3,N4,N5,N6,N7,N8,N9,N10,N11,
N12,D1,CL1) VALUES ('I',5,2,:B3 ,NULL,NULL,:B2 ,10
6867,670,713,1,6,4759,2,106867,NULL,NULL,NULL,NULL
,TO_DATE('2016-03-19 19:19:38',:B1 ),NULL)
.000419 1 INSERT INTO "SYS". "IMPDP_STATS" (TYPE,VERSION,FLA 0 743 2016-04-08/11:03:17 2016-04-08/11:03:17
GS,C1,C2,C3,C5,N1,N2,N3,N4,N5,N6,N7,N8,N9,N10,N11,
N12,D1,CL1) VALUES ('I',5,2,:B3 ,NULL,NULL,:B2 ,13
7849,1763,11,160,686,7556,2,137849,NULL,NULL,NULL,
NULL,TO_DATE('2016-02-20 19:20:18',:B1 ),NULL)
.000425 1 INSERT INTO "SYS". "IMPDP_STATS" (TYPE,VERSION,FLA 0 0 2016-04-08/11:03:17 2016-04-08/11:03:17
GS,C1,C2,C3,C5,N1,N2,N3,N4,N5,N6,N7,N8,N9,N10,N11,
N12,D1,CL1) VALUES ('I',5,2,:B3 ,NULL,NULL,:B2 ,70
9979,2005,3,668,18908,56726,2,709979,NULL,NULL,NUL
L,NULL,TO_DATE('2016-03-26 19:19:30',:B1 ),NULL)
.000451 1 INSERT INTO "SYS". "IMPDP_STATS" (TYPE,VERSION,FLA 0 280 2016-04-08/11:03:17 2016-04-08/11:03:17
GS,C1,C2,C3,C5,N1,N2,N3,N4,N5,N6,N7,N8,N9,N10,N11,
N12,D1,CL1) VALUES ('I',5,2,:B3 ,NULL,NULL,:B2 ,0,
0,0,0,0,0,0,0,NULL,NULL,NULL,NULL,TO_DATE('2016-02
-20 19:20:18',:B1 ),NULL)
.001567 1 delete from viewtrcol$ where obj#=:1 0 1405 2016-04-08/10:57:24 2016-04-08/11:03:18
.000182 1 ALTER PACKAGE "XXX"."XXX_AQ_PUT" COMPILE BODY 1 372 2016-04-08/11:03:25 2016-04-08/11:03:25
PLSQL_OPTIMIZE_LEVEL= 2 PLSQL_CODE_TYPE= I
NTERPRETED PLSQL_DEBUG= FALSE PLSCOPE_SETTI
NGS= 'IDENTIFIERS:NONE' REUSE SETTINGS TIMESTAMP
'2015-06-02 13:31:03'
.003691 1 insert into wrh$_filemetric_history (snap_id, 0 2914 2016-04-08/11:06:36 2016-04-08/11:06:36
dbid, instance_number, fileid, creationtime,
begin_time, end_time, intsize, group_id,
avgreadtime, avgwritetime, physicalread, phy
sicalwrite, phyblkread, phyblkwrite) select
:snap_id, :dbid, :instance_number, fileid, cr
eationtime, begtime, endtime, intsize_csec, g
roupid, avrdtime, avwrtime, phyread, phy
write, phybkrd, phybkwr from x$kewmflmv
.004734 1 INSERT INTO WRH$_METRIC_NAME(dbid, GROUP_ID, METRI 0 2384 2016-04-08/11:06:36 2016-04-08/11:06:36
C_ID, GROUP_NAME, METRIC_NAME, METRIC_UNIT) SELECT
DISTINCT :dbid, GROUP_ID, METRIC_ID, GROUP_NAME,
METRIC_NAME, METRIC_UNIT FROM V$METRICNAME
.009059 1 SELECT COUNT(*) FROM (SELECT TOP_LEVEL_CALL#, TOP_ 0 4325 2016-04-08/11:06:36 2016-04-08/11:06:36
LEVEL_CALL_NAME FROM V$TOPLEVELCALL MINUS SELECT T
OP_LEVEL_CALL#, TOP_LEVEL_CALL_NAME FROM WRH$_TOPL
EVELCALL_NAME WHERE dbid = :dbid)
.003014 1 delete from WRH$_ENQUEUE_STAT tab where (:beg_snap 0 2124 2016-04-08/11:26:19 2016-04-08/11:26:19
<= tab.snap_id and tab.snap_id <= :end_sn
ap and dbid = :dbid) and not exists (se
lect 1 from WRM$_BASELINE b whe
re (tab.dbid = b.dbid) and
(tab.snap_id >= b.start_snap_id) and
(tab.snap_id <= b.end_snap_id))
Not much to see en dba_resumables too
1* select * from dba_resumable
USER_ID SESSION_ID INSTANCE_ID COORD_INSTANCE_ID COORD_SESSION_ID STATUS TIMEOUT START_TIME SUSPEND_TIME RESUME_TIME NAME SQL_TEXT ERROR_NUMBER ERROR_PARAMETER1 ERROR_PARAMETER2 ERROR_PARAMETER3 ERROR_PARAMETER4 ERROR_PARAMETER5 ERROR_MSG
---------- ---------- ----------- ----------------- ---------------- --------- ---------- -------------------- -------------------- -------------------- ------------------------------ -------------------------------------------------- ------------ -------------------- -------------------- -------------------- -------------------- -------------------- --------------------------------------------------
0 196 1 NORMAL 7200 SYS.SYS_IMPORT_SCHEMA_01 BEGIN :1 := sys.kupc$que_int.receive(:2); END; 0
0 7 1 NORMAL 7200 SYS.SYS_IMPORT_SCHEMA_01.1 ALTER PACKAGE "XXX"."XXX_AQ_PUT" COMPILE BODY 0
PLSQL_OPTIMIZE_LEVEL= 2 PLSQL_CODE_TYPE= I
NTERPRETED PLSQL_DEBUG= FALSE PLSCOPE_SETTI
NGS= 'IDENTIFIERS:NONE' REUSE SETTINGS TIMESTAMP
'2015-06-02 13:31:03'
I feel stuck :-(
Answer
The simplest way to find blocking locks is to look at the sessions. It's usually best to look for who is blocking, not what is blocking.
select *
from gv$session
where blocking_session is not null
The ALTER may be waiting on a recursive SQL statement. Those statement do not always count as "blocking". Run this statement to see what other SQL is running. If you're lucky there will be a statement that has been running almost as long as the ALTER; that will be the next query to investigate:
select elapsed_time/1000000 seconds, gv$sql.*
from gv$sql
where users_executing > 0
order by users_executing desc;
For investigating space issues it is usually better to look at DBA_RESUMABLE instead of specific space sizes. There are a lot of ways for Oracle to run out of space. The tablespace may look fine, but ASM or the OS may be out of space.
select * from dba_resumable;
Based on the updates it looks like the imported data contains Advanced Queues objects. Advanced Queue's have additional import and export restrictions. Everything is "special" with AQ's. Hopefully your organization has someone who specializes in AQs. It wouldn't surprise me if you'll need a create a Support Request for this issue.