Profiling - Clusteranalyse
Beschreibung
Über ein Tool kann das Log eines Profiling-Laufes geclustert werden. Dazu ist Profiling.bat zu starten (in //iv/main/Inst/Profiling). Voraussetzung ist ein installiertes Java 1.4.
Das Tool fragt nach dem Dateinamen mit dem Profiling-Log und beginnt anschließend mit der Analyse. Am Ende wird der Lauf mit einer Meldung quittiert. Das Ergebnis wird in einer HTML-Datei abgelegt, die z.B. mit Excel weiter verarbeitet werden kann.
Beispiel eines XML-Exports
Makro | Durchschnitt | Anzahl | Gesamt (ms) |
---|---|---|---|
1. StopProfiling | 0 | 0 | 0 |
1. Price | 0,391 | 150.232 | 58.780,5 |
4. GetItemOfTxn | 0,752 | 286.238 | 215.373,4 |
3. GetOrderPredecessor | 1,447 | 150.485 | 217.738,6 |
3. SetUnitTable | 0,346 | 244.091 | 84.394,4 |
1. OutputQuantity | 4,017 | 150.232 | 603.434,3 |
3. TranslateQuantity | 0,799 | 56.373 | 45.066,6 |
2. GetItemOrCast | 0,441 | 300.464 | 132.635,1 |
2. GetItemOfTxn | 3,298 | 150.232 | 495.510,9 |
1. TypeOfTxnPicture | 0,664 | 150.232 | 99.817,7 |
1. ReferenceText | 2,069 | 150.232 | 310.826,7 |
4. GetItemOrCast | 0,492 | 393.221 | 193.538,4 |
1. GetStockSpace | 0,497 | 450.696 | 224.043,2 |
1. InputValue | 3,509 | 150.232 | 527.187,3 |
3. GetItemOrCast | 3,006 | 150.232 | 451.555,3 |
2. Value | 3,999 | 244.091 | 976.202,9 |
2. GetOrderPredecessor | 9,013 | 150.232 | 1.353.976 |
1. GetReferenceObject | 9,661 | 150.232 | 1.451.348,7 |
1. TypeOfTxnText | 0,648 | 150.232 | 97.331,4 |
1. ItemQuantity | 6,486 | 150.232 | 974.419,2 |
4. SetUnitTable | 0,359 | 229.865 | 82.536,8 |
2. ItemQuantity | 1,916 | 244.091 | 467.592,8 |
4. GetOrderPredecessor | 2,095 | 253 | 530,1 |
1. GetImportantDate | 0,733 | 150.232 | 110.141,8 |
5. GetItemOrCast | 0,489 | 286.238 | 139.936,6 |
3. GetItemOfTxn | 0,744 | 393.221 | 292.366,5 |
2. SetUnitTable | 0,44 | 150.232 | 66.050,9 |
1. Description | 1,21 | 150.232 | 181.727,1 |
2. Sign | 0,219 | 600.928 | 131.743 |
1. ItemUniqueID | 0,894 | 150.232 | 134.318,6 |
3. ItemQuantity | 2,001 | 229.865 | 459.903,4 |
1. OutputValue | 4,171 | 150.232 | 626.566,2 |
1. TxnManagerID | 1,039 | 150.232 | 156.093,7 |
2. GetReferenceObject | 1,859 | 150.232 | 279.214,4 |
2. TranslateQuantity | 2,368 | 149.130 | 353.068,8 |
1. InputQuantity | 2,847 | 150.232 | 427.637,3 |
database | 1,927 | 1.168.647 | 2.251.900 |
Hier sind alle Makros aufgeführt, die während des Profilings aufgerufen wurden. Die Zahl vor dem Namen gibt den Level an: 1 bedeutet, dass das Makro (hier) direkt von der ListView aus aufgerufen wurde; 2 bedeutet, dass das Makro von einem anderen Makro aufgerufen wurde. Im obigen Beispiel wird ItemQuantity mit Level 1 und Level 3 aufgeführt, d.h. das Makro wird an zwei Stellen aufgerufen.
Zusätzlich werden alle Datenbankaktivitäten unter 'database' zusammengefasst.
In der Spalte 'Anzahl' ist angegeben, wie oft das Makro insgesamt aufgerufen wurde. In 'Gesamt' ist die Zeit in Millisekunden angegeben, die das Makro insgesamt verbraucht hat. 'Durchschnitt' schließlich ist das Ergebnis der Division 'Gesamtzeit' / 'Anzahl'.
Hinweise
Die Zeit, die für ein Makro gemessen wird, ist immer inklusive der Zeit für die Datenbank und die aufgerufenen Makros. Wenn z.B. ein Makro A 5ms braucht und ein Makro B aufruft, das 2ms braucht, dann stecken die 2ms von B bereits in den 5ms von A drin! Es wäre also falsch, einfach alle Zeiten in der Statistik zu addieren. 'database' ist daher nur für vergleichende Zwecke geeignet, um zu sehen, wie viel Zeit anteilig von der Datenbank verbraucht werden.
Das obige Beispiel stammt aus einem XML-Export. Für die Auswertung wurden nur die Makros der ersten Ebene berücksichtigt. Dort drin enthalten sind bereits die Zeiten der anderen Makros und die Aufwände für die Datenbank. Die Zeiten der einzelnen Makros wurden nun zur Gesamtzeit in Relation gesetzt. Die Makros, die besonders viel Zeit in Anspruch nahmen, wurden optimiert.