أداة مريحة لقياس رمز C #

في منتج سريع الخطى وكبير ومعقد ، لا يعتبر العثور على الاختناقات من حيث الأداء مهمة تافهة. بالطبع ، هناك أدوات لحل هذه المشكلات ، على سبيل المثال ، BenchmarkDotNet . لا شك أن هذه أداة مفيدة وضرورية ، لكنها ليست مريحة دائمًا. يمكن اكتشاف ذلك ، على سبيل المثال ، عندما يكون من الضروري قياس الطريقة العامة ليس تمامًا عن طريق تعيين السمة المقابلة ، ولكن بعض التعليمات البرمجية داخل الطريقة الخاصة. هنا ، لن أنتقد الأداة المعينة بأي حال من الأحوال ، لكنني أريد فقط الإشارة إلى الحاجة إلى طريقة مختلفة قليلاً لجمع المقاييس لشظايا الكود. هناك طرق معقدة ومربكة للغاية ، مع التفريخ ، مع الحلقات ، والتعامل مع المواقف الاستثنائية ، وقد يكون مكان المشكلة في مكان ما في الداخل. للعثور عليه ، تحتاج إلى تغطية الكود بكمية كبيرة بالمتر ، بينما هناك رغبة واضحة في عدم لمس أو إعادة صياغة المنطق الحالي.

يمكنك استخدام فئة StopWatch لقياس وقت تنفيذ مقاطع التعليمات البرمجية.

شيء مثل هذا:

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

من أجل عدم وضع StopWatch بواسطة رمز في كل مرة ، يمكنك توحيد إجراء القياس من خلال وظيفة ذات ترتيب أعلى ، على سبيل المثال ، مثل هذا:

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

واستخدم هذه الطريقة:

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

يمكنك تحويل المكالمة من الداخل إلى الخارج من خلال الامتداد:

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

واستخدام مثل هذا:

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

يبدو أن المشكلة قد تم حلها ، لكن هذه التقنية محدودة للغاية. والحقيقة هي أنه يمكن أن يكون هناك مخرجات إرجاع في التعليمات البرمجية المقاسة ، لذلك لا يمكنك التفاف عليه في العمل. حتى باستخدام Func لن يحل المشكلة. أريد أدناه وصف تقنية استخدمتها أكثر من مرة ، مع وجود أصغر التغييرات في الكود سوف يحل مشكلة قياس المقاطع التعسفية من الكود. سنقوم ببناء مسجل بسيط وصغير لقياس سرعة التنفيذ ؛ وإذا لزم الأمر ، من السهل جدًا تعديله أيضًا لاحتياجات أخرى ، على سبيل المثال ، للبحث عن تسرب الذاكرة. لا تدعي التعليمة البرمجية أدناه أنها كاملة وعملية ، وإنما هي عرض للمبدأ الذي يمكنك من خلاله بناء أداة مفيدة وسهلة للغاية. ومع ذلك ، تعمل الشفرة ويمكن استخدامها لغرض جمع المقاييس كما هي أو تكييفها لمهام أكثر تحديدًا. أريد أيضًا أن أشير إلى أنه في الكود أدناه يتم جمع معلومات إضافية ، مثل معرف العملية أو اسم المضيف. كانت هذه المعلمات مفيدة لي في مواقف معينة ولم يتم تركها إلا كمثال. قد يحتاج أي شخص يقرر تكييف الرمز مع مهامه إلى جمع معلمات مختلفة تمامًا ، ولهذا السبب لم ينشر الرمز المحدد على GitHub العام كمنتج نهائي.

يحتوي C # على عبارة استخدام معروفة ومفيدة ، وهو قابل للتطبيق على الأنواع التي تدعم واجهة IDisposable. النقطة المهمة هي أنه عند الخروج من كتلة المشغل ، قم باستدعاء طريقة التخلص ، حيث يتم ، كقاعدة عامة ، تحرير الموارد. ومع ذلك ، يمكن استخدام هذه الآلية لمجموعة متنوعة من الأغراض. في حالتنا ، سيكون هذا قياسًا لوقت تنفيذ الكتلة ، يليه توفير نتيجة التحليل. والفكرة هي أنه يتم إنشاء مثيل للفئة في كتلة الاستخدام ، في وقت الإنشاء ، يتم جمع أنواع مختلفة من المعلومات المفيدة ويبدأ StopWatch. عندما يتم تنفيذ Dispos عند الخروج من الكتلة ، تكون النتيجة ثابتة ويتم إرسال الكائن لحفظ السجل.

عبارة الاستخدام عبارة عن سكر نحوي ، وعند التحويل البرمجي ، يتحول إلى كتلة اختبار نهائي.

على سبيل المثال ، الكود:

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

تم تحويله إلى تصميم عرض:

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

وبالتالي ، عند أي خروج من كتلة المحاولة ، سيتم ضمان طريقة التخلص وإعادتها فورًا ، بينما لن يتغير منطق الشفرة الموضوعة في الاستخدام بأي طريقة. كل ما قمنا بتغييره هو إضافة مكالمة التخلص. تسترشد هذه الفكرة ، وسوف نبذل أبسط قياس وقت التشغيل.

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

وهكذا ، ماذا يعطينا هذا؟

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

ما هو مفقود في التقنية الموصوفة؟ لم يتم الكشف عن موضوع كيفية تأمين النتيجة بالكامل ، فمن الواضح أنه لا يوجد معنى كبير في تسجيل النتيجة في وحدة التحكم. في معظم الحالات ، من الممكن تمامًا استخدام الأدوات الشعبية الشائعة NLog و Log4Net و Serilog مع الكعك المرئي والحد الأدنى من التحليلات. في الحالات الشديدة بشكل خاص ، قد تكون هناك حاجة إلى تحليلات أكثر تطوراً لمعرفة ما يحدث.

