One Line or Two Lines?

[Pradeep1210]

Just like the popular view, I thought lesser code means better performance.

I tested:

value = CType(object, ObjectType).Property

against

Dim obj As ObjectType = CType(object, ObjectType)
value = obj.Property

The first method doesn't need an intermediate variable in between to store my object. This should also put less burden on the garbage collector as there is no variable. The 2nd way has an intermediate variable required in memory. So I thought it must be faster using the first way rather than the second way. But test results shows just the opposite here.

Private Sub Button1_Click(ByVal sender As System.Object, ByVal e As System.EventArgs) Handles Button1.Click
    Dim sw As New Stopwatch, senderName As String
 
    For i As Integer = 1 To 5
        sw.Reset() : sw.Start()
        For j As Integer = 1 To 100000000
            senderName = CType(sender, Button).Name
        Next
        sw.Stop()
        Debug.Print("One Line : " & sw.ElapsedMilliseconds)
 
        sw.Reset() : sw.Start()
        For j As Integer = 1 To 100000000
            Dim btn As Button = CType(sender, Button)
            senderName = btn.Name
        Next
        sw.Stop()
        Debug.Print("Two Lines: " & sw.ElapsedMilliseconds)
    Next
End Sub

This is the result:

One Line : 3786
Two Lines: 3677
One Line : 3787
Two Lines: 3683
One Line : 3787
Two Lines: 3677
One Line : 3790
Two Lines: 3678
One Line : 3783
Two Lines: 3677

Anyone know why this happens? Is the CLR doing some smart optimizations?

Pradeep

[Shaggy Hiker]

Time to fire up ILDASM and look at the IL generated. For that reason alone, I prefer to put my two tests into two separate methods, so that you can bring up the IL for both functions in two different windows, align them side by side, and see exactly which lines are different.

I suspect that if you do that you will find that in the second case, the btn variable is created once when the function is entered. Despite the fact that it is declared within the loop, and has no scope outside of the loop, I think that is handled by the compiler, and the declaration in IL will be once at the top of the method.

You might find that in the first case, a button object is created each time through the loop. Not at all sure about this, though, which is why it is time for ILDASM.

[Shaggy Hiker]

Nevermind. I love this type of thing, so I modified your code and put it into my test project. Here are the two tests:

    Private Sub test1(ByVal arg As Object)
        Dim rating As Integer = 7
        Dim n As Long = 0
        Dim x As Integer

        For x = 0 To 4000000
            n += CType(arg, TestCase1).No
        Next


    End Sub

    Private Sub test2(ByVal arg As Object)
        Dim rating As Integer = 3
        Dim n As Long = 0
        Dim x As Integer
        Dim setI As TestCase1

        For x = 0 To 4000000
            setI = CType(arg, TestCase1)
            n += setI.No
        Next

    End Sub

Some of the declarations are just leftover junk. TestCase1 is just a little class I whipped up with a property that returns an integer. The class is created, then passed to each method in this order: Test1, Test2, Test2, Test1.

My results confirmed yours. Test2 was faster each time. I then followed my own suggestion and looked at the two side by side in ILDASM. There were definitely differences, but all the key items were in each one. The total number of lines of IL for the loop in Test1 was LESS than the total number of lines of IL in Test2 by two lines (since the object was stored, then loaded, in Test2), yet Test1 was slower than Test2.

Therefore, I see no reason why this should be true.

[MaximilianMayrhofer]

A brilliant, and ultimately pointless conclusion. Perhaps if we step below ILDASM to the assembly code generated for each?

[mendhak]

Rather than recreate a test by myself, can you show me the IL for the two cases?

[MaximilianMayrhofer]

I still think that the most information will come from examination of the assembly code. For all we know, the second method while generating more ILDASM code actually results in a more efficient memory structure, reducing the time taken for data to be shuffled in and out of the register.

[dbasnett]

have i ever mentioned how much i hate line numbers!

Public Class Form1
    Private Sub Button2_Click(ByVal sender As System.Object, ByVal e As System.EventArgs) Handles Button2.Click
        Dim sw As New Stopwatch, senderName As String
        Const loops As Integer = 100000000
        Debug.WriteLine(DateTime.Now.ToString)
        For i As Integer = 1 To 5
            sw.Reset() : sw.Start()
            For j As Integer = 1 To loops
                senderName = DirectCast(sender, Button).Name
            Next
            sw.Stop()
            Debug.Print("One Line : " & sw.ElapsedMilliseconds)


            sw.Reset() : sw.Start()
            For j As Integer = 1 To loops
                Dim btn As Button = DirectCast(sender, Button)
                senderName = btn.Name
            Next
            sw.Stop()
            Debug.Print("Two Lines: " & sw.ElapsedMilliseconds)
        Next
    End Sub
    'we can see who has the faster processor
    '2/15/2009 11:15:49 AM
    'One Line : 6108
    'Two Lines: 6267
    'One Line : 6064
    'Two Lines: 6264
    'One Line : 6048
    'Two Lines: 6277
    'One Line : 6138
    'Two Lines: 6243
    'One Line : 6064
    'Two Lines: 6324
End Class

[dbasnett]

i think that with loops that long i would have to call the results even. a lot goes on in the PC in seconds.

[dbasnett]

