将属性值连接到字符串时的 C# 反射 "strange" 基准

Question

我试着做了一些反射基准测试，但大多数时候我都弄糊涂了。请有人解释为什么这两个测试都通过了？

对于第一个，我预计它会失败，但我得到的时间是：

毫秒反射 - 4970 毫秒

毫秒 - 6935 毫秒

    [Fact]
    public void PropertiesGetterString()
    {
        var bar = new Bar
        {
            Id = 42,
            Number = "42",
        };

        string concat = string.Empty;
        string concatReflection = string.Empty;

        var props = bar.GetType().GetProperties();

        Stopwatch sw = new Stopwatch();
        sw.Start();

        for (int i = 0; i < 100000; i++)
        {
            concatReflection += props[1].GetValue(bar);
        }

        sw.Stop();

        long millisecondsReflection = sw.ElapsedMilliseconds;

        sw.Reset();

        sw.Start();

        for (int i = 0; i < 100000; i++)
        {
            concat += bar.Number;
        }

        sw.Stop();

        long milliseconds = sw.ElapsedMilliseconds;

        millisecondsReflection.Should().BeLessOrEqualTo(milliseconds);
    }

我想是跟字符串拼接或者类型转换有关，所以我改成了list append，得到了预期的结果，反射变慢了。

    [Fact]
    public void PropertiesGetterArray()
    {
        var bar = new Bar
        {
            Id = 42,
            Number = "42",
        };

        List<object> concat = new List<object>();
        List<object> concatReflection = new List<object>();

        var props = bar.GetType().GetProperties();

        Stopwatch sw = new Stopwatch();
        sw.Start();

        for (int i = 0; i < 1000000; i++)
        {
            concatReflection.Add(props[1].GetValue(bar));
        }

        sw.Stop();

        long millisecondsReflection = sw.ElapsedMilliseconds;

        sw.Reset();
        sw.Start();

        for (int i = 0; i < 1000000; i++)
        {
            concat.Add(bar.Number);
        }

        sw.Stop();

        long milliseconds = sw.ElapsedMilliseconds;

        millisecondsReflection.Should().BeGreaterOrEqualTo(milliseconds);
    }

这里的结果是：

毫秒反射 - 184 毫秒

毫秒 - 11 毫秒

我的问题是我在这里遗漏了什么？

P.S。所用时间是在调试模式下。如发布模式中的评论所示，时间彼此非常接近

Answer 1

摘要

造成这种差异的原因有两点：字符串连接的开销淹没了反射的开销；以及调试构建处理本地生命周期的方式的不同。

您在发布版本和调试版本之间看到的时间差异是由于调试版本使任何局部变量保持活动状态直到方法结束的方式，与发布版本相反。

这导致代码中两个字符串的 GC 在发布版本和调试版本之间表现得非常不同。

详细分析

如果您将测试代码更改为仅对字符串属性的长度求和，则会得到预期的结果。

这是我的结果（发布版本）：

Trial 1
Length = 20000000
Length = 20000000
Without reflection: 8
With reflection: 1613
Trial 2
Length = 20000000
Length = 20000000
Without reflection: 8
With reflection: 1606
Trial 3
Length = 20000000
Length = 20000000
Without reflection: 8
With reflection: 1598
Trial 4
Length = 20000000
Length = 20000000
Without reflection: 8
With reflection: 1609
Trial 5
Length = 20000000
Length = 20000000
Without reflection: 9
With reflection: 1619

以及测试代码：

using System;
using System.Diagnostics;

namespace Demo
{
    class Bar
    {
        public int Id { get; set; }
        public string Number { get; set; }
    }

    static class Program
    {
        static void Main()
        {
            for (int trial = 1; trial <= 5; ++trial)
            {
                Console.WriteLine("Trial " + trial);
                PropertiesGetterString();
            }
        }

        public static void PropertiesGetterString()
        {
            int count = 10000000;

            var bar = new Bar
            {
                Id = 42,
                Number = "42",
            };

            int totalLength = 0;

            var props = bar.GetType().GetProperties();

            Stopwatch sw = new Stopwatch();
            sw.Start();

            for (int i = 0; i < count; i++)
            {
                totalLength += ((string)props[1].GetValue(bar)).Length;
            }

            sw.Stop();
            long millisecondsReflection = sw.ElapsedMilliseconds;
            Console.WriteLine("Length = " + totalLength);

            sw.Reset();
            totalLength = 0;
            sw.Start();

            for (int i = 0; i < count; i++)
            {
                totalLength += bar.Number.Length;
            }

            sw.Stop();
            long milliseconds = sw.ElapsedMilliseconds;
            Console.WriteLine("Length = " + totalLength);

            Console.WriteLine("Without reflection: " + milliseconds);
            Console.WriteLine("With reflection: " + millisecondsReflection);
        }
    }
}

