Als PDF Downloaden!

PL/SQL Performancemessung mit DBMS_PROFILER

Passiert es Ihnen auch gelegentlich, dass eine Prozedur zwar fehlerfrei läuft, aber viel zu lange braucht? Dann beginnt die Suche nach den Gründen. Dabei kann Ihnen DBMS_PROFILER gute Dienste leisten. Mit Hilfe dieses Packages kann folgendes mitprotokolliert werden:

• Welche Programme wurden aufgerufen?
• Welche Zeilen wurden wie oft abgearbeitet?
• Wie lange dauerte die Abarbeitung einer Zeile gesamt, minimal, maximal?
• Wie lange dauerte der gesamte Lauf?

Voraussetzungen

Zunächst muss in 8i/9i das Package, das ab Version 8.1.5 zur Verfügung steht, installiert werden. Dies geschieht als User SYS durch Aufruf des Skripts profload.sql. Es befindet sich im Verzeichnis ORACLE_HOME\RDBMS\ADMIN.

-- Windows-Umgebung:
-- 8i/9i:
CONN / AS SYSDBA
@?\rdbms\admin\profload.sql

Ab Version 10g ist das Package standardmäßig installiert.

Im gleichen Verzeichnis findet sich das Skript proftab.sql. Dieses müssen Sie als derjenige User ausführen, unter dem Sie damit arbeiten wollen. Dadurch werden eine Sequenz (für die eindeutige ID eines Laufs) und drei Tabellen angelegt:

• PLSQL_PROFILER_RUNS listet alle Läufe des Profilers auf.
• PLSQL_PROFILER_UNITS listet alle Subprogramme auf, die aufgerufen wurden
• PLSQL_PROFILER_DATA beinhaltet die eigentlichen Informationen. Hier stehen die Details bezüglich Dauer einer bestimmten Anweisung u.ä..

CONN SCOTT/TIGER
@?\rdbms\admin\proftab.sql

Durchführung

Die Handhabung des Packages zum Aufzeichnen der Information ist ziemlich einfach. Zuerst muss der Profiler gestartet werden, dann wird die zu untersuchende Prozedur aufgerufen, und am Ende wird der Profiler gestoppt; dies ist Voraussetzung dafür, dass die gesammelten Informationen auch abgespeichert werden. Erfolgen nach dem Start mehrere Programmaufrufe, so können auch zwischenzeitlich die bis dahin gesammelten Informationen mit FLUSH_DATA in die Tabellen geschrieben werden. Bei allen drei Funktionen bedeutet ein Rückgabewert <> 0, dass ein Fehler aufgetreten ist.

Nach Beendigung des Laufs kann dann anhand der o.g. Tabellen das Ergebnis analysiert werden. Zeitangaben sind grundsätzlich in Nanosekunden. Es sollte aber erwähnt werden, dass gerade im Zusammenhang mit den absoluten Zeitangaben der ein oder andere Bug beschrieben ist. In den Versionen 8.1.5 bis 9.0.x  (nicht Version 9.2) werden viel zu große Zahlen - in der Größenordnung von drei Zehnerpotenzen - beschrieben (Bug Nr. 2207526), wie wir sie ebenfalls feststellen mussten. Das Verhältnis der Werte zueinander passt jedoch, so dass der Profiler auch in diesen Versionen gute Anhaltspunkte über mögliche "Bottlenecks" geben kann.

In PLSQL_PROFILER_RUNS finden sich der Beginn und die gesamte Dauer des Laufs, während in PLSQL_PROFILER_DATA die Zeiten aufgelistet werden, die zur Ausführung jedes einzelnen Befehls benötigt wurden. Die Summe aus PLSQL_PROFILER_DATA stimmt normalerweise nicht mit dem Wert in PLSQL_PROFILER_RUNS überein.
Anhand der LINE#-Spalte in PLSQL_PROFILER_DATA können dann die zeitaufwendigen Anweisungen im Quelltext identifiziert werden.

 

Beispiel:

Bei dem folgenden Beispiel beinhalten beide aufgerufenen Prozeduren nur eine einfache FOR-Schleife, in der der Schleifenzähler ausgegeben wird. Einmal wird vorwärts gezählt, einmal rückwärts. Es wurde die Datenbank-Version 9.2 benutzt.

SET SERVEROUTPUT ON
DECLARE
   v_start NUMBER;
   v_stop  NUMBER;
   v_flush NUMBER;
