I tried to make some reflection benchmark tests, but mostly I managed to confuse myself. Can please someone explain why both tests pass?
For the first one I was expecting it to fail, but the times I got were:
millisecondsReflection - 4970 ms
milliseconds - 6935 ms
[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 figured it is something to do with the string concatenation or type conversion, so I changed it to a list append, and got the expected results, i.e. the reflection was slower.
[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);
}
Here the results were:
millisecondsReflection - 184 ms
milliseconds - 11 ms
My question is what I am missing out here?
P.S. Times taken are while in Debug Mode. As shown in the comments in Release Mode the times are very close to each other
SUMMARY
This discrepancy is being caused two things: The overhead of string concatenation, which is swamping the overhead of the reflection; and a difference in the way that debug builds handle the lifetime of locals.
The difference in times you're seeing between release and debug builds is due to the way that a debug build keeps any locals alive until the end of a method, in contrast to a release build.
This is causing the GC of the two strings in the code to behave very differently between release and debug builds.
DETAILED ANALYSIS
If you change the test code to just sum the lengths of the string properties instead, you get the expected result.
Here's my results (release build):
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
And the test code:
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);
}
}
}
Also note that I can only reproduce your original results with a debug build rather than a release build.
If I change my test code to do string concatenation as per your OP, I get these results:
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
Finally, as a further attempt to minimise the effects of background GC on the two loops, I added the following code after each call to sw.Stop():
GC.Collect();
GC.WaitForPendingFinalizers();
Which changed the results to:
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 that change, all the "with reflection" results are slower than the "without reflection" results, as you'd expect.
Finally, let's investigate the difference observed in debug mode.
It would appear that the difference is occurring because of the order of the loops. If you try one test with the reflection loop before the direct loop, you get different results from vice-versa.
Here's the results of my final test program:
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
Note that whichever loop is run first is fastest, regardless of whether it is doing reflection. This implies that the difference is some artifact of the way that the string handling is being done in the debug build.
I suspect what might be happening is that the debug build keeps the concatenated string alive for the entire method, whereas for the release build does not, which will affect the GC.
Here's the test code for the above results:
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
I've reproduced the difference in a release build too. I think this proves that as I suspected, the difference is due to how long the strings are kept alive for.
Here's the test code, to be run as a RELEASE build:
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.
}
If I run that as-is, I get the following results:
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
Note how the first loop (with reflection) is faster than the second (without reflection).
Now comment out the last line of the method (the line that is outputting the length of the two strings) and run it again. This time the results are:
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
This, I think, proves that the difference between the debug and the release build times is due to the fact that a debug build keeps alive all locals until the end of a method (so that they can be displayed in the debugger even if you've stepped past the last use of them in the method).
By contrast, a release build can GC a reference any time after its last use in a method.