Public Class Form1
    Private Sub Button2_Click(ByVal sender As System.Object, ByVal e As System.EventArgs) Handles Button2.Click
        Dim sw As New Stopwatch, senderName As String
        Const loops As Integer = 1000
        Dim oneLine As Long
        Debug.WriteLine(DateTime.Now.ToString)
        For i As Integer = 1 To 5
            sw.Reset() : sw.Start()
            For j As Integer = 1 To loops
                senderName = DirectCast(sender, Button).Name
            Next
            sw.Stop()
            oneLine = sw.ElapsedTicks
            Debug.WriteLine("One Line : " & sw.ElapsedTicks)


            sw.Reset() : sw.Start()
            For j As Integer = 1 To loops
                Dim btn As Button = DirectCast(sender, Button)
                senderName = btn.Name
            Next
            sw.Stop()
            Debug.Write("Two Lines: " & sw.ElapsedTicks & " ")
            Debug.WriteLine((sw.ElapsedTicks - oneLine).ToString)
        Next
    End Sub
    'we can see who has the faster processor
    '2/15/2009 11:28:38 AM
    'One Line : 312
    'Two Lines: 284 -28
    'One Line : 313
    'Two Lines: 285 -28
    'One Line : 313
    'Two Lines: 314 1
    'One Line : 278
    'Two Lines: 311 33
    'One Line : 278
    'Two Lines: 315 37
End Class

[mendhak]

Never mind, I got the itch too. So I got this

Two lines

  IL_0060:  callvirt   instance void [System]System.Diagnostics.Stopwatch::Start()
  IL_0065:  nop
  IL_0066:  ldc.i4.1
  IL_0067:  stloc.s    V_5
  IL_0069:  ldarg.1
  IL_006a:  castclass  [System.Windows.Forms]System.Windows.Forms.Button
  IL_006f:  stloc.s    btn
  IL_0071:  ldloc.s    btn
  IL_0073:  callvirt   instance string [System.Windows.Forms]System.Windows.Forms.Control::get_Name()
  IL_0078:  stloc.0
  IL_0079:  nop
  IL_007a:  ldloc.s    V_5
  IL_007c:  ldc.i4.1
  IL_007d:  add.ovf
  IL_007e:  stloc.s    V_5
  IL_0080:  ldloc.s    V_5
  IL_0082:  ldc.i4     0x5f5e100
  IL_0087:  stloc.s    VB$CG$t_i4$S0
  IL_0089:  ldloc.s    VB$CG$t_i4$S0
  IL_008b:  ble.s      IL_0069
  IL_008d:  ldloc.1
  IL_008e:  callvirt   instance void [System]System.Diagnostics.Stopwatch::Stop()

One line

  IL_0060:  callvirt   instance void [System]System.Diagnostics.Stopwatch::Start()
  IL_0065:  nop
  IL_0066:  ldc.i4.1
  IL_0067:  stloc.s    V_5
  IL_0069:  ldarg.1
  IL_006a:  castclass  [System.Windows.Forms]System.Windows.Forms.Button
  IL_006f:  stloc.s    btn
  IL_0071:  ldloc.s    btn
  IL_0073:  callvirt   instance string [System.Windows.Forms]System.Windows.Forms.Control::get_Name()
  IL_0078:  stloc.0
  IL_0079:  nop
  IL_007a:  ldloc.s    V_5
  IL_007c:  ldc.i4.1
  IL_007d:  add.ovf
  IL_007e:  stloc.s    V_5
  IL_0080:  ldloc.s    V_5
  IL_0082:  ldc.i4     0x5f5e100
  IL_0087:  stloc.s    VB$CG$t_i4$S0
  IL_0089:  ldloc.s    VB$CG$t_i4$S0
  IL_008b:  ble.s      IL_0069
  IL_008d:  ldloc.1
  IL_008e:  callvirt   instance void [System]System.Diagnostics.Stopwatch::Stop()

They have a difference of two lines between them where 'btn' is stored on the stack and loaded from the stack. It appears that the V_5 may be the key here. Because in the two line method you've declared a variable, it can be loaded onto a stack using stloc.0, stloc.1 and so on.

But in the one line method, there's an implicit conversion and a need to hold it in a variable, which is why it declares a virtual label using stloc.s.

The difference between stloc.x and stloc.s and ldloc.x and ldloc.s is not entirely clear to me but it appears that there is a bit of overhead involved in the pushing and popping of the stack as the variables are moved and cast in the *.s IL methods.

Note that I simply copy pasted the code in #1, so I haven't bothered with optimization if any.

[Shaggy Hiker]

I disagree. Here is the output from the code I posted:

Single line (Test1())

.method private instance void test1(object arg) cil managed
{
// Code size 40 (0x28)
.maxstack 2
.locals init ([0] int64 n,
[1] int32 rating,
[2] int32 x,
[3] int32 VB$CG$t_i4$S0)
.language '{3A12D0B8-C26C-11D0-B442-00A0244A1DD2}', '{994B45C4-E6E9-11D2-903F-00C04FA302A1}', '{5A869D0B-6611-11D3-BD2A-0000F80849BD}'
// Source File 'C:\Documents and Settings\charrington\My Documents\Visual Studio 2005\Projects\TestApp\TestApp\Form1.vb'
//000066: Private Sub test1(ByVal arg As Object)
IL_0000: nop
//000067: Dim rating As Integer = 7
IL_0001: ldc.i4.7
IL_0002: stloc.1
//000068: Dim n As Long = 0
IL_0003: ldc.i4.0
IL_0004: conv.i8
IL_0005: stloc.0
//000069: Dim x As Integer
//000070:
//000071: For x = 0 To 4000000
IL_0006: ldc.i4.0
IL_0007: stloc.2
//000072: n += CType(arg, TestCase1).No
IL_0008: ldloc.0
IL_0009: ldarg.1
IL_000a: castclass TestApp.TestCase1
IL_000f: callvirt instance int32 TestApp.TestCase1::get_No()
IL_0014: conv.i8
IL_0015: add
IL_0016: stloc.0
//000073: Next
IL_0017: nop
IL_0018: ldloc.2
IL_0019: ldc.i4.1
IL_001a: add
IL_001b: stloc.2
IL_001c: ldloc.2
IL_001d: ldc.i4 0x3d0900
IL_0022: stloc.3
IL_0023: ldloc.3
IL_0024: ble.s IL_0008
//000074:
//000075:
//000076: End Sub
IL_0026: nop
IL_0027: ret
} // end of method Form1::test1

