关于奇怪的并行进程分析(二)

前几天的并行问题自己分析了下，也算有了一些进展，但是目前还没有找到让人信服的理由，有些读者也比较关心这个问题，所以第二篇中会把自己的分析过程写出来，第三篇中应该会对这个问题做一个了结。
之前发现剧烈的性能抖动似乎和数据库中存在的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
期待这种守株待兔的方式能够得到一些有用的信息。

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/23718752/viewspace-1788841/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/23718752/viewspace-1788841/