测量子时间成方法答案

【问题标题】：Measure sub time into a method测量子时间成方法
【发布时间】：2016-03-09 12:53:37
【问题描述】：

我正在使用 PostSharp 记录某些方法的性能和其他统计信息。我被要求测量一些子任务的性能和花费的时间，例如调用外部 Web 服务或大型数据库等。

例如，我有一个应用了 AoPLoggingAttribute 的方法。 AoPLoggingAttribute 继承自 OnMethodBoundaryAspect，因此它支持所有已知方法（OnEntry、OnExit、OnSuccess 等）

    [AoPLogging]
    public MyClass[] MyMainMethod(string myid)
    {
        //Some code here
        LongExecutingTask();
        //Rest of the code here
    }

测量 LongExecutingTask 所用时间的最佳方法是什么？我不在乎它是否是总执行时间的一部分，但不知何故我需要知道从这个任务中花费的时间。

【问题讨论】：

标签： performance statistics postsharp stopwatch

【解决方案1】：

如果你想使用 postsharp，你可以像这样制作一个计时器方面

public class TimingAttribute : OnMethodBoundaryAspect   
{     
    Stopwatch timer = new Stopwatch();
    public override void OnEntry(MethodExecutionArgs args)
    {
        timer.Reset();
        timer.Start();

        base.OnEntry(args);
    }

    public override void OnExit(MethodExecutionArgs args)
    {
        timer.Stop();

        Console.WriteLine("Execution took {0} milli-seconds", timer.ElapsedMilliseconds);

        base.OnExit(args);
    }
}

现在只需将方面附加到您要计时的方法上

[Timing]
public void LongExecutingTask() {}

请记住，postsharp 或一般的 AOP 通过附加到被调用的方法来工作。不是通过添加代码插入你的主要方法（或任何你调用方法的地方）

更新：如果你真的想跟踪整个调用堆栈，你可以这样做

public class TimingAttribute : OnMethodBoundaryAspect   
{     
    static List<Stopwatch> callstack = new List<Stopwatch>();
    static int callstackDepth = 0;

    public override void OnEntry(MethodExecutionArgs args)
    {
        var timer = new Stopwatch();
        timer.Start();

        callstack.Add(timer);

        ++callstackDepth;

        base.OnEntry(args);
    }

    public override void OnExit(MethodExecutionArgs args)
    {
        --callstackDepth;

        var timer = callstack[callstackDepth];
        timer.Stop();

        if (callstackDepth == 0) {
           //Add code to print out all the results
           Console.WriteLine("Execution took {0} milli-seconds", timer.ElapsedMilliseconds);

           callstack.Clear();
        }

        base.OnExit(args);
    }
}

现在这只适用于 1 个单独的调用堆栈。如果您的主要方法中有 2 个 LongExecutingTasks，您将不得不考虑如何报告这些问题。但也许这会让您了解如何跟踪整个调用堆栈。

【讨论】：

感谢巴达维亚的回答。这就是我现在正在做的事情，但是我需要测量子任务所花费的时间，在这个例子中是 LongExecutingTask()。使用您描述的方法，我正在测量父方法（在本例中为 MyMainMethod）所花费的总时间
实际上，如果您注意我的代码 sn-p 的最后一部分，您会看到我将时间属性添加到 LongExecutingTask 方法中。在这种情况下，它将测量该方法，而不是 MyMainMethod
是的 Batavia，我注意到了，但我需要从 MyMainMethod 和 LongExecutingTask 测量两次。假设我在两者上都应用了 Timing attr。如何将一个日志事件的两个时间相加？
谁必须是 1 个日志事件？2 个日志行（每个 1 个）不是一样好吗？
我确实添加了一些示例代码，您可以将它们作为同时跟踪它们的起点。

【解决方案2】：

您必须将计时器分配给 MethodExecutionArgs 才能在多线程环境中获得准确的结果。 PostSharp 在内部分配给静态类，因此任何成员都有被并发调用覆盖的风险。

public class TimingAttribute : OnMethodBoundaryAspect
{
    public override void OnEntry(MethodExecutionArgs args)
    {
        args.MethodExecutionTag = Stopwatch.StartNew();
    }

    public override void OnExit(MethodExecutionArgs args)
    {
        var sw = (Stopwatch)args.MethodExecutionTag;
        sw.Stop();

        System.Diagnostics.Debug.WriteLine("{0} executed in {1} seconds", args.Method.Name,
                                           sw.ElapsedMilliseconds / 1000);
    }
}

【讨论】：