Ein paar scheinbar unbedeutende Anpassungen in einer PL/SQL Prozedur, in einer weiteren nur ein neues, im „Trockentest“ rasend schnelles SQL Query hinzugefügt, noch eben ein kleiner Testdurchlauf auf dem Entwicklungssystem: Funktioniert, ist auch schnell genug. Also können die Erweiterungen in den Ladeprozess des Datawarehouse-Testsystems eingespielt werden. Was aber tun, wenn der veränderte Code auf dem Testsystem mit einem deutlich größeren Datenvolumen nun eben nicht mehr schnell genug ist und den vorher performanten Ladelauf ausbremst?
Anstatt jetzt sofort alle Code-Änderungen in Frage zu stellen, gibt es eine recht einfache Möglichkeit, zumindest das PL/SQL-Unterprogramm, dass für die Performanceverschlechterung verantwortlich ist, oder sogar die Zeile, in der ein langsamer SQL-Befehl steht, zu identifizieren: Der hierarchische Profiler im DBMS_HPROF-Package, das seit der Version 11g Release 1 in der Oracle-Datenbank enthalten ist! Dieser Profiler speichert das dynamische Ausführungsprofil von PL/SQL-Programmen und deren Unterprogrammen und lässt so die Analyse von z.B. Anzahl der Aufrufe und in einzelnen Unterprogrammen verbrauchter Zeit zu. Dieser Blogeintrag soll einen kleinen Einblick in die Möglichkeiten des Profilers geben.
Um das DBMS_HPROF-Package zu nutzen, müssen zunächst einige Voraussetzungen mit DBA-Rechten geschaffen werden:
1. Ein Oracle-Directory zum Ablegen einer Tracedatei durch DBMS_HPROF anlegen. Der im Beispiel verwendete Name profiler ist dabei beliebig gewählt.
CREATE OR REPLACE DIRECTORY profiler
AS '/home/oracle/profiler';
|
2. Lese- und Schreibrechte auf dem Verzeichnis vergeben, im Beispiel an den Benutzer dwh_target.
GRANT READ, WRITE ON DIRECTORY profiler TO dwh_target;
|
3. Zu guter Letzt muss noch das Privileg zum Ausführen des DBMS_HPROF-Package vergeben werden.
GRANT EXECUTE ON DBMS_HPROF TO dwh_target;
|
Das Profiling wird, z.B. in einem anonymen PL/SQL-Block, mit DBMS_HPROF.START_PROFILING (unter Angabe von Ziel-Directory und Ziel-Datei) gestartet und mit DBMS_HPROF.STOP_PROFILING wieder angehalten. Im Beispiel wird die Prozedur fehlerpruefung aus dem Package dq_check_pkg aufgerufen. Diese Prozedur ruft, wie später zu sehen sein wird, weitere Unterprogramme auf.
BEGIN
-- Profiling starten unter Angabe von Ziel-Directory und -Datei
DBMS_HPROF.START_PROFILING('PROFILER', 'profiler.log');
-- Aufruf der zu untersuchenden PL/SQL-Unterprogrammstruktur
dq_check_pkg.fehlerpruefung;
-- Profiling stoppen
DBMS_HPROF.STOP_PROFILING;
END;
|
Die dabei entstandene Datei kann man sich mit einem Texteditor anschauen.
P#V PLSHPROF Internal Version 1.0
P#! PL/SQL Timer Started
P#C PLSQL."DWH_TARGET"."DQ_CHECK_PKG"::11."__pkg_init"
P#X 5
P#R
P#C PLSQL."DWH_TARGET"."DQ_CHECK_PKG"::11."FEHLERPRUEFUNG"#980980e97e42f8ec #2130
P#X 26
P#C SQL."DWH_TARGET"."DQ_CHECK_PKG"::11."__static_sql_exec_line2147" #2147
P#X 89
P#R
P#X 14
P#C SQL."DWH_TARGET"."DQ_CHECK_PKG"::11."__static_sql_exec_line2153" #2153
P#X 31496559
P#R
P#X 22
P#C SQL."DWH_TARGET"."DQ_CHECK_PKG"::11."__static_sql_exec_line2157" #2157
P#X 9645
P#R
P#X 6
P#C PLSQL."DWH_TARGET"."DQ_CHECK_PKG"::11."FEHLERPRUEFUNG.C_SENDUNGEN"#980980e97e42f8ec #2140
P#X 22
P#C SQL."DWH_TARGET"."DQ_CHECK_PKG"::11."__static_sql_exec_line2141" #2141
P#X 937
P#R
P#X 2
.
.
.
P#R
P#C PLSQL."SYS"."DBMS_HPROF"::11."STOP_PROFILING"#980980e97e42f8ec #59
P#R
P#! PL/SQL Timer Stopped
Das Zeilenprefix beschreibt dabei den Inhalt der jeweiligen Zeile:
P#V: Startzeile mit Versionsinformation
P#C: Unterprogrammaufruf
P#R: Rückkehr / Rückgabe vom Unterprogramm
P#X: Zwischen vorherigem und folgendem Ereignis verstrichene Zeit (Mikrosekunden)
P#!: Kommentarzeile
Eine Aufrufzeile ist wie folgt aufgebaut:
Die Analyse der Ausführung mag für kleine Programmstrukturen noch anhand dieser Tracedatei möglich sein, je größer die Datei jedoch wird, desto schwieriger wird es auch, grundsätzliche Informationen auf einen Blick zu erkennen. In einem solchen Fall hilft wieder DBMS_HPROF weiter, denn das Package hält eine weitere nützliche Funktion bereit: DBMS_HPROF.ANALYZE. Mit dieser lassen sich die Ergebnisse aus der Tracedatei aufbereitet in Datenbanktabellen abspeichern.
Bevor die Analyse beginnen kann, muss noch die entsprechende Tabellenstruktur angelegt werden. Ein Script, das diese Aufgabe übernimmt, liegt unterhalb des Datenbank-Home-Verzeichnisses und kann z.B. mit SQL*Plus aufgerufen werden:
>sqlplus user/passwort@connect_id @$ORACLE_HOME/rdbms/admin/dbmshptab.sql
Dann wird der Inhalt der Tracedatei analysiert, z.B. mit folgenden Code:
DECLARE
runid NUMBER;
BEGIN
runid := DBMS_HPROF.ANALYZE(LOCATION => 'PROFILER',
FILENAME => 'profiler.log');
DBMS_OUTPUT.PUT_LINE('runid = ' || runid);
END;
|
Mit der RUNID, die zurückgegeben wird, lassen sich in den Tabellen die zum jeweiligen Analysedurchlauf gehörenden Datensätze identifizieren. Die Ergebnisse sind in den folgenden drei Tabellen zu finden:
DBMSHP_RUNS: Allgemeine Informationen über den Analysedurchlauf
RUNID: ID des Analysedurchlaufs
RUN_TIMESTAMP: Zeitstempel des Analysedurchlaufs
TOTAL_ELAPSED_TIME:Dauer des Analysedurchlaufs in Mikrosekunden
RUN_COMMENT: Kommentar, den man dem ANALYZE optional übergeben kann
DBMSHP_FUNCTION_INFO: Informationen über Unterprogramme
RUNID: ID des Analysedurchlaufs
SYMBOLID: Eindeutige ID für dieses Unterprogramm in diesem Analysedurchlauf
OWNER: Besitzer des Moduls, in dem das Unterprogramm definiert ist
MODULE: Modul, in dem das Unterprogramm definiert ist
TYPE: Typ des Moduls, in dem das Unterprogramm definiert ist
FUNCTION: Name des Unterprogramms
LINE#: Zeilennummer, an der das Unterprogramm im Modul definiert ist
HASH: MD5 Hash für die Signatur des Unterprogramms
NAMESPACE: Namespace des Unterprogramms (z.B. SQL oder PLSQL)
SUBTREE_ELAPSED_TIME: Im Unterprogramm und dessen Unterprogrammen verbrauchte Zeit
FUNCTION_ELAPSED_TIME:Im Unterprogramm verbrauchte Zeit
CALLS: Anzahl der Aufrufe dieses Unterprogramms
DBMSHP_PARENT_CHILD_INFO: Informationen über Eltern-Kind-Aufrufe
RUNID: ID des Analysedurchlaufs
PARENTSYMID: Eltern-SYMBOLID (DBMSHP_FUNCTION_INFO)
CHILDSYMID: Kind-SYMBOLID (DBMS_FUNCTION_INFO)
SUBTREE_ELAPSED_TIME: Im Unterprogramm und dessen Unterprogrammen beim Aufruf durch dieses Eltern-Element verbrauchte Zeit
FUNCTION_ELAPSED_TIME:Im Unterprogramm beim Aufruf durch dieses Eltern-Element verbrauchte Zeit
CALLS: Anzahl der Aufrufe dieses Unterprogramms durch dieses Eltern-Element
Verknüpft man nun die Tabellen DBMSHP_PARENT_CHILD_INFO und DBMSHP_FUNCTION_INFO in einem Query miteinander, kann man über entsprechende Filterbedingungen einzelne Unterprogrammaufrufstrukturen gezielt analysieren und erhält Ergebnisse, mit denen imperformante Unterprogramme und sogar Zeilen mit imperformantem SQL-Code identifiziert werden können:
SELECT pfi.module PARENT_MODULE,
pfi.function PARENT_FUNCTION,
pfi.namespace PARENT_NAMESPACE,
cfi.module CHILD_MODULE,
cfi.function CHILD_FUNCTION,
cfi.namespace CHILD_NAMESPACE,
pci.subtree_elapsed_time/1000000 SUBTREE_TIME_S,
pci.function_elapsed_time/1000000 FUNCTION_TIME_S,
pci.calls CALLS
FROM dbmshp_parent_child_info pci,
dbmshp_function_info pfi,
dbmshp_function_info cfi
WHERE pci.parentsymid = pfi.symbolid
AND pci.childsymid = cfi.symbolid
AND pci.runid = 1
START WITH pfi.function = 'FEHLERPRUEFUNG'
CONNECT BY PRIOR pci.childsymid = pci.parentsymid;
|
Beschäftigt man sich etwas mit den Möglichkeiten und Informationen, so lassen sich auch komplexere PL/SQL-Aufrufstrukturen relativ einfach analysieren.
