병렬 DML 모니터링 방법
# 병렬 DML과 V$PX_SESSION, V$PX_PROCESS
병렬 DML 이 어떤 서버 프로세스들에 의해 수행되고 있는지를 간편하게 조회하려면 V$PX_SESSION 뷰와 V$PX_PROCESS 뷰를 이용하면 됩니다.
SQL > alter session enable parallel dml;
SQL > insert /*+ append parallel(t1 4) */ into t1
select /*+ parallel(t2 4) */ * from t2;
10000 rows created.
SQL > select userenv('sid') from dual;
USERENV('SID')
--------------
213
select
c.sid as qcsid,
s.sid as slasid,
p.server_name
from
v$session c,
v$px_session s,
v$px_process p
where
c.sid = s.qcsid
and c.sid = &SID_OF_SESSION_1
and p.sid = s.sid
;
Enter value for sid_of_session_1: 213
old 11: and c.sid = &SID_OF_SESSION_1
new 11: and c.sid = 213
QCSID SLASID SERVER_N
---------- ---------- --------
213 204 P000
213 202 P001
213 206 P002
213 200 P003
213 195 P004
213 205 P005
213 199 P006
213 194 P007
# 병렬 DML과 SQL*Trace, AWR Report
병렬 작업에 대해 SQL*Trace 를 수행하면 그 내용이 프로세스 별로 기록됩니다.
즉 코디네이트 프로세스(현재 쿼리를 수행하는 세션)와 슬레이브 프로세스들의 트레이스 파일에 각각 정보가 기록됩니다.
따라서 SQL*Trace 의 결과를 보려면 각각의 트레이스 파일을 따로 조회해야 합니다.
아래와 같이 SQL*Trace(10046 진단 이벤트)를 레벨 8(대기 이벤트 기록)로 수행하고 TKPROF 리포트를 추출해보면 일량(Logical Reads)이나
대기 이벤트(direct path write 등)가 정확하게 나타나지 않는다는 것을 알 수 있습니다. ......> tpack 테스트 필요
AWR Repoert를 통해서 위의 작업을 모니터링 해보면 direct path write 이벤트나 db file scattered read 이벤트 같은 I/O관련 대기이벤트가
포함된 정보를 볼 수 있습니다.
-- snap_begin.sql 파일의 내용
/*
col begin_snap new_value begin_snap;
col db_id new_value db_id;
col inst_num new_value inst_num;
select dbid as db_id from v$database;
select instance_number as inst_num from v$instance;
select dbms_workload_repository.create_snapshot as begin_snap from dual;
*/
-- snap_end.sql 파일의 내용
/*
col end_snap new_value end_snap;
select dbms_workload_repository.create_snapshot as end_snap from dual;
*/
-- snap_report.sql 파일의 내용
/*
select * from table(
dbms_workload_repository.awr_report_text(
&db_id,
&inst_num,
&begin_snap,
&end_snap)
);
*/
-- AWR 작업 수행
SQL > @snap_begin
SQL > insert /*+ append parallel(scott.t1 4) */ into scott.t1
select /*+ parallel(scott.t2 4) */ * from scott.t2;
SQL > commit;
SQL > @snap_end
SQL > @snap_report
Wait Events DB/Inst: ORACLE3/oraSub3 Snaps: 17675-17676
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)
Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ------ ----------- ------- ---------
control file parallel write 19 .0 0 26 4.8
log file parallel write 11 .0 0 18 2.8
log file sync 3 .0 0 26 0.8
db file parallel write 5 .0 0 12 1.3
control file sequential read 686 .0 0 0 171.5
db file sequential read 14 .0 0 0 3.5
SQL*Net break/reset to clien 2 .0 0 0 0.5
SQL*Net message to client 7 .0 0 0 1.8
direct path write 8 .0 0 0 2.0
virtual circuit status 2 100.0 59 29297 0.5
jobq slave wait 19 94.7 56 2929 4.8
SQL*Net message from client 7 .0 55 7918 1.8
Streams AQ: qmn slave idle w 2 .0 55 27344 0.5
Streams AQ: qmn coordinator 4 50.0 55 13672 1.0
-------------------------------------------------------------
Background Wait Events DB/Inst: ORACLE3/oraSub3 Snaps: 17675-17676
-> ordered by wait time desc, waits desc (idle events last)
Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ------ ----------- ------- ---------
control file parallel write 19 .0 0 26 4.8
log file parallel write 11 .0 0 18 2.8
db file parallel write 5 .0 0 12 1.3
rdbms ipc message 197 95.4 2,212 11231 49.3
pmon timer 20 100.0 59 2930 5.0
Streams AQ: qmn slave idle w 2 .0 55 27344 0.5
Streams AQ: qmn coordinator 4 50.0 55 13672 1.0
-------------------------------------------------------------
Operating System Statistics DB/Inst: ORACLE3/oraSub3 Snaps: 17675-17676
Statistic Total
-------------------------------- --------------------
AVG_BUSY_TIME 3,080
AVG_IDLE_TIME 2,792
AVG_IOWAIT_TIME 0
AVG_SYS_TIME 2,499
AVG_USER_TIME 580
BUSY_TIME 6,163
IDLE_TIME 5,586
IOWAIT_TIME 0
SYS_TIME 5,001
USER_TIME 1,162
LOAD 1
OS_CPU_WAIT_TIME 200
RSRC_MGR_CPU_WAIT_TIME 0
VM_IN_BYTES 0
VM_OUT_BYTES 0
PHYSICAL_MEMORY_BYTES 1,868,386,304
NUM_CPUS 2
-------------------------------------------------------------
# 병렬 DML과 V$PQ_TQSTAT
병렬 DML이 종료된 후 병렬 작업의 실행 상황을 파악하는 좋은 방법 중 하나가 V$PQ_TQSTAT 뷰와 V$PQ_SESSTAT 뷰를 조회하는 것입니다.
병렬 DML을 수행한 해당 세션에서만 조회할 수 있습니다.
오라클 버전은 다음과 같습니다.
테이블을 만듭니다. C1 컬럼에 대해 자연스럽게 정렬이 되어 있는 형태입니다.UKJA@ukja1021> select * from v$version where rownum = 1 2 ; BANNER ---------------------------------------------------------------- Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Prod
테이블의 모든 로우를 페치하는 가장 단순한 형태의 병렬 실행입니다.UKJA@ukja1021> create table t1 2 as select level as c1 3 from dual 4 connect by level <= 100000 5 -- order by dbms_random.random 6 -- how the table is ordered may affect the result 7 ; Table created.
그 결과를 V$PQ_TQSTAT 뷰를 통해서 관찰해보겠습니다.UKJA@ukja1021> begin 2 for c in ( select /*+ parallel(t1,4)*/ * from t1) loop 3 null; 4 end loop; 5 end; 6 / PL/SQL procedure successfully completed.
그 결과는 다음과 같습니다.ed pq_stat.sql col process format a10 col server_type format a10 select dfo_number, tq_id, server_type, process, num_rows, bytes, avg_latency, waits, timeouts from v$pq_tqstat order by 1, 2, 3, 4, 5 ;
네 개의 슬레이브 프로세스가 테이블로부터 데이터를 읽는 생산자(Producer)로써 동작했습니다. 놀랍게도 P001, P003 두 개의 프로세스가 대부분의 데이터를 읽고, 나머지 두 개는 일부의 데이터만을 읽었습니다. 슬레이브 프로세스들간에 데이터를 골고루 읽지 못하고 있습니다. 이런 현상이 생기면 병렬 실행의 성능이 생각보다 높지 않은 현상이 생기게 됩니다.UKJA@ukja1021> @pq_stat DFO_NUMBER TQ_ID SERVER_TYP PROCESS NUM_ROWS BYTES AVG_LATENCY ---------- ---------- ---------- ---------- ---------- ---------- ----------- WAITS TIMEOUTS ---------- ---------- 1 0 Consumer QC 100000 595112 0 223 64 1 0 Producer P000 5913 33710 0 3 0 1 0 Producer P001 40870 243406 0 21 0 1 0 Producer P002 7884 45733 0 4 0 1 0 Producer P003 45333 272263 0 23 0 Elapsed: 00:00:00.01
ORDER BY 구문을 이용해서 정렬을 수행하면 더 심각한 결과가 나옵니다.
UKJA@ukja1021> begin 2 for c in ( select /*+ parallel(t1,4)*/ * from t1 order by c1) loop 3 exit; 4 end loop; 5 end; 6 / PL/SQL procedure successfully completed. Elapsed: 00:00:00.07 UKJA@ukja1021> UKJA@ukja1021> @pq_stat DFO_NUMBER TQ_ID SERVER_TYP PROCESS NUM_ROWS BYTES AVG_LATENCY ---------- ---------- ---------- ---------- ---------- ---------- ----------- WAITS TIMEOUTS ---------- ---------- 1 0 Consumer P000 1972 9925 0 9 2 1 0 Consumer P001 1971 10018 0 9 3 1 0 Consumer P002 1971 10018 0 8 2 1 0 Consumer P003 94086 565403 0 116 47 1 0 Producer P004 31015 183753 0 24 3 1 0 Producer P005 21681 129330 0 17 4 1 0 Producer P006 27594 165130 0 22 5 1 0 Producer P007 19710 117279 0 14 2 1 0 Ranger QC 372 3789 0 3 1 1 1 Consumer QC 100 1927 0 67 23 1 1 Producer P000 1166 5782 0 14 3 1 1 Producer P001 1146 5780 0 14 3 1 1 Producer P002 1146 5781 0 13 2 1 1 Producer P003 1146 5781 0 122 48 14 rows selected.
네 개의 프로세스(P004 ~ P007)가 생산자(Producer)로써 테이블로부터 데이터를 읽고 네 개의 프로세스(P000 ~ P003)가 소비자(Consumer)로써 정렬을 수행하는데 그 분포가 대단히 고르지 못합니다. 네번째 프로세스인 P003이 대부분의 작업(94%. 10,000건 중 94,086건)을 수행하는 것을 알 수 있습니다. 이대로라면 병렬이 아닌 직렬 작업으로 정렬하는 것에 비교해서 크게 유리할 것이 없다고 할 수 있습니다.
이런 현상은 인덱스를 생성할 때도 마찬가지입니다. 인덱스 생성은 내부적으로 정렬 작업이 발생합니다. 아래에 그 결과가 있습니다.
UKJA@ukja1021> create index t1_n1 on t1(c1) parallel 4; Index created. UKJA@ukja1021> @pq_stat DFO_NUMBER TQ_ID SERVER_TYP PROCESS NUM_ROWS BYTES AVG_LATENCY ---------- ---------- ---------- ---------- ---------- ---------- ----------- WAITS TIMEOUTS ---------- ---------- 1 0 Consumer P000 100000 1807692 0 4 1 1 0 Consumer P001 0 80 0 4 1 1 0 Consumer P002 0 80 0 4 1 1 0 Consumer P003 0 80 0 4 1 1 0 Producer P004 11826 212999 0 8 1 1 0 Producer P005 38899 705092 0 26 4 1 0 Producer P006 11826 213097 0 7 0 1 0 Producer P007 37449 676904 0 29 6 1 0 Ranger QC 0 160 0 5 1 1 1 Consumer QC 4 1272 0 4 1 1 1 Producer P000 1 318 0 0 0 1 1 Producer P001 1 318 0 0 0 1 1 Producer P002 1 318 0 0 0 1 1 Producer P003 1 318 0 0 0 14 rows selected.
이번에는 P000 프로세스가 모든 정렬 작업을 수행했습니다. 병렬 작업의 장점이 없다고 할 수 있습니다.
이런 현상은 데이터의 정렬 정도와도 관련이 있는 것 같습니다. 아래와 같이 테이블에 무작위적인 순서로 데이터가 들어가게끔 바꾸어 보겠습니다.
UKJA@ukja1021> create table t1 2 as select level as c1 3 from dual 4 connect by level <= 100000 5 order by dbms_random.random -- !! 6 -- how the table is ordered may affect the result 7 ; Table created.
이 경우에는 네개의 슬레이브 프로세스가 거의 공평하게 4등분해서 정렬 작업을 수행합니다. 가장 이상적인 경우라고 할 수 있습니다.
UKJA@ukja1021> begin 2 for c in ( select /*+ parallel(t1,4)*/ * from t1 order by c1) loop 3 exit; 4 end loop; 5 end; 6 / PL/SQL procedure successfully completed. Elapsed: 00:00:00.06 UKJA@ukja1021> UKJA@ukja1021> @pq_stat DFO_NUMBER TQ_ID SERVER_TYP PROCESS NUM_ROWS BYTES AVG_LATENCY ---------- ---------- ---------- ---------- ---------- ---------- ----------- WAITS TIMEOUTS ---------- ---------- 1 0 Consumer P000 23570 132528 0 39 13 1 0 Consumer P001 27176 164544 0 65 16 1 0 Consumer P002 27655 167454 0 50 18 1 0 Consumer P003 21599 130778 0 60 14 1 0 Producer P004 17739 105608 0 15 4 1 0 Producer P005 29044 173021 0 30 10 1 0 Producer P006 21681 129097 0 20 4 1 0 Producer P007 31536 187718 0 23 5 1 0 Ranger QC 372 4546 0 1 0 1 1 Consumer QC 100 1927 0 67 24 1 1 Producer P000 1166 5782 0 44 14 1 1 Producer P001 955 5782 0 70 17 1 1 Producer P002 955 5780 0 56 20 1 1 Producer P003 954 5777 0 66 16 14 rows selected.
하지만 인덱스를 생성할 경우에는 여전히 같은 문제가 발생합니다.
위의 현상을 볼 때 정렬 작업을 병렬 작업으로 진행하는 코드의 일부분에 로직의 오류가 있는 것으로 생각됩니다. V$PQ_TQSTAT 뷰가 아니면 이런 현상을 관찰하기는 쉽지 않습니다. 기회가 있을 때 꼭 활용해보시기 바랍니다.UKJA@ukja1021> create index t1_n1 on t1(c1) parallel 4; Index created. Elapsed: 00:00:00.54 UKJA@ukja1021> UKJA@ukja1021> @pq_stat DFO_NUMBER TQ_ID SERVER_TYP PROCESS NUM_ROWS BYTES AVG_LATENCY ---------- ---------- ---------- ---------- ---------- ---------- ----------- WAITS TIMEOUTS ---------- ---------- 1 0 Consumer P000 100000 1807712 0 4 1 1 0 Consumer P001 0 80 0 4 1 1 0 Consumer P002 0 80 0 4 1 1 0 Consumer P003 0 80 0 4 1 1 0 Producer P004 15768 285122 0 10 0 1 0 Producer P005 32986 596372 0 25 0 1 0 Producer P006 17739 320856 0 12 1 1 0 Producer P007 33507 605762 0 22 1 1 0 Ranger QC 0 160 0 1 0 1 1 Consumer QC 4 1272 0 3 1 1 1 Producer P000 1 318 0 0 0 1 1 Producer P001 1 318 0 0 0 1 1 Producer P002 1 318 0 0 0 1 1 Producer P003 1 318 0 0 0 14 rows selected.