Lade...
 

Profiling - Clusteranalyse

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.

Operativer Betrieb