Friday 15 February 2013

Timing Sections of PLSQL Code

Your PLSQL routine is running like a dog with three legs? Don't know where to start looking as it could be any of a number of issues? Then adapt this timing code and drop it in for testing. Wrap the start and end calls around suspected sections of code to find where the hold up is occuring.

DECLARE ----------------------------- -- Timing Declaration Start TYPE tt_timingStart IS TABLE OF TIMESTAMP(9) INDEX BY VARCHAR2(30); l_timingStart tt_timingStart; TYPE tt_timingTotal IS TABLE OF NUMBER INDEX BY VARCHAR2(30); l_timingCount tt_timingTotal; l_timingTotal tt_timingTotal; -- PROCEDURE timingStart( p_timingIndex IN VARCHAR2 ) IS BEGIN BEGIN IF l_timingTotal(p_timingIndex) IS NULL THEN NULL; END IF; EXCEPTION WHEN NO_DATA_FOUND THEN l_timingCount(p_timingIndex) := 0; l_timingTotal(p_timingIndex) := 0; END; l_timingStart(p_timingIndex) := SYSTIMESTAMP; END timingStart; -- PROCEDURE timingEnd( p_timingIndex IN VARCHAR2 ) IS l_duration INTERVAL DAY(9) TO SECOND(5) := SYSTIMESTAMP - l_timingStart(p_timingIndex); BEGIN l_timingCount(p_timingIndex) := l_timingCount(p_timingIndex) + 1; l_timingTotal(p_timingIndex) := l_timingTotal(p_timingIndex) + (EXTRACT(SECOND FROM l_duration)*1000) + (EXTRACT(MINUTE FROM l_duration)*60000) + (EXTRACT(HOUR FROM l_duration)*3600000) + (EXTRACT(DAY FROM l_duration)*86400000); END timingEnd; -- PROCEDURE timingOutput IS l_file UTL_FILE.FILE_TYPE; l_index VARCHAR2(30); BEGIN l_file := UTL_FILE.FOPEN('SCRATCH_DIR','TimingOutput.txt','W'); l_index := l_timingTotal.FIRST; WHILE l_index IS NOT NULL LOOP UTL_FILE.PUT_LINE(l_file,LPAD(l_index,20,'_')||': ' ||LPAD(ROUND(l_timingCount(l_index)),10)||'iterations' ||LPAD(ROUND(l_timingTotal(l_index)),10)||'ms' ||LPAD(ROUND(l_timingTotal(l_index)/1000),10)||'s' ||LPAD(ROUND(l_timingTotal(l_index)/60000),10)||'m'); l_index := l_timingTotal.NEXT(l_index); END LOOP; UTL_FILE.FCLOSE(l_file); END timingOutput; -- Timing Declaration End ----------------------------- BEGIN timingStart('Procedure'); FOR i IN 1..20 LOOP timingStart('First Sleep'); DBMS_LOCK.SLEEP(0.3); timingEnd('First Sleep'); timingStart('Second Sleep'); DBMS_LOCK.SLEEP(0.5); timingEnd('Second Sleep'); timingStart('Third Sleep'); DBMS_LOCK.SLEEP(0.1); timingEnd('Third Sleep'); END LOOP; timingEnd('Procedure'); timingOutput; END; /
This does assume there is a SCRATCH directory to output the file to. If you haven't got one it's easily modified to DBMS_OUTPUT.PUT_LINE.

Timed

No comments: