關於奇怪的並行程式分析(二)

前幾天的並行問題自己分析了下，也算有了一些進展，但是目前還沒有找到讓人信服的理由，有些讀者也比較關心這個問題，所以第二篇中會把自己的分析過程寫出來，第三篇中應該會對這個問題做一個了結。
之前發現劇烈的效能抖動似乎和資料庫中存在的scheduler有一定的關係。自己就順著這個思路進行了排查。
首先得到了離問題時間點比較接近的一個scheduler,然後抓取了對應的ddl語句。
 OWNER   JOB_NAME           LAST_START_DATE             
------- -------------- ---------------------------------------------
APP_TEST   SYN_D     27-AUG-15 07.11.00.002185 AM ASIA/SHANGHAI
發現這個scheduler job的過程其實很簡單，是一個重新整理物化檢視的操作。
CREATE REFRESH_UB_REG     
BEGIN   
dbms_scheduler.create_job('"SYN_D"', 
job_type=>'PLSQL_BLOCK', job_action=> 
'begin    
   dbms_mview.REFRESH(''XXX.USER_BASIC_TEST'');    
end;'     
, number_of_arguments=>0,    
start_date=>TO_TIMESTAMP_TZ('24-JUL-2011 12.00.00.000000000 AM ASIA/SHANGHAI','DD-MON-RRRR HH.MI.SSXFF AM TZR','NLS_DATE_LANGUAGE=english'), repeat_interval=> 
'FREQ=DAILY;BYHOUR=7;BYMINUTE=11;BYSECOND=0'  
, end_date=>NULL,  
job_class=>'"DEFAULT_JOB_CLASS"', enabled=>FALSE, auto_drop=>FALSE,comments=>  
NULL   
dbms_scheduler.set_attribute('"REFRESH_UB_REG"','logging_level',DBMS_SCHEDULER.LOGGING_RUNS);   
dbms_scheduler.enable('"SYN_D"');  
COMMIT; END; 
可以看到這個scheduler已經執行很長時間了。每天在早晨的固定時間點進行重新整理。然後嘗試檢視這個物化檢視的ddl語句。
SQL> select object_name,object_type from dba_objects where object_name='USER_BASIC_TEST';
  OBJECT_NAME          OBJECT_TYPE 
-------------------- -------------------     
USER_BASIC_TEST      TABLE  
USER_BASIC_TEST      MATERIALIZED VIEW 
對應的ddl類似下面的形式。
select dbms_metadata.get_ddl('MATERIALIZED_VIEW','USER_BASIC_TEST','XXX') FROM DUAL;
  CREATE MATERIALIZED VIEW "XXX"."USER_BASIC_TEST" ......                                                        
  AS SELECT xxxxx FROM "TEST2"."USER_BASIC_TEST"@DB84 "USER_BASIC_TEST"  
可以看到內部還是嘗試使用了db link,這個時候感覺已經抓到了一些規律。
先看看這個物化檢視中的資料，結果已檢視讓自己大吃一驚，裡面已經有好幾億條記錄了。
SQL> select count(*)from "XXX"."USER_BASIC_TEST";
  COUNT(*)
----------
 245362686
而重新整理物化檢視的時候，使用dbms_mview.REFRESH(''XXX.USER_BASIC_TEST'') 也沒有指定快速重新整理，很可能走了全量重新整理，那麼就會產生大量的redo，這個似乎和問題的特徵有些類似。
感覺這個時候問題已經離自己很近了。
連線到源頭資料庫中，帶著一絲自信開始嘗試建立物化檢視日誌，結果發現已經建立了。
SQL> create materialized view log on test2.USER_BASIC_TEST;
create materialized view log on test2.USER_BASIC_TEST
*
ERROR at line 1:
ORA-12000: a materialized view log already exists on table 'USER_BASIC_TEST'
帶著疑問在目標端進行重新整理，發現快速重新整理確實很快，但是不指定fast選項也是預設走快速重新整理。
--指定快速重新整理選項
SQL>  EXEC dbms_mview.REFRESH('xxx.USER_BASIC_TEST',method=>'FAST'); 
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.09
--不指定重新整理選項
SQL>  EXEC dbms_mview.REFRESH('xxx.USER_BASIC_TEST'); 
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.01
所以這個時候問題的分析無功而返， 看來還需要另闢蹊徑。
抓取了ash報告，但是從很精確的時間範圍內，也沒有得到相關的sql.可以看到一個相同點就是有一個等待事件。

Event	Event Class	% Event	Avg Active Sessions
SQL*Net vector data from client	Network	15.71	0.73

 在mos上面也沒有抓到相關的資訊，只有一篇1311281.1描述是個bug.但是我當前的條件還是有一些差距。

沒有了思路，決定重頭再來，既然有大量的並行，但是又從報告中看不到，郵件報警裡提示確實有大量的並行程式，我們可以化被動為主動。
既然並行程式持續時間很短，ash中還抓取不到，那麼我們可以使用來抓取。
於是我寫了下面的指令碼。這個指令碼會去查詢session中含有並行字樣的session,然後同時查詢v$px_session中的並行session. 每5秒輪詢一次，一晚上下來日誌差不多在幾十M,還是能夠接受的。
function check_sess
{ 
sqlplus  -s  / as sysdba <<EOF
set time on
set linesize 200
col machine format a20
col program format a32
col username format a10
col osuser format a10
col logon_time format a20
set feedback off
set pages 0
spool check_session.log append
select systimestamp from dual;
select sid,serial#,username,machine,program,osuser,status,LOGON_TIME,sql_id  from v\$session where upper(program) like '%(P%' and (program not like '%PMON%' and program not like '%PSP%' );
select sid,serial#,username,machine,program,osuser,status,LOGON_TIME,sql_id  from v\$session where sid in (select qcsid from v\$px_session group by qcsid) ;
select sid,serial#,qcsid,qcserial#,QCINST_ID,degree,server_set,server_group,req_degree from  v\$px_session;
EOF
}

for i in {1..36500}
do 
check_sess;
sleep 5 
done
期待這種守株待兔的方式能夠得到一些有用的資訊。