Assembly Binding Log Causing Slow Assembly Loading
Recently I was involved in troubleshooting a strange performance issue, manifesting itself in the form of long initialization time of each newly created process or AppDomain on one of the servers. Thanks to the application built-in logging functionality we quickly identified slow assembly loading as the root cause of the problem; on average each assembly took approximately 8 seconds to load.
As usually, we first checked for similar issues others might had in the past. The only one we came across was slow Authenticode signature verification due to inaccessible certificate revocation list. For several reasons this obviously wasn't happening in our case: the assemblies were not Authenticode signed and the issue does not happen in .NET 4, only in older versions.
This meant we had to gather more information about the problem. Since we couldn't directly debug a process on the production server, where the issue was happening, we had to resort to creating a memory dump during the assembly loading and analyze it with WinDbg to hopefully determine what was taking such a long time. We repeated the process several times to avoid a single random sample sending us into the wrong direction. It turned out in all of them the working thread had the same top of the stack trace:
1207ca00 73c8e47f (MethodDesc 739938f0 +0x5f
DomainNeutralILStubClass.IL_STUB_PInvoke(Char*, Int32, Char*, IntPtr))
1207ca38 73bd7aca (MethodDesc 73a2c4b0 +0xba
System.IO.PathHelper.GetFullPathName())
1207cc24 73bd23a5 (MethodDesc 73979e38 +0x65
System.String.CtorCharPtrStartLength(Char*, Int32, Int32))
1207cc54 73c53621 (MethodDesc 73979bc4 +0x51
System.String.Equals(System.String, System.String, System.StringComparison))
1207cc64 73bd77ce (MethodDesc 73984c5c +0x64e
System.IO.Path.NormalizePath(System.String, Boolean, Int32, Boolean))
1207cf04 73c4fd52 (MethodDesc 7397f394 +0x42
System.Array.CopyTo(System.Array, Int32))
1207cf28 73c4fcf4 (MethodDesc 739753c8 +0x74
System.Collections.ArrayList.InsertRange(Int32, System.Collections.ICollection))
1207cf84 73c5b4d3 (MethodDesc 7397f93c +0x23
System.Reflection.RuntimeAssembly.nLoad(System.Reflection.AssemblyName,
System.String, System.Security.Policy.Evidence,
System.Reflection.RuntimeAssembly, System.Threading.StackCrawlMark ByRef,
IntPtr, Boolean, Boolean, Boolean))
1207cfa8 73c4cf09 (MethodDesc 7397f75c +0x99
System.Reflection.RuntimeAssembly.InternalLoadAssemblyName(
System.Reflection.AssemblyName, System.Security.Policy.Evidence,
System.Reflection.RuntimeAssembly, System.Threading.StackCrawlMark ByRef,
IntPtr, Boolean, Boolean, Boolean))
1207cfe4 73bcdda3 (MethodDesc 73a28224 +0x67
System.Reflection.RuntimeAssembly.InternalLoadFrom(System.String,
System.Security.Policy.Evidence, Byte[],
System.Configuration.Assemblies.AssemblyHashAlgorithm, Boolean, Boolean,
System.Threading.StackCrawlMark ByRef))
1207d00c 742d098f (MethodDesc 73977d0c +0x23
System.Reflection.Assembly.ReflectionOnlyLoadFrom(System.String))
The thread was indeed in the middle of loading an assembly (Assembly.ReflectionOnlyLoadFrom()). But it was busy getting a file path. That couldn't take that long, or could it?
We were stuck for a while, until we got another bit of information about the server: there was a huge number of .htm files in the Internet Explorer cache folder of the system account (%windir% \SysWOW64\config\systemprofile\AppData\Local\Microsoft\Windows\Temporary Internet Files\Content.IE5). Then it struck me: could it be assembly binding log causing the performance issues? After all, the log is stored as a bunch of .htm files, placed by default in the user's IE cache folder.
Although Fusion Log Viewer was not installed on the machine, it turned out logging was indeed enabled; the settings are stored in the registry (HKLM\SOFTWARE\Microsoft\Fusion) and can of course be modified even without the tool. Obviously, having the logging enabled affects performance, but usually not in such an extreme manner. Due to how the logging is implemented, the performance can deteriorate significantly if it is enabled for a longer period of time without cleaning the selected log folder: because of too many files in the folder and the resulting log file name clashes it takes longer and longer to find a suitable file name for new log files. In our case it already took 8 seconds. As soon as we disabled the logging, the performance was back to normal. Deleting the log files freed up a significant amount of disk space, as well. We still don't know when the logging was enabled in the first place and why.
Lesson of the day? Don't log assembly binding on production machines, unless you really have to. As soon as you don't need it any more, turn it off immediately and delete the logs. It can save you a lot of headaches in the future.