Two lines (intermediate object) Test2

.method private instance void test2(object arg) cil managed
{
// Code size 44 (0x2c)
.maxstack 2
.locals init ([0] int64 n,
[1] int32 rating,
[2] class TestApp.TestCase1 setI,
[3] int32 x,
[4] int32 VB$CG$t_i4$S0)
.language '{3A12D0B8-C26C-11D0-B442-00A0244A1DD2}', '{994B45C4-E6E9-11D2-903F-00C04FA302A1}', '{5A869D0B-6611-11D3-BD2A-0000F80849BD}'
// Source File 'C:\Documents and Settings\charrington\My Documents\Visual Studio 2005\Projects\TestApp\TestApp\Form1.vb'
//000078: Private Sub test2(ByVal arg As Object)
IL_0000: nop
//000079: Dim rating As Integer = 3
IL_0001: ldc.i4.3
IL_0002: stloc.1
//000080: Dim n As Long = 0
IL_0003: ldc.i4.0
IL_0004: conv.i8
IL_0005: stloc.0
//000081: Dim x As Integer
//000082: Dim setI As TestCase1
//000083:
//000084: For x = 0 To 4000000
IL_0006: ldc.i4.0
IL_0007: stloc.3
//000085: setI = CType(arg, TestCase1)
IL_0008: ldarg.1
IL_0009: castclass TestApp.TestCase1
IL_000e: stloc.2
//000086: n += setI.No
IL_000f: ldloc.0
IL_0010: ldloc.2
IL_0011: callvirt instance int32 TestApp.TestCase1::get_No()
IL_0016: conv.i8
IL_0017: add
IL_0018: stloc.0
//000087: Next
IL_0019: nop
IL_001a: ldloc.3
IL_001b: ldc.i4.1
IL_001c: add
IL_001d: stloc.3
IL_001e: ldloc.3
IL_001f: ldc.i4 0x3d0900
IL_0024: stloc.s VB$CG$t_i4$S0
IL_0026: ldloc.s VB$CG$t_i4$S0
IL_0028: ble.s IL_0008
//000088:
//000089: End Sub
IL_002a: nop
IL_002b: ret
} // end of method Form1::test2

My code was stripped down to the bare bones for cleanliness, and compares integers instead of objects. I included the entire IL for each sub, just for completeness, but the difference is found between the For line and the Next line (naturally). I don't have any of that stlloc.s or stlloc.x stuff, yet I got the same results.

[mendhak]

You disagree? You're not an ILDASM! Your ILDASM disagrees. You are merely a humble and lowly messenger.

Oh but that aside, I think you should re-test or re-generate your IL after moving

Dim setI As TestCase1

to inside the loop rather than having it sit outside and be reused.

[mendhak]

Hmm, after modifying SH's code, I get this output

One line: 595
One line: 594
One line: 590
One line: 593
One line: 590
Two lines: 604
Two lines: 601
Two lines: 602
Two lines: 608
Two lines: 601

[Pradeep1210]

What about my case? I couldn't get even one test that says One Line is faster than Two Lines.

This is the lastest one:

One Line : 3790
Two Lines: 3672
One Line : 3793
Two Lines: 3682
One Line : 3787
Two Lines: 3673
One Line : 3782
Two Lines: 3677
One Line : 3784
Two Lines: 3680

[mendhak]

Hands up if you think this boils down to processors rather than code...

I think we can know for sure if we all try the exact same code.

[Shaggy Hiker]

You disagree? You're not an ILDASM! Your ILDASM disagrees. You are merely a humble and lowly messenger.

Oh but that aside, I think you should re-test or re-generate your IL after moving

Dim setI As TestCase1

to inside the loop rather than having it sit outside and be reused.

Lowly I may be, but humble I am not.

I'm not on that computer anymore, and won't get back on it just to test that.

How can this be a processor issue when all three of us got the same results? In all tests of one line vs two lines, two lines is always faster. The actual amounts vary due to the number of loops and processor speed, but the relative performance remains the same.

EDIT: Oops, misread what the frog posted. Ok, so Pradeep and I get the same results, and Mendhak is the exception that proves the rule.

Darn, maybe I WILL have to re-start that computer....but not for a few hours. Off to other things, for now.

[dbasnett]

What about my case? I couldn't get even one test that says One Line is faster than Two Lines.

This is the lastest one:

One Line : 3790
Two Lines: 3672
One Line : 3793
Two Lines: 3682
One Line : 3787
Two Lines: 3673
One Line : 3782
Two Lines: 3677
One Line : 3784
Two Lines: 3680

3 seconds on a PC is forever, so a .1 second difference is nothing really.

switch the running order and see if you get different results.

in your OP you said "Just like the popular view, I thought lesser code means better performance. " another adage is that 10% of the code accounts for 90% of the CPU usage.

[ntg]

I got itchy as well. My test code:

