Outil pratique pour mesurer le code C #

Dans un produit rapide, volumineux et complexe, trouver des goulots d'étranglement en termes de performances n'est pas une tâche triviale. Bien sûr, il existe des outils pour résoudre ces problèmes, par exemple BenchmarkDotNet . Sans aucun doute, c'est un outil utile et nécessaire, mais ce n'est pas toujours pratique. Cela peut être détecté, par exemple, lorsqu'il est nécessaire de mesurer non pas complètement la méthode publique en définissant l'attribut correspondant, mais un morceau de code à l'intérieur de la méthode privée. Ici, en aucun cas, je ne critiquerai l'outil désigné, mais je voudrais seulement souligner la nécessité d'une méthode légèrement différente de collecte des métriques pour les fragments de code. Il existe des méthodes très complexes et déroutantes, avec ramification, avec boucles, gestion de situations exceptionnelles, et le problème peut être quelque part à l'intérieur. Pour le trouver, vous devez couvrir abondamment le code avec des instruments de mesure, alors qu'il existe un désir évident de ne pas toucher ou traiter la logique existante.

Vous pouvez utiliser la classe StopWatch pour mesurer le temps d'exécution des sections de code.

Quelque chose comme ça:

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

Afin de ne pas placer StopWatch par code à chaque fois, vous pouvez unifier la procédure de mesure via une fonction d'ordre supérieur, par exemple, comme ceci:

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

Et utilisez de cette façon:

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

Vous pouvez transformer l'appel à l'envers via l'extension:

 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}"); //   } } 

Et utilisez comme ceci:

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

Il semble que le problème semble résolu, mais cette technique reste extrêmement limitée. Le fait est qu'il peut y avoir des sorties de retour dans le code mesuré, vous ne pouvez donc pas l'envelopper dans Action. Même l'utilisation de Func ne résoudra pas le problème. Ci-dessous, je veux décrire une technique que j'ai utilisée plus d'une fois, avec les plus petits changements dans le code, cela résoudra le problème de la mesure de sections arbitraires de code. Nous allons construire un enregistreur simple et compact pour mesurer la vitesse d'exécution; si nécessaire, il est également assez simple de le modifier pour d'autres besoins, par exemple, pour rechercher des fuites de mémoire. Le code ci-dessous ne prétend pas être complet et fonctionnel, mais plutôt une démonstration du principe sur la base duquel vous pouvez construire un outil vraiment utile et facile. Cependant, le code fonctionne et peut être utilisé dans le but de collecter des métriques tel quel ou adapté pour des tâches plus spécifiques. Je tiens également à noter que dans le code ci-dessous, des informations supplémentaires sont collectées, telles que l'ID de processus ou le nom d'hôte. Ces paramètres m'ont été utiles dans certaines situations et ne sont donnés qu'à titre d'exemple. Quiconque décide d'adapter le code à ses tâches peut avoir besoin de collecter des paramètres complètement différents, en partie pour cette raison, le code spécifié n'a pas été publié sur le GitHub public en tant que produit fini.

C # a une instruction using bien connue et utile, elle est applicable aux types qui prennent en charge l'interface IDisposable. Le fait est que, lorsque vous quittez le bloc opérateur, appelez la méthode Dispose, dans laquelle, en règle générale, les ressources sont libérées. Cependant, ce mécanisme peut être utilisé à diverses fins. Dans notre cas, il s'agira d'une mesure du temps d'exécution du bloc, suivie de l'enregistrement du résultat pour analyse. L'idée est qu'une instance de la classe est créée dans le bloc using, au moment de la création, différents types d'informations utiles sont collectés et StopWatch démarre. Lorsque Dispose s'exécute à la sortie du bloc, le résultat est corrigé et l'objet est envoyé pour enregistrer le journal.

L'instruction using est du sucre syntaxique; une fois compilée, elle se transforme en bloc try-finalaly.

Par exemple, le code:

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

Converti en un dessin de la forme:

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

Ainsi, à toute sortie du bloc try, la méthode Dispose sera garantie et immédiatement appelée, tandis que la logique du code placé dans using ne changera en rien. Tout ce que nous avons changé est d'ajouter un appel Dispose. Guidés par cette idée, nous ferons le mesureur d'exécution le plus simple.

 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}"); //   } } 

Et alors, qu'est-ce que cela nous donne?

 //       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); } } 

Qu'est-ce qui manque dans la technique décrite? Le sujet de la façon de sécuriser le résultat n'a pas été complètement divulgué, il est clair qu'il n'y a pas beaucoup de sens à enregistrer le résultat dans la console. Dans la plupart des cas, il est tout à fait possible d'utiliser les outils populaires populaires NLog, Log4Net, Serilog avec des petits pains de visualisation et des analyses minimales. Dans des cas particulièrement graves, des analyses plus sophistiquées peuvent être nécessaires pour comprendre ce qui se passe.

