BSP Profiling

Die Systemlastübersicht

Dialogschritte von BSP-Applikationen werden von der automatisch mitlaufenden Anwendungsstatistik aufgezeichnet. Das ist soweit nichts besonderes: Die Anwendungsstatistik zeichnet nämlich praktisch jede Aktion im System auf: jeden GUI-Dialogschritt, jeden RFC, jeden Batchjob. Auf diese Datensammlung können kurzfristige Auswertungen mit der Transaktion stad angewendet werden - interessanter ist jedoch meistens die Zusammenfassung im Workload Collector. Durch regelmässig laufende Jobs werden die Statistiksätze im Tages-, Wochen- und Monatsrhythmus verdichtet und können in Transaktion st03 ausgewertet werden.

Alle über einen HTTP-Port einlaufenden Requests werden in der Anwendungsstatistik unter dem Tasktyp HTTP (bzw. dem zugehörigen Domänenfestwert H) gespeichert. Eine wichtige Kennzahl für die Usability der Webanwendungen ist die durchschnittliche Antwortzeit pro Dialogschritt. Sie sollte für den Tasktyp HTTP nicht über 1 sec betragen, sondern deutlich darunter liegen. Wenn man bedenkt, dass die vom Benutzer gemessene Antwortzeit nur zu einem Teil aus der Antwortzeit des SAP-Servers besteht - es kommen im wesentlichen noch die Verbindungszeit des Netzwerks sowie die Rendering Time des Browsers hinzu - so ist serverseitige Antwortzeit von einer Sekunde pro Dialogschritt bereits als kritisch zu bewerten.

Die folgende, mit Transaktion st03 erzeugte Übersicht zeigt für das zentrale NonFood-Retailsystem der Migros die über alle fünf Applikationsserver verdichtete Systemlast für den Monat September 2008. Wir sehen, dass es im HTTP ebensoviele Dialogschritte gab wie im GUI - nämlich rund fünf Millionen. Zwar ist die Antwortzeit pro Dialogschritt für die HTTP-Tasks um 170 Millisekunden besser als die GUI-Antwortzeit – mit 613 Millisekunden ist sie aber durchaus verbesserbar: Man sollte genauer nach performancekritischen Strecken in den Web-Anwendungen suchen.

Das Transaktionsprofil

Um über die Systemlastübersicht hinausgehende Aussagen zu fällen, muss ausgewertet werden, wie sich die Systemlast auf die einzelnen ausgeführten Services aufteilt. Hierzu dient das Transaktionsprofil, das in der st03 weiter unten im Baum "Analysesichten" zu finden ist. Mit dem Button "Tasktyp" können Sie die Auswertung auf HTTP-Requests einschränken. Was Sie dann sehen, hängt davon ab, wie Sie den Workload-Collector eingestellt haben. Es ist möglich, dass Ihnen alle HTTP-Requests unter dem Reportnamen SAPMHTTP zusammengefasst werden, so dass keine weitergehende Analyse möglich ist. Mit dem Report SWNC_CONFIG_URL kann man die Verdichtung umstellen und die Zusammenfassung gemäss URL (genauer: gemäss URL-Endstück) erreichen. Nähere Angaben enthält der OSS-Hinweis 992474.

Das Transaktionsprofil wird im Normalfall über alle Server verdichtet betrachtet, d.h. man gibt den virtuellen Server TOTAL in der Serverselektion an. Es zeigt die durch die verschiedenen Tasks erzeugte Systemlast, d.h. die aufsummierte Antwortzeit aller Steps dieses Tasks, wobei die Tasks in einzelne Kästchen nach "Transaktion/Reportname" gespeichert werden. Passend eingestellt, steht hier für BSP-Applikationen der Controllername (oder die Kombination "BSP-Applikation/Controllername", falls der Controllername nicht eindeutig ist).