Module Module1
 
    Const LOOPS As Integer = 200000000
 
    Sub Main()
 
        TestWithoutCast()
        TestWithExplicitCast()
        TestWithoutCast()
        TestWithExplicitCast()
        Console.ReadLine()
 
    End Sub
 
    Private Sub TestWithExplicitCast()
 
        Dim sw As New Stopwatch
        sw.Start()
 
        For i As Integer = 1 To LOOPS
            Dim objTest As New test
            Dim obj As Object = objTest
 
            Dim otherObj As test = CType(obj, test)
            Dim val As Integer = otherObj.val
        Next
 
        Console.WriteLine(sw.ElapsedMilliseconds.ToString + " <<< With explicit cast")
    End Sub
 
    Private Sub TestWithoutCast()
 
        Dim sw As New Stopwatch
        sw.Start()
 
        For i As Integer = 1 To LOOPS
            Dim objTest As New test
            Dim obj As Object = objTest
 
            Dim val As Integer = CType(obj, test).val
        Next
 
        Console.WriteLine(sw.ElapsedMilliseconds.ToString + " <<< Without cast")
 
    End Sub
 
    Private Class test
        Public val As Integer = 1
    End Class
 
End Module

The reason I'm calling the tests twice is to have any JIT time cancelled out during the second run and I'm glad I put it there. IL code for the test methods:

.method private static void  TestWithExplicitCast() cil managed
{
  // Code size       82 (0x52)
  .maxstack  2
  .locals init ([0] class [System]System.Diagnostics.Stopwatch sw,
           [1] int32 i,
           [2] object obj,
           [3] class ConsoleApplication1.Module1/test objTest,
           [4] class ConsoleApplication1.Module1/test otherObj,
           [5] int32 val,
           [6] int64 VB$t_i8$S0)
  IL_0000:  newobj     instance void [System]System.Diagnostics.Stopwatch::.ctor()
  IL_0005:  stloc.0
  IL_0006:  ldloc.0
  IL_0007:  callvirt   instance void [System]System.Diagnostics.Stopwatch::Start()
  IL_000c:  ldc.i4.1
  IL_000d:  stloc.1
  IL_000e:  newobj     instance void ConsoleApplication1.Module1/test::.ctor()
  IL_0013:  stloc.3
  IL_0014:  ldloc.3
  IL_0015:  stloc.2
  IL_0016:  ldloc.2
  IL_0017:  castclass  ConsoleApplication1.Module1/test
  IL_001c:  stloc.s    otherObj
  IL_001e:  ldloc.s    otherObj
  IL_0020:  ldfld      int32 ConsoleApplication1.Module1/test::val
  IL_0025:  stloc.s    val
  IL_0027:  ldloc.1
  IL_0028:  ldc.i4.1
  IL_0029:  add.ovf
  IL_002a:  stloc.1
  IL_002b:  ldloc.1
  IL_002c:  ldc.i4     0xbebc200
  IL_0031:  ble.s      IL_000e
  IL_0033:  ldloc.0
  IL_0034:  callvirt   instance int64 [System]System.Diagnostics.Stopwatch::get_ElapsedMilliseconds()
  IL_0039:  stloc.s    VB$t_i8$S0
  IL_003b:  ldloca.s   VB$t_i8$S0
  IL_003d:  call       instance string [mscorlib]System.Int64::ToString()
  IL_0042:  ldstr      " <<< With explicit cast"
  IL_0047:  call       string [mscorlib]System.String::Concat(string,
                                                              string)
  IL_004c:  call       void [mscorlib]System.Console::WriteLine(string)
  IL_0051:  ret
} // end of method Module1::TestWithExplicitCast

.method private static void  TestWithoutCast() cil managed
{
  // Code size       78 (0x4e)
  .maxstack  2
  .locals init ([0] class [System]System.Diagnostics.Stopwatch sw,
           [1] int32 i,
           [2] object obj,
           [3] class ConsoleApplication1.Module1/test objTest,
           [4] int32 val,
           [5] int64 VB$t_i8$S0)
  IL_0000:  newobj     instance void [System]System.Diagnostics.Stopwatch::.ctor()
  IL_0005:  stloc.0
  IL_0006:  ldloc.0
  IL_0007:  callvirt   instance void [System]System.Diagnostics.Stopwatch::Start()
  IL_000c:  ldc.i4.1
  IL_000d:  stloc.1
  IL_000e:  newobj     instance void ConsoleApplication1.Module1/test::.ctor()
  IL_0013:  stloc.3
  IL_0014:  ldloc.3
  IL_0015:  stloc.2
  IL_0016:  ldloc.2
  IL_0017:  castclass  ConsoleApplication1.Module1/test
  IL_001c:  ldfld      int32 ConsoleApplication1.Module1/test::val
  IL_0021:  stloc.s    val
  IL_0023:  ldloc.1
  IL_0024:  ldc.i4.1
  IL_0025:  add.ovf
  IL_0026:  stloc.1
  IL_0027:  ldloc.1
  IL_0028:  ldc.i4     0xbebc200
  IL_002d:  ble.s      IL_000e
  IL_002f:  ldloc.0
  IL_0030:  callvirt   instance int64 [System]System.Diagnostics.Stopwatch::get_ElapsedMilliseconds()
  IL_0035:  stloc.s    VB$t_i8$S0
  IL_0037:  ldloca.s   VB$t_i8$S0
  IL_0039:  call       instance string [mscorlib]System.Int64::ToString()
  IL_003e:  ldstr      " <<< Without cast"
  IL_0043:  call       string [mscorlib]System.String::Concat(string,
                                                              string)
  IL_0048:  call       void [mscorlib]System.Console::WriteLine(string)
  IL_004d:  ret
} // end of method Module1::TestWithoutCast

