Tracing + TKProf = detaljna analiza za optimizaciju nekog (SQL) procesa
Friday, 23.11.2007 – DejanAko pred sobom imate neku sporu aplikaciju, tj. neki spor SQL upit, u većini slučajeva ćete prvo pogledati šta kaže EXPLAIN PLAN, a ako ni nakon toga ne uočite potencijalni problem, onda u pomoć dolazi trejsovanje (tracing) i TKProf.
Trejsovanje (tracing) označava prikupljanje informacija tokom izvršavanja nekog SQL upita, a u te informacije između ostalih spadaju: kompletan SQL upit, koji se analizira, vrijeme izvršavanja tog upita (Parse, Execute, Fetch), “wait events” i mnoge druge nama nebitne informacije. Sadržaj jedne trace datoteke je u nečitljivom tzv. “human non-readable” formatu.
Ovako izgleda sadržaj jedne trace datoteke:
PARSING IN CURSOR #1 len=46 dep=1 uid=45 oct=3 lid=45 tim=2979116519 hv=3999262762 ad='3e87af28' SELECT * FROM TEST_TRACING WHERE MOD_10_ID = 3 END OF STMT PARSE #1:c=31250,e=25142,p=3,cr=70,cu=3,mis=1,r=0,dep=1,og=1,tim=2979116515BINDS #1: WAIT #1: nam='rdbms ipc reply' ela= 326 from_process=20 timeout=2147483647 p3=0 obj#=22 tim=2979116961 WAIT #1: nam='rdbms ipc reply' ela= 81 from_process=20 timeout=2147483647 p3=0 obj#=22 tim=2979117161 WAIT #1: nam='enq: PS - contention' ela= 1490 name|mode=1347616774 instance=2 slave ID=0 obj#=22 tim=2979125792 WAIT #1: nam='enq: PS - contention' ela= 1055 name|mode=1347616774 instance=2 slave ID=2 obj#=22 tim=2979127098 WAIT #1: nam='PX Deq: Join ACK' ela= 666 sleeptime/senderid=268566528 passes=1 p3=0 obj#=22 tim=2979127911 WAIT #1: nam='PX Deq: Join ACK' ela= 51 sleeptime/senderid=268566528 passes=2 p3=0 obj#=22 tim=2979127991
TKProf je alat, koji standardno dolazi uz Oracle instalaciju, a služi analizi trace datoteka, tj. prikazivanju sadržaja it trace datoteke u čitljivom tzv. “human readable” formatu.
Ovako izgleda sadržaj trace datoteke nakon analize pomoću TKProfa:
SELECT * FROM TEST_TRACING WHERE MOD_10_ID = 3 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 6 0.01 0.02 0 8 1 0 Execute 6 0.04 1.01 0 18 0 0 Fetch 606 0.09 0.58 0 0 0 60000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 618 0.15 1.62 0 26 1 60000 Misses in library cache during parse: 6 Optimizer mode: ALL_ROWS Parsing user id: 45 (neki_korisnik) (recursive depth: 1) Rows Execution Plan ------- --------------------------------------------------- 0 SELECT STATEMENT MODE: ALL_ROWS 0 PX COORDINATOR 0 PX SEND (QC (RANDOM)) OF ':TQ10000' [:Q1000] 0 PX BLOCK (ITERATOR) [:Q1000] 0 TABLE ACCESS MODE: ANALYZED (FULL) OF 'TEST_TRACING' (TABLE) [:Q1000]
Pokazaću na jednom primjeru, kako se koriste tracing i TKProf, a usput i objasniti koje informacije su najbitnije za analizu nekog SQL upita…
Za potrebe ovog primjera trebamo kreirati jednu tabelu i popuniti ju podacima:
create table test_tracing ( test_id number, test_naziv varchar2(32), mod_10_id number) parallel (degree 4); insert /*+ APPEND */ into test_tracing SELECT LEVEL, 'naziv_' || TO_CHAR(level), mod(level, 10) FROM dual CONNECT BY LEVEL <= 100000; COMMIT;
Tracing ćemo aktivirati pomoću procedure START_TRACE u paketu DBMS_SUPPORT. Ukoliko nemate instaliran taj paket, onda ga instalirajte izvršavanjem SQL skripte dbmssupp.sql:
SQL> conn sys/pass as sysdba Connected. SQL> @?\rdbms\admin\dbmssupp.sql
Dodajte pravo korištenja ovog paketa potrebnom korisniku:
SQL> grant execute on dbms_support to neki_korisnik;
Ako ste se uvjerili da je DBMS_SUPPORT instaliran, izvršite slijedeći upit:
begin sys.dbms_support.start_trace(waits => true, binds => true); FOR rec IN (SELECT * FROM test_tracing WHERE mod_10_id = 3) LOOP NULL; END LOOP; sys.dbms_support.stop_trace; end;
U ovom slučaju će čitava tabela biti “skenirana” (“full table scan”). U to se možemo uvjeriti, ukoliko TKProf alatom analiziramo sadržaj kreirane trace datoteke:
C:\>tkprof C:\oracle\admin\testDB\udump\testDB_ora_3004.trc test_tracing.txt
waits=yes sys=no explain=neki_korisnik/sifra@testDB
Otvorimo datoteku test_tracing.txt i pronađimo gorekorišteni upit:
SELECT * FROM TEST_TRACING WHERE MOD_10_ID = 3 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 6 0.01 0.02 0 8 1 0 Execute 6 0.04 1.01 0 18 0 0 Fetch 606 0.09 0.58 0 0 0 60000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 618 0.15 1.62 0 26 1 60000 Misses in library cache during parse: 6 Optimizer mode: ALL_ROWS Parsing user id: 45 (neki_korisnik) (recursive depth: 1) Rows Execution Plan ------- --------------------------------------------------- 0 SELECT STATEMENT MODE: ALL_ROWS 0 PX COORDINATOR 0 PX SEND (QC (RANDOM)) OF ':TQ10000' [:Q1000] 0 PX BLOCK (ITERATOR) [:Q1000] 0 TABLE ACCESS MODE: ANALYZED (FULL) OF 'TEST_TRACING' (TABLE) [:Q1000]
Uočavamo da je nad tabelom primijenjen “full table scan”, a kao moguće rješenje se nameće kreiranje indexa nad korištenom kolonom u WHERE klauzuli (tzv. predikat kolona).
Dodajmo sad index nad kolonom mod_10_id, da bismo vidjeli razliku u izvršavanju tog SQL upita:
CREATE INDEX neki_korisnik.INDX_TEST_TRACING_MOD_ID ON neki_korisnik.TEST_TRACING(MOD_10_ID) LOGGING NOPARALLEL COMPUTE STATISTICS ONLINE;
Pokrenimo isti upit opet:
begin
sys.dbms_support.start_trace(waits => true, binds => true);
FOR rec IN (SELECT * FROM test_tracing WHERE mod_10_id = 3)
LOOP
NULL;
END LOOP;
sys.dbms_support.stop_trace;
end;
Sad možemo ponovo analizirati kreiranu trace datoteku i uočiti razliku između upita sa “full table scan” i upita sa korištenjem indexa:
SELECT * FROM test_tracing WHERE mod_10_id = 3 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 2 0.00 0.00 0 0 0 0 Execute 2 0.00 0.00 0 0 0 0 Fetch 2 0.00 0.00 6 8 0 2 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 6 0.00 0.01 6 8 0 2 Misses in library cache during parse: 2 Misses in library cache during execute: 2 Optimizer mode: ALL_ROWS Parsing user id: 45 (neki_korisnik) (recursive depth: 2) Rows Row Source Operation ------- --------------------------------------------------- 1 SORT AGGREGATE (cr=4 pr=3 pw=0 time=4410 us) 2500 VIEW (cr=4 pr=3 pw=0 time=8748 us) 2500 COUNT STOPKEY (cr=4 pr=3 pw=0 time=6245 us) 2500 INDEX RANGE SCAN INDX_TEST_TRACING_MOD_ID (cr=4 pr=3 pw=0 time=3741 us)(object id 88431) Rows Execution Plan ------- --------------------------------------------------- 0 SELECT STATEMENT MODE: HINT: ALL_ROWS 1 SORT (AGGREGATE) 2500 VIEW 2500 COUNT (STOPKEY) 2500 INDEX MODE: ANALYZED (RANGE SCAN) OF 'INDX_TEST_TRACING_MOD_ID' (INDEX)
Iz rezultata se vidi da je upit sa indexom daleko brži.
Ovo je najbanalniji primjer, ali princip korištenja trejsovanja i TKProfa možete koristiti i za kompletne aplikacije, a ne samo za pojedinačne SQL upite.