关于奇怪的并行进程分析(二) (r6笔记第46天)

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

在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 期待这种守株待兔的方式能够得到一些有用的信息。