يمكنك تخزين النتيجة في ملف نصي بسيط ، لكن بالنسبة لهذه المهمة ، أعتقد أن هذا ليس حلاً مناسبًا للغاية ، حيث يمكن أن يكون هناك العديد من الأجزاء البرمجية ، وربما يمكن تداخلها ، بالإضافة إلى العديد من مؤشرات الترابط المتوازية. لذلك ، فقط من أجل راحة التنقل في السجل ، نستخدم قاعدة بيانات SQLite.

نبدأ بتحديد فئة مسؤولة عن قياس الوقت والتقاط معلومات إضافية مفيدة لتحليلها لاحقًا.

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

يتم تمرير ارتباط لكائن التسجيل ومعلومات إضافية إلى مُنشئ فئة LogItem ، والاسم الكامل للطريقة التي يتم بها القياس وتسمية مع رسالة عشوائية. لفهم السجلات من تنفيذ التعليمات البرمجية غير المتزامنة ، سيساعد الحقل Tid (معرف مؤشر الترابط) ، والذي يمكنك من خلاله تجميع البيانات من سلسلة رسائل واحدة. أيضًا ، عند إنشاء كائن LogItem ، يكون وقت بدء القياس ثابتًا ويبدأ StopWatch. في طريقة التخلص ، أوقف StopWatch واتصل بطريقة تسجيل WriteLog ، لتمرير كائن مطلق النار الحالي وإصلاح جميع معلومات LogItem اللازمة لها.

يحتوي المسجل بشكل أساسي على مهمتين رئيسيتين: بدء تشغيل كائن LogItem وتسجيل النتيجة بعد اكتمال القياس. نظرًا لأنني ما زلت بحاجة إلى تسجيل النتيجة ليس فقط في SQLite ولكن أيضًا في ملفات نصية بتنسيقات أو قواعد بيانات مختلفة بخلاف SQLite ، يتم وضع منطق التفاعل في فصل منفصل. في فئة Logger ، يتم ترك الجزء العام فقط.

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

وهكذا ، فإن فئة Logger متوسطة ، وتتمثل مهمتها في جمع المعلومات المتعلقة بالبيئة التي يتم فيها بدء التسجيل. في المثال أعلاه ، هذا هو تسجيل دخول المستخدم واسم الجهاز ومعرف عنوان الشبكة واسم العملية. كل هذه المعلومات تكون مفيدة عندما نريد قياس وقت تنفيذ أقسام الكود على جهاز المستخدم ، أي أساسا لتحديد الهوية في حالة الكشف عن الحالات الشاذة. أعتقد أن القارئ سوف يوافق على أنه من المهم أن يكون للمسجل أثناء القياس تأثير ضئيل على وقت تنفيذ الكود المقاس. هذا هو السبب في أن حفظ النتيجة يتم عن طريق إضافته إلى قائمة الانتظار ، التي تدور العملية الخلفية ، أو حفظ النتيجة في قاعدة البيانات ، أو نقلها عبر الشبكة. هذا النهج له عيب خطير ، إذا كان هناك الكثير من أحداث التسجيل ، فإن قائمة الانتظار سوف تملأ أسرع من الدوران حتى تستهلك كل الذاكرة المتاحة للتطبيق. ولكن لإثارة هذا الموقف ، لا تزال بحاجة إلى المحاولة. يتم تنفيذ إجراءات المعالج لحفظ الفئات المختلفة من خلال قاموس يكون فيه المفتاح من النوع ، والقيمة هي الإجراء الخاص بحفظ كائن من هذا النوع.

بالنسبة لفئة التسجيل ، التي سيتم توفيرها أدناه ، من الضروري تلبية التبعية عن طريق تثبيت حزمة 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(); } } } } } 

كما سبق ذكره ، فإن فئة SqliteLogger هي المسؤولة عن تخزين نتائج القياس في قاعدة البيانات. قبل البدء في استخدام قاعدة البيانات ، تحتاج إلى إنشائها ؛ يتم تكريس المزيد من أسطر التعليمات البرمجية لهذا الغرض. هنا سيقوم الفصل بتسجيل حقيقة إنشاء المسجل (من المفهوم أن هذا يحدث في وقت واحد مع بدء تشغيل التطبيق) ، سيتم حفظ النتيجة في جدول T_MAINRECORD. سنقوم أيضًا بحفظ نتيجة القياس في الجدول T_CALLLOG. تعتبر أساليب LogMainRecord و LogCall مسؤولة عن تخزين هذين الحدثين ؛ يتم تخزين المراجع إليها في قاموس المرسل. لإنشاء كائن LogItem بشكل صحيح ، تحتاج إلى استخدام وظيفة Watch في كتلة التهيئة الخاصة بجملة الاستخدام.

على سبيل المثال ، مثل هذا:

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

الآن ، لاستخدام هذه الأداة ، يلزمك ترتيب استخدام الكتل في الأماكن المشكوك فيها والسماح للتطبيق بالعمل. بعد ذلك ، يبقى تحليل المعلومات التي تم جمعها ، والتي آمل أن تكون كافية لتحديد مكان المشكلة. أقترح التفكير في المقاييس الأخرى التي يمكن جمعها باستخدام هذه التقنية؟

شكرا لك على الاهتمام ، حظا سعيدا ورمز سريع :-)