Praktisches Tool zum Messen von C # -Code

In einem schnelllebigen, großen und komplexen Produkt ist es keine triviale Aufgabe, Engpässe in Bezug auf die Leistung zu finden. Natürlich gibt es Tools zur Lösung solcher Probleme, zum Beispiel BenchmarkDotNet . Zweifellos ist dies ein nützliches und notwendiges Werkzeug, aber es ist nicht immer bequem. Dies kann beispielsweise erkannt werden, wenn die öffentliche Methode nicht vollständig gemessen werden muss, indem das entsprechende Attribut festgelegt wird, sondern ein Teil des Codes innerhalb der privaten Methode. Hier werde ich in keinem Fall das vorgesehene Tool kritisieren, sondern nur auf die Notwendigkeit einer etwas anderen Art der Erfassung von Metriken für Codefragmente hinweisen. Es gibt sehr komplexe, verwirrende Methoden mit Verzweigung, Schleifen, Umgang mit Ausnahmesituationen, und der Problempunkt kann sich irgendwo im Inneren befinden. Um es zu finden, müssen Sie den Code reichlich mit Messgeräten abdecken, während es offensichtlich den Wunsch gibt, die vorhandene Logik nicht zu berühren oder zu verarbeiten.

Mit der StopWatch-Klasse können Sie die Ausführungszeit von Codeabschnitten messen.

So etwas wie das:

var sw = new Stopwatch(); sw.Start(); //   sw.Stop(); Console.WriteLine(sw.Elapsed); //   

