關於奇怪的並行程序分析(二) (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
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; 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 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
期待這種守株待兔的方式能夠得到一些有用的資訊。