After looking at the IL, the declaration and use of otherObj (created and loaded from the stack) seems to be the only difference.

Build in release mode with optimizations enabled. Results from within the IDE:
3015 <<< Without cast
3112 <<< With explicit cast
3023 <<< Without cast
3100 <<< With explicit cast

Results from the command line:
1254 <<< Without cast
1199 <<< With explicit cast
1129 <<< Without cast
1199 <<< With explicit cast

Note that when run from the command line the first test without cast is slower than the first test with the cast. This is because the code gets JITted behind the scenes and that time affects the test. In the second run of both tests, the results are what one would expect. BTW, I think that the declaration or not of an intermediate variable does not really help GC - it can routinely spot things like that otherwise there would be lots of crying .Net developers out there.

Interestingly enough, when I disable optimizations I get the VB$CG$t_i4$S0 variable in my IL, just like mendhak and Shaggy.

[Shaggy Hiker]

OK, I moved the declaration inside the loop, so that my code for Test2 looks like this:

Private Sub test2(ByVal arg As Object)
        Dim rating As Integer = 3
        Dim n As Long = 0
        Dim x As Integer

        For x = 0 To 4000000
            Dim setI As TestCase1
            setI = CType(arg, TestCase1)
            n += setI.No
        Next

    End Sub

I also moved the whole thing to a different computer. The timing is different on the two computers, of course, but the relative results are the same.

The IL for the new version of Test2 is this:

.method private instance void test2(object arg) cil managed
{
// Code size 37 (0x25)
.maxstack 2
.locals init ([0] int64 n,
[1] int32 rating,
[2] int32 x,
[3] class TestApp.TestCase1 setI)
IL_0000: ldc.i4.3
IL_0001: stloc.1
IL_0002: ldc.i4.0
IL_0003: conv.i8
IL_0004: stloc.0
IL_0005: ldc.i4.0
IL_0006: stloc.2
IL_0007: ldarg.1
IL_0008: castclass TestApp.TestCase1
IL_000d: stloc.3
IL_000e: ldloc.0
IL_000f: ldloc.3
IL_0010: callvirt instance int32 TestApp.TestCase1::get_No()
IL_0015: conv.i8
IL_0016: add
IL_0017: stloc.0
IL_0018: ldloc.2
IL_0019: ldc.i4.1
IL_001a: add
IL_001b: stloc.2
IL_001c: ldloc.2
IL_001d: ldc.i4 0x3d0900
IL_0022: ble.s IL_0007
IL_0024: ret
} // end of method Form1::test2

This IL version is the release version, rather than the, easier to follow, debug version, but the result is still the same. When compared to the release version of Test1 (the code is the same as in my original post):

.method private instance void test1(object arg) cil managed
{
// Code size 35 (0x23)
.maxstack 2
.locals init ([0] int64 n,
[1] int32 rating,
[2] int32 x)
IL_0000: ldc.i4.7
IL_0001: stloc.1
IL_0002: ldc.i4.0
IL_0003: conv.i8
IL_0004: stloc.0
IL_0005: ldc.i4.0
IL_0006: stloc.2
IL_0007: ldloc.0
IL_0008: ldarg.1
IL_0009: castclass TestApp.TestCase1
IL_000e: callvirt instance int32 TestApp.TestCase1::get_No()
IL_0013: conv.i8
IL_0014: add
IL_0015: stloc.0
IL_0016: ldloc.2
IL_0017: ldc.i4.1
IL_0018: add
IL_0019: stloc.2
IL_001a: ldloc.2
IL_001b: ldc.i4 0x3d0900
IL_0020: ble.s IL_0007
IL_0022: ret
} // end of method Form1::test1

Test2 performs considerably better than Test1 in release version (~10%), and marginally better than Test1 in debug version (~2%). I didn't test the release version of the code on the first computer.

Therefore, I don't see how computer differences can account for this. There are two extra lines of IL (a store and load) in Test2 than in Test1, yet Test2 runs faster. The only way I can account for Mendhaks anomalous results are by attacking his character, which, while satisfying and politically correct, really doesn't help anything.

[Pradeep1210]

3 seconds on a PC is forever, so a .1 second difference is nothing really.

switch the running order and see if you get different results.

in your OP you said "Just like the popular view, I thought lesser code means better performance. " another adage is that 10% of the code accounts for 90% of the CPU usage.

Maybe it is a very small difference, but worth knowing why there is such a difference. It can't be due to external factors like OS doing some other background tasks during that time, since it seems to affect only one of them and not the other.
I was just interested in knowing how the two lines are always faster than the single line code, though logically single line code should have performed better as the compiler has lesser overheads involved.
How does the compiler favor 2 lines instead of the one line code even after having overheads of more instructions and memory?

Switching the order of test doesn't seem to affect the test result. 2 lines are still faster than the single line code.

[SJWhiteley]

Honestly, looking the results, no conclusion can be drawn beyond the fact that one piece of code produces different results than another.

There are many many optimizations that the compiler can perform: for example:

Dim d as double = 1

produces different assembly from:

Dim d as double = 53.4

This is a 'special' case scenario; just as casting is a special case scenario, and has nothing to do with the number of lines of code typed into the IDE. It doesn't necessarily apply in this case, but the point is that the quantity of code we write has absolutely no correlation with performance. Indeed, more lines of IDE code can result in a significant performance increase in some cases (my brush with this was going from a nice, compact routine to a horrible piece of lengthy code with many nested if/then statements).

