用10046找出impdp创建索引时异常缓慢的原因

expdp导出，在linux+oracle11.2.0.4单实例上使用impdp导入; 有大量表只有很少数据或无数据，对应的索引有25000多个；发现在impdp导入表后的Processing object type SCHEMA_EXPORT/TABLE/INDEX/INDEX ，创建索引速度比较慢。很少数据的表上的索引创建速度相比以前测试也不正常，大约5秒左右创建一个，在此次的创建20000多个很小索引的场景，就导致索引创建过程需要耗费10几个小时了； 

对此问题排查，大约思路如下: 

1.系统资源：CPU/MEMORY/IO使用正常 

2.查看DB等待事件，无明显异常，redo log切换正常； 

3.增大了shared pool/streams_pool_size 后，无明显改善 

4.10046跟踪impdp的进程，发现执行sys.kupc$que_int.receive平均需要5秒； 收集了数据字典表统计信息后，不再出现，但是创建索引依然缓慢 

5.10046跟踪impdp的进程，发现有个基表执行平均需要近4秒 

6.AWRSQL脚本查看此访问基表SQL，发现执行计划有变化 

7.重新收集基表相关统计信息，执行计划依然不正确 ，绑定基表SQL执行计划，执行速度恢复正常。 

8.修复此基表执行计划异常问题后，创建索引速度正常。 简单记录一下10046跟踪impdp进程排查问题的过程：

1.找到IMPDP的进程OSPID: 
SQL> select to_char(sysdate,'YYYY-MM-DD HH24:MI:SS') "DATE", s.program, s.sid,    
  2         s.status, s.username, d.job_name, p.spid, s.serial#    
  3    from v$session s, v$process p, dba_datapump_sessions d   
  4   where p.addr=s.paddr and s.saddr=d.saddr;  
 
DATE                PROGRAM                              SID STATUS   USERNAME   JOB_NAME                       SPID    SERIAL#
------------------- -------------------------------- ------- -------- ---------- ------------------------------ ------- -------
2018-01-11 11:13:48 (DW02)            157 ACTIVE   SYSTEM     SYS_IMPORT_FULL_01             9919          1
2018-01-11 11:13:48 (DW01)            133 ACTIVE   SYSTEM     SYS_IMPORT_FULL_01             9917          5
2018-01-11 11:13:48 (DW03)            182 ACTIVE   SYSTEM     SYS_IMPORT_FULL_01             9921          1
2018-01-11 11:13:48 (DW00)             28 ACTIVE   ZHV25      SYS_IMPORT_FULL_01             9750          3
2018-01-11 11:13:48 (DM00)              3 ACTIVE   SYSTEM     SYS_IMPORT_FULL_01             9748          1
2018-01-11 11:13:48  (TNS V1-V3)          178 ACTIVE   SYSTEM     SYS_IMPORT_FULL_01             9744          5
 
6 rows selected.
 
#########2.使用oradebug 10046方法跟踪IMPDP进程：
SQL> oradebug setospid 9750
Oracle pid: 31, Unix process pid: 9750, image: (DW00)
SQL> oradebug event 10046 trace name context forever,level 12;
Statement processed.
SQL> 
…………等一段时间
 
SQL> oradebug event 10046 trace name context off;
Statement processed.
SQL> oradebug tracefile_name
/u01/app/oracle/diag/rdbms/AAORA/AAORA/trace/AAORA_dw00_9750.trc
 
 
#########3.tkprof格式化并分析trace
$ tkprof /u01/app/oracle/diag/rdbms/AAORA/AAORA/trace/AAORA_dw00_9750.trc 
output = dm2.log
从格式化的trace最后查看，总的执行信息：
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse    30348      1.57       1.71        132      22360          0           0
Execute  48930     11.30      56.73        368  742535018     181619       18462
Fetch    52137   1503.85    1504.66          0  740901206        450       67977
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   131415   1516.74    1563.11        500 1483458584     182069       86439
 
往前面查看，b7qwhm1b31mv2的执行情况，达到elapsed==1497.50 
SQL ID: b7qwhm1b31mv2 Plan Hash: 1662171274
 
SELECT KEY.KEY_NAME INDEX_NAME, KEY.COLUMN_NAME, KEY.DESCEND 
FROM
 (SELECT C.CONSTRAINT_NAME KEY_NAME, C.COLUMN_NAME COLUMN_NAME, C.POSITION 
  POSITION, 'ASC' DESCEND FROM DBA_CONS_COLUMNS C WHERE C.OWNER = :B2 AND 
  C.TABLE_NAME = :B1 AND C.CONSTRAINT_NAME = ( SELECT MIN(CON1.NAME) FROM 
  SYS.USER$ USER1, SYS.USER$ …………
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse      446      0.01       0.00          0          0          0           0
Execute    448      0.22       0.21          0          0          0           0
Fetch      448   1496.45    1497.29          0  740645947          0        1155
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1342   1496.68    1497.50          0  740645947          0        1155
 
继续分析这条语句执行计划，并修正，之后执行速度正常。
 
 
#########3.SQL语句执行计划固定前后执行速度对比：
SQL> select SQL_ID,EXECUTIONS,CHILD_NUMBER,HASH_VALUE,ELAPSED_TIME/EXECUTIONS from v$sql where sql_id='b7qwhm1b31mv2';
 
SQL_ID        EXECUTIONS CHILD_NUMBER HASH_VALUE ELAPSED_TIME/EXECUTIONS
------------- ---------- ------------ ---------- -----------------------
b7qwhm1b31mv2        716            0 1446039394              2452111.12
b7qwhm1b31mv2        487            1 1446039394              3340427.51
 
SQL>select SQL_ID,EXECUTIONS,CHILD_NUMBER,PLAN_HASH_VALUE,SQL_PROFILE,ELAPSED_TIME/EXECUTIONS/1000 "microseconds/1000" from v$sql where sql_id='b7qwhm1b31mv2';
 
SQL_ID        EXECUTIONS CHILD_NUMBER PLAN_HASH_VALUE SQL_PROFILE                    microseconds/1000
------------- ---------- ------------ --------------- ------------------------------ -----------------
b7qwhm1b31mv2       4955            0      3049612612 coe_b7qwhm1b31mv2_3049612612          1.42824622
 
 
###############
另一个有问题的语句sys.kupc$que_int.receive(:2)，收集数据字典信息后恢复正常。
SQL ID: bjf05cwcj5s6p Plan Hash: 0
 
BEGIN :1 := sys.kupc$que_int.receive(:2); END;
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute     10      0.01      50.28          0         10          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       10      0.01      50.28          0         10          0           0