Um StopWatch nicht jedes Mal per Code zu platzieren, können Sie den Messvorgang beispielsweise über eine Funktion höherer Ordnung vereinheitlichen:

 static void LambdaMeter(string label, Action act) { var sw = new Stopwatch(); sw.Start(); act(); sw.Stop(); Console.WriteLine($"{label} : {sw.Elapsed}"); //   } 

Und benutze diesen Weg:

 LambdaMeter("foo", () => { // TODO something }); 

Sie können den Anruf über die Nebenstelle auf den Kopf stellen:

 public static class TimeInspector { public static void Meter(this Action act, string label) { var sw = new Stopwatch(); sw.Start(); act(); sw.Stop(); Console.WriteLine($"{label} : {sw.Elapsed}"); //   } } 

Und verwenden Sie wie folgt:

 new Action(() => { // TODO something }).Meter("foo"); 

Es scheint, als sei das Problem gelöst, aber diese Technik ist immer noch äußerst begrenzt. Tatsache ist, dass der gemessene Code Rückgaben enthalten kann, sodass Sie ihn nicht in Aktion umschließen können. Selbst die Verwendung von Func wird das Problem nicht lösen. Im Folgenden möchte ich eine Technik beschreiben, die ich mehr als einmal verwendet habe. Mit den kleinsten Änderungen im Code wird das Problem der Messung beliebiger Codeabschnitte gelöst. Wir werden einen einfachen und kompakten Logger zur Messung der Ausführungsgeschwindigkeit erstellen. Falls erforderlich, ist es auch recht einfach, ihn für andere Anforderungen zu ändern, z. B. um nach Speicherlecks zu suchen. Der folgende Code erhebt keinen Anspruch auf Vollständigkeit und Funktionsfähigkeit, sondern ist eine Demonstration des Prinzips, auf dessen Grundlage Sie ein wirklich nützliches und einfaches Werkzeug erstellen können. Der Code funktioniert jedoch und kann zum Sammeln von Metriken wie sie sind oder für spezifischere Aufgaben angepasst werden. Ich möchte auch darauf hinweisen, dass im folgenden Code zusätzliche Informationen wie die Prozess-ID oder der Hostname gesammelt werden. Diese Parameter waren in bestimmten Situationen für mich nützlich und dienen nur als Beispiel. Jeder, der sich entscheidet, den Code an seine Aufgaben anzupassen, muss möglicherweise völlig andere Parameter erfassen, teilweise aus diesem Grund wurde der angegebene Code nicht als fertiges Produkt auf dem öffentlichen GitHub veröffentlicht.

C # hat eine bekannte und nützliche using-Anweisung. Sie gilt für Typen, die die IDisposable-Schnittstelle unterstützen. Der Punkt ist, wenn Sie den Operatorblock verlassen, die Dispose-Methode aufzurufen, bei der in der Regel Ressourcen freigegeben werden. Dieser Mechanismus kann jedoch für eine Vielzahl von Zwecken verwendet werden. In unserem Fall ist dies eine Messung der Ausführungszeit des Blocks, gefolgt vom Speichern des Ergebnisses zur Analyse. Die Idee ist, dass eine Instanz der Klasse im using-Block erstellt wird. Zum Zeitpunkt der Erstellung werden verschiedene Arten nützlicher Informationen gesammelt und StopWatch gestartet. Wenn Dispose beim Verlassen des Blocks ausgeführt wird, wird das Ergebnis korrigiert und das Objekt zum Speichern des Protokolls gesendet.

Die using-Anweisung ist syntaktischer Zucker und verwandelt sich beim Kompilieren in einen try-finaly-Block.

Zum Beispiel der Code:

 using(var obj = new SomeDisposableClass()) { // TODO something } 

In ein Design des Formulars konvertiert:

 IDisposable obj = new SomeDisposableClass(); try { // TODO something } finally { if (obj != null) { obj.Dispose(); } } 

Daher wird bei jedem Verlassen des try-Blocks die Dispose-Methode garantiert und sofort aufgerufen, während sich die Logik des verwendeten Codes in keiner Weise ändert. Wir haben lediglich einen Dispose-Aufruf hinzugefügt. Anhand dieser Idee werden wir den einfachsten Laufzeitmesser erstellen.

 public class Meter :IDisposable { private Stopwatch _sw; private string _label; public static Meter Job(string lable) { return new Meter(lable); } Meter(string label) { _label = label; _sw = Stopwatch.StartNew(); } public void Dispose() { _sw.Stop(); Console.WriteLine($"{_label} : {_sw.Elapsed}"); //   } } 

Und was gibt uns das?

 //       return static int Case0() { using (Meter.Job("case-0")) { return 1; } return 2; } //     yield return static IEnumerable<string> Case1() { yield return "one"; using (Meter.Job("case-1")) { yield return "two"; yield return "three"; } yield return "four"; } //     break static void Case2() { while (true) { using (Meter.Job("case-2")) { // todo something break; } } } //    switch    static int Case3(int @case) { using (Meter.Job("case-3")) { switch (@case) { case 1: using (Meter.Job($"case-3-{@case}")) { // todo something break; } case 2: using (Meter.Job($"case-3-{@case}")) { // todo something return @case; } } return @case; } } //       static void Case4() { try { using (Meter.Job($"case-4")) { // todo something throw new Exception(); } } catch (Exception e) { Console.WriteLine(e); } } 

Was fehlt in der beschriebenen Technik? Das Thema, wie das Ergebnis gesichert werden kann, wurde nicht vollständig offengelegt. Es ist klar, dass es nicht sinnvoll ist, das Ergebnis in der Konsole aufzuzeichnen. In den meisten Fällen ist es durchaus möglich, die beliebten Tools NLog, Log4Net und Serilog mit Visualisierungsbrötchen und minimaler Analyse zu verwenden. In besonders schweren Fällen sind möglicherweise komplexere Analysen erforderlich, um herauszufinden, was passiert.

Sie können das Ergebnis in einer einfachen Textdatei speichern, aber für diese Aufgabe halte ich dies für keine sehr bequeme Lösung, da es viele Codeteile geben kann und diese wahrscheinlich zusätzlich mehrere parallele Threads verschachteln können. Aus diesem Grund verwenden wir ausschließlich zur Navigation im Protokoll die SQLite-Datenbank.

Wir definieren zunächst eine Klasse, die für die Zeitmessung verantwortlich ist, und erfassen zusätzliche nützliche Informationen für die spätere Analyse.

 public class LogItem : IDisposable { public string Id; // Log item unique id public string Label; // User text labl public string Lid; // Log Id public string Method; // Method name public int Tid; // Thread Id public DateTime CallTime; // Start time public TimeSpan Elapsed; // Metering public long ElapsedMs; // Metering miliseconds public long ElapsedTicks; // Metering ticks private Stopwatch _sw; private Logger _cl; public LogItem(Logger cl, string method, string label) { Id = Guid.NewGuid().ToString("N"); _cl = cl; Lid = _cl.LId; Label = label; Method = method; Tid = Thread.CurrentThread.ManagedThreadId; CallTime = DateTime.Now; _sw = new Stopwatch(); _sw.Start(); } public void Dispose() { _sw.Stop(); Elapsed = _sw.Elapsed; ElapsedMs = _sw.ElapsedMilliseconds; ElapsedTicks = _sw.ElapsedTicks; _cl.WriteLog(this); } } 

Ein Link zum Logger-Objekt und zusätzliche Informationen werden an den Konstruktor der LogItem-Klasse übergeben, der vollständige Name der Methode, in der die Messung durchgeführt wird, und eine Beschriftung mit einer beliebigen Nachricht. Um die Protokolle aus der Ausführung von asynchronem Code zu verstehen, hilft das Feld Tid (Thread-ID), mit dem Sie Daten aus einem Thread gruppieren können. Außerdem wird beim Erstellen eines LogItem-Objekts die Startzeit der Messung festgelegt und StopWatch gestartet. Stoppen Sie in der Dispose-Methode StopWatch und rufen Sie die WriteLog-Logger-Methode auf, übergeben Sie das Objekt des aktuellen Shooters und korrigieren Sie alle erforderlichen LogItem-Informationen.

Der Logger hat im Wesentlichen zwei Hauptaufgaben: ein LogItem-Objekt zu initiieren und das Ergebnis nach Abschluss der Messung aufzuzeichnen. Da ich das Ergebnis immer noch nicht nur in SQLite, sondern auch in Textdateien verschiedener Formate oder Datenbanken außer SQLite aufzeichnen muss, wird die Interaktionslogik in eine separate Klasse eingeordnet. In der Logger-Klasse bleibt nur der allgemeine Teil übrig.

 public class Logger { public string LId; // Log id public string Login; // User login public int Pid; // Process Id public string App; // Application name public string Host; // Host name public string Ip; // Ip address private ConcurrentQueue<dynamic> queue; // Queue log items to save public Dictionary<Type, Action<dynamic>> LogDispatcher; // Different log objects handlers dispatcher public bool IsEnabled = true; public Logger(Dictionary<Type, Action<dynamic>> logDispatcher) { queue = new ConcurrentQueue<dynamic>(); LogDispatcher = logDispatcher; LId = Guid.NewGuid().ToString("N"); Login = WindowsIdentity.GetCurrent().Name; Host = Dns.GetHostName(); Ip = Dns.GetHostEntry(Host).AddressList.FirstOrDefault(f => f.AddressFamily == System.Net.Sockets.AddressFamily.InterNetwork)?.ToString(); var proc = Process.GetCurrentProcess(); Pid = proc.Id; App = proc.ProcessName; queue.Enqueue(this); // Save the starting of a new measurement new Thread(() => { // Dequeue and save loop dynamic logItem; while (true) { if (queue.TryDequeue(out logItem)) { var logT = logItem.GetType(); if (LogDispatcher.ContainsKey(logT)) { LogDispatcher[logT](logItem); } } else { Thread.Sleep(500); } }}) { IsBackground = true}.Start(); } public LogItem Watch(int level, string label = null) { return new LogItem(this, GetMethodFullName(level), label); } private static string GetMethodFullName(int level) { var t = new StackTrace().GetFrames()?[level].GetMethod(); if (t == null) return ""; var path = t.ReflectedType != null ? t.ReflectedType.FullName : "_"; return $"{path}.{t.Name}"; } public void WriteLog(LogItem li) { if (IsEnabled) { queue.Enqueue(li); } } } 

Die Logger-Klasse ist also eine Zwischenstufe. Ihre Aufgabe besteht darin, Informationen über die Umgebung zu sammeln, in der die Protokollierung gestartet wird. Im obigen Beispiel sind dies die Benutzeranmeldung, der Computername, die Netzwerkadress-ID und der Prozessname. All diese Informationen sind nützlich, wenn wir die Ausführungszeit von Codeabschnitten auf dem Computer des Benutzers messen möchten, d. H. Im Wesentlichen zur Identifizierung bei Erkennung von Anomalien. Ich denke, der Leser wird zustimmen, dass es wichtig ist, dass der Logger während der Messung einen minimalen Einfluss auf die Ausführungszeit des gemessenen Codes hat. Aus diesem Grund wird das Ergebnis gespeichert, indem es der Warteschlange hinzugefügt wird, die der Hintergrundprozess dreht, das Ergebnis in der Datenbank, Datei oder über das Netzwerk speichert. Dieser Ansatz hat einen schwerwiegenden Nachteil: Wenn zu viele Protokollierungsereignisse vorliegen, füllt sich die Warteschlange schneller als beim Hochfahren, bis der gesamte für die Anwendung verfügbare Speicher belegt ist. Aber um diese Situation zu provozieren, müssen Sie es noch versuchen. Das Versenden von Handlerprozeduren zum Speichern verschiedener Klassen erfolgt über ein Wörterbuch, in dem der Schlüssel ein Typ ist. Der Wert ist die Prozedur zum Speichern eines Objekts dieses Typs.

Für die Protokollierungsklasse, die unten angegeben wird, muss die Abhängigkeit durch Installieren des Nuget-Pakets System.Data> SQLite erfüllt werden.

  public class SqliteLogger { private readonly HLTimeCall.Logger _iternalLogger; protected string _connectionString; static object dbLocker = new object(); public SqliteLogger() { InitDb(); var dispatcher = new Dictionary<Type, Action<dynamic>>(); dispatcher[typeof(HLTimeCall.Logger)] = o => LogMainRecord(o); dispatcher[typeof(HLTimeCall.LogItem)] = o => LogCall(o); _iternalLogger = new HLTimeCall.Logger(dispatcher); } private void InitDb() { const string databaseFile = "TimeCallLogs.db"; _connectionString = $"Data Source = {Path.GetFullPath(databaseFile)};"; var dbFileName = Path.GetFullPath(databaseFile); if (!File.Exists(dbFileName)) { SQLiteConnection.CreateFile(dbFileName); Bootstrap(); } } struct DbNames { public const string TMainRecord = "T_MAINRECORD"; public const string TCalllog = "T_CALLLOG"; public const string FLid = "LID"; public const string FLogin = "LOGIN"; public const string FPid = "PID"; public const string FApp = "APP"; public const string FHost = "HOST"; public const string FIp = "IP"; public const string FId = "ID"; public const string FLabel = "LABEL"; public const string FMethod = "METHOD"; public const string FTid = "TID"; public const string FCallTime = "CALL_TIME"; public const string FElapsed = "ELAPSED"; public const string FElapsedMs = "ELAPSED_MS"; public const string FElapsedTicks = "ELAPSED_TICKS"; } public void Bootstrap() { lock (dbLocker) { using (var conn = Connect()) { using (var cmd = conn.CreateCommand()) { cmd.Transaction = conn.BeginTransaction(); cmd.CommandType = System.Data.CommandType.Text; cmd.CommandText = $"CREATE TABLE {DbNames.TMainRecord} ({DbNames.FLid} VARCHAR(45) PRIMARY KEY UNIQUE NOT NULL, {DbNames.FLogin} VARCHAR(45), {DbNames.FPid} INTEGER, {DbNames.FApp} VARCHAR(45), {DbNames.FHost} VARCHAR(45), {DbNames.FIp} VARCHAR(45))"; cmd.ExecuteNonQuery(); cmd.CommandText = $"CREATE TABLE {DbNames.TCalllog} ({DbNames.FId} VARCHAR(45) PRIMARY KEY UNIQUE NOT NULL, {DbNames.FLabel} VARCHAR(45), {DbNames.FLid} VARCHAR(45) NOT NULL, {DbNames.FMethod} VARCHAR(150), {DbNames.FTid} VARCHAR(45), {DbNames.FCallTime} DATETIME, {DbNames.FElapsed} TIME, {DbNames.FElapsedMs} INTEGER, {DbNames.FElapsedTicks} INTEGER)"; cmd.ExecuteNonQuery(); cmd.Transaction.Commit(); } } } } private DbConnection Connect() { var conn = new SQLiteConnection(_connectionString); conn.Open(); return conn; } public HLTimeCall.LogItem Watch(string label = null) { return _iternalLogger.Watch(3, label); } static object CreateParameter(string key, object value) { return new SQLiteParameter(key, value ?? DBNull.Value); } private void LogMainRecord(HLTimeCall.Logger logItem) { lock (dbLocker) { using (var conn = Connect()) { using (var cmd = conn.CreateCommand()) { cmd.Transaction = conn.BeginTransaction(); cmd.CommandType = System.Data.CommandType.Text; cmd.Parameters.Add(CreateParameter(DbNames.FLid, logItem.LId)); cmd.Parameters.Add(CreateParameter(DbNames.FLogin, logItem.Login)); cmd.Parameters.Add(CreateParameter(DbNames.FPid, logItem.Pid)); cmd.Parameters.Add(CreateParameter(DbNames.FApp, logItem.App)); cmd.Parameters.Add(CreateParameter(DbNames.FHost, logItem.Host)); cmd.Parameters.Add(CreateParameter(DbNames.FIp, logItem.Ip)); cmd.CommandText = $"INSERT INTO {DbNames.TMainRecord}({DbNames.FLid},{DbNames.FLogin},{DbNames.FPid},{DbNames.FApp},{DbNames.FHost},{DbNames.FIp})VALUES(:{DbNames.FLid},:{DbNames.FLogin},:{DbNames.FPid},:{DbNames.FApp},:{DbNames.FHost},:{DbNames.FIp})"; cmd.ExecuteNonQuery(); cmd.Transaction.Commit(); } } } } private void LogCall(HLTimeCall.LogItem logItem) { lock (dbLocker) { using (var conn = Connect()) { using (var cmd = conn.CreateCommand()) { cmd.Transaction = conn.BeginTransaction(); cmd.CommandType = System.Data.CommandType.Text; cmd.Parameters.Add(CreateParameter(DbNames.FId, logItem.Id)); cmd.Parameters.Add(CreateParameter(DbNames.FLabel, logItem.Label)); cmd.Parameters.Add(CreateParameter(DbNames.FLid, logItem.Lid)); cmd.Parameters.Add(CreateParameter(DbNames.FMethod, logItem.Method)); cmd.Parameters.Add(CreateParameter(DbNames.FTid, logItem.Tid)); cmd.Parameters.Add(CreateParameter(DbNames.FCallTime, logItem.CallTime)); cmd.Parameters.Add(CreateParameter(DbNames.FElapsed, logItem.Elapsed)); cmd.Parameters.Add(CreateParameter(DbNames.FElapsedMs, logItem.ElapsedMs)); cmd.Parameters.Add(CreateParameter(DbNames.FElapsedTicks, logItem.ElapsedTicks)); cmd.CommandText = $"INSERT INTO {DbNames.TCalllog}({DbNames.FId},{DbNames.FLabel},{DbNames.FLid},{DbNames.FMethod},{DbNames.FTid},{DbNames.FCallTime},{DbNames.FElapsed},{DbNames.FElapsedMs},{DbNames.FElapsedTicks})VALUES(:{DbNames.FId},:{DbNames.FLabel},:{DbNames.FLid},:{DbNames.FMethod},:{DbNames.FTid},:{DbNames.FCallTime},:{DbNames.FElapsed},:{DbNames.FElapsedMs},:{DbNames.FElapsedTicks})"; cmd.ExecuteNonQuery(); cmd.Transaction.Commit(); } } } } } 

Wie bereits erwähnt, ist die SqliteLogger-Klasse für das Speichern der Messergebnisse in der Datenbank verantwortlich. Bevor Sie die Datenbank verwenden können, müssen Sie sie erstellen. Weitere Codezeilen sind dafür vorgesehen. Hier protokolliert die Klasse die Tatsache, dass der Logger erstellt wurde (es versteht sich, dass dies gleichzeitig mit dem Start der Anwendung geschieht). Das Ergebnis wird in der Tabelle T_MAINRECORD gespeichert. Wir werden das Messergebnis auch in der Tabelle T_CALLLOG speichern. Die Methoden LogMainRecord und LogCall sind für das Speichern dieser beiden Ereignisse verantwortlich. Verweise darauf werden im Dispatcher-Wörterbuch gespeichert. Um das LogItem-Objekt korrekt zu erstellen, müssen Sie die Watch-Funktion im Initialisierungsblock der using-Anweisung verwenden.

Zum Beispiel so:

 var cMeter = new SqliteLogger(); using (cMeter.Watch("   ")) { // TODO } 

Um dieses Tool verwenden zu können, müssen Sie Blöcke an fragwürdigen Stellen anordnen und die Anwendung arbeiten lassen. Danach bleibt es, die gesammelten Informationen zu analysieren, von denen ich hoffe, dass sie ausreichen, um den Problemort zu identifizieren. Ich schlage vor, darüber nachzudenken, welche anderen Metriken mit dieser Technik erfasst werden können.

Vielen Dank für Ihre Aufmerksamkeit, viel Glück und schnellen Code :-)