Die Tabelle ist nach der Spalte "Summe Antwortzeit" absteigend sortiert. Man sieht also den Task zuoberst, der das System am meisten beschäftigt hat - sei es, weil er sehr oft ausgeführt wurde (Spalte "# Schritte"), oder weil er ein Performanceproblem hat, worauf die Spalte "Durchschnitts-Antwortzeit pro Dialogschritt" einen Hinweis geben kann. Jeder Dialogschritt innerhalb der Applikation zählt dabei als eigener Task.

In diesem Beispiel fällt uns die durch den Controller wstan.do bediente Applikation als kritisch auf: Einfach deshalb, weil wir aus früheren Analysen wissen, dass die Durchschnittsantwortzeit dieses Controllers bei 600-800 Millisekunden lag und sich mit aktuell 1023 Millisekunden offenbar deutlich verschlechtert hat. Diese Applikation (der SRS-Filialauftrag) ist auch deshalb ein dankbarer Kandidat für Optimierungen, weil sie mit 500.000 Dialogschritten sehr stark benutzt wird (nur der Kundenauftrag hat noch mehr Verwendungen) und Laufzeitverbesserungen die gesamte, durch den HTTP-Stack verursachte Systemlast messbar senken.

Das Transaktionsprofil erlaubt noch einige weitergehende Analysen. Interessante Hinweise ergeben sich aus den Anteilen der CPU- und der Datenbankzeit an der Gesamtantwortzeit. Für unseren fraglichen Controller wstan.do finden wir, dass der Applikationsrechner rund ein Viertel, die Datenbank drei Viertel der Gesamtzeit beansprucht. Das ist noch eine relativ ausgewogene Verteilung. Einen Hinweis auf ein potentielles Problem hat man häufig, wenn diese beiden Zeiten extrem ungleich verteilt sind - bei einem Verhältnis ab 9:1 ist es wahrscheinlich, dass man entweder auf Datenbankseite ein Problem hat (dann meist mit einem uneffizienten select), oder auf Seiten der ABAP-Verarbeitung (dann meist mit ineffizienten Schleifen oder Zugriffen auf interne Tabellen).

Wie also weiter mit wstan.do? Wie finde ich heraus, was für die Verlangsamung des Service verantwortlich ist?

BSP-Laufzeitanalysen

Wenn es klar ist, dass die Hauptlast eines Service bei der Datenbank liegt (was man, wie gesagt, im Transaktionsprofil an der Verteilung der Antwortzeiten auf DB und CPU erkennen kann), so ist ein SQL-Trace mittels Transaktion st05 hilfreich. Meist lässt sich die lange Laufzeit bereits mit dem eigenen User reproduzieren, so dass keine speziellen Filter bemüht werden müssen, sondern der SQL-Trace in Transaktion st05 ein- und nach Beendigung des Dialogschritts wieder ausgestellt werden kann. Um in der aufgezeichneten Liste den Wald vor lauter Bäumen noch zu sehen, empfiehlt sich für eine grobe Übersicht, zunächst die DB-Operationen auf Tabellenebene zu verdichten: Dafür gibt es einen eigenen Menüpunkt. Danach kann man dann ins Detail gehen und schauen, welche Statements der Datenbank besonders zu schaffen gemacht hat.

In unserem Fall ist die Systemlast aber ausgewogen auf DB und CPU verteilt, und die Antwortzeiten sind relativ kurz. Es empfiehlt sich daher, nicht einen SQL-Trace, sondern eine Laufzeitanalyse vorzunehmen. Laufzeitanalysen vermessen nicht nur jede Datenbankoperation, sondern darüberhinaus auch jede einzelne Modularisierungseinheit: Jedes Unterprogramm, jeden Funktionsbaustein, jede Methode, auf Wunsch sogar jedes read table Statement und jede Schleife über eine interne Tabelle. Die Laufzeitanalyse kann in einem verdichteten Modus laufen, der die Aufrufe pro Modularisierungseinheit kumuliert, oder in einem detaillierten Modus, in dem jeder einzelen Aufruf separat aufgezeichnet wird. Letzteres sprengt bei längeren Abläufen sehr schnell die Grenzen der Datei und sollte nur für die Detailanalyse einer kleineren Codestrecke verwendet werden. Wir erstellen also eine Variante CONDENSED, in der die volle Aggregation der Aufrufe eingestellt ist.

