Tracing + TKProf = detaljna analiza za optimizaciju nekog (SQL) procesa

Friday, 23.11.2007 – Dejan

Ako 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.

Post a Comment