👩🏽‍🎤 ☔️ 🎊 测量C＃代码的便捷工具 👩🏼‍🤝‍👨🏿 🎸 🧚🏽

在快节奏，大型而复杂的产品中，发现性能瓶颈并不是一件容易的事。当然，有解决此类问题的工具，例如BenchmarkDotNet 。无疑，这是一个有用且必要的工具，但并不总是很方便。例如，当需要通过设置相应的属性而不是完全测量公共方法，而是私有方法内部的某些代码时，可以检测到这一点。在这里，我绝不会批评指定的工具，而只是想指出需要一种稍微不同的方式来收集代码片段度量的需求。有非常复杂，令人困惑的方法，带有分支，带有循环，处理特殊情况，并且问题所在可能在内部。要找到它，您需要用仪表大量地覆盖代码，同时显然希望不要触摸或修改现有逻辑。

您可以使用StopWatch类来测量代码段的执行时间。

像这样：

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

为了避免每次都按代码放置秒表，您可以通过一个高阶函数来统一测量过程，例如，如下所示：

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

看来问题似乎已解决，但该技术仍然极为有限。事实是，被测代码中可能有返回输出，因此您不能将其包装在Action中。即使使用Func也无法解决问题。下面，我要描述一种不止一次使用的技术，它在代码中的更改最少，可以解决测量任意代码段的问题。我们将构建一个简单而紧凑的记录器来测量执行速度；如果需要，修改它以满足其他需求（例如搜索内存泄漏）也非常简单。下面的代码并不声称是完整的和可运行的，而是对原理的演示，您可以在此基础上构建一个真正有用且简单的工具。但是，该代码正在运行，并且可以用于按原样收集度量标准或将其用于更具体的任务。我还想指出，下面的代码收集了其他信息，例如进程ID或主机名。这些参数在某些情况下对我很有用，仅作为示例。任何决定使代码适应其任务的人都可能需要收集完全不同的参数，部分原因是指定的代码未作为最终产品发布在公共GitHub上。

C＃有一个众所周知的有用的using语句，它适用于支持IDisposable接口的类型。关键是，当退出操作员块时，请调用Dispose方法，其中通常释放资源。但是，该机制可以用于多种目的。在我们的例子中，这将是对块执行时间的度量，然后保存结果以供分析。这个想法是在using块中创建该类的实例，在创建时，将收集各种有用的信息并启动StopWatch。当退出该块时执行Dispose时，结果是固定的，并发送对象以保存日志。

using语句是语法糖；编译后将其转换为try-finaly块。

例如，代码：

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

转换为视图设计：

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

因此，在try块的任何退出处，将保证并立即调用Dispose方法，而使用中放置的代码的逻辑将不会以任何方式改变。我们更改的只是添加一个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（线程ID）字段，您可以通过该字段将一个线程中的数据分组。同样，在创建LogItem对象时，测量的开始时间是固定的，并且StopWatch将开始。在Dispose方法中，停止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类是中间类，它的任务是收集有关启动日志记录的环境的信息。在上面的示例中，这是用户登录名，计算机名称，网络地址ID和进程名称。当我们要测量用户机器上的代码段的执行时间时，所有这些信息都是有用的。主要用于识别异常情况下的识别。我认为读者会同意，在测量期间记录器对被测代码的执行时间影响最小是很重要的。这就是为什么通过将结果添加到队列（后台进程旋转），将结果保存到数据库，文件或通过网络传输来执行保存结果的原因。这种方法有一个严重的缺点，如果日志事件太多，则队列将比开始填充更快，直到它占用了应用程序可用的所有内存。但是要引起这种情况，您仍然需要尝试。用于保存不同类的处理程序的分发是通过字典执行的，其中字典是一种类型，值是用于保存此类型的对象的过程。

对于下面将给出的日志记录类，有必要通过安装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对象，需要在using语句的初始化块中使用Watch函数。

例如，像这样：

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

现在，要使用此工具，您需要在有问题的地方安排使用块，然后让应用程序正常工作。之后，仍然需要分析收集到的信息，我希望这足以确定问题所在。我建议考虑使用此技术还可以收集哪些其他指标？

感谢您的关注，祝您好运和快速的代码:-)

测量C＃代码的便捷工具

More articles: