Mehr Performance! Tuning von APEX-Anwendungen - Teil 1: Tracing, Analyse und Diagnose

Performance ist bei APEX-Anwendungen immer wieder ein Thema - je mehr Nutzer mit einer APEX-Anwendung arbeiten, desto wichtiger ist es, dass die Anwendungsseiten schnell und flüssig dargestellt werden. In diesem und einigen der nächsten Community-Tipps stellen wir einige Ansätze zum Performance-Tuning von APEX-Anwendungen vor. Der erste Teil beschäftigt sich vor allem mit der Diagnose von Performanceproblemen. Wie findet man heraus, welche SQL-Abfragen problematisch sind und wie lassen sich Details zu deren Ausführung ermitteln? Dazu werden die in APEX eingebauten Möglichkeiten vorgestellt, aber auch auf Möglichkeiten in SQL*Plus oder dem Oracle Enterprise Manager eingegangen.

Die kritische APEX-Komponente identifizieren: #TIMING#

Vor allem wenn mehrere Berichte auf einer Seite enthalten sind, sollte man zuallererst herausfinden, welcher Bericht wieviel Zeit benötigt - das die am längsten laufenden werden dann als erstes angegangen. Hierfür ist das Schlüsselwort #TIMING#, welches in den Regions-Footer gesetzt werden kann, sehr hilfreich. Abbildung 1 zeigt eine APEX-Anwendungsseite mit drei Berichten und den Angaben zum Zeitverbrauch, die mit dem #TIMING# Schlüsselwort ausgegeben wurden.