另请注意，我只能使用调试版本而不是发布版本来重现您的原始结果。

如果我更改我的测试代码以根据您的 OP 进行字符串连接，我会得到这些结果：

Trial 1
Without reflection: 3686
With reflection: 3661
Trial 2
Without reflection: 3584
With reflection: 3688
Trial 3
Without reflection: 3587
With reflection: 3676
Trial 4
Without reflection: 3550
With reflection: 3700
Trial 5
Without reflection: 3564
With reflection: 3659

最后，为了进一步减少后台 GC 对两个循环的影响，我在每次调用 sw.Stop() 后添加了以下代码：

GC.Collect();
GC.WaitForPendingFinalizers();

将结果更改为：

Trial 1
Without reflection: 3565
With reflection: 3665
Trial 2
Without reflection: 3538
With reflection: 3631
Trial 3
Without reflection: 3535
With reflection: 3597
Trial 4
Without reflection: 3558
With reflection: 3629
Trial 5
Without reflection: 3551
With reflection: 3599

随着这一变化，所有 "with reflection" 结果都比 "without reflection" 结果慢，如您所料。

最后，让我们研究一下在调试模式下观察到的差异。

看起来差异是由于循环的顺序造成的。如果您在直接循环之前尝试使用反射循环进行一项测试，反之亦然。

这是我最终测试程序的结果：

Trial 1
PropertiesGetterStringWithoutThenWithReflection()
Without reflection: 3228
With reflection: 5866
PropertiesGetterStringWithThenWithoutReflection()
Without reflection: 5780
With reflection: 3273
Trial 2
PropertiesGetterStringWithoutThenWithReflection()
Without reflection: 3207
With reflection: 5921
PropertiesGetterStringWithThenWithoutReflection()
Without reflection: 5802
With reflection: 3318
Trial 3
PropertiesGetterStringWithoutThenWithReflection()
Without reflection: 3246
With reflection: 5873
PropertiesGetterStringWithThenWithoutReflection()
Without reflection: 5882
With reflection: 3297
Trial 4
PropertiesGetterStringWithoutThenWithReflection()
Without reflection: 3261
With reflection: 5891
PropertiesGetterStringWithThenWithoutReflection()
Without reflection: 5778
With reflection: 3298
Trial 5
PropertiesGetterStringWithoutThenWithReflection()
Without reflection: 3267
With reflection: 5948
PropertiesGetterStringWithThenWithoutReflection()
Without reflection: 5830
With reflection: 3306

请注意，第一个循环运行是最快的，无论它是否在进行反射。这意味着差异是在调试版本中完成字符串处理的方式的一些工件。

我怀疑可能发生的情况是调试版本在整个方法中保持连接的字符串处于活动状态，而对于发布版本则不会，这将影响 GC。

以上结果的测试代码如下：

using System;
using System.Diagnostics;

namespace Demo
{
    class Bar
    {
        public int Id { get; set; }
        public string Number { get; set; }
    }

    static class Program
    {
        static void Main()
        {
            for (int trial = 1; trial <= 5; ++trial)
            {
                Console.WriteLine("Trial " + trial);
                PropertiesGetterStringWithoutThenWithReflection();
                PropertiesGetterStringWithThenWithoutReflection();
            }
        }

        public static void PropertiesGetterStringWithoutThenWithReflection()
        {
            Console.WriteLine("PropertiesGetterStringWithoutThenWithReflection()");

            int count = 100000;

            var bar = new Bar
            {
                Id = 42,
                Number = "42",
            };

            var props = bar.GetType().GetProperties();
            string concat1 = "";
            string concat2 = "";

            Stopwatch sw = new Stopwatch();
            sw.Start();

            for (int i = 0; i < count; i++)
            {
                concat2 += bar.Number;
            }

            sw.Stop();
            GC.Collect();
            GC.WaitForPendingFinalizers();
            long milliseconds = sw.ElapsedMilliseconds;
            sw.Restart();

            for (int i = 0; i < count; i++)
            {
                concat1 += (string)props[1].GetValue(bar);
            }

            sw.Stop();
            GC.Collect();
            GC.WaitForPendingFinalizers();
            long millisecondsReflection = sw.ElapsedMilliseconds;

            Console.WriteLine("Without reflection: " + milliseconds);
            Console.WriteLine("With reflection: " + millisecondsReflection);
        }

