10046 genişletilmiş SQL izleme dosyaları, bir instance için değişik seviyelerde detay almak için kullanılmaktadır. Genişletilmiş SQL izlemeleri, level 4(bind değişkenleri), level 8 (bekleme olayları) veya level 12 (bind değişkenleri ve bekleme olayları) Event(olay) 10046 ayarı ile etkinleştirilir. Olay 10046’yı etkinleştirebilmek için bazı metotlar vardır, genelde Oracle sürümüne bağlı olsada ve oturum içinde interaktif olarak ayaralanamayan olaylara dahil olsada, bu metotlar aşağıda yer almaktadır.
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';
veya
EXEC SYS.DBMS_SYSTEM.SET_EV(SID,SERIAL#,10046,12,'');
veya
EXEC SYS.DBMS_SUPPORT.START_TRACE_IN_SESSION(SID,SERIAL#,WAITS=>TRUE,BINDS=>FALSE);
veya
EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(SESSION_ID=>SID,SERIAL_NUM=>SERIAL#,WAITS=>TRUE,BINDS=>TRUE)
veya
EXEC SYS.DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(SID,SERIAL#,TRUE);
İlgilenilen oturumun V$SESSION görünümünde SID ve SERIAL# kolonlarına sorgu çekilerek, SID ve seri numarası elde edilebilir. SYS.DBMS_SYSTEM.SET_EV metodu, Oracle 11g sürümünde artık desteklenmesede, diğer metotların olmadığı eski sürümlerde çok iyi şekilde çalışmaktadır. Yukardaki metotların bazılarının eski Oracle sürümlerinde çalışmadığını bildirmekte fayda var. Oracle sunucusunun udump dizininde izleme dosyaları oluşturulacaktır(Oracle 11g sürümünden itibaren trace dizini altında oluşturulur). Bununla beraber izlenmesi istenen oturum veya oturumlarda, logon olduklarından itibaren otomatik olarak 10046 izlemesinin aktif olması isteniyorsa, bir logon tetikleyicisi oluşturulabilir. Aynı programı çalıştıran oturumlar veya belirli bir programı çalıştıran tek bir oturum, bu logon tetikleyicisinin hedef alanına dahil edilebilir. 10046 izlemeleri ayrıca SQL*Plus ORADEBUG özelliği ilede etkinleştirilebilir.
Aşağıdaki örnekte ilk üç harfi CRY veya MVX ile başlayan programları çalıştıran oturumlar için logon oldukları andan itibaren 10046 izlemesi başlatılacaktır. Programın yolu V$SESSION görünümünün PROGRAM kısmında yer almaktadır. DECODE fonksiyonunu kullanarak ilave program listeleri için tetikleyici etkinleştirilebilir.
CREATE OR REPLACE TRIGGER LOGON_10046_IZLEME AFTER LOGON ON DATABASE
DECLARE
CALISTIR INTEGER;
BEGIN
SELECT DECODE(SUBSTR(UPPER(PROGRAM),1,3),'CRY',1,'MVX',1,0)
+DECODE(INSTR(PROGRAM,'\',-1),0,0,DECODE(SUBSTR(UPPER(SUBSTR(PROGRAM,INSTR(PROGRAM,'\',-1)+1)),1,3),'CRY',1,'MVX',1,0))
INTO CALISTIR FROM V$SESSION
WHERE SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1);
IF CALISTIR > 0 THEN
EXECUTE IMMEDIATE 'ALTER SESSION SET EVENTS ''10046 TRACE NAME CONTEXT FOREVER, LEVEL 12''';
END IF;
END;
/
Yukardaki komutlardan birisini çalıştırılmadan önce(bilhassa ALTER SYSTEM ile etkinleştirilirse), başlama metoduna bağlı olarak 10046 izlemesinin nasıl devre dışı bırakılacağının belirlenmesi gerekir:
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
veya
EXEC SYS.DBMS_SYSTEM.SET_EV(SID,SERIAL#,10046,0,'');
veya
EXEC SYS.DBMS_SUPPORT.STOP_TRACE_IN_SESSION(SID,SERIAL#);
veya
EXEC SYS.DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(SID,SERIAL#,FALSE);
10046 SQL izlemesi raporları içinde karşılaşılacak bazı anahtar kelimelerin anlamları aşağıda yer almaktadır:
len = SQL komutundaki karakter sayısı
dep = SQL komutun çalışmasında uygulama/tetikleyici derinliğini gösterir. Mesela; dep = 0 istemci tarafından çalıştırılmayı işaret eder. dep=1, SQL komutunun bir tetikleyici, Oracle iyileştiricisi veya alan yönetim çağrısı tarafından çalıştırıldığını işaret eder. dep = 2, SQL komutunun bir tetikleyici içinden çağrıldığını işaret eder. dep = 3, SQL komutunun bir tetikleyici içinden çağrılan diğer bir tetikleyici içinden çağrıldığını işaret eder.
tim = 10046 izleme dosyasında izlenen süreç için kullanılabilen 1/1.000.000 saniye içinde ölçülen zaman mühürüdür. En güncel tim= değerinin delta değerini alıp ilk tim= değerini çıkarıp, çıkan sonucu 1,000,000’a bölünmesiyle elde edilecek olan değer, izleme dosyasındaki toplam saniye değerine eşittir.
c = CPU saniyesi, çalıştırmada o noktadaki CPU toplamıdır. 1,000,000 ile bölünerek toplam saniye değeri elde edilir.
e= Tamamlanma süresi, çalıştırmada o noktadaki yüksek hassasiyet saatiyle ölçülen toplam saniye değeridir. 1,000,000 ile bölümü sonucu toplam saniye elde edilir.
p = Diskten yapılan fiziksel okumalar.
cr = Sürekli okumalar
cu = Mevcut mod içindeki sürekli okumalar
mis = Bir çalıştırma evresindeki paylaşımlı havuz kayıplarının sayısı
r = Çağrı sonucu dönen satır sayısı
og = Optimizer hedefi – 1=ALL_ROWS, 2=FIRST_ROWS (ve FIRST_ROWS_n), 3=RULE, 4=CHOOSE
XCTEND rlbk = 0 değeri istemcinin COMMIT yayınladığını işaret eder, rd_only = 1 değeri ise COMMIT işlemi sonrasında veritabanında bir bilgi değişmediğini işaret eder.
ela = geçen süre. 1,000,000 ile bölümü ile toplam saniye elde edilir.
p1 = bekleme olayına bağlıdır
p2 = bekleme olayına bağlıdır
p3 = bekleme olayına bağlıdır
dep = SQL komutun çalışmasında uygulama/tetikleyici derinliğini gösterir. Mesela; dep = 0 istemci tarafından çalıştırılmayı işaret eder. dep=1, SQL komutunun bir tetikleyici, Oracle iyileştiricisi veya alan yönetim çağrısı tarafından çalıştırıldığını işaret eder. dep = 2, SQL komutunun bir tetikleyici içinden çağrıldığını işaret eder. dep = 3, SQL komutunun bir tetikleyici içinden çağrılan diğer bir tetikleyici içinden çağrıldığını işaret eder.
tim = 10046 izleme dosyasında izlenen süreç için kullanılabilen 1/1.000.000 saniye içinde ölçülen zaman mühürüdür. En güncel tim= değerinin delta değerini alıp ilk tim= değerini çıkarıp, çıkan sonucu 1,000,000’a bölünmesiyle elde edilecek olan değer, izleme dosyasındaki toplam saniye değerine eşittir.
c = CPU saniyesi, çalıştırmada o noktadaki CPU toplamıdır. 1,000,000 ile bölünerek toplam saniye değeri elde edilir.
e= Tamamlanma süresi, çalıştırmada o noktadaki yüksek hassasiyet saatiyle ölçülen toplam saniye değeridir. 1,000,000 ile bölümü sonucu toplam saniye elde edilir.
p = Diskten yapılan fiziksel okumalar.
cr = Sürekli okumalar
cu = Mevcut mod içindeki sürekli okumalar
mis = Bir çalıştırma evresindeki paylaşımlı havuz kayıplarının sayısı
r = Çağrı sonucu dönen satır sayısı
og = Optimizer hedefi – 1=ALL_ROWS, 2=FIRST_ROWS (ve FIRST_ROWS_n), 3=RULE, 4=CHOOSE
XCTEND rlbk = 0 değeri istemcinin COMMIT yayınladığını işaret eder, rd_only = 1 değeri ise COMMIT işlemi sonrasında veritabanında bir bilgi değişmediğini işaret eder.
ela = geçen süre. 1,000,000 ile bölümü ile toplam saniye elde edilir.
p1 = bekleme olayına bağlıdır
p2 = bekleme olayına bağlıdır
p3 = bekleme olayına bağlıdır
STAT çizgileri satır kaynak çalıştırma planıdır
id = çizgi tanımlayıcısı
cnt = dönen veya işlenen satır sayısı
pid = ebeveyn(parent) operasyon tanımlayıcısı( planın satırbaşını belirlemeye yarar)
obj = Planın evresindeki referans alınan objenin obje numarası
id = çizgi tanımlayıcısı
cnt = dönen veya işlenen satır sayısı
pid = ebeveyn(parent) operasyon tanımlayıcısı( planın satırbaşını belirlemeye yarar)
obj = Planın evresindeki referans alınan objenin obje numarası
Bütün parçaları birleştirerek, bir 10046 genişletilmiş SQL izlemesinden aşağıdaki formatta işlenmemiş analiz verisi alınır.
PARSING IN CURSOR #12 len=170 dep=0 uid=31 oct=3 lid=31 tim=768609360 hv=205969412 ad='a64cba88'
SELECT A1 , SUBSTR(C2,1,20) C2 FROM K2 WHERE
EXISTS (
SELECT
1
FROM
K4
WHERE
K4.A1=K2.A1)
AND K2.A1 BETWEEN :1 AND :2
END OF STMT
PARSE #12:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=768609356
BINDS #12:
kkscoacd
Bind#0
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=00 fl2=1000010 frm=00 csi=178 siz=48 off=0
kxsbbbfp=151423d0 bln=22 avl=02 flg=05
value=1
Bind#1
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=00 fl2=1000010 frm=00 csi=178 siz=0 off=24
kxsbbbfp=151423e8 bln=22 avl=03 flg=01
value=81000
EXEC #12:c=0,e=807,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=768611110
WAIT #12: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=114176 tim=768611226
WAIT #12: nam='db file sequential read' ela= 184 file#=4 block#=1779171 blocks=1 obj#=114178 tim=768611561
WAIT #12: nam='db file scattered read' ela= 213 file#=4 block#=1779172 blocks=5 obj#=114178 tim=768612046
WAIT #12: nam='db file sequential read' ela= 103 file#=4 block#=1138380 blocks=1 obj#=114177 tim=768612399
WAIT #12: nam='db file sequential read' ela= 87 file#=4 block#=1754469 blocks=1 obj#=114177 tim=768612648
WAIT #12: nam='db file sequential read' ela= 88 file#=4 block#=1138382 blocks=1 obj#=114177 tim=768612865
WAIT #12: nam='db file sequential read' ela= 81 file#=4 block#=1138374 blocks=1 obj#=114176 tim=768613103
FETCH #12:c=0,e=2195,p=10,cr=51,cu=0,mis=0,r=14,dep=0,og=1,tim=768613513
WAIT #12: nam='SQL*Net message from client' ela= 3432 driver id=1413697536 #bytes=1 p3=0 obj#=114176 tim=768617150
STAT #12 id=1 cnt=14 pid=0 pos=1 obj=0 op='FILTER (cr=51 pr=10 pw=0 time=2170 us)'
STAT #12 id=2 cnt=14 pid=1 pos=1 obj=0 op='NESTED LOOPS (cr=51 pr=10 pw=0 time=2137 us)'
STAT #12 id=3 cnt=14 pid=2 pos=1 obj=0 op='SORT UNIQUE (cr=7 pr=6 pw=0 time=984 us)'
STAT #12 id=4 cnt=14 pid=3 pos=1 obj=114178 op='TABLE ACCESS FULL K4 (cr=7 pr=6 pw=0 time=900 us)'
STAT #12 id=5 cnt=14 pid=2 pos=2 obj=114176 op='TABLE ACCESS BY INDEX ROWID K2 (cr=44 pr=4 pw=0 time=1131 us)'
STAT #12 id=6 cnt=14 pid=5 pos=1 obj=114177 op='INDEX UNIQUE SCAN SYS_C0010352 (cr=30 pr=3 pw=0 time=820 us)'
İzleme dosyasını zaman çizelgesine adreslemek her zaman en iyi yaklaşım olmayabilir, ancak belirli bir SQL komutunun rolünü anlamak, performans probleminin sebebini anlamaktan daha kritik öneme sahiptir.
Elbette eğer
SELECT
*
FROM
TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'))
Bu sorgu sonucunda SQL komutunun çıktısı aşağıdaki gibi olmaktadır:
SQL_ID cgfjqr745ep41, child number 0
-------------------------------------
SELECT A1 , SUBSTR(C2,1,20) C2 FROM K2 WHERE EXISTS ( SELECT 1 FROM K4 WHERE
K4.A1=K2.A1) AND K2.A1 BETWEEN :1 AND :2
Plan hash value: 1996673128
--------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | Used-Mem |
--------------------------------------------------------------------------------------------------------------------------------------------
|* 1 | FILTER | | 1 | | 14 |00:00:00.01 | 51 | 10 | | | |
| 2 | NESTED LOOPS | | 1 | 1 | 14 |00:00:00.01 | 51 | 10 | | | |
| 3 | SORT UNIQUE | | 1 | 1 | 14 |00:00:00.01 | 7 | 6 | 9216 | 9216 | 8192 (0)|
|* 4 | TABLE ACCESS FULL | K4 | 1 | 1 | 14 |00:00:00.01 | 7 | 6 | | | |
| 5 | TABLE ACCESS BY INDEX ROWID| K2 | 14 | 1 | 14 |00:00:00.01 | 44 | 4 | | | |
|* 6 | INDEX UNIQUE SCAN | SYS_C0010352 | 14 | 1 | 14 |00:00:00.01 | 30 | 3 | | | |
--------------------------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(:1<=:2)
4 - filter(("K4"."A1">=:1 AND "K4"."A1"<=:2))
6 - access("K4"."A1"="K2 "."A1")
filter(("K2 "."A1"<=:2 AND "K2 "."A1">=:1))
Eğer bekleme olaylarınınP1, P2 ve P3 değerlerinin birbirine yakın olduğu incelendiğinde, işlenmemiş 10046 genişletilmiş SQL izlemesinin DBMS_XPLAN çıktısına nazaran bir kısım ek avantajlara sahip olduğu görülecektir.
nam='db file scattered read' ela= 213 file#=4 block#=1779172 blocks=5 obj#=114178 tim=768612046
Yukarda, 1779172 bloğundan başlayarak 4 numaralı salt dosyasının çoklu blok okumasının tamamlanması için 0.000213 saniye gerekmekte ve 5 blok uzaması uygulanmıştır. Bloklar 114178 numaralı objeye aittir ve izleme dosyasındaki diğer çizgilerin ardışık zamanını referans edebilmek üzere, izleme dosyasının 768612046 ardışık zamanında gerçekleşmiştir.
Oracle 10.2 üzerinde bir izleme dosyası oluşturmayı deneyelim. Önce, her biri 10,000 kayıt içerek olan iki tane tablo oluşturuyorum ve tablolar ile birincil anahtar indeksleri için istatistikleri topluyorum.
CREATE TABLE T1 (
A1 NUMBER,
C2 VARCHAR2(255),
PRIMARY KEY (A1));
CREATE TABLE T2 (
A1 NUMBER,
C2 VARCHAR2(255),
PRIMARY KEY (A1));
INSERT INTO
T1
SELECT
ROWNUM,
DBMS_RANDOM.STRING(‘U’,255)
FROM
DUAL
CONNECT BY
LEVEL<=10000;
INSERT INTO
T2
SELECT
ROWNUM,
DBMS_RANDOM.STRING(‘U’,255)
FROM
DUAL
CONNECT BY
LEVEL<=10000;
COMMIT;
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>UGUR,TABNAME=>'T1',CASCADE=>TRUE)
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>UGUR,TABNAME=>'T2',CASCADE=>TRUE)
Her biri 10,000 satır içeren iki tablomuz mevcut. Şimdi SQL*Plus üzerinden aşağıdaki planda yer alan işlemleri sırasıyla uygulayacağız.
- Fiziksel okumaları zorlaması için tampon önbelleğini iki sefer boşaltıyorum.
- Her bir satır alıp getirme(fetch) çağrısı için SQL*Plus üzerinde varsayılan değer olan 15 satır olarak ayarlıyorum.
- İstemci taraflı gecikmeleri sınırlandırmak için veritabanından dönecek olan satırların çıktısını devre dışı bırakıyorum.
- 1 ve 2 değerlerine sahip iki adet bind değişkeni oluşturuyorum.
- Seviye 12’de genişletilmiş 10046 SQL izlemesini etkinleştiriyorum.
- İzleme dosyasını kolayca bulabilmek için kolay bir isim belirliyorum.
- Her iki tabloyu birleştirecek bir sorgu oluşturuyorum.
- Fetch dizin boyutunu her bir fetch çağrısı için 50 olarak ayarlıyorum.
- İkinci bind değişkeninin değerini 10,000’e çıkarıyorum.
- Yedinci adımda çalıştırdığımız sorguyu tekrar çalıştırıyoruz.
ALTER SYSTEM FLUSH BUFFER_CACHE; -- 1. adım --
ALTER SYSTEM FLUSH BUFFER_CACHE;
SET ARRAYSIZE 15 -- 2.adım --
SET AUTOTRACE TRACEONLY STATISTICS -- 3.adım --
VARIABLE U1 NUMBER -- 4.adım --
VARIABLE U2 NUMBER
EXEC :U1 := 1
EXEC :U2 := 2
EXEC DBMS_SESSION.SESSION_TRACE_ENABLE(WAITS=>TRUE, BINDS=>TRUE) -- 5.adım --
ALTER SESSION SET TRACEFILE_IDENTIFIER='10046_TEST_BULMA'; -- 6.adım --
SELECT -- 7.adım --
T1.A1,
T2.C2
FROM
T1,
T2
WHERE
T1.A1=T2.A1
AND T1.A1 BETWEEN :U1 AND :U2;
SET ARRAYSIZE 50 -- 8.adım --
EXEC :U1 := 1
EXEC :U2 := 10000 -- 9.adım --
SELECT -- 10.adım --
T1.A1,
T2.C2
FROM
T1,
T2
WHERE
T1.A1=T2.A1
AND T1.A1 BETWEEN :U1 AND :U2;
SELECT SYSDATE FROM DUAL;
EXEC DBMS_SESSION.SESSION_TRACE_DISABLE;
Her iki sorgunun bekleme olaylarının SQL*Plus çıktısı aşağıda yer almaktadır.
Statistics
---------------------------------------------------
1 recursive calls
0 db block gets
9 consistent gets
5 physical reads
0 redo size
897 bytes sent via SQL*Net to client
347 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
2 rows processed
Statistics
---------------------------------------------------
0 recursive calls
0 db block gets
10791 consistent gets
404 physical reads
0 redo size
2727906 bytes sent via SQL*Net to client
2641 bytes received via SQL*Net from client
211 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
10000 rows processed
Yukardaki sonuçtan, ilk çalıştırılan sorgunun 9 sürekli alımına ihtiyaç duyduğu ve bu alınan bloklardan 5 tanesinin diskten blok okumasını kapsadığı görülmektedir. Sunucu, istemciye 2 gidiş-dönüş yolculuğundan 897 byte veri göndermiş ve 2 satır almıştır. İkinci sorgu ise 10,791 sürekli blok alımına ihtiyaç duymuş ve bunlardan 404 tanesi fiziksel okumaları kapsamıştır Sunucu, istemciye 10,000 satır içinde 211 gidiş-dönüş yolculuğunda toplamda 2,72 MB veri göndermiştir Güzel bir analiz, ancak ne olduğu hakkında daha fazla bilgi sahibi olunması gerekmekte. Böylece, daha fazlasını görebilmek için aşağıdaki gibi TKPROF ile SQL izleme dosyasını inceleyeceğiz.
tkprof aysun_ora_3702_10046_test_bulma.trc aysun_ora_3702_10046_test_bulma.txt
Yukardaki örnek için TKPROF çıktısının bir bölümü aşağıdaki gibi olmaktadır.
****************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
****************************************************************
SELECT
T1.A1,
T2.C2
FROM
T1,
T2
WHERE
T1.A1=T2.A1
AND T1.A1 BETWEEN :U1 AND :U2
call count cpu elapsed disk query current rows
------- ------ ----- ------- ---- ------ ------- ------
Parse 2 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 203 0.28 0.38 409 10991 0 10002
------- ------ ----- ------- ---- ------ ------- ------
total 208 0.28 0.38 409 10991 0 10002
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 31
Rows Row Source Operation
------- ---------------------------------------------------
2 FILTER (cr=9 pr=5 pw=0 time=19577 us)
2 NESTED LOOPS (cr=9 pr=5 pw=0 time=19569 us)
2 TABLE ACCESS BY INDEX ROWID T2 (cr=5 pr=3 pw=0 time=13843 us)
2 INDEX RANGE SCAN SYS_C0010411 (cr=3 pr=2 pw=0 time=9231 us)(object id 107421)
2 INDEX UNIQUE SCAN SYS_C0010422 (cr=4 pr=2 pw=0 time=5788 us)(object id 107424)
Elapsed times include waiting on following events:
Event waited on Times_Waited Max. Wait Total Waited
------------------------------- ---------- --------- ------------
SQL*Net message to client 204 0.00 0.00
db file sequential read 409 0.00 0.21
SQL*Net message from client 204 0.00 0.07
SQL*Net more data to client 1200 0.00 0.02
Yukardaki sonuç aslında çalıştırılan test SQL komutu için izleme dosyası içerisinde ne bulunduğu ile ilgili güzel bir özet bilgi… Peki ne yazmakta? Her bir çağrı için 1 seferden toplamda 2 çözümleme(parse) çağrısının olduğunu ve (execute-parse) formulü sonucunda, bu çağrılardan birisinin “hard parse” ile sonuçlandığını, yani önbellekten sonuçlarının bütünlüğünü sağlayamadığından tekrardan çözümleme için ilaveten bir fiziksel I/O işlemi yaptığını anlatmaktadır. Toplamda alınan 10,002 satır için 203 fetch çağrısı olduğunu ki buradanda istemcinin fetch çağrısı başına ortalama 49,27 satır alıp getirme yaptığını görüyoruz. Çalıştırma için tüm süre, 0,28 saniye CPU süresi ve çalıştırma için geçen 0.38 saat saniye toplamındaki fetch çağrısında meydana gelmiştir. Toplamda 10,991 sürekli alıma gerek duyulmuş ve diskten 409 blok okunmuştur.
Yukardaki çalıştırma planı, iki satır birarada listelendiği için yanıltıcı olabilir. Gerçi, Oracle 11.1.6.0 sürümünden itibaren her bir komut ayrı çalıştırma planına sahiptir. T2 tablosunun birincil anahtarı olan SYS_C0010411 indeksi üzerinde, 1 ve 2 değerleri arasında olan tüm A1 değerlerinin yerinin saptanması için indeks aralığı taraması uygulanmaktadır. Çalıştırma planının en üst satırında, toplamda sorgunun 9 sürekli alım, 5 fiziksel blok okuması ve çalıştırma için 0,019577 saniyeye gerek duyduğu görülmektedir(FILTER (cr=9 pr=5 pw=0 time=19577 us). SYS_C0010411 indeks aralığı taramasında 3 sürekli alım ve bu 3 sürekli alımı karşılamak üzere 2 fiziksel blok okumasının gerektiği görülmektedir(INDEX RANGE
Bekleme olaylarında,diskten bir seferde fiziksel olarak 1 blok okunduğunu işaret eden
Bununla beraber çıktının analizini işlenmemiş 10046 izleme dosyasındanda yapmakta fayda vardır. Bu noktada izleme dosyasının işlenmemiş çıktısı neye benzeyecektir? Bu konuya girmeden önce işlenmemiş izleme dosyasını okurken bize yardımcı olacak indeks ve tabloların obje ID’lerini aşağıdaki gibi bulmak yararlı olacaktır.
COLUMN TABLE_NAME FORMAT A10
SELECT
TABLE_NAME,
INDEX_NAME
FROM
DBA_INDEXES
WHERE
TABLE_NAME IN ('T1','T2')
ORDER BY
TABLE_NAME;
TABLE_NAME INDEX_NAME
---------- ------------
T1 SYS_C0010422
T2 SYS_C0010411
COLUMN OBJECT_NAME FORMAT A15
SELECT
OBJECT_ID,
OBJECT_NAME,
OBJECT_TYPE
FROM
DBA_OBJECTS
WHERE
OBJECT_NAME IN ('T1','T2','SYS_C0010422','SYS_C0010411')
ORDER BY
OBJECT_NAME;
OBJECT_ID OBJECT_NAME OBJECT_TYPE
---------- --------------- -----------
107424 SYS_C0010422 INDEX
107421 SYS_C0010411 INDEX
114209 T1 TABLE
114207 T2 TABLE
Yukardaki sonuçtan, T1 tablosundaki SYS_C0010422 adlı indeksin obje ID’sinin 107424, T2 tablosunun SYS_C0010411 adlı indeksinin obje ID’sinin ise 107421 olduğunu buluyoruz. T1 tablosunun obje ID’si 114209, T2 tablosunun obje ID’si ise 114207’dir. İşlenmemiş 10046 izleme dosyasının bir bölümü altta yer almaktadır.
PARSING IN CURSOR #3 len=91 dep=0 uid=31 oct=3 lid=31 tim=4963261335 hv=3021110247 ad='982ab100'
SELECT
T1.A1,
T2.C2
FROM
T1,
T2
WHERE
T1.A1=T2.A1
AND T1.A1 BETWEEN :U1 AND :U2
END OF STMT
PARSE #3:c=0,e=1113,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=4963261327
BINDS #3:
kkscoacd
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
kxsbbbfp=13ce8870 bln=22 avl=02 flg=05
value=1
Bind#1
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24
kxsbbbfp=13ce8888 bln=22 avl=02 flg=01
value=2
Yukarda ilk çözümleme işleminin “hard parse” olduğunu(parse #3 satırındaki mis=1 değernden anlaşılıri), bu işlem için 0 CPU zamanı ve 0.001113 saat saniyesi gerektiği görülmektedir. İlave olarak, iki bind değişkeni geçilmiştir. Seviye 4 veya seviye 12 deki 10046 genişletilmiş SQL izleme dosyasında, yukarda görüldüğü gibi önerilmiş bind değişkenleride dahil olacaktır(Bind#0 ve Bind#1). Bind değişken veri tipinin(oacdty) numara ile tanımlanmış olan kodunu çözmek için aşağıdaki liste referans alınabilir.
0 - Arguman içermeyen bir prosedürün yer göstericisi satırıdır.
1 - VARCHAR2 (or NVARCHAR)
2 - NUMBER
3 - NATIVE INTEGER (for PL/SQL's BINARY_INTEGER)
8 - LONG
11 - ROWID
12 - DATE
23 - RAW
24 - LONG RAW
96 - CHAR (or NCHAR)
112 - CLOB or NCLOB
113 - BLOB
114 - BFILE
106 - MLSLABEL
250 - PL/SQL RECORD
251 - PL/SQL TABLE
252 - PL/SQL BOOLEAN
İzleme dosyası aşağıdaki gibi devam etmektedir:
EXEC #3:c=0,e=3538,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=4963265927
WAIT #3: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=4963266031
WAIT #3: nam='db file sequential read' ela= 4816 file#=4 block#=1138316 blocks=1 obj#=107421 tim=4963271120
WAIT #3: nam='db file sequential read' ela= 3934 file#=4 block#=1138318 blocks=1 obj#=107421 tim=4963275219
WAIT #3: nam='db file sequential read' ela= 4443 file#=4 block#=1138310 blocks=1 obj#=114207 tim=4963279805
WAIT #3: nam='db file sequential read' ela= 5221 file#=4 block#=1093148 blocks=1 obj#=107424 tim=4963285172
WAIT #3: nam='db file sequential read' ela= 236 file#=4 block#=1093150 blocks=1 obj#=107424 tim=4963285569
FETCH #3:c=15625,e=19589,p=5,cr=5,cu=0,mis=0,r=1,dep=0,og=1,tim=4963285717
WAIT #3: nam='SQL*Net message from client' ela= 364 driver id=1413697536 #bytes=1 p3=0 obj#=107424 tim=4963286240
WAIT #3: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=107424 tim=4963286494
FETCH #3:c=0,e=180,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,tim=4963286588
Yukarda, (T2 tablosunun SYS_C0010411 adlı indeksinin)107421 numaralı objenin 1138316 ve 1138318 bloklarından 2 tekil blok okumasını, (T2 tablosunun) 114207 nolu objenin 1138310 bloğundan tek tekil blok okumasını ve (T1 tablosunun SYS_C0010422 adlı indeksinin) 107424 numaralı objenin 1093148 ve 1093150 bloklarından 2 adet tekil okumasıyla birlikte toplamda 5 fiziksel blok okuması yapıldığı görülmektedir. Bu toplam 5 fiziksel blok okumasının 0.000236 saniyede tamamlandığıda burada görülmektedir. İlk “fetch” çağrısı tek satır döndürmesine rağmen, “fetch” dizin boyutu 15 olarak ayarlanmıştı. Ancak, bu “fetch” işleminin ardından 5 fiziksel blok okumasına gerek duyan sürekli 5 okumaya gerek duymuştur. İlk satır istemciye gönderilmiş, ardından (4963286588 – 4963285717)/1,000,000 = 0.000871 saniye sonra ikinci satır alınıp getirilmiştir. İzleme dosyasının devamı aşağıda yer almaktadır.
WAIT #3: nam='SQL*Net message from client' ela= 319 driver id=1413697536 #bytes=1 p3=0 obj#=107424 tim=4963287035
*** SESSION ID:(141.14281) 2011-04-29 12:35:24.251
STAT #3 id=1 cnt=2 pid=0 pos=1 obj=0 op='FILTER (cr=9 pr=5 pw=0 time=19577 us)'
STAT #3 id=2 cnt=2 pid=1 pos=1 obj=0 op='NESTED LOOPS (cr=9 pr=5 pw=0 time=19569 us)'
STAT #3 id=3 cnt=2 pid=2 pos=1 obj=114207 op='TABLE ACCESS BY INDEX ROWID T2 (cr=5 pr=3 pw=0 time=13843 us)'
STAT #3 id=4 cnt=2 pid=3 pos=1 obj=107421 op='INDEX RANGE SCAN SYS_C0010411 (cr=3 pr=2 pw=0 time=9231 us)'
STAT #3 id=5 cnt=2 pid=2 pos=2 obj=107424 op='INDEX UNIQUE SCAN SYS_C0010422 (cr=4 pr=2 pw=0 time=5788 us)'
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=107424 tim=4963289021
WAIT #0: nam='SQL*Net message from client' ela= 2329 driver id=1413697536 #bytes=1 p3=0 obj#=107424 tim=4963291420
3 numaralı imleç kapanmıştır, böylece Oracle, TKPROF çıktısında görüldüğü gibi STAT satırlarının çıktısını alır. Bu izleme dosyasına giriş yapmadan önce PARSING IN CURSOR satırındaki “oct” kısmı Oracle komut tipini belirtmektedir ve V$SESSION görünümünün COMMAND kolonu ile ve V$SQL görünümünün COMMAND_TYPE kolonu ile ilişkilidir. Aşağıda yaygın komut tiplerinin değerleri yer almaktadır.
1 - CREATE TABLE
2 - INSERT
3 - SELECT
6 - UPDATE
7 - DELETE
Şimdi izleme dosyasına bakalım.
...
PARSING IN CURSOR #4 len=91 dep=0 uid=31 oct=3 lid=31 tim=4963302762 hv=3021110247 ad='982ab100'
SELECT
T1.A1,
T2.C2
FROM
T1,
T2
WHERE
T1.A1=T2.A1
AND T1.A1 BETWEEN :U1 AND :U2
END OF STMT
PARSE #4:c=0,e=118,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=4963302756
BINDS #4:
kkscoacd
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
kxsbbbfp=13ce8870 bln=22 avl=02 flg=05
value=1
Bind#1
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24
kxsbbbfp=13ce8888 bln=22 avl=02 flg=01
value=10000
EXEC #4:c=0,e=699,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=4963304299
WAIT #4: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=107424 tim=4963304383
FETCH #4:c=0,e=94,p=0,cr=5,cu=0,mis=0,r=1,dep=0,og=1,tim=4963304564
WAIT #4: nam='SQL*Net message from client' ela= 718 driver id=1413697536 #bytes=1 p3=0 obj#=107424 tim=4963305403
WAIT #4: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=107424 tim=4963305590
WAIT #4: nam='SQL*Net more data to client' ela= 29 driver id=1413697536 #bytes=2146 p3=0 obj#=107424 tim=4963305766
WAIT #4: nam='SQL*Net more data to client' ela= 20 driver id=1413697536 #bytes=1862 p3=0 obj#=107424 tim=4963305913
WAIT #4: nam='SQL*Net more data to client' ela= 17 driver id=1413697536 #bytes=2128 p3=0 obj#=107424 tim=4963306065
WAIT #4: nam='db file sequential read' ela= 2272 file#=4 block#=1138311 blocks=1 obj#=114207 tim=4963308471
WAIT #4: nam='SQL*Net more data to client' ela= 27 driver id=1413697536 #bytes=1868 p3=0 obj#=114207 tim=4963308686
WAIT #4: nam='SQL*Net more data to client' ela= 18 driver id=1413697536 #bytes=2122 p3=0 obj#=114207 tim=4963308841
WAIT #4: nam='SQL*Net more data to client' ela= 13 driver id=1413697536 #bytes=2128 p3=0 obj#=114207 tim=4963309001
FETCH #4:c=0,e=3573,p=1,cr=54,cu=0,mis=0,r=50,dep=0,og=1,tim=4963309109
Bu sefer “hard parse” olayının olmadığını gözlemliyoruz(parse #4 satırında mis=0 değerinden) . Bu noktada ilk iki “fetch” işlemi tamamlanmaktadır. İlk “fetch” tek satır döndürürken(r=1), ikinci “fetch” işlemi 50 satır döndürmektedir(r=50). İkinci “fetch” satırından önce, “SQL*Net more data to client” beklemesinin olduğunu görüyoruz ki bu bekleme olayının her biri bir önceki istemciye gönderilen SDU boyutunun aşıldığını göstermektedir. Ayrıca, sadece tek bir fiziksel blok okumasının olduğunu ve bu okuma işleminde ilk 51 satırın alınıp getirilmesi esnasında 0.0002272 saniye gerektiği görülmektedir(diğer bloklar zaten tampon önbelleğindedir). İzleme dosyası aşağıdaki gib devam etmektedir.
WAIT #4: nam='SQL*Net message from client' ela= 256 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963309476
WAIT #4: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963309654
WAIT #4: nam='db file sequential read' ela= 226 file#=4 block#=1138312 blocks=1 obj#=114207 tim=4963309995
WAIT #4: nam='SQL*Net more data to client' ela= 32 driver id=1413697536 #bytes=2116 p3=0 obj#=114207 tim=4963310197
WAIT #4: nam='SQL*Net more data to client' ela= 14 driver id=1413697536 #bytes=2096 p3=0 obj#=114207 tim=4963310353
WAIT #4: nam='SQL*Net more data to client' ela= 13 driver id=1413697536 #bytes=1834 p3=0 obj#=114207 tim=4963310488
WAIT #4: nam='db file sequential read' ela= 1762 file#=4 block#=1138308 blocks=1 obj#=114207 tim=4963312390
WAIT #4: nam='SQL*Net more data to client' ela= 23 driver id=1413697536 #bytes=2096 p3=0 obj#=114207 tim=4963312551
WAIT #4: nam='SQL*Net more data to client' ela= 16 driver id=1413697536 #bytes=2096 p3=0 obj#=114207 tim=4963312783
WAIT #4: nam='SQL*Net more data to client' ela= 13 driver id=1413697536 #bytes=1834 p3=0 obj#=114207 tim=4963312904
FETCH #4:c=0,e=3345,p=2,cr=55,cu=0,mis=0,r=50,dep=0,og=1,tim=4963312955
114207 numaralı objenin iki fazla fiziksel blok okuması isteciye bir sonraki 50 satırı döndürür. İzleme dosyasındaki son iki “fetch” işlemine tekrardan dalarsak;
...
FETCH #4:c=0,e=1259,p=2,cr=55,cu=0,mis=0,r=50,dep=0,og=1,tim=4963757700
WAIT #4: nam='SQL*Net message from client' ela= 842 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963758586
WAIT #4: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963758653
WAIT #4: nam='SQL*Net more data to client' ela= 16 driver id=1413697536 #bytes=2124 p3=0 obj#=114207 tim=4963758766
WAIT #4: nam='db file sequential read' ela= 242 file#=4 block#=1773782 blocks=1 obj#=114207 tim=4963759071
WAIT #4: nam='SQL*Net more data to client' ela= 17 driver id=1413697536 #bytes=2104 p3=0 obj#=114207 tim=4963759182
WAIT #4: nam='SQL*Net more data to client' ela= 13 driver id=1413697536 #bytes=1841 p3=0 obj#=114207 tim=4963759268
WAIT #4: nam='SQL*Net more data to client' ela= 17 driver id=1413697536 #bytes=2104 p3=0 obj#=114207 tim=4963759365
WAIT #4: nam='SQL*Net more data to client' ela= 13 driver id=1413697536 #bytes=1841 p3=0 obj#=114207 tim=4963759453
WAIT #4: nam='db file sequential read' ela= 226 file#=4 block#=1773852 blocks=1 obj#=114207 tim=4963759715
WAIT #4: nam='SQL*Net more data to client' ela= 20 driver id=1413697536 #bytes=2104 p3=0 obj#=114207 tim=4963759867
FETCH #4:c=0,e=1290,p=2,cr=54,cu=0,mis=0,r=49,dep=0,og=1,tim=4963759912
Yukardaki sonuçtan, Oracle her bir “fetch” çağrısı için ortalama iki tekil blok fiziksel okumanın gerçekleştiği görülmektedir ve sonuç “fetch” çağrısı ile 49 satır alınmıştır(r=49). İzleme dosyasına devam edersek;
WAIT #4: nam='SQL*Net message from client' ela= 792 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963760775
*** SESSION ID:(141.14281) 2011-04-29 12:54:51.107
STAT #4 id=1 cnt=10000 pid=0 pos=1 obj=0 op='FILTER (cr=10982 pr=404 pw=0 time=680024 us)'
STAT #4 id=2 cnt=10000 pid=1 pos=1 obj=0 op='NESTED LOOPS (cr=10982 pr=404 pw=0 time=670018 us)'
STAT #4 id=3 cnt=10000 pid=2 pos=1 obj=114207 op='TABLE ACCESS BY INDEX ROWID T2 (cr=781 pr=387 pw=0 time=590006 us)'
STAT #4 id=4 cnt=10000 pid=3 pos=1 obj=107421 op='INDEX RANGE SCAN SYS_C0010411 (cr=218 pr=17 pw=0 time=10038 us)'
STAT #4 id=5 cnt=10000 pid=2 pos=2 obj=107424 op='INDEX UNIQUE SCAN SYS_C0010422 (cr=10201 pr=17 pw=0 time=77882 us)'
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963764774
WAIT #0: nam='SQL*Net message from client' ela= 2789 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963767585
Yukardan, TKRPOF çıktısında gözükmeyen bir bilgi olan ikinci çalıştırmanın çalıştırma planı görülmektedir. Satır sayısının oldukça geniş olduğu durumlarda, iki “full table scan” ile “hash join” birleştirmesi, indeks üzerinden “nested loop” birleşmelerine nazaran muhtemelen daha verimli olacaktır. Bu bind değişkenleri kullanıldığında potensiyel problemlerden birisi olmaktadır. Oracle 11.1.0.6 sürümünden itibaren, farklı bind değişkenleri ataması ile satır sayılarında belirgin miktarda değişiklik olduğunu Oracle hissettiğinde, gelecekteki çalıştırmalar için çalıştırma planında değişiklikler yapabilmektedir, bu olay “adaptive cursor sharing “ olarak adlandırılmaktadır. Bir sonraki yazıda 10046 bekleme olayı ile ilgili benzer bir analizin Oracle 11.2 sürümündeki incelemesini yazacağım.
Kayıtlar
0 yorum:
Yorum Gönder