PL/SQL Performance Analyse mittels DBMS_PROFILER

Veröffentlicht am von

Das DBMS_PROFILER Package ermöglicht es, Statistiken über die Laufzeit von PL/SQL Code zu ermitteln. Dies ist relevant um mögliche Performance Probleme innerhalb des Quellcode zu finden.

Um das DBMS_PROFILER Package verwenden zu können, müssen erst die benötigten Tabellen angelegt werden. Dazu wird das PROFTAB.SQL Skript – welches sich im Ordner $ORACLE_HOME/rdbms/admin befindet – verwendet .

DBMS_PROFILER kann Statistiken erfassen für alle PL/SQL Objekte auf welche der ausführende Nutzer create Rechte besitzt. Ein Neukompilieren der Objekte ist nicht notwendig.

Für einen Test können die folgenden Objekte genutzt werden. Das commit innerhalb der fill_table Prozedur ist zur Veranschaulichung bewusst in der FOR Schleife positioniert worden.

DROP TABLE profiler_test_table;

CREATE TABLE profiler_test_table
(
   pk_value       NUMBER CONSTRAINT pk_slow_table PRIMARY KEY,
   beschreibung   VARCHAR2(200)
);

CREATE OR REPLACE PROCEDURE fill_table AS
BEGIN
   FOR i IN 1 .. 10000
   LOOP
      INSERT INTO profiler_test_table(pk_value, beschreibung)
           VALUES (DBMS_RANDOM.VALUE(1, 1000), DBMS_RANDOM.string('A', 20));

      COMMIT;
   END LOOP;
END fill_table;
/

CREATE OR REPLACE FUNCTION fast_function(p_value IN NUMBER)
   RETURN NUMBER IS
BEGIN
   RETURN p_value;
EXCEPTION
   WHEN OTHERS THEN
      ROLLBACK;
      RAISE;
END;
/

CREATE OR REPLACE PROCEDURE test_profiler AS
   l_result   NUMBER;
BEGIN
   FOR i IN 1 .. 10
   LOOP
      l_result := fast_function(i);

      fill_table;
   END LOOP;
END test_profiler;
/

Ziel ist es die Prozedur test_profiler zu analysieren um mögliche Optimierungen zu finden.

BEGIN
   DBMS_PROFILER.start_profiler('test_profiler');
   test_profiler;
   DBMS_PROFILER.stop_profiler;
END;
/

Der Übergabeparameter der DBMS_PROFILER.start_profiler Prozedur kann später genutzt werden um den entsprechenden Lauf in der vorher angelegten Tabellenstruktur wieder zu finden. Nach dem Start des Profilers wird die test_profiler Prozedur gestartet. Ist diese abgeschlossen wird auch der Profiler gestoppt. Mit dem Stoppen des Profilers werden die erfassten Daten in den Tabellen festgeschrieben.

  SELECT u.unit_owner,
         u.unit_name,
         p.line# "Zeile",
         src.text "Code",
         r.run_total_time / 1000000 "Gesamtlaufzeit in ms",
         p.total_occur "Anzahl Aufrufe",
         p.min_time / 1000000 "Min. Laufzeit ms",
         p.max_time / 1000000 "Max. Laufzeit ms",
         p.total_time / 1000000 "Gesamtzeit / ms"
    FROM plsql_profiler_runs r,
         plsql_profiler_units u,
         plsql_profiler_data p,
         all_source src
   WHERE r.runid = (SELECT MAX(runid)
                      FROM plsql_profiler_runs
                     WHERE run_comment = 'test_profiler')
     AND u.runid = r.runid
     AND p.runid = u.runid
     AND p.unit_number = u.unit_number
     AND src.owner(+) = u.unit_owner
     AND src.name(+) = u.unit_name
     AND src.line(+) = p.line#
ORDER BY p.total_time DESC;

Das select liefert diverse Daten zu dem aktuellsten Lauf mit dem Kommentar ‚test_profiler‘. Ein wichtiger Punkt der erfassten Daten ist, das eine Verbindung zu der all_source Tabelle hergestellt werden kann. Somit kann direkt der entsprechende Quellcode dargestellt werden. Nicht möglich ist dies bei anonymen Blöcken, da der entsprechende Quellcode nicht vorgehalten wird. Zu erkennen ist dies an den Spalten UNIT_OWNER / UNIT_NAME welche mit den Daten „<anonymous>“ gefüllt sind.

In dem hier dargestellten Beispiel konnten bei Testläufen in allen Fällen die Folgenden Schlüsse gezogen werden.

  1. Die meiste execute Zeit wurde durch das commit; erzeugt welches 10.000x ausgeführt wurden. Dies verdeutlicht die Kosten eines commit deutlich.
  2. Ein weiteres im Verhältnis teures Statement ist – wie zu erwarten – das insert Statement welches 10.000x über DBMS_RANDOM Zufallswerte erzeugt.

Die Gesamtlaufzeit der DBMS_PROFILER Sitzung überschreitet die zusammengerechnete Laufzeit der einzelnen Statements bei weitem. Die Erklärung dazu ist recht einfach. DBMS_PROFILER betrachtet die execute Zeiten welche durch die Statements verbraucht werden. Nicht betrachtet werden Wartezeiten z.B. auf das Storage. Enthält der PL/SQL Code z.B. ein select Statement mit einem Full-Table-Scan, muss dieses nicht zwingend oben in der Liste erscheinen. Um diese Lücke zu schließen, kann ein Trace über das DBMS_MONITOR Package hinzugezogen werden mit einer anschließenden tkprof Auswertung.

In dem hier gezeigten Beispiel beträgt die Gesamtlaufzeit etwa 17.000 ms. Wird das commit; Statement erst zum Ende des Codes ausgeführt, verringert sich die Laufzeit auf dem Testsystem bereits auf rund 13.000 ms.

Schreibe einen Kommentar