StackFrame的表现如何?

40 .net c# performance logging

我正在考虑使用类似StackFrame stackFrame = new StackFrame(1)记录执行方法的东西,但我不知道它的性能影响.堆栈是否跟踪了每个方法调用时构建的内容,因此性能不应该是一个问题,还是仅在被要求时才构建?您是否建议在性能非常重要的应用程序中反对它?如果是这样,这是否意味着我应该为发布禁用它?

STW*_*STW 33

编辑:一些背景


我们有一个类似的功能,99%的时间被禁用; 我们使用的方法如下:

public void DoSomething()
{
    TraceCall(MethodBase.GetCurrentMethod().Name);
    // Do Something
}

public void TraceCall(string methodName)
{
    if (!loggingEnabled) { return; }
    // Log...
}

TraceCall(MethodBase.GetCurrentMethod().Name)
Run Code Online (Sandbox Code Playgroud)

这很简单,但无论是否启用了跟踪,我们都会因使用Reflection查找方法名称而受到性能影响.

我们的选择是要么在每个方法中需要更多的代码(并且冒着简单的错误或拒绝的风险),要么在启用了日志记录时切换到使用StackFrame来确定调用方法.

选项A:

public void DoSomething()
{
    if (loggingEnabled)
    {
        TraceCall(MethodBase.GetCurrentMethod().Name);
    }
    // Do Something
}

public void TraceCall(string methodName)
{
    if (!loggingEnabled) { return; }
    // Log...
}
Run Code Online (Sandbox Code Playgroud)

选项B:

public void DoSomething()
{
    TraceCall();
    // Do Something
}

public void TraceCall()
{
    if (!loggingEnabled) { return; }
    StackFrame stackFrame = new StackFrame(1);
    // Log...
}
Run Code Online (Sandbox Code Playgroud)

我们选择了选项B. 当禁用日志记录时,它在选项A上提供了显着的性能改进,99%的时间并且实现起来非常简单.

这是对迈克尔代码的更改,以显示此方法的成本/收益

using System;
using System.Diagnostics;
using System.Reflection;

namespace ConsoleApplication
{
    class Program
    {
        static bool traceCalls;

        static void Main(string[] args)
        {
            Stopwatch sw;

            // warm up
            for (int i = 0; i < 100000; i++)
            {
                TraceCall();
            }

            // call 100K times, tracing *disabled*, passing method name
            sw = Stopwatch.StartNew();
            traceCalls = false;
            for (int i = 0; i < 100000; i++)
            {
                TraceCall(MethodBase.GetCurrentMethod());
            }
            sw.Stop();
            Console.WriteLine("Tracing Disabled, passing Method Name: {0}ms"
                             , sw.ElapsedMilliseconds);

            // call 100K times, tracing *enabled*, passing method name
            sw = Stopwatch.StartNew();
            traceCalls = true;
            for (int i = 0; i < 100000; i++)
            {
                TraceCall(MethodBase.GetCurrentMethod());
            }
            sw.Stop();
            Console.WriteLine("Tracing Enabled, passing Method Name: {0}ms"
                             , sw.ElapsedMilliseconds);

            // call 100K times, tracing *disabled*, determining method name
            sw = Stopwatch.StartNew();
            traceCalls = false;
            for (int i = 0; i < 100000; i++)
            {
                TraceCall();
            }
            Console.WriteLine("Tracing Disabled, looking up Method Name: {0}ms"
                       , sw.ElapsedMilliseconds);

            // call 100K times, tracing *enabled*, determining method name
            sw = Stopwatch.StartNew();
            traceCalls = true;
            for (int i = 0; i < 100000; i++)
            {
                TraceCall();
            }
            Console.WriteLine("Tracing Enabled, looking up Method Name: {0}ms"
                       , sw.ElapsedMilliseconds);

            Console.ReadKey();
        }

        private static void TraceCall()
        {
            if (traceCalls)
            {
                StackFrame stackFrame = new StackFrame(1);
                TraceCall(stackFrame.GetMethod().Name);
            }
        }

        private static void TraceCall(MethodBase method)
        {
            if (traceCalls)
            {
                TraceCall(method.Name);
            }
        }

        private static void TraceCall(string methodName)
        {
            // Write to log
        }
    }
}
Run Code Online (Sandbox Code Playgroud)

结果:

Tracing Disabled, passing Method Name: 294ms
Tracing Enabled,  passing Method Name: 298ms
Tracing Disabled, looking up Method Name: 0ms
Tracing Enabled,  looking up Method Name: 1230ms
Run Code Online (Sandbox Code Playgroud)


Mic*_*tta 19

一个快速而天真的测试表明,对于性能敏感的代码,是的,你想要注意这个:

不产生100K帧:3ms

生成100K帧:1805ms

在我的机器上每个生成的帧约20微秒.不是很多,但是在大量迭代中存在可测量的差异.

说到你以后的问题("我应该在我的应用程序中禁用StackFrame生成吗?"),我建议你分析你的应用程序,做我在这里做的性能测试,看看性能差异是否与你的工作量.

using System;
using System.Diagnostics;

namespace ConsoleApplication
{
    class Program
    {
        static bool generateFrame;

