The customer complains about slow import.
The import was going about 40h at METADATA ONLY mode. The CPU consumption is about 0. Database alert log shows no errors, but simetime
*************************
NI cryptographic checksum mismatch error: 12599.
VERSION INFORMATION:
TNS for Linux: Version 19.0.0.0.0 - Production
Oracle Bequeath NT Protocol Adapter for Linux: Version 19.0.0.0.0 - Production
TCP/IP NT Protocol Adapter for Linux: Version 19.0.0.0.0 - Production
Version 19.3.0.0.0
Time: 06-OCT-2020 17:05:00
Tracing not turned on.
Tns error struct:
ns main err code: 12599
TNS-12599: TNS:cryptographic checksum mismatch
ns secondary err code: 12656
nt main err code: 0
nt secondary err code: 0
nt OS err code: 0
2020-10-06T17:10:00.113924+03:00
*************************
Is the import actually running? Check DBA_DATAPUMP_JOBS to find out:
select owner_name, job_name, operation, job_mode
from dba_datapump_jobs
where state='EXECUTING' ;
Which gives something like:
OWNER_NAME JOB_NAME OPERATION JOB_MODE
---------- ------------------ --------- --------
... SYS_IMPORT_FULL_01 IMPORT FULL
Yes, at least one full import job is running. Good news.
Do we have any sessions running though?
select owner_name, job_name, session_type
from dba_datapump_sessions;
And we see this:
OWNER_NAME JOB_NAME SESSION_TYPE
---------- ------------------ -------------
... SYS_IMPORT_FULL_01 DBMS_DATAPUMP
... SYS_IMPORT_FULL_01 MASTER
... SYS_IMPORT_FULL_01 WORKER
... SYS_IMPORT_FULL_01 WORKER
... SYS_IMPORT_FULL_01 WORKER
... SYS_IMPORT_FULL_01 WORKER
What import's sessions are doing? Let check the wait event:
select v.status,v.inst_id,v.sid,v.serial#,io.block_changes,event
from gv$sess_io io, gv$session v
where io.sid = v.sid
and v.saddr in (
select saddr
from dba_datapump_sessions
) order by inst_id,sid;
STATUS SID SERIAL# BLOCK_CHANGES EVENT
-------- ---- ------- ------------- --------------------------------------------
ACTIVE 82 31744 90864 wait for unread message on broadcast channel
INACTIVE 102 44694 722 SQL*Net message from client
ACTIVE 2396 7781 169755 wait for unread message on broadcast channel
ACTIVE 2410 11021 241385 wait for unread message on broadcast channel
select s.inst_id,s.sid,s.module,s.state,
substr(s.event, 1, 21) as event,
s.seconds_in_wait as secs,
substr(sql.sql_text, 1, 30) as sql_text
from gv$session s
join gv$sql sql on sql.sql_id = s.sql_id
where s.module like 'Data Pump%'
order by s.inst_id, s.module, s.sid;
INST_ID SID MODULE STATE EVENT SECS SQL_TEXT
------- ---- ---------------- ------- --------------------- ---- ------------------------------
1 82 Data Pump Worker WAITING wait for unread messa 1 BEGIN :1 := sys.kupc$que_int.t
1 82 Data Pump Worker WAITING wait for unread messa 1 BEGIN :1 := sys.kupc$que_int.t
1 82 Data Pump Worker WAITING wait for unread messa 1 BEGIN :1 := sys.kupc$que_int.t
1 2396 Data Pump Worker WAITING wait for unread messa 0 BEGIN :1 := sys.kupc$que_int.t
1 2396 Data Pump Worker WAITING wait for unread messa 0 BEGIN :1 := sys.kupc$que_int.t
1 2396 Data Pump Worker WAITING wait for unread messa 0 BEGIN :1 := sys.kupc$que_int.t
1 2410 Data Pump Worker WAITING wait for unread messa 0 BEGIN :1 := sys.kupc$que_int.t
1 2410 Data Pump Worker WAITING wait for unread messa 0 BEGIN :1 := sys.kupc$que_int.t
1 2410 Data Pump Worker WAITING wait for unread messa 0 BEGIN :1 := sys.kupc$que_int.t
2 54 Data Pump Master WAITING wait for unread messa 0 BEGIN :1 := sys.kupc$que_int.r
2 34 Data Pump Worker WAITING wait for unread messa 4 BEGIN :1 := sys.kupc$que_int.t
2 34 Data Pump Worker WAITING wait for unread messa 4 BEGIN :1 := sys.kupc$que_int.t
2 34 Data Pump Worker WAITING wait for unread messa 4 BEGIN :1 := sys.kupc$que_int.t
2 61 Data Pump Worker WAITING wait for unread messa 4 BEGIN :1 := sys.kupc$que_int.t
2 61 Data Pump Worker WAITING wait for unread messa 4 BEGIN :1 := sys.kupc$que_int.t
2 61 Data Pump Worker WAITING wait for unread messa 4 BEGIN :1 := sys.kupc$que_int.t
2 2358 Data Pump Worker WAITING wait for unread messa 5 BEGIN :1 := sys.kupc$que_int.t
2 2358 Data Pump Worker WAITING wait for unread messa 5 BEGIN :1 := sys.kupc$que_int.t
2 2358 Data Pump Worker WAITING wait for unread messa 5 BEGIN :1 := sys.kupc$que_int.t
2 2394 Data Pump Worker WAITING wait for unread messa 3 BEGIN :1 := sys.kupc$que_int.t
2 2394 Data Pump Worker WAITING wait for unread messa 3 BEGIN :1 := sys.kupc$que_int.t
2 2394 Data Pump Worker WAITING wait for unread messa 3 BEGIN :1 := sys.kupc$que_int.t
What the wait event "wait for unread message on broadcast channel" is? I've found no useful information in the MOS or in the internet.
What is system doing?
select * from (
select event,p1,p2,p3,count(*)
from V$ACTIVE_SESSION_HISTORY
where sample_time> (sysdate-1/24)
group by event,p1,p2,p3
order by count(*) desc)
where rownum <10;
EVENT P1 P2 P3 COUNT(*)
---------------------------- ------------ ------------ ------------ --------
1213661190 7 7552 4
0 0 0 2
Sync ASM rebalance 0 0 0 2
102400588528 60691899808 0 2
100 0 0 1
control file sequential read 0 56 1 1
3456712662 425201762304 21474836480 1
268566527 1 100263033448 1
268632063 1 101462207064 1
It looks like the system is doing nothing !
Datapump Worker DW00:
select inst_id,session_id, session_state,count(*)
from GV$ACTIVE_SESSION_HISTORY
where sample_time> (sysdate-1/24)
and session_id = 2396 and inst_id=1
group by inst_id,session_id, session_state;
INST_ID SESSION_ID SESSION_STATE COUNT(*)
------- ---------- ------------- --------
1 2396 ON CPU 1
Datapump Master:
select inst_id,session_id, session_state,count(*)
from GV$ACTIVE_SESSION_HISTORY
where sample_time> (sysdate-1/24)
and session_id = 54 and inst_id=2
group by inst_id,session_id, session_state;
INST_ID SESSION_ID SESSION_STATE COUNT(*)
------- ---------- ------------- --------
2 54 WAITING 3
Which objects are createing now? We see the VIEW is last:
select * from dba_objects
order by created desc
OBJECT_NAME OBJECT_TYPE CREATED
------------------------------ ----------- -------------------
items_MYSQL_MATRIX_rv VIEW 06.10.2020 17:10:29
replenishments_MYSQL_MATRIX_rv VIEW 06.10.2020 16:52:45
bb_PROCUREMENT VIEW 06.10.2020 16:35:08
XXWH_ONHAND_QUANTITIES_INC VIEW 06.10.2020 16:35:07
bb_xxwh_repairs_v VIEW 06.10.2020 16:35:07
xxwh_repairs_v VIEW 06.10.2020 16:35:07
New messages in alert log are:
*************************
NI cryptographic checksum mismatch error: 12599.
VERSION INFORMATION:
TNS for Linux: Version 19.0.0.0.0 - Production
Oracle Bequeath NT Protocol Adapter for Linux: Version 19.0.0.0.0 - Production
TCP/IP NT Protocol Adapter for Linux: Version 19.0.0.0.0 - Production
Version 19.3.0.0.0
Time: 06-OCT-2020 17:05:00
Tracing not turned on.
Tns error struct:
ns main err code: 12599
TNS-12599: TNS:cryptographic checksum mismatch
ns secondary err code: 12656
nt main err code: 0
nt secondary err code: 0
nt OS err code: 0
2020-10-06T17:10:00.113924+03:00
*************************
The reason is: during the creation of a view, a remote object is accessed via database link.
If remote database is unavailable, then TCP timeout = 600 seconds occurs.
After the timeout expires, an error is written to the alert log.
And the import moves to the next view.
After DBA has configured the access to the remote database the import completed in 5 minutes.