At this point, I'd like to say that I get 'opposite' results than the OP with the OP code - opposite in that the difference number of milliseconds out of a 5 second execution time for each loop is around 100. Essentially, the execution time is the same - this is in debug mode, verses release mode.

A cursory glance at the generated (debug and release) assembly indicates that the 'two line' entry results in an additional line of assembly.

While inline code can be very useful, it doesn't necessarily tell the whole story. The underlying assembly language is probably a better indicator of performance, since you will be able to see compiler optimizations (inlining and constant substitution, for example).

Declaring a variable in a loop or outside a loop makes no difference - we can put that one to to rest, but all are welcome to prove (demonstrate?) that for themselves.

[Shaggy Hiker]

What's your point? Would you not look at this? If you found a difference, would you not wonder why? Surely you wouldn't take any difference and just pass it off as some kind of compiler optimization, nor would you find a difference and just ignore it. So what are you getting at?

[dbasnett]

the test is flawed.

if the difference is troublesome the first place to start is to explain why all of the test of a certain type aren't identical.

	One	Two	
	3786	3677	109
			
	3787	3683	104
			
	3787	3677	110
			
	3790	3678	112
			
	3783	3677	106
			
Average	3786.6	3678.4	108.2
Median	3786.8	3677.5	109.3

High	3790	3683	107
Small	3783	3677	106
StdDev	2.50998008	2.607680962
57.07743279

if the numbers were 4000 and 2000 it would be different.

[dbasnett]

        Dim stpw As New Stopwatch, i, z As Integer
        Const i1 As Integer = 1, iLoop As Integer = 500000000, tests As Integer = 5
        Dim results As New List(Of Long)
        For z = i1 To tests
            stpw.Start()
            For i = i1 To iLoop
            Next
            stpw.Stop()
            results.Add(stpw.ElapsedMilliseconds)
            stpw.Reset()
        Next
        For i = 0 To results.Count - 1
            Debug.WriteLine("'" & results(i).ToString)
        Next

        '1705
        '1632
        '1607
        '1605
        '1696

shouldn't these results be identical????????

[dbasnett]

http://www.codinghorror.com/blog/archives/001218.html

[Shaggy Hiker]

Not sure what you are getting at. Are you suggesting that the differences we are seeing are just simple variation about a mean? That's not the case for the tests I posted, as the variation I was observing within a group was dwarfed by the variation I was observing between the two groups. The confidence intervals were never even close to overlapping. For instance, I was seeing a 10% difference between the means of the two groups in the second test (with release code), while the maximum variation within the group was around 0.5%

[Shaggy Hiker]

Having read the link, which you posted while I was writing that, I would argue that, while micro optimization is not going to make much of a difference in any business code, there are still two reasons to partake:

1) You learn more about the language and how it works. Who knows how and when the knowledge will be of benefit, but the more you know, the better you will do.

2) It's fun. If you don't think so, look at the list of people in this thread who put together tests of one thing or another and cited nothing more than curiosity.

[dbasnett]

the difference in the test, using the original numbers, was within the margin of error (twice the standard deviation?).

[Shaggy Hiker]

I don't see that. In your post #23, you show the range and SD of the two groups. The SD in both cases was ~2.5, while the difference between the means was 108.2 That's 50x the SD, which is considerably larger than 2x.

This one passes the Interocular Arm-Length Test, which is the most robust statistical test in existence.

Edit: Not 50x, but 43x, which is still a big number.

[dbasnett]

the difference in each line was 100'ish and the SD of the entire set was 57.

[SJWhiteley]

What's your point? Would you not look at this? If you found a difference, would you not wonder why? Surely you wouldn't take any difference and just pass it off as some kind of compiler optimization, nor would you find a difference and just ignore it. So what are you getting at?

If you referring to my post...who said anything about 'ignoring it'? The 'point', is that the compiler does perform optimizations which you may not be aware of - is it the case in this situation? perhaps not, but you cannot dismiss that. Looking at the assembly code, it resulted in a single line of assembly code difference between the two large loops - yet two lines of IL code.

That was an attempt to explain and examine the difference, even though it doesn't explain why Pradeep got faster times for the 'two line' loop verses the 'one line' loop.

Additionally, the different results from different people demonstrate that we are examining the results from a flawed test. As dbasnett demonstrated, and raised the question, why are the results from the same loop so different?

Maybe it is a very small difference, but worth knowing why there is such a difference. It can't be due to external factors like OS doing some other background tasks during that time, since it seems to affect only one of them and not the other.
I was just interested in knowing how the two lines are always faster than the single line code, though logically single line code should have performed better as the compiler has lesser overheads involved.
How does the compiler favor 2 lines instead of the one line code even after having overheads of more instructions and memory?

I would be curious about the scalability, Pradeep: what results do you get if you run the loops for 10 times the values you have given in the original post? Does it scale and give the same relative difference?

I don't get the size of variation that you post; I posted your exact code into a new project.

[Shaggy Hiker]

the difference in each line was 100'ish and the SD of the entire set was 57.

You don't compare the SD of the entire set, but the error of each group. The question is whether an item of set A can reasonably be mistaken for an item of set B. In this case, with no overlap between the groups, that type of mistake can't be made. The two are significantly different by any test.

@SJWhiteley: Ok, I understand you now, I think. Normally, when you see a difference in performance between two minor chunks of code, you need look no further than the IL, which I mentioned in my first post in this thread. The interesting point about this particular difference is that you can't explain the difference via IL alone. While I recognize that the conversion from IL to machine code is not simplistic, and ripe for optimization, in my experience, I have never before seen a question like this that required digging deeper than the IL, so for me, it is novel.