        public static void PropertiesGetterStringWithThenWithoutReflection()
        {
            Console.WriteLine("PropertiesGetterStringWithThenWithoutReflection()");

            int count = 100000;

            var bar = new Bar
            {
                Id = 42,
                Number = "42",
            };

            var props = bar.GetType().GetProperties();
            string concat1 = "";
            string concat2 = "";

            Stopwatch sw = new Stopwatch();
            sw.Start();

            for (int i = 0; i < count; i++)
            {
                concat1 += (string)props[1].GetValue(bar);
            }

            sw.Stop();
            GC.Collect();
            GC.WaitForPendingFinalizers();
            long millisecondsReflection = sw.ElapsedMilliseconds;
            sw.Restart();

            for (int i = 0; i < count; i++)
            {
                concat2 += bar.Number;
            }

            sw.Stop();
            GC.Collect();
            GC.WaitForPendingFinalizers();
            long milliseconds = sw.ElapsedMilliseconds;

            Console.WriteLine("Without reflection: " + milliseconds);
            Console.WriteLine("With reflection: " + millisecondsReflection);
        }
    }
}

更新

我也在发布版本中重现了差异。我认为这证明了正如我所怀疑的那样，差异是由于字符串保持活动状态的时间长短所致。

这是测试代码，运行作为 RELEASE 版本：

public static void PropertiesGetterString()
{
    int count = 100000;

    var bar = new Bar
    {
        Id = 42,
        Number = "42",
    };

    var props = bar.GetType().GetProperties();
    string concat1 = "";
    string concat2 = "";

    Stopwatch sw = new Stopwatch();
    sw.Start();

    for (int i = 0; i < count; i++)
    {
        concat1 += (string)props[1].GetValue(bar);
    }

    sw.Stop();
    GC.Collect();
    GC.WaitForPendingFinalizers();
    long millisecondsReflection = sw.ElapsedMilliseconds;
    sw.Restart();

    for (int i = 0; i < count; i++)
    {
        concat2 += bar.Number;
    }

    sw.Stop();
    GC.Collect();
    GC.WaitForPendingFinalizers();
    long milliseconds = sw.ElapsedMilliseconds;

    Console.WriteLine("Without reflection: " + milliseconds);
    Console.WriteLine("With reflection: " + millisecondsReflection);
    Console.WriteLine(concat1.Length + concat2.Length); // Try with and without this line commented out.
}

如果我按原样运行，我会得到以下结果：

Trial 1
Without reflection: 4957
With reflection: 3646
400000
Trial 2
Without reflection: 4941
With reflection: 3626
400000
Trial 3
Without reflection: 4969
With reflection: 3609
400000
Trial 4
Without reflection: 5021
With reflection: 3690
400000
Trial 5
Without reflection: 4769
With reflection: 3637
400000

注意第一个循环（有反射）比第二个（没有反射）更快。

现在注释掉该方法的最后一行（输出两个字符串长度的行）并再次运行。这次的结果是：

Trial 1
Without reflection: 3558
With reflection: 3690
Trial 2
Without reflection: 3653
With reflection: 3624
Trial 3
Without reflection: 3606
With reflection: 3663
Trial 4
Without reflection: 3592
With reflection: 3660
Trial 5
Without reflection: 3629
With reflection: 3644

我认为，这证明调试构建时间和发布构建时间之间的差异是由于调试构建使所有局部变量保持活动状态直到方法结束（以便它们可以显示在调试器，即使您已经跳过了方法中最后一次使用它们）。

相比之下，发布版本可以在最后一次在方法中使用引用后的任何时间对其进行 GC。

将属性值连接到字符串时的 C# 反射 "strange" 基准

C# Reflection "strange" benchmarks when concatenating property values to a string

c#

reflection

benchmarking

将 属性 值连接到字符串时的 C# 反射 "strange" 基准

C# Reflection "strange" benchmarks when concatenating property values to a string

c#

reflection

benchmarking

将属性值连接到字符串时的 C# 反射 "strange" 基准