C# Отражение «странных» эталонов при конкатенации значений свойств в строку

Question

Я попытался провести некоторые тесты теста отражения, но в основном мне удалось смутить себя. Может ли кто-нибудь объяснить, почему проходят оба теста?

Для первого я ожидал, что это не получится, но раз я получил, были:

millisecondsReflection - 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); 
    } 

I что это как-то связано с конкатенацией строк или преобразованием типов, поэтому я изменил его на список и получил ожидаемые результаты, т. е. отражение был медленнее.

[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); 
    } 

Здесь результаты:

millisecondsReflection - 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); 
     } 
    } 
} 

Также обратите внимание, что я могу только воспроизвести исходные результаты с отладочных, а не сборки выпуска ,

Если изменить мой тестовый код, чтобы сделать конкатенацию в соответствии с вашим О.П., я получаю эти результаты:

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 

С этим изменением все результаты «с отражением» медленнее, чем результаты «без отражения», как и следовало ожидать.

Наконец, давайте рассмотрим разницу, наблюдаемую в режиме отладки.

Похоже, что разница возникает из-за порядка циклов. Если вы попробуете один тест с циклом отражения до прямого цикла, вы получите разные результаты от наоборот.

Вот результаты моей последней тестовой программы:

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); 
     } 
    } 
} 

---

UPDATE

Я воспроизвел разницу в сборки релиза тоже. Я думаю, это доказывает, что, как я подозревал, разница объясняется тем, как долго сохраняются строки.

Вот тестовый код, который будет работать в качестве сборки выпуска:

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-ссылку в любое время после ее последнего использования в методе.