测量许多方法的执行时间

Question

我在 WPF 项目中工作，该项目使用实体框架和 SQL Server。那里的优化是垃圾。一切都太慢了。我想诊断代码的哪些部分会降低性能 - 我认为只有少数（我的意思是很多，但不是全部）地方设计不佳并降低了性能。

现在对于每张桌子我们都有课程，例如

UserRepository

。它不完全是存储库模式。这些类具有诸如：

GetAll(...), GetById(...), GetNewest(...), GetAllWithHigherSalaryThan(int salary, int companyId)

等方法，等等，许多方法访问器到db。数据库仅在存储库类中使用。

我不想在这里谈论重构。我只是想测量每个方法执行了多长时间以及在运行时执行了多少次。通过这些信息我将能够找到错误。

我想测量大约 100 个方法，这些方法在许多类中都有“从数据库中选择”。 SQL Server Profiler 并不能解决这个问题，因为这些方法会被执行无数次，并且如果可能的话，使用我们的数据库方法来分析来自探查器的日志将是一场噩梦。

示例方法：

public IEnumerable<Foo> GetFoo(int y, int z)
{
    return Context.Where(p =>
        p.X == null &&
        p.Y == y &&
        p.Time >= z).OrderBy(x => x.Time).AsEnumerable();
}
    

现在我正在考虑为每个方法添加秒表，测量执行时间，计算执行次数并将其传递给某个单例或其他东西，然后显示它。当然，当我完成它时，我会关闭这个诊断，但是这种方法非常周，我需要编辑每个方法，而且我不知道如何在之后关闭它 - 我的意思是我知道我可以使用类似于

#define DEBUG

但无论如何它都很蹩脚。

我试图用 Reflections 解决一些问题，但没有效果...也许有一种方法可以查看 C# 中方法的执行时间？

你有什么推荐？

Answer 1

我的第一个推荐是合适的分析器，我最喜欢的是 Jetbrains 的 dotTrace，但还有其他的。

如果不知何故这不是一个选择，而你坚持自己做：

我推荐 Postsharp - 或另一个 AOP 包。它可以做的是轻松地向许多方法添加方面。

使用 Postsharp 你可以写一个方面：

[Serializable] 
public class TraceAttribute : OnMethodBoundaryAspect 
{ 
    public override void OnEntry( MethodExecutionArgs args ) 
    { 
        // start measuring time here
    } 

    public override void OnExit( MethodExecutionArgs args ) 
    { 
        // stop measuring here 
    } 
}

然后将该方面应用于一堆方法（来自 MyNamespace 的所有公共方法）：

#if DEBUG 
[assembly: Trace( AttributeTargetTypes = "MyNamespace.*", 
    AttributeTargetTypeAttributes = MulticastAttributes.Public, 
    AttributeTargetMemberAttributes = MulticastAttributes.Public )] 
#endif 

这是一次检测多种方法所需的所有代码。

我最近就是这样做的，我将所有测量结果转储到 csv 文本文件中，然后将其转储到 SQL Server 中，在那里我可以轻松地进行选择和分组，例如找出某个方法消耗的总时间。我没有使用分析器，因为我在生产环境中进行了测量 - 仪器对性能的影响并不大（如果程序无论如何都很慢）。

以下是更多信息： http://www.postsharp.net/aspects/examples/logging

甚至免费版本 - PostSharp Express - 也足以做到这一点。

Answer 2

语言本身没有内置的分析器。如果您不介意指定您正在使用的内容，您的 IDE/调试器可能有一些内置的分析器。

如果您按照指示运行 MSSQL，则您可能无法以适合您的方式进行分析。这是两个对我来说非常有效的查询：

SELECT TOP 10 SUBSTRING(qt.TEXT, (qs.statement_start_offset/2)+1,
 ((CASE qs.statement_end_offset
 WHEN -1 THEN DATALENGTH(qt.TEXT)
 ELSE qs.statement_end_offset
 END - qs.statement_start_offset)/2)+1),
 qs.execution_count,
 qs.total_logical_reads, qs.last_logical_reads,
 qs.total_logical_writes, qs.last_logical_writes,
 qs.total_worker_time,
 qs.last_worker_time,
 qs.total_elapsed_time/1000000 total_elapsed_time_in_S,
 qs.last_elapsed_time/1000000 last_elapsed_time_in_S,
 qs.last_execution_time,
 qp.query_plan
 FROM sys.dm_exec_query_stats qs
 CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) qt
 CROSS APPLY sys.dm_exec_query_plan(qs.plan_handle) qp
 ORDER BY qs.total_logical_reads DESC -- logical reads
 -- ORDER BY qs.total_logical_writes DESC -- logical writes
 -- ORDER BY qs.total_worker_time DESC -- CPU time

来源

SELECT DISTINCT TOP 10
 t.TEXT QueryName,
 s.execution_count AS ExecutionCount,
 s.max_elapsed_time AS MaxElapsedTime,
 ISNULL(s.total_elapsed_time / s.execution_count, 0) AS AvgElapsedTime,
 s.creation_time AS LogCreatedOn,
 ISNULL(s.execution_count / DATEDIFF(s, s.creation_time, GETDATE()), 0) AS FrequencyPerSec
 FROM sys.dm_exec_query_stats s
 CROSS APPLY sys.dm_exec_sql_text( s.sql_handle ) t
 ORDER BY
 s.max_elapsed_time DESC
 GO 

来源

这里的神奇之处在于，您可以找出哪些命令总体上占用了最多时间，无论它是运行 10 次极其缓慢的命令，还是运行 1,000,000 次但速度非常快的命令。

你也可能会做一些更高层次的事情。我之前已经能够通过将探查器附加到每个 Web 请求的开头和结尾来调试项目，但话又说回来，这不会找到导致问题的特定命令。