Der Controller wstan.do, den wir analysieren wollen, wird tagsüber pro Stunde einige tausend Mal aufgerufen. Wenn wir bereits genau wüssten, was zu den schlechten Antwortzeiten führt, könnten wir selbst die entsprechenden Anwendungsschritte ausführen und die Aktivitäten des eigenen Benutzers vermessen. In diesem Fall wissen wir es aber nicht genau, sondern wollen in einem ersten Schritt eruieren, was "da draussen" gemacht wird und was in der Laufzeit zu Buche schlägt. Hierfür gibt es die Möglichkeit, die Laufzeitanalyse für alle HTTP-Requests auf eine bestimmte URL zu aktivieren. In Transaktion sicf positionieren wir den zu analysierenden Knoten und wählen dann übers Menü den Punkt "Laufzeitanalyse aktivieren" aus. Im erscheinenden Popup geben wir an, dass wir benutzerübergreifend sämtliche auf diesen Server eingehende Requestsverarbeitungen für die BSP-Applikation zsrs_wstan protokollieren wollen, und zwar mit der Analysevariante CONDENSED des Benutzers RPLANTIK (die alle Einträge nur verdichtet sammelt und darüberhinaus Zugriffe auf interne Tabellen protokolliert). Die Aufzeichnung wird standardmässig auf fünf Minuten eingeschränkt. Für Services, die - wie diese BSP-Applikation - massiv genutzt werden, ist das mehr als genug.

Nach Druck auf "aktivieren" werden im logischen Verzeichnis DIR_ATRA Analysefiles erzeugt. Wir können uns das Verzeichnis in Transaktion AL11 ansehen und zuschauen, wie sie entstehen. Der normale Ort, um die Files anzuschauen, ist aber die Laufzeitanalyse selbst - die Transaktion se30. Die durch die oben beschriebene Massenaktivierung erzeugten Files werden unter dem Benutzernamen SAPSYS abgelegt. Unter "Laufzeitanalyse->Auswerten->Andere Datei" erhalten wir alle aufgeschriebenen Laufzeitanalysefiles zur Auswahl:

Wenn wir in der Liste eine Datei per Doppelclick auswählen, kommen wir zunächst in das Summenbild. Erst dort - und leider erst dort - sehen wir, wie lange dieser Schritt gedauert hat und wie sich die Laufzeit auf CPU und Datenbank verteilt hat. Der hier ausgewählte Step war mit 300 ms durchaus OK. Eine weitere Analyse mit dem "Hitliste"-Icon oben links lohnt sich in diesem Fall nicht. Wir müssten uns nun durch weitere Steps durchklicken, bis wir eine langsame Aufzeichnung finden.

Der Report Z_ATRA_WITH_TIME

Der Grund dafür, dass in der SE30 bei Auswahl der Files nicht die Gesamtlaufzeit angezeigt wird, ist schlicht der, dass sie nicht als explizites Feld in der Datei enthalten ist, sondern aus sämtlichen in der Datei fortgeschriebenen Einträgen erst summiert werden muss. Da es mich gestört hat, erst jede Analyse anklicken zu müssen, um zu sehen, wie lang der betreffende Dialogschritt dauert, habe ich einen Report geschrieben, der die Gesamtlaufzeit vor Anzeige der Dateiliste berechnet. Er ist self-contained, und Sie können ihn sich vom Code-Repository unter dem Link /code/prog/z_atra_with_time herunterladen und verwenden. Er stellt die ATRA-Files, die Sie noch etwaig mit einem regulären Ausdruck filtern können, als Liste dar, wobei die Dateien nach der gemessenen Gesamtlaufzeit absteigend sortiert sind.