As for the variations between runs: I didn't examine it carefully, but most people were running tests on different code, and everybody was running tests on different computers (of course). No absolute measurement, nor any single measurement, has any meaning. There are interrupts being handled by the OS at a level well below our code, and we can't predict the exact state of any particular run, which is why it is essential to run many times with very high iteration rates. The high iteration rates reduces the error in any one iteration to a negligible level (though it is not a random error, but shows a distinct bias high), while averaging multiple tests takes care of the variation between the tests as far as we care.

[SJWhiteley]

Shaggy: you are right, you wouldn't normally need to go down to assembly level. In fact, it's not often that you need to go and look at IL... You brought up a good point that something like this is rarely necessary in business code - the impact is usually minimal.

Then again, these are the sorts of things which bite us on the bum, so to speak. Although not relevant to this topic, IL code won't show when a compile in-lines a function to increase performance.

And you are right - the IL cannot give a reason for a difference, and neither can the assembly. But it hints at a much smaller difference than what the OP is seeing, and indeed, would indicate a difference in the other direction.

In any case, I suppose I'm just chucking ideas out there...code timing is actually a fickle thing. db, I think, has shown that the basis on which we are working is fundamentally flawed; in addition there isn'a a commonality between the posts with code - kind of like arguing which of us gets to work the quickest between two routes we may take (I think I'd beet all of y'all...).

[Pradeep1210]

the test is flawed.

if the difference is troublesome the first place to start is to explain why all of the test of a certain type aren't identical.

	One	Two	
	3786	3677	109
			
	3787	3683	104
			
	3787	3677	110
			
	3790	3678	112
			
	3783	3677	106
			
Average	3786.6	3678.4	108.2
Median	3786.8	3677.5	109.3

High	3790	3683	107
Small	3783	3677	106
StdDev	2.50998008	2.607680962
57.07743279

if the numbers were 4000 and 2000 it would be different.

This is OK... but why is each individual result row of 2 lines test always faster than the one line test whatever way we test. Not even one result points the opposite?
We would take statistical analysis only when the results are mixed. Isn't it? But here the speedometer always points towards 2 lines test and not once towards one line test.


Pradeep

[dbasnett]

Ctype

Start Normal
2/17/2009 8:48:28 AM
ONE  	TWO  	DIFF  
1936	2073	-137
1968	1975	-7
2002	1943	59
1938	1971	-33
1942	1954	-12
1953	1955	-2
1949	2077	-128
2008	1983	25
1978	1989	-11
1973	2005	-32
2/17/2009 8:49:07 AM


Start Highest
2/17/2009 8:47:11 AM
ONE  	TWO  	DIFF  
1836	1837	-1
1853	1839	14
1857	1847	10
1834	1848	-14
1845	1837	8
1836	1843	-7
1832	1835	-3
1833	1833	0
1836	1843	-7
1840	1832	8
2/17/2009 8:47:49 AM


DirectCast

Start Normal
2/17/2009 8:50:20 AM
ONE  	TWO  	DIFF  
1964	2112	-148
1989	2062	-73
1996	2054	-58
1968	2105	-137
2004	2031	-27
1987	2022	-35
1960	2156	-196
1992	2077	-85
2012	2029	-17
1964	2034	-70
2/17/2009 8:51:00 AM

Start Highest
2/17/2009 8:51:44 AM
ONE  	TWO  	DIFF  
1837	1847	-10
1838	1832	6
1861	1833	28
1835	1847	-12
1840	1847	-7
1835	1837	-2
1834	1831	3
1838	1838	0
1836	1847	-11
1834	1832	2
2/17/2009 8:52:21 AM

Option Strict On : Option Explicit On
Imports System.Threading
Public Class Form1
    Private Sub Form1_Shown(ByVal sender As Object, ByVal e As System.EventArgs) Handles Me.Shown
        Timer1.Interval = 1000
        Timer1.Start()
        Me.WindowState = FormWindowState.Minimized
    End Sub
    Dim t As Thread = New Thread(AddressOf test)
    Private Sub Timer1_Tick(ByVal sender As System.Object, ByVal e As System.EventArgs) Handles Timer1.Tick
        Timer1.Stop()
        t.Priority = ThreadPriority.Highest
        Debug.WriteLine("Start " & t.Priority.ToString)
        t.Start()
    End Sub
    Private Sub test()
        Dim but As New Button
        DUT(DirectCast(but, Object))
    End Sub
    Private Sub DUT(ByVal sender As System.Object)
        Dim sw As New Stopwatch, senderName As String
        Dim one, two As Long
        Const loops As Integer = 20000000
        Debug.WriteLine(DateTime.Now.ToString)
        Debug.WriteLine("ONE  " & ControlChars.Tab & "TWO  " & ControlChars.Tab & "DIFF  ")
        For i As Integer = 1 To 10
            'one
            sw.Reset() : sw.Start()
            For j As Integer = 1 To loops
                senderName = DirectCast(sender, Button).Name
            Next
            sw.Stop()
            one = sw.ElapsedMilliseconds

            'two
            sw.Reset() : sw.Start()
            For j As Integer = 1 To loops
                Dim btn As Button = DirectCast(sender, Button)
                senderName = btn.Name
            Next
            sw.Stop()
            two = sw.ElapsedMilliseconds

            Debug.WriteLine(one.ToString.PadRight(4, " "c) & ControlChars.Tab & _
                            two.ToString.PadRight(4, " "c) & ControlChars.Tab & _
                            (one - two).ToString)
        Next
        Debug.WriteLine(DateTime.Now.ToString)
    End Sub