APEX-Anwendungsseite mit Informationen zu verbrauchter Zeit (#TIMING#)

Abbildung 1: APEX-Anwendungsseite mit Informationen zu verbrauchter Zeit (#TIMING#)

Es ist deutlich zu erkennen, dass der Bericht oben rechts (Produkte) die meiste Zeit verbraucht. Einem Bericht liegt stets eine SQL-Abfrage als Datenquelle zugrunde - im Beispiel ist das die folgende ... 

select 
 p.prod_id,
 p.prod_name,
 (select sum(quantity_sold * amount_sold) from sh.sales s where s.prod_id = p.prod_id) summe_sale,
 (select avg(quantity_sold * amount_sold) from sh.sales s where s.prod_id = p.prod_id) avg_sale,
 (select max(quantity_sold * amount_sold) from sh.sales s where s.prod_id = p.prod_id) min_sale,
 (select min(quantity_sold * amount_sold) from sh.sales s where s.prod_id = p.prod_id) max_sale
from sh.products p

APEX Debugging

Eine weitere wichtige Informationsquelle ist das APEX-Debugging. Sie erreichen es mit dem Link Debug in der Developer Toolbar unterhalb der Anwendungsseite oder mit dem Debug-Schalter in der Seiten-URL (Abbildung 2). 

http://sccloud033:8080/apex/f?p=106:1:1177401953320137::YES
APEX-Anwendungsseite mit Debug-Informationen

Abbildung 2: APEX-Anwendungsseite mit Debug-Informationen

Wie in Abbildung 2 erkennbar ist, werden im Debug-Modus die einzelnen Prozeßpunkte (samt evtl. auftretender Fehlermeldungen) und eine Zeitinformation angezeigt. Im Gegensatz zu #TIMING# können Sie über die Debug-Funktion auch die Laufzeit der onLoad-Seitenprozesse messen und langlaufende Kandidaten identifizieren. Übrigens: In APEX 4.0 hat sich das Debugging grundliegend verändert. Es wird in einem interaktiven Bericht dargestellt, so dass Sie ganz bequem auswerten können.

Debugging-Informationen in APEX 4.0 anzeigen

Abbildung 2a: Debugging-Informationen in APEX 4.0 anzeigen

Diagnose mit SQL*Plus

Schauen wir uns nun nochmals die konkrete SQL-Anweisung des langlaufenden Berichts an. Erfahrene APEX-Entwickler erkennen sofort, dass dieses SQL nicht so günstig formuliert ist. Ein erster Blick gilt dem Ausführungsplan, den Sie mit Werkzeugen wie dem SQL Developer anzeigen können - im folgenden sei aber die Vorgehensweise in SQL*Plus gezeigt. SQL*Plus kennt das schon etwas ältere set autotrace-Kommando, welches nicht nur einen Ausführungsplan angibt, sondern auch Informationen zu gelesenen Blöcken ausgeben kann. Hat man ein fertiges SQL-Kommando und kennt man auch alle Parameter, ist dies ein sehr wertvolles Hilfsmittel.

Um das SQL*Plus Autotrace-Kommando nutzen zu können, muss der DBA (oder auf Ihrer Entwicklerdatenbank: Sie selbst) einige Vorbereitungen treffen. Auch wenn Sie mit einem anderen Werkzeug arbeiten: Sie brauchen immer das Privileg für Abfragen im Data Dictionary; die Rolle SELECT ANY DICTIONARY sollten Sie zur Diagnose langsamer SQL-Anweisungen also auf jeden Fall haben.

  • Spielen Sie als SYS das Skript im Verzeichnis $ORACLE_HOME/sqlplus/admin/plustrce.sql ein.
  • Vergeben Sie die darin erzeugte Rolle PLUSTRACE an das Datenbankschema, mit dem Sie arbeiten.

Verbinden Sie sich nun mit SQL*Plus auf Ihre Datenbank und setzen Sie das set autotrace-Kommando, gefolgt von der SQL-Abfrage ab. 

SQL> set autotrace traceonly

select 
 p.prod_id,
 p.prod_name,
 (select sum(quantity_sold * amount_sold) from sh.sales s where s.prod_id = p.prod_id) summe_sale,
 (select avg(quantity_sold * amount_sold) from sh.sales s where s.prod_id = p.prod_id) avg_sale,
 (select max(quantity_sold * amount_sold) from sh.sales s where s.prod_id = p.prod_id) min_sale,
 (select min(quantity_sold * amount_sold) from sh.sales s where s.prod_id = p.prod_id) max_sale
from sh.products p

Neben dem Ausführungsplan (hier verkürzt dargestellt) sollten Sie dann etwa folgende Ausgabe sehen ... 

----------------------------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name           | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
----------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |                |    72 |  2160 |     4  (25)| 00:00:01 |       |       |
|   1 |  SORT AGGREGATE                     |                |     1 |    12 |            |          |       |       |
|   2 |   PARTITION RANGE ALL               |                | 12762 |   149K|   514  (19)| 00:00:07 |     1 |    28 |
|   3 |    TABLE ACCESS BY LOCAL INDEX ROWID| SALES          | 12762 |   149K|   514  (19)| 00:00:07 |     1 |    28 |
|   4 |     BITMAP CONVERSION TO ROWIDS     |                |       |       |            |          |       |       |
|*  5 |      BITMAP INDEX SINGLE VALUE      | SALES_PROD_BIX |       |       |            |          |     1 |    28 |
|   6 |  SORT AGGREGATE                     |                |     1 |    12 |            |          |       |       |
|   7 |   PARTITION RANGE ALL               |                | 12762 |   149K|   514  (19)| 00:00:07 |     1 |    28 |
|   8 |    TABLE ACCESS BY LOCAL INDEX ROWID| SALES          | 12762 |   149K|   514  (19)| 00:00:07 |     1 |    28 |
|   9 |     BITMAP CONVERSION TO ROWIDS     |                |       |       |            |          |       |       |
|* 10 |      BITMAP INDEX SINGLE VALUE      | SALES_PROD_BIX |       |       |            |          |     1 |    28 |
|   : |  :                                  | :              |     : |     : |           :|        : |       |       |
----------------------------------------------------------------------------------------------------------------------

Statistiken
----------------------------------------------------------
          0  recursive calls
          0  db block gets
      31514  consistent gets
          0  physical reads
          0  redo size
       5867  bytes sent via SQL*Net to client
        455  bytes received via SQL*Net from client
          6  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
         72  rows processed

Die Statistiken am Ende sind sehr interessant. Die consistent gets besagen, wieviele Datenbankblöcke zur Ausführung der Abfrage gelesen werden mussten (die physical reads geben an, wieviele von der Platte geholt werden mussten). In der Beispieldatenbank ist die Blockgröße der Datenbank 8Kb, für diese Abfrage wurden also ca. 252MB Daten gelesen.

Betrachtet man den Ausführungsplan, wird das ganze Dilemma dieser Abfrage schon deutlich: Die SQL-Abfrage selektiert die Tabelle PRODUCTS und macht in der SELECT-Liste nochmals vier Unterabfragen auf die (recht große) Tabelle SALES . Und jede dieser Abfragen wird für sich ausgeführt, obwohl man, wenn man die Summe berechnet, auch direkt das Maximum, das Minimum und den Durchschnitt ausrechnen kann. Was hier gemacht werden soll, ist eigentlich ein Join - und das Umformulieren der Abfrage ... 

select 
 p.prod_id,
 p.prod_name,
 sum(s.quantity_sold * s.amount_sold) summe_sale,
 avg(s.quantity_sold * s.amount_sold) avg_sale,
 max(s.quantity_sold * s.amount_sold) max_sale,
 min(s.quantity_sold * s.amount_sold) min_sale
from sh.products p join sh.sales s on (p.prod_id = s.prod_id)
group by p.prod_id, p.prod_name

... bringt einen besseren Ausführungsplan und massiv verbesserte Statistiken: Es werden nur noch 1722 Datenbankblöcke (ca. 14MB) gelesen. 

----------------------------------------------------------------------------------------------------
| Id  | Operation               | Name     | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
----------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT        |          |    72 |  7128 | 13399  (97)| 00:02:41 |       |       |
|   1 |  HASH GROUP BY          |          |    72 |  7128 | 13399  (97)| 00:02:41 |       |       |
|*  2 |   HASH JOIN             |          |    72 |  7128 | 13398  (97)| 00:02:41 |       |       |
|   3 |    VIEW                 | VW_GBC_5 |    72 |  4968 | 13394  (97)| 00:02:41 |       |       |
|   4 |     HASH GROUP BY       |          |    72 |   864 | 13394  (97)| 00:02:41 |       |       |
|   5 |      PARTITION RANGE ALL|          |   918K|    10M|  3595  (87)| 00:00:44 |     1 |    28 |
|   6 |       TABLE ACCESS FULL | SALES    |   918K|    10M|  3595  (87)| 00:00:44 |     1 |    28 |
|   7 |    TABLE ACCESS FULL    | PRODUCTS |    72 |  2160 |     4  (25)| 00:00:01 |       |       |
----------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("P"."PROD_ID"="ITEM_1")


Statistiken
----------------------------------------------------------
          1  recursive calls
          0  db block gets
       1722  consistent gets
          0  physical reads
          0  redo size
       5855  bytes sent via SQL*Net to client
        455  bytes received via SQL*Net from client
          6  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
         72  rows processed

Und auch in der APEX-Anwendung profitiert man sofort von der verbesserten SQL-Abfrage. Wie Abbildung 3 zeigt, werden im Beispiel anstelle von 2,38 Sekunden nur noch 1,25 Sekunden benötigt.

APEX Anwendungsseite nach dem Tuning des Berichts

Abbildung 3: APEX Anwendungsseite nach dem Tuning des Berichts

Tiefergehende Diagnose mit Tracing

Das Umschreiben der SQL-Abfrage hat also schon etwas geholfen. Bevor man nun über weitere Tuning-Maßnahmen nachdenkt, wäre es hilfreich, noch etwas genauer zu wissen, was die Datenbank in diesen 1,25 Sekunden genau getan hat. Und auch hierfür bietet APEX ein Werkzeug an. Fügen Sie der URL der APEX-Anwendungsseite ein &p_trace=yes hinzu und rufen Sie sie erneut ab. 

http://sccloud033:8080/apex/f?p=106:1:3224888850756826:::::&P_TRACE=YES

Zunächst sieht die Anwendungsseite genauso aus wie vorher. Im Hintergrund hat der Datenbankserver nun allerdings eine sog. Tracedatei geschrieben. Sie liegt in der user dump destination; einem speziellen Verzeichnis des Datenbankservers. Um an diese Datei heranzukommen, benötigen Sie einen Betriebssystemzugriff für den Datenbankserver, also ggfs. die Hilfe des Datenbankadministrators. Das folgende Listing zeigt eine Beispielkonfiguration. Wenn Sie mit dem PL/SQL Embedded Gateway arbeiten, tragen die Tracedateien ein s00x im Namen, ansonsten beginnen Sie mit der SID der Datenbank, gefolgt von "ora". Sie sollten sich den Zeitpunkt, zu dem Sie die URL mit dem Parameter P_TRACE aufgerufen haben, gut behalten. 

[oracle@sccloud033 trace]$ pwd
/opt/oracle/diag/rdbms/orcl/orcl/trace

[oracle@sccloud033 trace]$ ls -ltr
-rw-r----- 1 oracle oinstall       234 May 31 13:50 orcl_s000_1720.trm
-rw-r----- 1 oracle oinstall    475061 May 31 13:50 orcl_s000_1720.trc
-rw-r----- 1 oracle oinstall        44 May 31 13:52 orcl_ora_10271.trm
-rw-r----- 1 oracle oinstall       850 May 31 13:52 orcl_ora_10271.trc
-rw-r----- 1 oracle oinstall       647 May 31 13:56 orcl_lgwr_1706.trm
-rw-r----- 1 oracle oinstall      7783 May 31 13:56 orcl_lgwr_1706.trc
-rw-r----- 1 oracle oinstall    157059 May 31 13:58 orcl_vktm_1688.trm
-rw-r----- 1 oracle oinstall   1609200 May 31 13:58 orcl_vktm_1688.trc

Diese Tracedateien sind allerdings nicht gut lesbar - daher werden sie im nächsten Schritt mit dem Werkzeug tkprof lesbar gemacht. Am besten tun Sie das gleich auf dem Datenbankserver - sie sind ja ohnehin gerade dort. 

[oracle@sccloud033 trace]$ tkprof orcl_s000_1720.trc ausgabe.txt


TKPROF: Release 11.2.0.1.0 - Development on Mon May 31 14:03:15 2010

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

Die dabei entstandene Datei ausgabe.txt können Sie sich nun mit einem Texteditor ansehen. Sie finden darin nun alle SQL-Anweisungen, die von APEX zum Aufbau der Webseite abgesetzt wurden, nebst detaillierten Statistiken zu deren Ausführung. Enthalten sind übrigens auch APEX-Spezifische SQL-Abfragen und Anweisungen. Schaut man sich darin ein wenig um, so findet man auch die soeben "getunte" SQL-Anweisung wieder ... 

select 
 p.prod_id,
 p.prod_name,
 sum(s.quantity_sold * s.amount_sold) summe_sale,
 avg(s.quantity_sold * s.amount_sold) avg_sale,
 max(s.quantity_sold * s.amount_sold) max_sale,
 min(s.quantity_sold * s.amount_sold) min_sale
from sh.sales s join sh.products p on (p.prod_id = s.prod_id)
group by p.prod_id, p.prod_name
 order by 3,1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       12      1.68       1.99          0       1724          0          12
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       14      1.70       1.99          0       1724          0          12

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 95     (recursive depth: 2)

Rows     Row Source Operation
-------  ---------------------------------------------------
     12  SORT ORDER BY (cr=1724 pr=0 pw=0 time=0 us cost=24294 size=151830 card=3615)
     72   HASH GROUP BY (cr=1724 pr=0 pw=0 time=0 us cost=24294 size=151830 card=3615)
 918843    HASH JOIN  (cr=1724 pr=0 pw=0 time=18558 us cost=4697 size=38591406 card=918843)
     72     TABLE ACCESS FULL PRODUCTS (cr=4 pr=0 pw=0 time=0 us cost=4 size=2160 card=72)
 918843     PARTITION RANGE ALL PARTITION: 1 28 (cr=1720 pr=0 pw=0 time=7935 us cost=3595 size=11026116 card=918843)
 918843      TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=1720 pr=0 pw=0 time=3959 us cost=3595 size=11026116 card=918843)

Die Tabelle direkt unterhalb der SQL-Anweisung gibt Informationen über die verbrauchte Zeit und über die verarbeiteten Datenbankblöcke und Tabellenzeilen wieder - letztere Information hatte auch schon das SQL*Plus Kommando set autotrace geliefert. Interessant sind aber die Zeiten - diese werden ausgewiesen für die drei Phasen, in denen eine SQL-Abfrage ausgeführt wird ...

  • Parse: In dieser Phase wird zunächst die Syntax der SQL-Abfrage geprüft. Danach wird festgestellt, ob benötigten Objekte und alle nötigen Privilegien vorhanden sind. Die Phase endet mit der Erstellung des Ausführungsplans.
  • Execute: In dieser Phase wird das SQL ausgeführt.
  • Fetch: In dieser Phase wird die Ergebnismenge ausgelesen.

Im Beispiel verbrauchte die gesamte Abfrage ca. 2 Sekunden (etwas länger als oben) und der größte Anteil davon war verbrauchte CPU-Zeit während der Fetch-Phase. Die Differenz (hier ca. eine Drittelsekunde) sind Warte- und I/O-Zeiten. Da die SQL-Abfrage vor allem rechnet (Summe, Durchschnitt, Minimum und Maximum), ist dieses Verhalten gut erklärbar. Diese Information ist nun sehr wichtig für das weitere Tuning - denn eine solche Maßnahme muss auf das Einsparen des CPU-Verbrauchs durch das Rechnen abzielen. Bei der Art und Weise, wie das SQL ausgeführt wird (Join-Methode) oder bei den Plattenzugriffen gibt es in diesem Beispiel nichts zu optimieren. Um es vorwegzunehmen: Die nächste Maßnahme bei dieser Abfrage wäre eine Materialized View.

Diagnose aus der Entfernung: Oracle Enterprise Manager

Mitunter kommt es jedoch vor, dass sich Situationen am Entwickler-PC nicht so einfach nachstellen lassen; denn die Berichtsausführung hängt vielfach von bestimmten Sitzungsparametern ab - und nicht zuletzt auch von der konkreten Nutzer-ID. Administratoren und Entwickler bemerken solche Situationen meist nicht selbst; sie werden vom Nutzer darauf hingewiesen: "Heute um 11:00 war die Applikation echt langsam" ... Mit dem Oracle Enterprise Manager können allerdings auch solche Situationen nachträglich diagnostiziert werden. Da Entwickler normalerweise nicht mit dem Enterprise Manager arbeiten, benötigen Sie hier wahrscheinlich die Hilfe des Datenbankadministrators.

Die im Folgenden beschriebene Funktion des Oracle Enterprise Manager gehört zum Diagnostic Pack; um das nachvollziehen zu können, muss neben der Enterprise Edition also das EM Diagnostic Pack lizensiert sein.

Die folgenden Screenshots sind mit dem Oracle EM Database Control gemacht - Database Control ist in der Installation der Datenbanksoftware enthalten. Es wird davon ausgegangen, dass Database Control auf dem APEX-Datenbankserver konfiguriert ist. Nach dem Einloggen in Database Control klicken Sie zunächst auf den Reiter Performance.

Oracle Enterprise Manager: Bereich Performance

Abbildung 4: Oracle Enterprise Manager: Bereich "Performance"

Scrollen Sie ein wenig herunter und klicken Sie auf SQL Suchen (Abbildung 5).

SQL Suchen im Oracle Enterprise Manager

Abbildung 5: SQL Suchen im Oracle Enterprise Manager

Klicken Sie oben links zunächst die Datenquellen an. Der Cursor Cache bezieht sich auf die SQL-Informationen, die im Hauptspeicher des Datenbankservers liegen und bei Bedarf wiederverwendet werden. Darüber hinaus schreibt die Datenbank diese Informationen in regelmäßigen Abständen ins Automated Workload Repository (AWR); dort werden die Informationen normalerweise 7 Tage lang aufgehoben.

Doch wie soll man in den vielen SQL-Anweisungen die richtige finden? Zum Glück ist APEX hervorragend instrumentiert. Alles, was Sie wissen müssen, ist die APEX Applikations-ID, die Seiten-ID und den APEX-Nutzernamen, mit dem gearbeitet wurde. Stellen Sie den Filter entsprechend ein (Abbildung 6):

  • Die Applikations-ID suchen Sie mit dem Filter MODUL; geben Sie ihn in der Form APEX:APPLICATION XXX ein.
  • Die Seitennummer wird mit dem Filter AKTION gesucht; geben Sie ihn in der Form PAGE Y ein.
  • Den APEX-Nutzernamen filtern Sie mit CLIENT_INFO.
APEX-Berichts-SQL im Enterprise Manager suchen

Abbildung 6: APEX-Berichts-SQL im Enterprise Manager suchen

Nach Klick auf SQL Suchen wird Ihnen eine Liste passender SQL-Anweisungen aus der Cursor Cache bzw. dem AWR präsentiert. Suchen Sie das passende SQL heraus und klicken Sie drauf. Sie sehen dann die gleichen Details, die Sie mit dem SQL*Plus-Kommando set autotrace gesehen haben - nur dass Sie hier direkt die Details der konkreten SQL-Ausführung des Nutzers sehen - es sind Originaldaten, keine nachgestellten Tests. Den verwendeten Ausführungsplan können Sie sich im Bereich Plan oberhalb der Zusammenfassung ansehen.

Details eines konkret ausgeführten SQL-Kommandos

Abbildung 7: Details eines konkret ausgeführten SQL-Kommandos

Zusammenfassung und Ausblick

APEX und die Oracle-Datenbank bieten verschiedene Varianten zur Analyse von SQL-Anweisungen und Diagnose von Problemen an. Entwickler können gut mit SQL*Plus, dem #TIMING#-Schlüsselwort oder dem Tracing arbeiten. Letzteres kann sogar für den Endanwender verfügbar gemacht werden; so könnte man recht einfach einen Link auf der APEX-Seite platzieren, welcher die Seite mit gleichen Parametern zuzüglich dem Parameter P_TRACE nochmal aufruft und vom Nutzer auf Anweisung "des Supports" geklickt wird. Natürlich gibt es darüber hinaus zahlreiche, teils kommerzielle, teils frei verfügbare Werkzeuge zur Diagnose von SQL-Problemen - alle aufzuzählen, ist sicherlich unmöglich: Der Schwerpunkt des Tipps liegt auf den mit der Datenbank ohnehin ausgelieferten Methoden.

Wie man diagnostizierte Probleme löst, also effizientes SQL- und PL/SQL schreibt, wird in einem späteren Community-Tipp betrachtet.

Zurück zur Community-Seite