Vous pouvez stocker le résultat dans un fichier texte simple, mais pour cette tâche, je pense que ce n'est pas une solution très pratique, car il peut y avoir de nombreux morceaux de code, et ils peuvent probablement être imbriqués, en plus, plusieurs threads parallèles. Par conséquent, uniquement pour la commodité de la navigation dans le journal, nous utilisons la base de données SQLite.

Nous commençons par définir une classe chargée de mesurer le temps et de capturer des informations utiles supplémentaires pour une analyse ultérieure.

 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); } } 

Un lien vers l'objet enregistreur et des informations supplémentaires sont transmis au constructeur de la classe LogItem, le nom complet de la méthode dans laquelle la mesure est effectuée et une étiquette avec un message arbitraire. Pour comprendre les journaux de l'exécution du code asynchrone, le champ Tid (Thread id) vous aidera, par lequel vous pouvez regrouper les données d'un thread. De plus, lors de la création d'un objet LogItem, l'heure de début de la mesure est fixe et StopWatch démarre. Dans la méthode Dispose, arrêtez StopWatch et appelez la méthode de journalisation WriteLog, en passant l'objet du tireur actuel et en lui fixant toutes les informations LogItem nécessaires.

L'enregistreur a essentiellement deux tâches principales: initier un objet LogItem et enregistrer le résultat une fois la mesure terminée. Comme j'ai toujours besoin d'enregistrer le résultat non seulement dans SQLite mais aussi dans des fichiers texte de différents formats ou bases de données autres que SQLite, la logique d'interaction est placée dans une classe distincte. Dans la classe Logger, seule la partie générale est laissée.

 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); } } } 

Et donc, la classe Logger est intermédiaire, sa tâche est de collecter des informations concernant l'environnement dans lequel la journalisation est lancée. Dans l'exemple ci-dessus, il s'agit de la connexion utilisateur, du nom de la machine, de l'ID de l'adresse réseau et du nom du processus. Toutes ces informations sont utiles lorsque nous voulons mesurer le temps d'exécution de sections de code sur la machine de l'utilisateur, c'est-à-dire Essentiellement pour l'identification en cas de détection d'anomalies. Je pense que le lecteur conviendra qu'il est important que l'enregistreur pendant la mesure ait un impact minimal sur le temps d'exécution du code mesuré. C'est pourquoi l'enregistrement du résultat s'effectue en l'ajoutant à la file d'attente, que le processus d'arrière-plan fait tourner, en enregistrant le résultat dans la base de données, le fichier ou en le transférant sur le réseau. Cette approche présente un sérieux inconvénient, s'il y a trop d'événements de journalisation, la file d'attente se remplit plus rapidement que la rotation jusqu'à ce qu'elle occupe toute la mémoire disponible pour l'application. Mais pour provoquer cette situation, vous devez encore essayer. L'envoi des procédures de gestionnaire pour l'enregistrement de différentes classes s'effectue via un dictionnaire dans lequel la clé est un type, la valeur est la procédure d'enregistrement d'un objet de ce type.

Pour la classe de journalisation, qui sera donnée ci-dessous, il est nécessaire de satisfaire la dépendance en installant le package nuget System.Data> SQLite.

  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(); } } } } } 

Comme déjà mentionné, la classe SqliteLogger est responsable du stockage des résultats de mesure dans la base de données. Avant de commencer à utiliser la base de données, vous devez la créer; plus de lignes de code y sont consacrées. Ici, la classe enregistrera le fait de créer l'enregistreur (il est entendu que cela se produit simultanément au lancement de l'application), le résultat sera enregistré dans la table T_MAINRECORD. Nous enregistrerons également le résultat de la mesure dans le tableau T_CALLLOG. Les méthodes LogMainRecord et LogCall sont responsables du stockage de ces deux événements; les références à ceux-ci sont stockées dans le dictionnaire du répartiteur. Pour créer correctement l'objet LogItem, vous devez utiliser la fonction Watch dans le bloc d'initialisation de l'instruction using.

Par exemple, comme ceci:

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

Maintenant, pour utiliser cet outil, vous devez organiser l'utilisation de blocs dans des endroits douteux et laisser l'application fonctionner. Après cela, il reste à analyser les informations collectées, ce qui, je l'espère, suffira à identifier l'endroit problématique. Je propose de réfléchir à quelles autres mesures peuvent être collectées à l'aide de cette technique?

Merci de votre attention, bonne chance et code rapide :-)