End Class

[Pradeep1210]

...
I would be curious about the scalability, Pradeep: what results do you get if you run the loops for 10 times the values you have given in the original post? Does it scale and give the same relative difference?

I don't get the size of variation that you post; I posted your exact code into a new project.

I tried with increasing the loops to 10 times instead of 5. Here are the results:

One Line : 3812
Two Lines: 3705
One Line : 3818
Two Lines: 3702
One Line : 3807
Two Lines: 3700
One Line : 3808
Two Lines: 3700
One Line : 3809
Two Lines: 3696
One Line : 3806
Two Lines: 3699
One Line : 3811
Two Lines: 3701
One Line : 3808
Two Lines: 3703
One Line : 3810
Two Lines: 3700
One Line : 3809
Two Lines: 3698

[SJWhiteley]

I tried with increasing the loops to 10 times instead of 5. Here are the results:

I mean multiply your inner loop by 10, so you are running it for half a minute or so per loop.

Basically, if it takes 3800ms for loop 1 and 3700 for loop 2, what would be the results for 1x the number of loops. We will get:

Loop One: 38000 ms
Loop Two: 37000 ms (1 second difference)

or:

Loop One: 38000 ms
Loop Tow: 37900 ms (still a 100ms difference)

or, something else.

Personally, I don't get the same results as you at all - the results are all within 10mS or so on my PC, so don't see a problem.

Obviously, you do see a difference; the IL and assembly code would contradict your evidence, so we'd have to determine a pattern for the results to see if there's potentially another reason for the discrepancy.

[dbasnett]

i can't replicate the results that pradeep had. it is still my opinion that the experiment is flawed.

in post #24 i think i showed that.

'Start Normal
'2/17/2009 2:13:56 PM
'BaseLine
'288
'300
'293
'292
'287
'Test
'509
'497
'496
'487
'510

'Start Highest
'2/17/2009 2:14:07 PM
'BaseLine
'300
'289
'283
'284
'284
'Test
'479
'478
'475
'476
'475
Option Strict On : Option Explicit On : Option Infer Off
Imports System.Threading
Public Class Form1
    Dim stpw As New Stopwatch, i, z As Integer
    Const i1 As Integer = 1, iLoop As Integer = 50000000, tests As Integer = 5
    Dim results As New List(Of Long)
    Private Sub test()
        Debug.WriteLine("'" & DateTime.Now.ToString)
        Debug.WriteLine("'BaseLine")
        BaseLine()
        Debug.WriteLine("'Test")
        UnitTest()
    End Sub
    Private Sub BaseLine()
        results.Clear()
        For z = i1 To tests
            stpw.Start()
            For i = i1 To iLoop
                'shouldn't .ElapsedMilliseconds be the same???????
            Next
            stpw.Stop()
            results.Add(stpw.ElapsedMilliseconds)
            stpw.Reset()
        Next
        For i = 0 To results.Count - 1
            Debug.WriteLine("'" & results(i).ToString)
        Next
    End Sub
    Dim foo As Double
    Private Sub UnitTest()
        results.Clear()
        For z = i1 To tests
            stpw.Start()
            For i = i1 To iLoop
                foo = CDbl(i)
            Next
            stpw.Stop()
            results.Add(stpw.ElapsedMilliseconds)
            stpw.Reset()
        Next
        For i = 0 To results.Count - 1
            Debug.WriteLine("'" & results(i).ToString)
        Next
    End Sub
    Private Sub Timer1_Tick(ByVal sender As System.Object, ByVal e As System.EventArgs) Handles Timer1.Tick
        Dim t As Thread = New Thread(AddressOf test)
        Timer1.Stop()
        If CheckBox1.Checked Then t.Priority = ThreadPriority.Highest
        Debug.WriteLine("'Start " & t.Priority.ToString)
        t.Start()
    End Sub
    Private Sub Button1_Click(ByVal sender As System.Object, ByVal e As System.EventArgs) Handles Button1.Click
        Timer1.Interval = 1000
        If Not Timer1.Enabled Then
            Debug.WriteLine("")
            Timer1.Start()
        End If
    End Sub
End Class

[Pradeep1210]

I mean multiply your inner loop by 10, so you are running it for half a minute or so per loop.

Basically, if it takes 3800ms for loop 1 and 3700 for loop 2, what would be the results for 1x the number of loops. We will get:

Loop One: 38000 ms
Loop Two: 37000 ms (1 second difference)

or:

Loop One: 38000 ms
Loop Tow: 37900 ms (still a 100ms difference)

or, something else.

Personally, I don't get the same results as you at all - the results are all within 10mS or so on my PC, so don't see a problem.

Obviously, you do see a difference; the IL and assembly code would contradict your evidence, so we'd have to determine a pattern for the results to see if there's potentially another reason for the discrepancy.

Multiplied the inner loops by 10 (increased one zero). Here are the results now:

One Line : 36727
Two Lines: 36702
One Line : 36713
Two Lines: 36713
One Line : 36714
Two Lines: 36709
The thread 0x17c has exited with code 0 (0x0).
One Line : 36702
Two Lines: 36708
One Line : 36700
Two Lines: 36707
One Line : 36704
Two Lines: 36702
One Line : 36699
Two Lines: 36708
One Line : 36711
Two Lines: 36705
One Line : 36737
Two Lines: 36718
One Line : 36709
Two Lines: 36716

Amazingly the difference seems to be reducing instead of increasing

[MaximilianMayrhofer]

Which just means that the first one has a fixed overhead associated with it. The more loops you run, the less significant the overhead to the total time taken.