如何在Log4Net中记录已用时间

Question

我想记录我的API的运行时间.我在这里看到两种不同的方法:

1. 用一个stopwatch.在输入API之后立即创建一个新的秒表,然后stop()在退出之前调用它(在日志本身上打印已用时间).

2. 制作两个日志打印输出,一个在输入API之后,另一个在退出之前.经过的时间将被"存储"为两个日志时间戳之间的时间差.

您认为哪种方法最好？

第一个似乎很好,但我需要到处创建一个新的秒表.第二个是更清洁,但在读回日志时必须完成一些数学运算

Answer 1

我会选择第一个选项.创建一个Stopwatch非常便宜.使用一个好的包装器,每个API方法中所需的代码可以像下面这样简单:

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

该类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 | 调试| 执行时间| MyApiMethod()耗时42毫秒.

请注意,当API方法在其中引发异常时,也会生成日志输出using,因为ExecutionTimeLogger实例将被处理掉.

该methodName参数将由编译器自动填充,因为它具有该[CallerMemberName]属性.你并不需要在每次创建时传递ExecutionTimeLogger.

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

如果您使用Unity作为DI框架,您还可以编写一个UnityContainerExtension包含具有特定自定义属性(LogExecutionTimeAttribute例如)的每个方法,并使用所需的度量和日志记录代码.但这要复杂得多.