We ran into an interesting problem at work the other day. A unit test was always passing locally, but failing on the build server. Here’s a minimal reproduction of the code involved, so we can take a look at what went wrong.
The (relevant bits of the) class that was being tested looked something like this:
public class Foo
{
private static readonly ConcurrentDictionary<int, Foo> _map
= new ConcurrentDictionary<int, Foo>();
public Foo(int id)
{
Trace.WriteLine($"Constructed Foo, Id = {id}");
if (!_map.TryAdd(id, this))
{
throw new ArgumentException($"Id {id} is already registered.");
}
}
}
It kept a static dictionary of constructed instances of itself, and did not allow multiple instances with the same Id to be constructed. Here’s the corresponding unit test:
[TestClass]
public class FooTests
{
[TestMethod, ExpectedException(typeof(ArgumentException))]
public void Ctor_Given_Id_Already_In_Use_Should_Throw()
{
// act
var foo = new FooFake(1);
}
public class FooFake : Foo
{
static readonly Foo c1 = new FooFake(1);
static readonly Foo c2 = new FooFake(2);
static readonly Foo c3 = new FooFake(3);
public FooFake(int id)
: base(id)
{
}
}
}
I’ll admit that in isolation this looks like an odd way of testing this particular function, but that’s beside the point here. This test ran fine locally, but kept failing on the build server. We quickly realized the problem was not with the build server itself, but with the build configuration that was being used. We ran the test locally using debug builds, while the build server was using a release build. When we tried a release build locally, we were able to reproduce the test failing.
Looking at the trace output produced during the test, we could see the debug build outputting the following:
Debug Trace:
Constructed Foo, Id = 1
Constructed Foo, Id = 2
Constructed Foo, Id = 3
Constructed Foo, Id = 1
…while running the test in release mode produced this:
Debug Trace:
Constructed Foo, Id = 1
Based on this, we concluded that the unused c1, c2, and c3 variables were being optimized away in the release build. Knowing the cause, we were able to fix our test quite easily. However, out of curiosity I decided to dig a little deeper, to see what was going on under the hood. To test our hunch about compiler optimizations being the culprit, I opened the debug and release builds in dnSpy to compare their IL.
Here’s the FooFake class, debug build:
// Token: 0x02000003 RID: 3
.class nested public auto ansi beforefieldinit FooFake
extends [ConsoleApp]ConsoleApp.Foo
{
// Fields
// Token: 0x04000001 RID: 1
.field private static initonly class [ConsoleApp]ConsoleApp.Foo c1
// Token: 0x04000002 RID: 2
.field private static initonly class [ConsoleApp]ConsoleApp.Foo c2
// Token: 0x04000003 RID: 3
.field private static initonly class [ConsoleApp]ConsoleApp.Foo c3
// Methods
// Token: 0x06000003 RID: 3 RVA: 0x0000206E File Offset: 0x0000026E
.method public hidebysig specialname rtspecialname
instance void .ctor (
int32 id
) cil managed
{
// Header Size: 1 byte
// Code Size: 10 (0xA) bytes
.maxstack 8
/* 0x0000026F 02 */ IL_0000: ldarg.0
/* 0x00000270 03 */ IL_0001: ldarg.1
/* 0x00000271 281300000A */ IL_0002: call instance void [ConsoleApp]ConsoleApp.Foo::.ctor(int32)
/* 0x00000276 00 */ IL_0007: nop
/* 0x00000277 00 */ IL_0008: nop
/* 0x00000278 2A */ IL_0009: ret
} // end of method FooFake::.ctor
// Token: 0x06000004 RID: 4 RVA: 0x00002079 File Offset: 0x00000279
.method private hidebysig specialname rtspecialname static
void .cctor () cil managed
{
// Header Size: 1 byte
// Code Size: 34 (0x22) bytes
.maxstack 8
/* 0x0000027A 17 */ IL_0000: ldc.i4.1
/* 0x0000027B 7303000006 */ IL_0001: newobj instance void TestApp.FooTests/FooFake::.ctor(int32)
/* 0x00000280 8001000004 */ IL_0006: stsfld class [ConsoleApp]ConsoleApp.Foo TestApp.FooTests/FooFake::c1
/* 0x00000285 18 */ IL_000B: ldc.i4.2
/* 0x00000286 7303000006 */ IL_000C: newobj instance void TestApp.FooTests/FooFake::.ctor(int32)
/* 0x0000028B 8002000004 */ IL_0011: stsfld class [ConsoleApp]ConsoleApp.Foo TestApp.FooTests/FooFake::c2
/* 0x00000290 19 */ IL_0016: ldc.i4.3
/* 0x00000291 7303000006 */ IL_0017: newobj instance void TestApp.FooTests/FooFake::.ctor(int32)
/* 0x00000296 8003000004 */ IL_001C: stsfld class [ConsoleApp]ConsoleApp.Foo TestApp.FooTests/FooFake::c3
/* 0x0000029B 2A */ IL_0021: ret
} // end of method FooFake::.cctor
} // end of class FooFake
…and here’s the release build:
// Token: 0x02000003 RID: 3
.class nested public auto ansi beforefieldinit FooFake
extends [ConsoleApp]ConsoleApp.Foo
{
// Fields
// Token: 0x04000001 RID: 1
.field private static initonly class [ConsoleApp]ConsoleApp.Foo c1
// Token: 0x04000002 RID: 2
.field private static initonly class [ConsoleApp]ConsoleApp.Foo c2
// Token: 0x04000003 RID: 3
.field private static initonly class [ConsoleApp]ConsoleApp.Foo c3
// Methods
// Token: 0x06000003 RID: 3 RVA: 0x00002061 File Offset: 0x00000261
.method public hidebysig specialname rtspecialname
instance void .ctor (
int32 id
) cil managed
{
// Header Size: 1 byte
// Code Size: 8 (0x8) bytes
.maxstack 8
/* 0x00000262 02 */ IL_0000: ldarg.0
/* 0x00000263 03 */ IL_0001: ldarg.1
/* 0x00000264 281300000A */ IL_0002: call instance void [ConsoleApp]ConsoleApp.Foo::.ctor(int32)
/* 0x00000269 2A */ IL_0007: ret
} // end of method FooFake::.ctor
// Token: 0x06000004 RID: 4 RVA: 0x0000206A File Offset: 0x0000026A
.method private hidebysig specialname rtspecialname static
void .cctor () cil managed
{
// Header Size: 1 byte
// Code Size: 34 (0x22) bytes
.maxstack 8
/* 0x0000026B 17 */ IL_0000: ldc.i4.1
/* 0x0000026C 7303000006 */ IL_0001: newobj instance void TestApp.FooTests/FooFake::.ctor(int32)
/* 0x00000271 8001000004 */ IL_0006: stsfld class [ConsoleApp]ConsoleApp.Foo TestApp.FooTests/FooFake::c1
/* 0x00000276 18 */ IL_000B: ldc.i4.2
/* 0x00000277 7303000006 */ IL_000C: newobj instance void TestApp.FooTests/FooFake::.ctor(int32)
/* 0x0000027C 8002000004 */ IL_0011: stsfld class [ConsoleApp]ConsoleApp.Foo TestApp.FooTests/FooFake::c2
/* 0x00000281 19 */ IL_0016: ldc.i4.3
/* 0x00000282 7303000006 */ IL_0017: newobj instance void TestApp.FooTests/FooFake::.ctor(int32)
/* 0x00000287 8003000004 */ IL_001C: stsfld class [ConsoleApp]ConsoleApp.Foo TestApp.FooTests/FooFake::c3
/* 0x0000028C 2A */ IL_0021: ret
} // end of method FooFake::.cctor
} // end of class FooFake
Besides the release build removing a few nop instructions in the constructor, they are identical.
So, it’s not a compiler issue. That just leaves the runtime itself as a suspect. How about the JIT, then? We’ll place the following breakpoints in our class:
When debugging the debug build, both breakpoints are hit. We can then right-click the code and select “Go To Disassembly” to see what the JIT compiler has produced. In this case, we can clearly see that the static constructor that initializes the three Foo instances has been compiled to native code:
--- FooTests.cs ----------------------------------------------------------------
static readonly Foo c1 = new FooFake(1);
06EB3A20 push ebp
06EB3A21 mov ebp,esp
06EB3A23 push edi
06EB3A24 push esi
06EB3A25 push ebx
06EB3A26 sub esp,38h
06EB3A29 xor eax,eax
06EB3A2B mov dword ptr [ebp-3Ch],eax
06EB3A2E mov dword ptr [ebp-40h],eax
06EB3A31 mov dword ptr [ebp-44h],eax
06EB3A34 mov dword ptr [ebp-10h],eax
06EB3A37 mov dword ptr [ebp-1Ch],eax
06EB3A3A cmp dword ptr ds:[6C3A298h],0
06EB3A41 je 06EB3A48
06EB3A43 call 627E4030
06EB3A48 mov ecx,6C9B2C4h
06EB3A4D call 00C430F4
06EB3A52 mov dword ptr [ebp-3Ch],eax
06EB3A55 mov ecx,dword ptr [ebp-3Ch]
06EB3A58 mov edx,1
06EB3A5D call 06BC43C8
06EB3A62 mov eax,dword ptr [ebp-3Ch]
06EB3A65 lea edx,ds:[3B7EF88h]
06EB3A6B call 6249E6C0
static readonly Foo c2 = new FooFake(2);
06EB3A70 mov ecx,6C9B2C4h
06EB3A75 call 00C430F4
06EB3A7A mov dword ptr [ebp-40h],eax
06EB3A7D mov ecx,dword ptr [ebp-40h]
06EB3A80 mov edx,2
06EB3A85 call 06BC43C8
06EB3A8A mov eax,dword ptr [ebp-40h]
06EB3A8D lea edx,ds:[3B7EF8Ch]
06EB3A93 call 6249E6C0
static readonly Foo c3 = new FooFake(3);
06EB3A98 mov ecx,6C9B2C4h
06EB3A9D call 00C430F4
06EB3AA2 mov dword ptr [ebp-44h],eax
06EB3AA5 mov ecx,dword ptr [ebp-44h]
06EB3AA8 mov edx,3
06EB3AAD call 06BC43C8
06EB3AB2 mov eax,dword ptr [ebp-44h]
06EB3AB5 lea edx,ds:[3B7EF90h]
06EB3ABB call 6249E6C0
06EB3AC0 nop
06EB3AC1 lea esp,[ebp-0Ch]
06EB3AC4 pop ebx
06EB3AC5 pop esi
06EB3AC6 pop edi
06EB3AC7 pop ebp
06EB3AC8 ret
--- No source file -------------------------------------------------------------
06EB3AC9 add byte ptr [eax],al
06EB3ACB add byte ptr [eax],al
06EB3ACD add byte ptr [eax],al
06EB3ACF add ah,bh
06EB3AD1 jge 06EB3ABD
06EB3AD3 push es
06EB3AD4 add byte ptr [eax],al
06EB3AD6 add byte ptr [eax],al
06EB3AD8 les edi,fword ptr [ebp-16h]
06EB3ADB push es
06EB3ADC test al,0B2h
06EB3ADE leave
06EB3ADF push es
--- FooTests.cs ----------------------------------------------------------------
: base(id)
06EB3AE0 push ebp
06EB3AE1 mov ebp,esp
06EB3AE3 push edi
06EB3AE4 push esi
: base(id)
06EB3AE5 push ebx
06EB3AE6 sub esp,44h
06EB3AE9 mov esi,ecx
06EB3AEB lea edi,[ebp-50h]
06EB3AEE mov ecx,11h
06EB3AF3 xor eax,eax
06EB3AF5 rep stos dword ptr es:[edi]
06EB3AF7 mov ecx,esi
06EB3AF9 xor eax,eax
06EB3AFB mov dword ptr [ebp-1Ch],eax
06EB3AFE mov dword ptr [ebp-3Ch],ecx
06EB3B01 mov dword ptr [ebp-40h],edx
06EB3B04 cmp dword ptr ds:[6C3A298h],0
06EB3B0B je 06EB3B12
06EB3B0D call 627E4030
06EB3B12 mov ecx,dword ptr [ebp-3Ch]
06EB3B15 mov edx,dword ptr [ebp-40h]
06EB3B18 call 06BC43B0
06EB3B1D nop
{
06EB3B1E nop
Trace.WriteLine($"FooFake {id}");
06EB3B1F mov ecx,614AF2DCh
06EB3B24 call 00C430F4
06EB3B29 mov dword ptr [ebp-44h],eax
06EB3B2C mov eax,dword ptr ds:[3B840FCh]
06EB3B32 mov dword ptr [ebp-4Ch],eax
06EB3B35 mov eax,dword ptr [ebp-44h]
06EB3B38 mov edx,dword ptr [ebp-40h]
06EB3B3B mov dword ptr [eax+4],edx
06EB3B3E mov eax,dword ptr [ebp-44h]
06EB3B41 mov dword ptr [ebp-50h],eax
06EB3B44 mov ecx,dword ptr [ebp-4Ch]
06EB3B47 mov edx,dword ptr [ebp-50h]
06EB3B4A call 613AE100
06EB3B4F mov dword ptr [ebp-48h],eax
06EB3B52 mov ecx,dword ptr [ebp-48h]
06EB3B55 call dword ptr ds:[6D63BFCh]
06EB3B5B nop
}
06EB3B5C nop
06EB3B5D lea esp,[ebp-0Ch]
06EB3B60 pop ebx
06EB3B61 pop esi
06EB3B62 pop edi
06EB3B63 pop ebp
06EB3B64 ret
When repeating these steps in release mode, things are a little different. To be able to debug in release mode in the first place, we’ll need to make sure the following preconditions are met:
- In our project’s build settings, debugging information has been set to “pdb-only”.
- In the debugging options, “Enable Just My Code” and “Suppress JIT optimization on module load” are unchecked.
When we now run the test, we find that the first breakpoint is not hit at all; only the second breakpoint is hit. When we try to “Go To Disassembly” on the c1, c2, or c3 lines, Visual Studio tells us that “Disassembly cannot be displayed for the source location. The expression has not yet been translated to native machine code.”
This is, of course, because those particular lines have been optimized away. If we look at the disassembly for the FooFake constructor, we see that it is still there:
--- FooTests.cs ----------------------------------------------------------------
: base(id)
06B439B0 push ebp
06B439B1 mov ebp,esp
06B439B3 push edi
06B439B4 push esi
06B439B5 sub esp,10h
06B439B8 xor eax,eax
06B439BA mov dword ptr [ebp-18h],eax
06B439BD mov dword ptr [ebp-14h],eax
06B439C0 mov dword ptr [ebp-10h],eax
06B439C3 mov dword ptr [ebp-0Ch],eax
06B439C6 mov esi,edx
06B439C8 mov edx,esi
06B439CA call dword ptr ds:[692B204h]
{
Trace.WriteLine($"FooFake {id}");
06B439D0 mov ecx,614AF2DCh
06B439D5 call 009A30F4
06B439DA mov dword ptr [eax+4],esi
06B439DD mov edx,eax
06B439DF lea edi,[ebp-18h]
06B439E2 xorps xmm0,xmm0
06B439E5 movq mmword ptr [edi],xmm0
06B439E9 movq mmword ptr [edi+8],xmm0
06B439EE lea ecx,[ebp-18h]
06B439F1 call 61BA0F50
06B439F6 lea eax,[ebp-18h]
06B439F9 push dword ptr [eax+0Ch]
06B439FC push dword ptr [eax+8]
06B439FF push dword ptr [eax+4]
06B43A02 push dword ptr [eax]
06B43A04 mov edx,dword ptr ds:[38C40FCh]
06B43A0A xor ecx,ecx
06B43A0C call 61397A00
06B43A11 mov ecx,eax
06B43A13 call dword ptr ds:[69F40E0h]
06B43A19 lea esp,[ebp-8]
06B43A1C pop esi
06B43A1D pop edi
06B43A1E pop ebp
06B43A1F ret
However, the static constructor is nowhere to be found. The most likely explanation is that the JIT, as part of the various optimizations it performs in release configuration, has detected that the c1, c2, and c3 variables aren’t used anywhere in the program, and has decided to remove them.
Okay, this all makes sense so far. But here’s where things get a little funny. Because what happens if we change our class to the following:
public class FooFake : Foo
{
static readonly Foo c1;
static readonly Foo c2;
static readonly Foo c3;
static FooFake()
{
c1 = new FooFake(1);
c2 = new FooFake(2);
c3 = new FooFake(3);
}
public FooFake(int id)
: base(id)
{
}
}
We now explicitly initialize the variables from the static constructor.
And again, here’s the IL that gets produced in debug mode:
// Token: 0x02000003 RID: 3
.class nested public auto ansi FooFake
extends [ConsoleApp]ConsoleApp.Foo
{
// Fields
// Token: 0x04000001 RID: 1
.field private static initonly class [ConsoleApp]ConsoleApp.Foo c1
// Token: 0x04000002 RID: 2
.field private static initonly class [ConsoleApp]ConsoleApp.Foo c2
// Token: 0x04000003 RID: 3
.field private static initonly class [ConsoleApp]ConsoleApp.Foo c3
// Methods
// Token: 0x06000003 RID: 3 RVA: 0x0000206E File Offset: 0x0000026E
.method private hidebysig specialname rtspecialname static
void .cctor () cil managed
{
// Header Size: 1 byte
// Code Size: 35 (0x23) bytes
.maxstack 8
/* 0x0000026F 00 */ IL_0000: nop
/* 0x00000270 17 */ IL_0001: ldc.i4.1
/* 0x00000271 7304000006 */ IL_0002: newobj instance void TestApp.FooTests/FooFake::.ctor(int32)
/* 0x00000276 8001000004 */ IL_0007: stsfld class [ConsoleApp]ConsoleApp.Foo TestApp.FooTests/FooFake::c1
/* 0x0000027B 18 */ IL_000C: ldc.i4.2
/* 0x0000027C 7304000006 */ IL_000D: newobj instance void TestApp.FooTests/FooFake::.ctor(int32)
/* 0x00000281 8002000004 */ IL_0012: stsfld class [ConsoleApp]ConsoleApp.Foo TestApp.FooTests/FooFake::c2
/* 0x00000286 19 */ IL_0017: ldc.i4.3
/* 0x00000287 7304000006 */ IL_0018: newobj instance void TestApp.FooTests/FooFake::.ctor(int32)
/* 0x0000028C 8003000004 */ IL_001D: stsfld class [ConsoleApp]ConsoleApp.Foo TestApp.FooTests/FooFake::c3
/* 0x00000291 2A */ IL_0022: ret
} // end of method FooFake::.cctor
// Token: 0x06000004 RID: 4 RVA: 0x00002092 File Offset: 0x00000292
.method public hidebysig specialname rtspecialname
instance void .ctor (
int32 id
) cil managed
{
// Header Size: 1 byte
// Code Size: 10 (0xA) bytes
.maxstack 8
/* 0x00000293 02 */ IL_0000: ldarg.0
/* 0x00000294 03 */ IL_0001: ldarg.1
/* 0x00000295 281300000A */ IL_0002: call instance void [ConsoleApp]ConsoleApp.Foo::.ctor(int32)
/* 0x0000029A 00 */ IL_0007: nop
/* 0x0000029B 00 */ IL_0008: nop
/* 0x0000029C 2A */ IL_0009: ret
} // end of method FooFake::.ctor
} // end of class FooFake
…and release mode:
// Token: 0x02000003 RID: 3
.class nested public auto ansi FooFake
extends [ConsoleApp]ConsoleApp.Foo
{
// Fields
// Token: 0x04000001 RID: 1
.field private static initonly class [ConsoleApp]ConsoleApp.Foo c1
// Token: 0x04000002 RID: 2
.field private static initonly class [ConsoleApp]ConsoleApp.Foo c2
// Token: 0x04000003 RID: 3
.field private static initonly class [ConsoleApp]ConsoleApp.Foo c3
// Methods
// Token: 0x06000003 RID: 3 RVA: 0x00002061 File Offset: 0x00000261
.method private hidebysig specialname rtspecialname static
void .cctor () cil managed
{
// Header Size: 1 byte
// Code Size: 34 (0x22) bytes
.maxstack 8
/* 0x00000262 17 */ IL_0000: ldc.i4.1
/* 0x00000263 7304000006 */ IL_0001: newobj instance void TestApp.FooTests/FooFake::.ctor(int32)
/* 0x00000268 8001000004 */ IL_0006: stsfld class [ConsoleApp]ConsoleApp.Foo TestApp.FooTests/FooFake::c1
/* 0x0000026D 18 */ IL_000B: ldc.i4.2
/* 0x0000026E 7304000006 */ IL_000C: newobj instance void TestApp.FooTests/FooFake::.ctor(int32)
/* 0x00000273 8002000004 */ IL_0011: stsfld class [ConsoleApp]ConsoleApp.Foo TestApp.FooTests/FooFake::c2
/* 0x00000278 19 */ IL_0016: ldc.i4.3
/* 0x00000279 7304000006 */ IL_0017: newobj instance void TestApp.FooTests/FooFake::.ctor(int32)
/* 0x0000027E 8003000004 */ IL_001C: stsfld class [ConsoleApp]ConsoleApp.Foo TestApp.FooTests/FooFake::c3
/* 0x00000283 2A */ IL_0021: ret
} // end of method FooFake::.cctor
// Token: 0x06000004 RID: 4 RVA: 0x00002084 File Offset: 0x00000284
.method public hidebysig specialname rtspecialname
instance void .ctor (
int32 id
) cil managed
{
// Header Size: 1 byte
// Code Size: 8 (0x8) bytes
.maxstack 8
/* 0x00000285 02 */ IL_0000: ldarg.0
/* 0x00000286 03 */ IL_0001: ldarg.1
/* 0x00000287 281300000A */ IL_0002: call instance void [ConsoleApp]ConsoleApp.Foo::.ctor(int32)
/* 0x0000028C 2A */ IL_0007: ret
} // end of method FooFake::.ctor
} // end of class FooFake
Aside from the constructors being in a different order for some reason, they seem to be pretty much the same. So this shouldn’t make a difference, right?
Except that it does, and our test is now also green in release mode. If we place a breakpoint in the static constructor and debug the release build, it will get hit. How about that, huh?
I actually don’t have a proper explanation for this (I simply don’t know enough about the .NET compiler internals to speak with any authority on it), but I can take a guess. The only relevant difference between the first versions of the IL and the second set, is the absence of the beforefieldinit keyword in the latter. I know that this keyword influences when the type initializer gets called, and that having it present means the initializer gets called before the first reference to a static field. Since there are no references to the c1, c2, and c3 fields, the type initializer won’t ever have to be called, and can be optimized away. I think. In the latter case, having the beforefieldinit modifier not present means the type initializer gets called before the first reference to any static or instance field or before the first call to any static, virtual, or instance method of this type. Since we do have one of those (assuming the constructor counts), the type initializer would have to be called, and can’t be optimized away. I think. Again.
So even though I previously thought that the first and second versions of the FooFake class would be identical, it turns out they aren’t. It would explain why our unit test fails in release mode, but it doesn’t explain why the test passes in debug mode. If I understand things correctly (and I’m not sure that I do), the beforefieldinit modifier only guarantees that the type initializer gets called before the first reference to any static field, but other than that it’s completely nondeterministic. So the fact that it gets called before the unit test calls the constructor is just lucky, I guess.
This has been an interesting deep dive, but I’ll have to leave it at this for now. I’ll have to read up on this subject some more.