如何在 Log4Net 中记录运行时间

Question

我想记录我的 API 秒的经过时间。我在这里看到两种不同的方法：

使用 stopwatch。在输入 API 之后创建一个新的秒表，然后在退出之前调用 stop()（在日志本身上打印经过的时间）。
打印两份日志，一份在进入API之后，另一份在退出之前。经过的时间将是 "stored" 作为两个日志时间戳之间的时间差。

您认为哪种方法最好？

第一个看起来不错，但我需要在所有地方创建一个新的秒表。第二个更干净但是在回读日志时必须做一些数学运算

Answer 1

我会选择第一个选项。 Stopwatch 的创建非常便宜。有了一个好的包装器，每个 API 方法中所需的代码可以像这样简单：

public int MyApiMethod()
{
    using (new ExecutionTimeLogger())
    {
        // All API functionality goes inside this using block.
        var theResultValue = 23;
        return theResultValue;
    }
}

class ExecutionTimeLogger 看起来像这样：

using System;
using System.Diagnostics;
using System.Runtime.CompilerServices;
using log4net;

public class ExecutionTimeLogger : IDisposable
{
    private readonly ILog log = LogManager.GetLogger("ExecutionTimes");
    private readonly string methodName;
    private readonly Stopwatch stopwatch;

    public ExecutionTimeLogger([CallerMemberName] string methodName = "")
    {
        this.methodName = methodName;
        stopwatch = Stopwatch.StartNew();
    }

    public void Dispose()
    {
        log.Debug(methodName + "() took " + stopwatch.ElapsedMilliseconds + " ms.");
        GC.SuppressFinalize(this);
    }
}

根据您的记录器实现，输出可能如下所示：

15:04:23.4477 | DEBUG | ExecutionTimes | MyApiMethod() took 42 ms.

请注意，当API方法在using中抛出异常时也会生成日志输出，因为ExecutionTimeLogger实例将被释放。

methodName参数会被编译器自动填充，因为它有[CallerMemberName] attribute。您 不需要 每次创建 ExecutionTimeLogger.

时都需要传递它

行 GC.SuppressFinalize(this) 告诉垃圾收集器不必安排对 ExecutionTimeLogger 实例的终结器的调用，因为我们知道它从未创建非托管资源。

如果您使用 Unity 作为 DI 框架，您还可以编写一个 UnityContainerExtension 来包装每个具有特定自定义属性（例如 LogExecutionTimeAttribute）的方法以及所需的测量和日志记录代码.不过这要复杂得多。

Answer 2

我更喜欢第一种方法（使用 stopwatch）。
如果您的方法称为同步，则不必为每个 API 调用创建一个新的 Stopwatch 对象。您可以定义 Stopwatch 的全局实例，并在调用 Stop() 之后调用 Reset() , 或 Restart() 从头开始计数。

如何在 Log4Net 中记录运行时间

How to log elapsed time in Log4Net

.net

c#

logging

log4net