Bunte Diagramme

Ebenso wie im J2EE-Umfeld (siehe Artikel „Wo es klemmt“ auf Seite 42) ist auch im .Net Framework die einfachste Form des Profiling durch Zeitvergleich zu erzielen. Das statische Attribut Now der Klasse System.DateTime liefert die aktuelle Uhrzeit auf die Millisekunde genau. Eine gespeicherte Anfangszeit kann der Entwickler später auf einfache Weise von der aktuellen Zeit subtrahieren und die Differenz in Millisekunden ausgeben:

System.DateTime startzeit = System.DateTime.Now;
for(int a=0;a<100000000;a++); // Zeitvertreib     
Console.WriteLine((DateTime.Now.Subtract(startzeit).TotalMilliseconds))

Möchte man viele derartige Messungen in ein Programm einbauen, empfiehlt sich die Kapselung in eine Klasse. Listing 1 zeigt die Realisierung eines sehr einfachen Profilers mit Hilfe von System.DateTime.Now. (Dieses und die folgenden Listings sind in Form von VS-Projekten auf dem iX-FTP-Server zu finden.) Eine Instanz der implementierten Klasse de.ITVisions.Timer kann beliebig viele benannte Teilmessungen verwalten. Start(„Name“) beginnt eine Teilmessung, während Stop() die aktuelle Messung beendet und in einer Hashtable ablegt. Die Teilmessung kann später wieder über Start() neu durchlaufen werden. Die Results()-Methode liefert die Durchschnittsdauer aller Durchläufe einer Teilmessung sowie die Gesamtdauer.

' Simple .NET Profiler
' (C) Dr. Holger Schwichtenberg
' http://www.dotnetframework.de
Imports System.Windows.Forms
Namespace de.ITVisions
  ' ////////////////////////// Zeitmesser
  Public Class Timer
    Public anzahl As Long ' Anzahl der Durchläufe
    Public summe As Double ' Summe der verbrauchten Zeit
    Public Silent As Boolean = True ' Ausgabe nach jeder Messung?
    Public counter As Long ' Counter für Ausgabe
    Public startzeit As DateTime ' Startzeit der aktuellen Messung
    Public timername As String ' Name der aktuellen Messung
    Public Shared timers As New Hashtable ' Speicherung aller Messungen
    ' === Zeitnahme beginnen
    Public Sub Start(ByVal name As String)
      timername = name
      startzeit = DateTime.Now
    End Sub
    ' === Zeitnahme beenden
    Public Sub Stop()
      Dim zeit As Long
      zeit = Int(DateTime.Now.Subtract(startzeit).TotalMilliseconds)
      If Not Silent Then out("Timer Stoped: " & timername & ":" & zeit & " ms")
      If timers.ContainsKey(timername) Then  ' bestehender Timer
        timers.Item(timername).summe += zeit
        timers.Item(timername).anzahl += 1
      Else ' Neuer Timer
        Dim t As New Timer
        t.anzahl = 1
        t.summe = zeit
        timers.Add(timername, t)
      End If
    End Sub
  ' === Zeitauswertung
    Public Sub Results()
      Dim AlleSumme As Double
      Dim AlleAnzahl As Long
      out("========================================")
      out("Timer-Auswertung (Durchschnittswerte):")
      For Each timername As String In timers.Keys
        Dim t As Timer = timers(timername)
        out(timername & " = " & t.summe / t.anzahl & _
        " ms (" & t.anzahl & ")")
        AlleSumme += t.summe
        AlleAnzahl += t.anzahl
      Next
      out("---")
      out("Gesamtzeit = " & AlleSumme)
    End Sub
    ' === Ausgabefunktionen
    Sub out(ByVal s As Object)
      counter += 1
      outnn(counter & vbTab & s)
    End Sub
    Sub outnn(ByVal s As Object)
      Console.WriteLine(s)
      Application.DoEvents()
    End Sub
  End Class
End Namespace

Wendet man diese Zeitmessmethode auf eine speichergefräßige Anwendung an (Listing 2 und 3), so dürfte man erhebliche Unterschiede feststellen: Obwohl sowohl der „HungrigeLoewe“ als auch der „GefraessigeHai“ jeweils 10 000 Beutetiere mit jeweils einer Länge von 26 Zeichen erlegen, brauchen sie niemals die gleiche Zeit, der Unterschied erreicht Faktor 2. Ursache dafür ist der (nicht-deterministische) Garbage Collector (GC) des .Net Framework, der bei Bedarf den Speicher aufräumt.

Timer t = new Timer();
System.Collections.ArrayList Tiere = new System.Collections.ArrayList ();
Console.WriteLine("Start!");
for(int a = 0; a< 10000; a++)
{
  t.Start("Loewe");
  HungrigerLoewe y = new HungrigerLoewe();
  Tiere.Add(y);
  t.Stop();
  t.Start("Hai");
  GefraessigerHai x = new GefraessigerHai();
  Tiere.Add(x);
  t.Stop();
}
t.Results();
Console.WriteLine("Fertig!");

// Klassen für sehr hungrige Löwen
public class HungrigerLoewe : Loewe
{
  const long ANZAHL = 10000;
  public Beute[] GefresseneTiere;
  public HungrigerLoewe()
  {     
    // ========== Beute einfangen
    this.GefresseneTiere = new Beute[ANZAHL];
    for (int a= 0; a < ANZAHL; a++)  
      GefresseneTiere[a] = new Beute("abcdefgijklmnopqrstuvwxyz",1000* new Random().NextDouble());
  }
}

Performance-Counter des Systemmonitors

Das .Net Framework bietet aber noch anspruchsvollere Messmethoden als den einfachen Zeitvergleich. In der Windows-Welt gibt es mit den Leistungsindikatoren ein ins Betriebssystem integriertes Messinstrument.

Ein Indikator wird anhand von vier Daten eindeutig identifiziert: Computername, Kategorie (alias „Datenobjekt“), Objekt- und Instanzname. Der eindeutige Name wird dabei in der Form \\Computername\Kategorie(Instanzname)\Objektname gebildet, beispielweise \\Essen\.Net CLR Speicher(Speicherfresser)\GC-Zeitdauer in Prozent. Dies ist der Anteil der Zeit, die die Anwendung speicherfresser.exe mit der Speicherverwaltung beschäftigt ist. Dieser Wert liegt idealerweise unter 15 %.

Zur Anzeige der Leistungsindikatoren bietet Windows ein Snap-in für die Management-Konsole mit Namen „System Monitor“. Das Snap-in „Performance Logs and Alerts“ ermöglicht die Speicherung von Leistungsdaten in Protokolldateien und das Setzen von Alarmschwellen mit entsprechenden Reaktionen. In Abbildung 1 sieht man an der gelben Kurve, dass der GC nicht nur an einigen Stellen weit über die empfohlenen 15 % hinaus tätig werden musste, sondern auch noch nach Beendigung der speicherfresser.exe eine ganze Weile an der Anwendung zu knabbern hat.

Das Bild zeigt nicht nur die Kurve für „GC-Zeitdauer in Prozent“, sondern auch die Größe des Heaps getrennt nach Generationen. Der .Net-GC ist ein so genannter Generational Sweep & Mark Garbage Collector, der die Objekte in neue (Generation 0), jüngere (Generation 1) und langlebige Objekte (Generation 2) einteilt. Dafür gilt die Empfehlung für ein Verhältnis 100:10:1, das heißt, es sollte nur jedes einhundertste Objekt ein langlebiges sein.

Den vollständigen Artikel finden Sie in der aktuellen Printausgabe. Siehe auch die Leseprobe zum Profiling in .Net. (wm)