Sunday, October 25, 2020

Slow DataPump impdp, wait event is "wait for unread message on broadcast channel"

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.

Does DEALLOCATE UNUSED or SHRINK SPACE will free space occupied by LOB segment?

Lets check how it works. My env is DB 19.20@Linux-x64 1) I created the table with 4 LOB columns of 4 different LOB types: BASICFILE BLOB, BA...