ORACLE HARD PARSING TRACE 비교 v1.1
from
1. 개요
A. HARD PARSING을 유발하는 쿼리에 대해 저번에 배웠다. 이번에는 같은 SQL 쿼리가 상황에 따라 어떤 영향력을 가지는지 비교해보도록 하겠다.
2. 시나리오
A. 상황
i. 세션만 다른 경우 ( 동일 USER, SQL 쿼리 동일 )
ii. 세션과 USER가 다른경우 ( SQL 쿼리 다름 )
iii. 세션과 USER와 객체(소유주)가 다른경우 ( SQL 쿼리 동일, 객체 구조는 동일 )
B. 환경
i. 세션 A, B 두개를 사용
ii. 실행타임은 A가 0초에 실행 후 15초 후에 B를 실행
iii. 각 세션의 쿼리를 실행전 SHARED_POOL FLUSH
iv. 값을 비교하는데 있어 SQL_TRACE의 실행타임을 사용하였다.
3. 실행타임비교/분석
A. 세션만 다른 경우 ( SQL 쿼리 동일 )
i. A세션
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 38.49 38.29 0 800 0 0
Execute 4 0.03 0.02 0 0 0 0
Fetch 1 0.00 0.00 0 3 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 38.52 38.32 0 803 0 0
Misses in library cache during parse: 2
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 0.01 0.01
SQL*Net more data from client 2 0.00 0.00
SQL*Net more data to client 20 0.00 0.00
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS
ii. B세션
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.01 23.99 0 0 0 0
Execute 4 0.00 0.00 0 0 0 0
Fetch 1 0.01 0.00 0 3 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 0.02 23.99 0 3 0 0
Misses in library cache during parse: 0
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 0.00 0.01
SQL*Net more data from client 2 0.00 0.00
library cache pin 8 2.99 23.97
SQL*Net more data to client 20 0.00 0.00
Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: SYS
i.
ii.
iii. 비교 및 분석
아쉽게도 TRACE 한 파일 내부엔 SQL을 실행한 시각에 대한 정보가 없다. ( TKPROF 를 실행한 시간에 대해서는 나와있다. ) 필자가 멋대로 시계보고 재어본 결과는
0, 15, 40, 40 로 A세션이 시작하고 40초 B세션이 시작하고 25초가 걸렸고 두개의 세션 실행타임은 15초의 갭을 가지며 개개의 결과 갭은 0초이다. ( 상황에 따라 오차있음 )
위에서 B세션을 보도록하자. A, B 모두 그렇듯이 EXECUTE, FETCH 과정은 거의 0 에 가깝다. 대부분의 시간이 PARSING에 소모된다. B의 경우엔 PARSING 에 소모한 시간이 23.99(s)이면서 CPU 사용률이 0에 가깝다. 이 시간은 B세션이 대기한 시간과 거의 동일하다. 결과적으로 세션B는 거의 기다리는 시간으로 소모했다.
위와 같은 결과는 A세션이 하드파싱을 하면서 실행계획을 생성하게 되는데에 있다. A가 하드파싱을 시작하면 해쉬밸류를 가지고 버킷에 핸들을 가지고 LCO를 생성하게 된다. LCO에는 실행계획이 존재한다. 세션 B의 입장에서는 해당하는 SQL ( A와 동일한 SQL문 ) 문에 해당하는 HASH VALUE를 가지고 있기 때문에 LIBRARY CACHE를 탐색하게 된다. 여기서 실행계획을 확인 후 하드파싱을 할지 소프트파싱을 할지 결정하게 된다. 하지만 실행계획은 A에 의해 생성중이다. 때문에 이 작업이 완료 될 때까지 WAIT 상태에 빠진다.
이후 해당하는 LCO를 발견한 세션B는 파싱없이 실행계획을 이용해 바로 실행한다.
B. 세션과 USER가 다른경우 ( SQL 쿼리 다름 )
i. A 세션
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 38.77 59.82 0 800 0 0
Execute 4 0.03 0.13 0 0 0 0
Fetch 1 0.00 0.00 0 3 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 38.80 59.96 0 803 0 0
Misses in library cache during parse: 2
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 0.01 0.02
SQL*Net more data from client 2 0.00 0.00
SQL*Net more data to client 20 0.00 0.00
ii. B 세션
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 36.98 57.31 0 0 0 0
Execute 4 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 3 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 36.98 57.32 0 3 0 0
Misses in library cache during parse: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 0.01 0.02
SQL*Net more data from client 4 0.00 0.00
SQL*Net more data to client 20 0.00 0.00
iii. 비교 및 분석
A 세션과 B 세션의 실행결과는 거의 동일하다. 수치에서 나오는 차이는 CPU 사용률에 의해 나온 값으로 보인다. 쿼리의 차이점은 타겟 테이블에 대해 다른 유저가 실행하였다는 점이다. 위에서는 편집의 실수로 날려버렸지만 실지로 보면 PARSING USER ID 값이 서로 다른 것을 볼 수 있다. -_-; ( sys를 제외하고 일반유저는 숫자값으로 나오는데 숫자값은 dba_users 의 user_id 값과 동일하다. user_name과 함께 dba_users에 쿼리하면 얻을 수 있다. )
A와 B의 차이는 from 절에 사용한 테이블이 tb1, tb2, … tb800 과 sys.tb1, sys.tb2, …
sys.tb800 이라는 것이다. cursor_sharing 파라미터는 exact로 되어있고 따라서 위의 두 쿼리는 완전히 다른 쿼리로 각각 하드파싱하게 된다. (similar도 같은 상황이다. )
cursor_sharing = 'force' 로 주어도 ( 각 세션이 구동한 쿼리의 차이는 스키마의 유무였다. )
각각 하드파싱하게 된다. (trace 의 실행시간 정보를 보면 알 수 있다. )
/*+ cursor_sharing의 파라미터 밸류 선택의 범위 */
때문에 같은 환경에서 같은 쿼리를 각각 하드파싱한 듯한 결과를 얻는다.
C. 세션과 USER와 객체가 다른경우 ( SQL 쿼리 동일 )
각 USER가 동일한 이름과 형태의 객체를 가지고 있지만 그 소유주가 다름 ( ex – sys.tb1 / test.tb1 )
i. A 세션
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 38.71 38.50 0 800 0 0
Execute 4 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 3 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 38.71 38.50 0 803 0 0
Misses in library cache during parse: 2
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 0.01 0.01
SQL*Net more data from client 2 0.00 0.00
SQL*Net more data to client 20 0.00 0.00
ii. B 세션
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 37.73 64.27 800 800 0 0
Execute 4 0.00 0.00 0 0 0 0
Fetch 1 0.01 0.00 0 3 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 37.74 64.28 800 803 0 0
Misses in library cache during parse: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 0.01 0.01
SQL*Net more data from client 2 0.00 0.00
library cache pin 8 2.99 23.98
db file sequential read 800 0.04 3.02
SQL*Net more data to client 20 0.00 0.00
iii. 비교 및 분석
위에서 B세션의 수행시간을 보면 64.28로 통상보다 매우 길다. CPU 시간을 보면 A와 B 거의 동일하다. 나머지 시간은 WAIT에 소모 되었다는 걸 의미한다. 위의 wait 항목을 보면 library cache pin 을 볼 수 있다. 이 wait는 첫 번째 예에서도 관찰된다. 그렇다면 왜 세 번째 경우엔 수행시간이 더 길어졌는지 확인해 보자. total elapsed 값에서 CPU TOTAL 값을 빼면 WAIT 타임과 거의 동일하다. WAIT에서 대부분을 차지하는 EVENT는 LIBRARY CACHE PIN 이다.
쿼리 수행 중에 library cache pin wait의 v$session_wait.p3를 조회해보면 값이 200인데 이는 shared 모드로 cursor를 사용하려 했기 때문에 나타난다. 사용하려는 LCO는 현재 LIBRARY CACHE PIN은 A가 실행계획을 생성하고 있는 생성하고 있는 관계로 EXCLUSIVE로 잡고 있다. 세션 B는 해당 작업이 끝날 때까지 대기하게 된다. A의 작업이 끝나면 세션 B는 LCO를 그제서야 확인하게 된다. 이 때가 되서야 해당 실행계획을 사용할 수 없음을 알고 자신의 실행계획을 생성하기 시작한다. 결과적으로 execute, fetch 값을 무시하고 본다면 B는 A가 파싱을 마치고서야 파싱을 시작하였다.
4. Hard parsing에 대한 정리
위에서 세가지 케이스를 보았다.
i. 세션만 다른 경우 ( SQL 쿼리 동일 )
ii. 세션과 USER가 다른경우 ( SQL 쿼리 다름 )
iii. 세션과 USER와 객체(소유주)가 다른경우 ( SQL 쿼리 동일, 객체구조 동일 )
처음의 경우 뒤따르는 세션의 쿼리는 전자의 파싱이 끝나길 대기한다.
두번째 경우 앞의 쿼리와 상관없이 바로 파싱한다.
세번째 경우 뒤따르는 세션의 쿼리는 전자의 파싱이 끝나길 대기하고 끝나면 그제서야 자신의 쿼리를 파싱한다.
세번째의 경우가 최악의 경우라 할 수 있다.
두번째의 경우 SYNONYM을 사용해 하드파싱을 피할 수 있다. 이 경우는 동일한 OBJECT를 사용하고자 하는 경우에 한한다.
첫번째의 경우 다른 쿼리의 WAIT는 선행 쿼리에 달려있다.