BEGIN
   v_start := DBMS_PROFILER.START_PROFILER;
   IF v_start <> 0 THEN
      DBMS_OUTPUT.PUT_LINE('Fehler beim Starten');
      RETURN;
   END IF;
   PROC1;
   v_flush := DBMS_PROFILER.FLUSH_DATA;
   IF v_flush<> 0 THEN
      DBMS_OUTPUT.PUT_LINE('Fehler beim Flush');
      RETURN;
   END IF;
   PROC2;
   v_stop  := DBMS_PROFILER.STOP_PROFILER;
   IF v_stop<> 0 THEN
      DBMS_OUTPUT.PUT_LINE('Fehler beim Stoppen');
   END IF;
END;
/

Analyse der Tabellen:

SELECT RUNID, RUN_DATE, RUN_TOTAL_TIME
  FROM PLSQL_PROFILER_RUNS
 ORDER BY runid DESC;

RUNID     RUN_DATE RUN_TOTAL_TIME
--------- -------- --------------
       18 07.10.03      328389000

SELECT UNIT_NUMBER, UNIT_TYPE, UNIT_NAME
  FROM PLSQL_PROFILER_UNITS
 WHERE runid = (SELECT MAX(runid) FROM PLSQL_PROFILER_RUNS);

UNIT_NUMBER UNIT_TYPE                        UNIT_NAME
----------- -------------------------------- ------------
          1 ANONYMOUS BLOCK                  <anonymous>
          2 PROCEDURE                        PROC1
          3 PROCEDURE                        PROC2

                  
SELECT UNIT_NUMBER, LINE#, TOTAL_OCCUR,
       TOTAL_TIME, MIN_TIME, MAX_TIME
  FROM PLSQL_PROFILER_DATA
 WHERE runid = (SELECT MAX(runid) FROM PLSQL_PROFILER_RUNS)
   AND total_occur > 0
   AND unit_number <> 1
 ORDER BY total_time DESC;

UNIT_NUMBER     LINE# TOTAL_OCCUR TOTAL_TIME  MIN_TIME  MAX_TIME
----------- --------- ----------- ---------- --------- ---------
          2         5          20      80000      2000     31000
          3         5          20      74000      2000     22000
          2         4          21      41000      1000      5000
          3         4          21      41000      1000      3000


/* Ausgabe 10g/11g:
UNIT_NUMBER      LINE# TOTAL_OCCUR TOTAL_TIME   MIN_TIME   MAX_TIME
----------- ---------- ----------- ---------- ---------- ----------
          2          5          20      51857        845      33636
          3          5          20      34460        863      16752
          3          4          21      14167        572       1151
          2          4          21      11106        500        686
          2          7           1        764        764        764
          3          7           1        722        722        722
*/

SELECT line, text
  FROM USER_SOURCE
 WHERE name IN  ('PROC1', 'PROC2')
   AND line IN (4, 5)
 ORDER BY name, line;

LINE      TEXT
--------- -------------------------------------------------------------
        4    FOR i IN 1..20 LOOP
        5       DBMS_OUTPUT.PUT_LINE(i);
        4    FOR i IN REVERSE 1..20 LOOP
        5       DBMS_OUTPUT.PUT_LINE(i);

--alternativ:

SELECT  s.name, LINE#, text, d.TOTAL_TIME
  FROM PLSQL_PROFILER_DATA d,
       PLSQL_PROFILER_units u,
       USER_SOURCE s
 WHERE d.runid= (SELECT MAX(runid) FROM PLSQL_PROFILER_RUNS)
   AND d.unit_number = u.unit_number
   AND d.runid = u.runid
   AND u.unit_name = s.name
   AND d.line# = s.line
   AND total_occur > 0
   AND d.unit_number <> 1
 ORDER BY total_time DESC;

NAME      LINE# TEXT                            TOTAL_TIME
----- --------- ------------------------------- ----------
PROC1         5       DBMS_OUTPUT.PUT_LINE(i);       80000
PROC2         5       DBMS_OUTPUT.PUT_LINE(i);       74000
PROC1         4    FOR i IN 1..20 LOOP               41000
PROC2         4    FOR i IN REVERSE 1..20 LOOP       41000

/* Ausgabe 10g/11g:

NAME       LINE# TEXT                            TOTAL_TIME
----- ---------- ------------------------------- ----------
PROC1          5        DBMS_OUTPUT.PUT_LINE(i);      51857
PROC2          5        DBMS_OUTPUT.PUT_LINE(i);      34460
PROC2          4     FOR i IN REVERSE 1..20 LOOP      14167
PROC1          4     FOR i IN 1..20 LOOP              11106
PROC1          7  END;                                  764
PROC2          7  END;                                  722
*/

Suche