        static void Main(string[] args)
        {
            Stopwatch sw;

            // warm up
            for (int i = 0; i < 100000; i++)
            {
                CallA();
            }

            // call 100K times; no stackframes
            sw = Stopwatch.StartNew();
            for (int i = 0; i < 100000; i++)
            {
                CallA();
            }
            sw.Stop();
            Console.WriteLine("Don't generate 100K frames: {0}ms"
                                 , sw.ElapsedMilliseconds);

            // call 100K times; generate stackframes
            generateFrame = true;
            sw = Stopwatch.StartNew();
            for (int i = 0; i < 100000; i++)
            {
                CallA();
            }
            Console.WriteLine("Generate 100K frames: {0}ms"
                           , sw.ElapsedMilliseconds);

            Console.ReadKey();
        }

        private static void CallA()
        {
            CallB();
        }

        private static void CallB()
        {
            CallC();
        }

        private static void CallC()
        {
            if (generateFrame)
            {
                StackFrame stackFrame = new StackFrame(1);
            }
        }
    }
}
Run Code Online (Sandbox Code Playgroud)


小智 17

我知道这是一个旧帖子,但万一有人遇到它,如果你的目标是.Net 4.5,还有另一种选择

您可以使用CallerMemberName属性来标识调用方法名称.它比反射或StackFrame快得多.以下是迭代一百万次的快速测试结果.与反射相比,StackFrame非常慢,而新属性使它们看起来都像是静止不动.这是在IDE中运行的.

反思结果:00:00:01.4098808

StackFrame结果00:00:06.2002501

CallerMemberName属性结果:00:00:00.0042708

完成

以下是来自编译的exe: 反射结果:00:00:01.2136738 StackFrame结果00:00:03.6343924 CallerMemberName属性结果: 00:00:00.0000947 完成

        static void Main(string[] args)
    {

        Stopwatch sw = new Stopwatch();

        sw.Stop();

        Console.WriteLine("Reflection Result:");

        sw.Start();
        for (int i = 0; i < 1000000; i++)
        {
            //Using reflection to get the current method name.
            PassedName(MethodBase.GetCurrentMethod().Name);
        }
        Console.WriteLine(sw.Elapsed);

        Console.WriteLine("StackFrame Result");

        sw.Restart();

        for (int i = 0; i < 1000000; i++)
        {
            UsingStackFrame();
        }

        Console.WriteLine(sw.Elapsed);

        Console.WriteLine("CallerMemberName attribute Result:");

        sw.Restart();
        for (int i = 0; i < 1000000; i++)
        {
            UsingCallerAttribute();
        }

        Console.WriteLine(sw.Elapsed);

        sw.Stop();



        Console.WriteLine("Done");
        Console.Read();
    }


    static void PassedName(string name)
    {

    }

    static void UsingStackFrame()
    {
        string name = new StackFrame(1).GetMethod().Name;
    }


    static void UsingCallerAttribute([CallerMemberName] string memberName = "")
    {

    }
Run Code Online (Sandbox Code Playgroud)

  • 该属性更快的原因是编译器实际上将其直接刻录到生成的图像中。在调用使用编译器服务属性的方法的所有地方,这些值被替换为编译器应该提供的任何内容(CallerMemberName、CallerFileName、CallerLineNumber)。它基本上是二进制重写。这可以使用 ILDASM 工具进行确认。 (2认同)

Pau*_*ams 6

从MSDN文档中,似乎一直在创建StackFrames:

对于在执行线程期间进行的每个函数调用,都会在调用堆栈上创建并推送StackFrame.堆栈帧始终包含MethodBase信息,并且可选地包括文件名,行号和列号信息.

new StackFrame(1)你打电话的构造函数会这样做:

private void BuildStackFrame(int skipFrames, bool fNeedFileInfo)
{
    StackFrameHelper sfh = new StackFrameHelper(fNeedFileInfo, null);
    StackTrace.GetStackFramesInternal(sfh, 0, null);
    int numberOfFrames = sfh.GetNumberOfFrames();
    skipFrames += StackTrace.CalculateFramesToSkip(sfh, numberOfFrames);
    if ((numberOfFrames - skipFrames) > 0)
    {
        this.method = sfh.GetMethodBase(skipFrames);
        this.offset = sfh.GetOffset(skipFrames);
        this.ILOffset = sfh.GetILOffset(skipFrames);
        if (fNeedFileInfo)
        {
            this.strFileName = sfh.GetFilename(skipFrames);
            this.iLineNumber = sfh.GetLineNumber(skipFrames);
            this.iColumnNumber = sfh.GetColumnNumber(skipFrames);
        }
    }
}
Run Code Online (Sandbox Code Playgroud)

GetStackFramesInternal是一种外部方法. CalculateFramesToSkip有一个只运行一次的循环,因为你只指定了1帧.其他一切看起来都很快.

您是否尝试过测量创建100万个片段需要多长时间?

  • 或者他们可能以不同的方式创建它们,或者在请求之前它可能是本机构造,或者文档可能是错误的.我假设CLR需要跟踪托管堆栈,因此随着堆栈的增长,在本机内存设置中必须有*something*. (4认同)
  • 迈克尔的测试表明堆栈帧不是"在执行线程期间为每个函数调用创建并推送到调用堆栈上",因为它需要更长的时间来请求它. (3认同)

Mic*_*tum 5

我正在考虑使用类似StackFrame stackFrame = new StackFrame(1)的日志记录执行方法

出于兴趣:为什么?如果只需要当前方法,则

string methodName = System.Reflection.MethodBase.GetCurrentMethod().Name;
Run Code Online (Sandbox Code Playgroud)

似乎更好。也许性能不高(我没有进行比较,但是反射显示GetCurrentMethod()不仅创建了StackFrame,而且还做了一些“魔术”),但意图更加明确。