In unserem Beispiel ergibt sich nachstehendes Bild. Wir sehen, dass es während unserer Aufzeichnungszeit einige langsame Requests mit mehr als einer Sekunde Antwortzeit gab. Um das Performanceproblem zu analysieren, lohnt es sich, diese anzuschauen. Wir sehen auch, zumindest bei den oberen, also langsamsten Ausführungen, ein Schwergewicht bei der Datenbankzeit. Das Problem dürfte, vereinfacht gesagt, also eher mit einem select als mit einer loop zu tun haben.

Die Optimierung

Die obersten Tracefiles, also die mit den längsten Gesamtlaufzeiten, versprechen uns Aufschluss über möglicherweise ineffiziente Codestrecken. Durch Doppelclick kommen wir in das "Welcome Panel" der normalen Laufzeitanalyse und von dort in die Hitliste, die alle durchlaufenen Modularisierungseinheiten sowie einige elementare Befehle (wie Datenbankoperationen oder Zugriffe auf interne Tabellen) aufführt - und zwar absteigend sortiert nach Bruttolaufzeit. In unserem Fall ist das Bild eindeutig - wir haben offenbar Probleme mit einer Datenbanktabelle namens WSAO_WORK_CTRL:

Was ist hier passiert?

Die Tabelle WSAO_WORK_CTRL soll den SRS-Benutzer darüber informieren, für welche Warengruppen seiner Filiale aktuelle MDE-Vorgänge vorliegen. Die Tabelle war im Laufe der Zeit immer weiter angewachsen, ohne dass dies jemand bemerkt hätte. Aktuell hat sie ca. 1.5 Millionen Einträge und schlägt nun bei den Dialogzeiten zu Buche.

Es muss daher ein Reorganisationsprogramm verfast werden, um die veralteteten Einträge loszuwerden, und dieses Programm muss im Produktivsystem regelmässig eingeplant werden. Nach dem ersten Programmlauf sollte aufgrund der massiven Reduktion der Tabellengrösse eine datenbankseitige Tabellenreorganisation ausgeführt werden. Danach genügt es, dass die Tabelle mit Hilfe des regelmässig laufenden Programms klein gehalten wird.

Darüberhinaus zeigt eine Analyse der Aufrufstelle (in der Laufzeitanalyse ist die Aufrufstelle nur einen Click entfernt), dass auch das verwendete Select-Statement optimierbar ist. Statt satzweise unter Angabe vieler Selektionskriterien einzulesen,

* Alter Code
  select * from wsao_work_ctrl                                  
     into table lt_work                                         
     for all entries in lt_nav                                  
     where customer_site         = g_customer_site and          
           assortlist_type       = lt_nav-assortlist_type and   
           sorting_method        = lt_nav-sorting_method and    
           matl_group            = lt_nav-matl_group and        
           layout_mod            = lt_nav-layout_mod and        
           department_no         = lt_nav-department_no and     
           vend_part             = lt_nav-vend_part.            
ist es effizienter, gleich sämtliche Sätze für diese Filiale einzulesen (der Overhead ist gering, die Tabelle wird nur rund 400 Einträge haben), auch weil ein Sekundärindex mit der customer_site als erstem Feld existiert.
*&---------------------------------------------------------------------*
*&      Form  get_wsao_work_ctrl
*&---------------------------------------------------------------------*
*       Selects auf die WSAO_WORK_CTRL immer über diese Routine
*       faktorisieren!
*----------------------------------------------------------------------*
form get_wsao_work_ctrl using iv_site type locnr
                        changing et_work type ref to zwsao_work_ctrl.

  statics: st_work type zwsao_work_ctrl,
           sv_site type locnr.

  if sv_site ne iv_site.
    sv_site = iv_site.
    select * from wsao_work_ctrl into table st_work
             where customer_site = iv_site.
  endif.

  get reference of st_work into et_work.

endform.                   "get_wsao_work_ctrl
 
Optimierungen dieser Art sollte man beständig am System vornehmen, um die Antwortzeiten und die gesamte Systemlast niedrig zu halten. Es ist für alle Benutzer angenehm, mit einem hochperformanten System zu arbeiten!

Zurück