Alois Kraus

Using WPT For Batch Script Profiling

Alois Kraus — Thu, 17 Jan 2013 23:23:53 GMT

Originally posted on: http://geekswithblogs.net/akraus1/archive/2013/01/17/151871.aspx

In the process of digging deeper into WPT I did find many new ways to explore my system. The Windows Performance Toolkit for Windows 8 is NOT only for Windows 8 but it does run on Windows Vista and later. This toolkit is the the Hubble Space Telescope of performance engineering. It gives you call stacks far far away in the kernel and back across all processes of your system. But it is not only a tool for kernel hackers. You can use it also as an easy and free batch script profiler. It does not matter what you use (cmd, powershell, perl, ..) as long as your main work of the script does consist of calling one process after another.

When you want to install the Windows Performance Toolkit you get more infos here.

To start profiling your system you only need to execute 4 steps.

Open a command prompt and do cd “C:\Program Files\Windows Kits\8.0\Windows Performance Toolkit”
Now type xperf -on PROC_THREAD
Execute your script
Stop profiling and save the trace file to the defautl location: xperf –stop
View the profiling information: wpa c:\kernel.etl

To show how the trace file does look like I have started several cmd.exe processes and stopped them to have something to graph. When I view the trace file with wpa.exe I do get this:

The graph shows on the x axis the time in seconds since you did start recording the trace. Every process start and stop with full command line information is recorded. The y-axis does contain the started processes so you can follow the timeline of your script and you can directly see which process has the longest bar which might be worth optimizing. I do show you this with xperf since for this very useful graph you do need to enable only the PROC_THREAD kernel provider. A list of the most useful providers is documented here. This allows you to capture long traces with very small trace files (about 1MB/min). WPA can handle trace files with decent performance up to 1GB. The other recording tools of WPT are WPR and the gui WPRUI which do enable myriads of kernel providers which logs trace data with a rate of ca. 1 GB/min on a busy system. That is not a suitable setup for taking data for some hours or even minutes.

It was never so easy to to benchmark your scripts as it is with WPT. The “old” xperf tool can do this stuff since many years but it was only known to driver developers. If you want to capture ETW events on a customer machine you do not need to install WPT on them for simple tasks. You can capture and save traces with logman.exe as well.

Start Profiling: logman create trace -ets "NT Kernel Logger" -o kernel_logman.etl -p "Windows Kernel Trace" (process)
Stop Profiling: logman stop -ets "NT Kernel Logger"
View Captured Data: wpa kernel_logman.etl

This is the equivalent to our previous XPerf call. There seem to be many aliases built in into the tools which makes it a bit hard to find out what options I do actually need. But hey it does work. If you search for logman in your favorite search engine there are surprisingly few hits. It is time to change that. If it is so easy to profile your batch scripts these things should get more attention.

How To Make Your System Slower With WMI

Alois Kraus — Sat, 29 Dec 2012 00:38:57 GMT

Originally posted on: http://geekswithblogs.net/akraus1/archive/2012/12/28/151662.aspx

With the new Windows Performance Toolkit you can now identify bottlenecks in your system which did not show up in any profiler. Lets e.g. query for some system properties via WMI.

    static void Main(string[] args)
    {
        var sw = Stopwatch.StartNew();
        string[] queries = new string[] { "Win32_Processor", "Win32_Printer", "Win32_ComputerSystem", "Win32_VideoController", "Win32_PhysicalMemory", "Win32_LogicalDisk" };

        foreach(var wmiColl in queries.Select(x=> new ManagementObjectSearcher(new SelectQuery(x)))
                                      .Select(query => query.Get()))
        {
            foreach(var prop in wmiColl.Cast<ManagementBaseObject>()
                                       .SelectMany(x=>x.Properties.Cast<PropertyData>()))
            {
                //Console.WriteLine("{0} - {1}", prop.Name, prop.Value);
            }
        }
        sw.Stop();
        Console.WriteLine("Time: {0:F1}s", sw.Elapsed.TotalSeconds);
    }

This takes around 1,6s on my machine. When I do look at my process (ConsoleApplication1.exe) the CPU consumption is rather low.

So where is the time spent? It could be some disc IO happening during the queries. The check for disc IO we need the Disc Usage “Utilization by Process, IO Type” graph. As you can see for the specified time there was no disc IO at all happening. A flat line does not mean that there were no CreateFile/ReadFile calls at all. But if you call ReadFile on a file which contents are already cached by the OS reading from a file is only a matter of a CopyMemory call. This graph will show you only real disc accesses.

In the CPU graph you can see that the ConsoleApplication1.exe was not the process with most CPU consumption. Most CPU cycles were spent in WmiPrvSE, spoolsv and svchost. So lets graph them as well. You can enable or disable items in the graph by left clicking on the color box or via the context menu. In the context menu you have Enable … or Disable … menus to enable or disable all or only the selected processes/threads, …

We see that although our process did only consume 2,8% of CPU for all WMI queries we did max out one core with a WMI worker process (50% is one core for a dual core machine. If you have an 8 core machine one core would be 12,5%). In total we did consume 45% CPU time which means one core was fully utilized to process the WMI queries! At least this is the working hypothesis that our WMI queries did cause the load in the other processes. How can we verify this? First we can have a look at the call stacks in our process.

Here we do see nicely the full managed call stacks. ~~At least with .NET 4.5. If you have~~ ~~.NET 4.0 you will only see only the first managed stack~~ ~~frame and then nothing.~~ ~~It is better than nothing but it should be improved for .NET 4.0 as well.~~

Update:

To get full managed stacks it does work with .NET 4.0 as well for x86 processes. It does only fail when you want to profile 64 bit processes under Windows Vista or Windows 7. There is a bug in the stalk walking algorithm which does stop when it does encounter the first dynamically generated stack frame which address is not inside a loaded module. To workaround this issue you can NGen your assemblies to get full call stacks as well. This is a bit cumbersome to work with but it does work very nicely. The only issue is that truly dynamic code like WCF proxies and stuff like this will not work out as expected.

The other fix to this issue is to use Windows 8.

The ManagementObjectCollection does some COM calls to communicate with the WMI service where we do wait for a response from a COM object. When our thread gives up its time slice by calling some wait method the OS does schedule the next thread in the ready queue. This topic is covered in greater detail here which is part of the WPT docu. Here is a copy of the relevant part:

Each thread exists in a particular execution state at any given time. Windows uses three states that are relevant to performance; these are: Running, Ready, and Waiting.

Threads that are currently being executed are in the Running state. Threads that can execute but are currently not running are in the Ready state. Threads that cannot run because they are waiting for a particular event are in the Waiting state.

A state to state transition is shown in Figure 1 Thread State Transitions:

Figure 1 Thread State Transitions

Figure 1 Thread State Transitions is explained as follows:

A thread in the Running state initiates a transition to the Waiting state by calling a wait function such as WaitForSingleObject or Sleep(> 0).

A running thread or kernel operation readies a thread in the Waiting state (for example, SetEvent or timer expiration). If a processor is idle or if the readied thread has a higher priority than a currently running thread, the readied thread can switch directly to the Running state. Otherwise, it is put into the Ready state.

A thread in the Ready state is scheduled for processing by the dispatcher when a running thread waits, yields (Sleep(0)), or reaches the end of its quantum.

A thread in the Running state is switched out and placed into the Ready state by the dispatcher when it is preempted by a higher priority thread, yields (Sleep(0)), or when its quantum ends.

A thread that exists in the Waiting state does not necessarily indicate a performance problem. Most threads spend significant time in the Waiting state, which allows processors to enter idle states and save energy. Thread state becomes an important factor in performance only when a user is waiting for a thread to complete an operation.

This means that we can see where our thread was rescheduled by the OS to execute the next non waiting thread. To see the next executing thread you need to right click on the column header of the list and add ReadyThreadStack. This allows you to follow the trail of your thread from one process to the next process. It is not a 100% correlation but the chances are good that the next ready thread is the one that the OS has scheduled as next thread to execute now. Since the the WPT toolkit does record the call stacks after every context switch we can get a deep understanding how the threads do interact with each other. When we do follow now the ReadThreadStack until it does give up control by itself we do see that we did end up in svhost (1028). It would be interesting to see which system services were running inside it to confirm that our process has something to do with it.

Unfortunately there is no column command line or running services available in this view. But there is a view called Processes “Lifetime By Process” which does give us the command line of all processes and the hosted services if any. This way we do see that our call did end up in the service which does host the WMI (Winmgmt) service which sounds reasonable.

When we do look into the call stacks of our WMI service host process we do find in the ReadyThreadStack many times our console application which is not surprising since it does need to send the results back to our process. There are only a few calls to WmiPrvSE.exe (1516) which do execute the WMI queries in some WMI worker process where the actual WMI provider objects are living. When we do inspect the WMI worker process more closely we will find that it does some work with svchost(700) which is responsible for DCOM calls. No we have a pretty good understanding what is actually going on.

ConsoleApplication1 does issue some WMI query calls.
These calls are processed by the WMI service (svchost 1028) which does hand these calls to a WMI worker process
WmiPrvSE.exe (1516) does execute the actual queries.
The execution of the “Win32_Printer” query does cause some heavy load in the print spooling service (spoolsv 1648).
Some WMI call (the fetching of display device infos) requires the activation of some remote COM object which causes some load in the DCOM system service (svchost 700).

From this we can conclude that our process did cause with a 2,8% CPU load in our process a total load of nearly 50% (that means one core was full utilized). The load in our process did cause a 15 times higher load in other processes in the system!

I do really love this tool since it allows you to analyze cross process correlations which no other profiler can do I have encountered so far. It seems that the initial target audience of this tool were kernel developers but over the years XPerf has now reached the state of a full system wide profiler for managed and unmanaged applications. The managed part does work best with .NET 4.5 but you can get useful insights with .NET 4.0 already. Now we have found hat the WMI calls in our process were rather cheap but the whole system was under quite high load due to the WMI queries. Be careful to not overuse WMI since it might hurt overall system performance for no good reasons.

There is good content in the WPT toolkit online to guide you to more CPU scenarios. I found the thread starvation analysis especially interesting. If you see in your thread high Ready (us) times then you have a problem because this means that your thread was sitting too long in the Thread Ready queue to be scheduled for execution. Now you can not only see that your thread was treated unfair by the OS but you can also find out which other thread did get in your way (could be another process, higher thread priority …).

I am still shocked to see how many professional developers do not use profiling tools at all. I am not sure how they tackle tricky performance or memory issues. But I do think the answer is: They do not do it. If performance problems are tackled by “normal” devs only on demand by management because customers did complain about crappy performance they will only be able to iron out the big performance bottlenecks. The medium and small ones will be left as an exercise for the next dev. There may still be big issues in the product but they will not be able to analyze it down to the root cause. Part of the issue was that there was no good tool available to analyze managed and unmanaged code at the same time.

The tool problem is gone now.

There is no longer an excuse to say: I do not know how to dig deeper.

But there is another excuse left: I do not know how to read kernel stacks…

Now you can dig from your process and thread into the kernel and back to another process in another thread with a few clicks. Yes this tool is complex but this is our software we do write today as well. And there are times where all these nice abstractions of a managed execution environment, automated garbage collection, dynamic code generation, kernel mode transitions, OS thread scheduling need to become white boxes to see what is actually going on. Some problems are only solvable when you have such detailed information at hand.

Profiling Code – The Microsoft Way

Alois Kraus — Wed, 19 Dec 2012 23:50:35 GMT

Originally posted on: http://geekswithblogs.net/akraus1/archive/2012/12/19/151604.aspx

A colleague of mine asked me how he can find out why his laptop does consume 30% CPU in the SYSTEM process after it did wake up from hibernate. That is easy I replied: Open Process Explorer select the SYSTEM process, double click it, select the thread tab, sort by CPU and double click on the first thread which does consume so much CPU to get the call stack.

A few days later I got a mail back that it did not work. Ok could be some elevation problem. I did try it on my machine and sure enough access denied also here. Ups it is not so easy after all. A little googling around did lead to a very good article from Mark Russinovich dealing with the exact same issue. Mark did use Kernrate which seems to work still on Windows 7 but it does look rather unsupported. A few other articles indicated that xperf should also be able to do it. So I did look where to get the latest edition of XPerf. It turns out that it is part of the Windows 8 SDK and the Windows Assessment and Deployment Kit (ADK) für Windows® 8. You do not need to download GBs of stuff. Only select the Windows Performance Toolkit and uncheck all other stuff. That gives you a nice ~50MB download which will install it to

%PROGRAMFILES(X86)%\Windows Kits\8.0\Windows Performance Toolkit

Besides the well known Xperf tool I have written several years ago some new stuff was added. Recording performance with the latest version of the Windows Performance Toolkit has never been so easy. There is a tool called WPRUI.exe which allows you to record a trace session with a nice GUI. An interesting side note is that this tool is missing in the Windows 8 SDK delivered with Visual Studio 2012. If you download the latest version again you get the GUI tool as well. It does seem to have full support from MS and they did even localize the UI which is rather unusual for such low level tools.

When you select CPU, Disc and File IO you should be able to troubleshoot pretty much anything. The UI is easy to use and is even so nice to set some arcane registry key if you are using Windows 7 x64 to enable full stack walks in kernel drivers which seems to be broken otherwise. After you have saved the trace etl file you should cancel recording or you will be recording GB of additional data.

Now you are ready to load the trace file into the viewer which is called wpa.exe. After a little rearranging the stuff you get a pretty good picture what VS is doing during the first startup which is called cold startup because no files are in the OS file system cache yet. That means much more disc accesses during the first startup compared to a second warm startup of VS. How much more? We will shortly see. Here comes the picture:

Holy crap. What is all this? Well I have cut out most columns. This is already a simplified view ;-). On the left side you can select from the Graph Explorer many diagram types via drag and drop or context menu and add it to the Analysis pane. First I want to see what my CPU was doing by selecting “CPU Usage (precise) Utilization by Process Thread”. Next I do filter only for devenv.exe in each graph. But wait: Did you say filter for process? Yes this tool gives you view of the complete system with all processes at once. It goes so far that you can even watch the OS scheduler doing its work. The call stacks with the official MS symbols can be resolved into the kernel and to all user mode processes. Lets say you call in one thread BeginInvoke and wait for some other event you can see in the CPU graph with the columns Old/New Thread Stacks to which other thread/process the OS scheduler has moved control.

Besides CPU consumption disc IO is the most important metric to closely have a look at. For this I did select the graph “Utilization by Process, IO Type” to see at which times the disc is maxed out. I can see the file names which were access and I can see how much time the OS did spend with the hard disc reading this file. The most important column there is Disc Service Time which gives you the timing at ns granularity. Here we do e.g. see that during the cold startup we did spend 0,355s loading the file System.Xml.ni.dll. When you click at the file you see in the graph at which points of time it was read. The bigger blue bars indicate the first and last read event. In the CPU Graph I did also get a lot of selected rows. Why is this? First I thought it was an error but it was of course a feature.

Since we have a complete view of the system at our hands the tooling is able to follow all call stacks. This means that when I select the accessed file the tool does select all processes and threads that were blocked during one of the accesses to this file! Now I can find out why my mouse cursor does jump when I do start a very disc intensive application. Some years ago this stuff was unmanaged land only. But the latest version of it is also able to fully traverse managed call stacks now as you can see in the above call stack of the CPU graph. There you do see also a blue selected method called GetProfile which will obviously later lead to a blocking call in the call stack when trying to deserialize its data with XmlSerializer leading to reads to System.Xml.ni.dll.

The managed call stacks for native images are retrieved by a matching pdb for each native image. When you do google for “ngen create pdb” you will find more info about this feature. It does look like a Windows 8 and .NET 4.5 feature but it is not. This does work on Windows 7 with .NET 4.0 perfectly well. The first trace collection will take a quite long time because for each native image is ngen createpdb called to store a synthetic pdb at C:\ProgramData\WindowsPerformanceRecorder. This little thingy allows it to fully walk managed and unmanaged call stacks. But what about assemblies that are not NGened?

Good question. The short and good answer is: It does work. Below is a screen shot of a normal application I did create to read from the event log. You do see the Main method, the wrapped delegate call…. All is there. There is some stuff in the NGen images stored which is needed because I do get no such stack when I did not load the unmanaged and synthetic Ngen symbols before.

My symbol path does therefore look like this:

It does not include the MS symbol server because I have the most important symbols stored at C:\Windows\symbols already. This makes symbol loading a matter of seconds and not many minutes. PerfMonitor was a tool that was enabled mixed mode stack walking with ETW events first. You can read more at Naveens blog. For the NGen pdb support there seems to be pretty much magic involved which includes some CLR Rundown ETW traces you can read more about at the official docs which makes this look like a Windows 8 feature again. Anyway. It does work on Windows 7 perfectly well and I do not care about the exact details.

Now we can start VS 2012 a second time and compare CPU and disc utilization.

The second startup is much faster. It is only about 3s compared to 6s the first time. The warm vs cold startup performance is a mystery you cannot solve with most profilers which are commercially available. Now you can see all with a free tool. The disc utilization is practically zero this time. We do spend only 13ms compared to 2163ms during the second startup in accessing the disc. All other data comes from the OS cache which boils down to a memcpy when the application does call ReadFile. As you can see this view gives you not a API level view of the disc where we do read from “disc” when we call CreateFile and ReadFile to open and read from it. This gives you direct insights when the hard disc is shuffling data around.

This tool has the potential to supersede many other profilers because you get a holistic view of the complete system with full managed call stack support now.

There is much more to say about this fantastic tool. But I need some sleep now.

Profiling Startup Of VS2012 – SpeedTrace Profiler

Alois Kraus — Sun, 02 Dec 2012 16:17:02 GMT

Originally posted on: http://geekswithblogs.net/akraus1/archive/2012/12/02/151431.aspx

SpeedTrace is a relatively unknown profiler made a company called Ipcas. A single professional license does cost 449€+VAT. For the test I did use SpeedTrace 4.5 which is currently Beta. Although it is cheaper than dotTrace it has by far the most options to influence how profiling does work.

First you need to create a tracing project which does configure tracing for one process type. You can start the application directly from the profiler or (much more interesting) it does attach to a specific process when it is started. For this you need to check “Trace the specified …” radio button and enter the process name in the “Process Name of the Trace” edit box. You can even selectively enable tracing for processes with a specific command line. Then you need to activate the trace project by pressing the Activate Project button and you are ready to start VS as usual. If you want to profile the next 10 VS instances that you start you can set the Number of Processes counter to e.g. 10. This is immensely helpful if you are trying to profile only the next 5 started processes.

As you can see there are many more tabs which do allow to influence tracing in a much more sophisticated way. SpeedTrace is

~~the only~~ a profiler which does not rely entirely on the profiling Api of .NET. Instead it does modify the IL code (instrumentation on the fly) to write tracing information to disc which can later be analyzed. This approach is not only very fast but it does give you unprecedented analysis capabilities. Once the traces are collected they do show up in your workspace where you can open the trace viewer.

I do skip the other windows because this view is the most useful one. You can sort the methods not only by Wall Clock time but also by CPU consumption and wait time which none of the other products support in their views at the same time. If you want to optimize for CPU consumption sort by CPU time. If you want to find out where most time is spent you need Clock Total time and Clock Waiting. There you can directly see if the method did take long because it did wait on something or it did really execute stuff that did take so long.

Once you have found a method you want to drill deeper you can double click on a method to get to the Caller/Callee view which is similar to the JetBrains Method Grid view. But this time you do see much more. In the middle is the clicked method. Above are the methods that call you and below are the methods that you do directly call. Normally you would then start digging deeper to find the end of the chain where the slow method worth optimizing is located. But there is a shortcut.

You can press the magic button to calculate the aggregation of all called methods. This is displayed in the lower left window where you can see each method call and how long it did take. There you can also sort to see if this call stack does only contain methods (e.g. WCF connect calls which you cannot make faster) not worth optimizing. YourKit has a similar feature where it is called Callees List.

In the Functions tab you have in the context menu also many other useful analysis options

One really outstanding feature is the View Call History Drilldown. When you select this one you get not a sum of all method invocations but a list with the duration of each method call. This is not surprising since SpeedTrace does use tracing to get its timings. There you can get many useful graphs how this method did behave over time. Did it become slower at some point in time or was only the first call slow? The diagrams and the list will tell you that.

That is all fine but what should I do when one method call was slow? I want to see from where it was coming from. No problem select the method in the list hit F10 and you get the call stack. This is a life saver if you e.g. search for serialization problems. Today Serializers are used everywhere. You want to find out from where the 5s XmlSerializer.Deserialize call did come from? Hit F10 and you get the call stack which did invoke the 5s Deserialize call. The CPU timeline tab is also useful to find out where long pauses or excessive CPU consumption did happen. Click in the graph to get the Thread Stacks window where you can get a quick overview what all threads were doing at this time. This does look like the Stack Traces feature in YourKit. Only this time you get the last called method first which helps to quickly see what all threads were executing at this moment. YourKit does generate a rather long list which can be hard to go through when you have many threads.

The thread list in the middle does not give you call stacks or anything like that but you see which methods were found most often executing code by the profiler which is a good indication for methods consuming most CPU time.

This does sound too good to be true? I have not told you the best part yet. The best thing about this profiler is the staff behind it. When I do see a crash or some other odd behavior I send a mail to Ipcas and I do get usually the next day a mail that the problem has been fixed and a download link to the new version. The guys at Ipcas are even so helpful to log in to your machine via a Citrix Client to help you to get started profiling your actual application you want to profile. After a 2h telco I was converted from a hater to a believer of this tool. The fast response time might also have something to do with the fact that they are actively working on 4.5 to get out of the door. But still the support is by far the best I have encountered so far.

The only downside is that you should instrument your assemblies including the .NET Framework to get most accurate numbers. You can profile without doing it but then you will see very high JIT times in your process which can severely affect the correctness of the measured timings. If you do not care about exact numbers you can also enable in the main UI in the Data Trace tab logging of method arguments of primitive types. If you need to know what files at which times were opened by your application you can find it out without a debugger.

Since SpeedTrace does read huge trace files in its reader you should perhaps use a 64 bit machine to be able to analyze bigger traces as well. The memory consumption of the trace reader is too high for my taste. But they did promise for the next version to come up with something much improved.

Profiling Startup Of VS2012 – JustTrace Profiler

Alois Kraus — Sun, 02 Dec 2012 15:25:26 GMT

Originally posted on: http://geekswithblogs.net/akraus1/archive/2012/12/02/151430.aspx

JustTrace is made by Telerik which is mainly known for its collection of UI controls. The current version (2012.3.1127.0) does include a performance and memory profiler which does cost 614€ and is currently with a special offer for 306€ on sale. It does include one year of free upgrades. The uneven € numbers are calculated from the 799€ and 399$ discount price. The UI is already in Metro style and simple to use. Multi process,

~~attach~~, Update (attach is supported when you select as Profilee type “Running Application” in sampling mode) method recording filter are not supported.

It looks like JustTrace is like Ants a Just My Code profiler by default.

~~At least I have not (yet) found an option to see all methods.~~ Update: There is a button there as well. I did not press it since it did look disabled to me. I guess I just too old to spot the difference between disabled and not enabled. You need to press the Minor Methods button to see all methods. Now I do see much more but unfortunately I still cannot sort by total time which is strange for a profiler. In the All Threads window there is a Total Time column but I do not get it why I do not have it in the All Methods view. For stuff where you do not have the pdbs or you want to dig deeper into the BCL code you will not get far. After getting the profile data you get in the All Methods grid a plain list with hit count and own time. The method list for all methods is also suspiciously short which is a clear sign that you will not get far during the analysis of foreign code. It looks like this is intentional because I cannot configure the displayed columns where I get at least the total time as well.

But at least there is also a memory profiler included. For this I have to choose in the first window for Profiling Type “Memory Profiler” to check the memory consumption of VS. There are some interesting number to see but I do really miss from YourKit the thread stack window. How am I supposed to get a clue when much memory is allocated and the CPU consumption is high in which places I should look?

The Snapshot summary gives a rough overview which is ok for a first impression.

Next is Assemblies? This gives you a list of all loaded assemblies. Not terribly useful.

The By Type view gives you exactly what it is supposed to do. You have to keep in mind that this list is filtered by the types you did check in the Assemblies list.

The By Type instance list does only show types from assemblies which do not originate from Microsoft. By default mscorlib and System are not checked. That is the reason why for the first time my By Type window looked like

The idea behind this feature is to show only your instances because you are ultimately responsible for the overall memory consumption. I am not sure if I do like this feature because by default it does hide too much. I do want to see at least how many strings and arrays are allocated. A simple namespace filter would also do it in my opinion. Now you can examine all string instances and look who in the object graph does keep a reference on them.

That is nice but YourKit has the big plus that you can also look into the string contents. I am also not sure how in the graph cycles are visualized and what will happen if you have thousands of objects referencing you. That's pretty much it about JustTrace. It can help the average developer to pinpoint performance and memory issues by just looking at his own code and instances. Showing them more will not help them because the sheer amount of information will overwhelm them. And you need to have a pretty good understanding how the GC and the CLR does work. When you have a performance issue at a customer machine it is sometimes very helpful to be able a bring a profiler onto the machine (no pdbs, …) and to get a full snapshot of all processes which are in the problematic use case involved. For these more advanced use cased JustTrace is certainly the wrong tool.

Next: SpeedTrace

Profiling Startup Of VS2012 – YourKit Profiler

Alois Kraus — Sun, 02 Dec 2012 13:14:04 GMT

Originally posted on: http://geekswithblogs.net/akraus1/archive/2012/12/02/151429.aspx

The YourKit (v7.0.5) profiler is interesting in terms of price (79€ single place license, 409€ + 1 year support and upgrades) and feature set. You do get a performance and memory profiler in one package for which you normally need also to pay extra from the other vendors. As an interesting side note the profiler UI is written in Java because they do also sell Java profilers with the same feature set. To get all methods of a VS startup you need first to configure it to include System* in the profiled methods and you need to configure * to measure wall clock time. By default it does record only CPU times which allows you to optimize CPU hungry operations. But you will never see a Thread.Sleep(10000) in the profiler blocking the UI in this mode.

It can profile as all others processes started from within the profiler but it can also profile the next or all started processes.

As usual it can profile in sampling and tracing mode. But since it is a memory profiler as well it does by default also record all object allocations > 1MB. With allocation recording enabled VS2012 did crash but without allocation recording there were no problems. The CPU tab contains the time line of the application and when you click in the graph you the call stacks of all threads at this time. This is really a nice feature. When you select a time region you the CPU Usage estimation for this time window.

I have seen many applications consuming 100% CPU only because they did create garbage like crazy. For this is the Garbage Collection tab interesting in conjunction with a time range.

This view is like the CPU table only that the CPU graph (green) is missing. All relevant information except for GCs/s is already visible in the CPU tab. Very handy to pinpoint excessive GC or CPU bound issues.

The Threads tab does show the thread names and their lifetime. This is useful to see thread interactions or which thread is hottest in terms of CPU consumption.

On the CPU tab the call tree does exist in a merged and thread specific view. When you click on a method you get below a list of all called methods. There you can sort for methods with a high own time which are worth optimizing.

In the Method List you can select which scope you want to see. Back Traces are the methods which did call you.

Callees ist the list of methods called directly or indirectly by your method as a flat list. This is not a call stack but still very useful to see which methods were slow so you can see the “root” cause quite quickly without the need to click trough long call stacks.

The last view Merged Calles is a call stacked view of the previous view. This does help a lot to understand did call each method at run time. You would get the same view with a debugger for one call invocation but here you get the full statistics (invocation count) as well.

Since YourKit is also a memory profiler you can directly see which objects you have on your managed heap and which objects do hold most of your precious memory. You can in in the Object Explorer view also examine the contents of your objects (strings or whatsoever) to get a better understanding which objects where potentially allocating this stuff.

YourKit is a very easy to use combined memory and performance profiler in one product. The unbeatable single license price makes it very attractive to straightly buy it. Although it is a Java UI it is very responsive and the memory consumption is considerably lower compared to dotTrace and ANTS profiler. What I do really like is to start the YourKit ui and then start the processes I want to profile as usual. There is no need to alter your own application code to be able to inject a profiler into your new started processes. For performance and memory profiling you can simply select the process you want to investigate from the list of started processes.

That's the way I like to use profilers. Just get out of the way and let the application run without any special preparations.

Next: Telerik JustTrace

Profiling Startup Of VS2012 – dotTrace Profiler

Alois Kraus — Sat, 01 Dec 2012 21:12:13 GMT

Originally posted on: http://geekswithblogs.net/akraus1/archive/2012/12/01/151413.aspx

Jetbrains which is famous for the Resharper tool has also a profiler in its portfolio. I downloaded dotTrace 5.2 Professional (569€+VAT) to check how far I can profile the startup of VS2012. The most interesting startup option is “.NET Process”. With that you can profile the next started .NET process which is very useful if you want to profile an application which is not started by you.

I did select Tracing as and Wall time to get similar options across all profilers. For some reason the attach option did not work with .NET 4.5 on my home machine. But I am sure that it did work with .NET 4.0 some time ago. Since we are profiling devenv.exe we can also select “Standalone Application” and start it from the profiler. The startup time of VS does increase about a factor 3 but that is ok. You get mainly three windows to work with. The first one shows the threads where you can drill down thread wise where most time is spent.

The next window is the call tree which does merge all threads together in a similar view.

The last and most useful view in my opinion is the Plain List window which is nearly the same as the Method Grid in Ants Profiler. But this time we do get when I enable the Show system functions checkbox not a 150 but 19407 methods to choose from! I really tried with Ants Profiler to find something about out how VS does work but look how much we were missing!

When I double click on a method I do get in the lower pane the called methods and their respective timings. This is something really useful and I can nicely drill down to the most important stuff. The measured time seems to be Wall Clock time which is a good thing to see where my time is really spent. You can also use Sampling as profiling method but this does give you much less information. Except for getting a first idea where to look first this profiling mode is not very useful to understand how you system does interact.

The options have a good list of presets to hide by default many method and gray them out to concentrate on your code. It does not filter anything out if you enable Show system functions. By default methods from these assemblies are hidden or if the checkbox is checked grayed out.

All in all JetBrains has made a nice profiler which does show great detail and it has nice drill down capabilities. The only thing is that I do not trust its measured timings. I did fall several times into the trap with this one to optimize at places which were already fast but the profiler did show high times in these methods. After measuring with Tracing I was certain that the measured times were greatly exaggerated. Especially when IO is involved it seems to have a hard time to subtract its own overhead. What I did miss most was the possibility to profile not only the next started process but to be able to select a process by name and perhaps a count to profile the next n processes of this name.

Next: YourKit

Profiling Startup Of VS2012 – Ants Profiler

Alois Kraus — Fri, 30 Nov 2012 23:33:55 GMT

Originally posted on: http://geekswithblogs.net/akraus1/archive/2012/11/30/151409.aspx

I just downloaded ANTS Profiler 7.4 to check how fast it is and how deep I can analyze the startup of Visual Studio 2012. The Pro version which is useful does cost 445€ which is ok. To measure a complex system I decided to simply profile VS2012 (Update 1) on my older Intel 6600 2,4GHz with 3 GB RAM and a 32 bit Windows 7. Ants Profiler is really easy to use. So lets try it out.

The Ants Profiler does want to start the profiled application by its own which seems to be rather common. I did choose Method Level timing of all managed methods. In the configuration menu I did want to get all call stacks to get full details. Once this is configured you are ready to go.

After that you can select the Method Grid to view Wall Clock Time in ms. I hate percentages which are on by default because I do want to look where absolute time is spent and not something else.

From the Method Grid I can drill down to see where time is spent in a nice and I can look at the decompiled methods where the time is spent.

This does really look nice. But did you see the size of the scroll bar in the method grid? Although I wanted all call stacks I do get only about 4 pages of methods to drill down. From the scroll bar count I would guess that the profiler does show me about 150 methods for the complete VS startup.

Update: I did miss to uncheck the checkbox Hide Insignificant methods. Sorry about that one. After that I do get a reasonable method list. Yes I am aware that I can attach to a process later but then I do get only sampled call stacks and not full details like

with tracing which is much better.

This is nonsense. I will never find a bottleneck in VS when I am presented only a fraction of the methods that were actually executed. I have also tried in the configuration window to also profile the extremely trivial functions but there was no noticeable difference. It seems that the Ants Profiler does filter away way too many details to be useful for bigger systems. If you want to optimize a CPU bound operation inside NUnit then Ants Profiler is with its line level timings a very nice tool to work with. But for bigger stuff it is certainly not usable. I also do not like that I must start the profiled application from the profiler UI. This makes it hard to profile processes which are started by some other process.

Next: JetBrains dotTrace

Performance Optimization – It Is Faster When You Can Measure It

Alois Kraus — Fri, 30 Nov 2012 20:27:40 GMT

Originally posted on: http://geekswithblogs.net/akraus1/archive/2012/11/30/151407.aspx

Performance optimization in bigger systems is hard because the measured numbers can vary greatly depending on the measurement method of your choice. To measure execution timing of specific methods in your application you usually use

Time Measurement Method

Potential Pitfalls

Stopwatch

Most accurate method on recent processors. Internally it uses the RDTSC instruction. Since the counter is processor specific you can get greatly different values when your thread is scheduled to another core or the core goes into a power saving mode. But things do change luckily:

Intel's Designer's vol3b, section 16.11.1

"16.11.1 Invariant TSC

The time stamp counter in newer processors may support an enhancement, referred to as invariant TSC. Processor's support for invariant TSC is indicated by CPUID.80000007H:EDX[8].

The invariant TSC will run at a constant rate in all ACPI P-, C-. and T-states. This is the architectural behavior moving forward. On processors with invariant TSC support, the OS may use the TSC for wall clock timer services (instead of ACPI or HPET timers). TSC reads are much more efficient and do not incur the overhead associated with a ring transition or access to a platform resource."

DateTime.Now

Good but it has only a resolution of 16ms which can be not enough if you want more accuracy.

Reporting Method	Potential Pitfalls
Console.WriteLine	Ok if not called too often.
Debug.Print	Are you really measuring performance with Debug Builds? Shame on you.
Trace.WriteLine	Better but you need to plug in some good output listener like a trace file. But be aware that the first time you call this method it will read your app.config and deserialize your system.diagnostics section which does also take time.

In general it is a good idea to use some tracing library which does measure the timing for you and you only need to decorate some methods with tracing so you can later verify if something has changed for the better or worse. In my previous article I did compare measuring performance with quantum mechanics. This analogy does work surprising well. When you measure a quantum system there is a lower limit how accurately you can measure something. The Heisenberg uncertainty relation does tell us that you cannot measure of a quantum system the impulse and location of a particle at the same time with infinite accuracy. For programmers the two variables are execution time and memory allocations.

If you try to measure the timings of all methods in your application you will need to store them somewhere. The fastest storage space besides the CPU cache is the memory. But if your timing values do consume all available memory there is no memory left for the actual application to run.

On the other hand if you try to record all memory allocations of your application you will also need to store the data somewhere. This will cost you memory and execution time.

These constraints are always there and regardless how good the marketing of tool vendors for performance and memory profilers are:

Any measurement will disturb the system in a non predictable way.

Commercial tool vendors will tell you they do calculate this overhead and subtract it from the measured values to give you the most accurate values but in reality it is not entirely true. After falling into the trap to trust the profiler timings several times I have got into the habit to

Measure with a profiler to get an idea where potential bottlenecks are.
Measure again with tracing only the specific methods to check if this method is really worth optimizing.
Optimize it
Measure again.
Be surprised that your optimization has made things worse.
Think harder
Implement something that really works.
Measure again
Finished! - Or look for the next bottleneck.

Recently I have looked into issues with serialization performance. For serialization DataContractSerializer was used and I was not sure if XML is really the most optimal wire format. After looking around I have found protobuf-net which uses Googles Protocol Buffer format which is a compact binary serialization format. What is good for Google should be good for us.

A small sample app to check out performance was a matter of minutes:

using ProtoBuf;
using System;
using System.Diagnostics;
using System.IO;
using System.Reflection;
using System.Runtime.Serialization;

[DataContract, Serializable]
class Data
{
    [DataMember(Order=1)]
    public int IntValue { get; set; }

    [DataMember(Order = 2)]
    public string StringValue { get; set; }

    [DataMember(Order = 3)]
    public bool IsActivated { get; set; }

    [DataMember(Order = 4)]
    public BindingFlags Flags { get; set; }
}

class Program
{
    static MemoryStream _Stream = new MemoryStream();

    static MemoryStream Stream 
    {
        get 
        {
            _Stream.Position = 0;
            _Stream.SetLength(0);
            return _Stream;
        }
    }

    static void Main(string[] args)
    {
        DataContractSerializer ser = new DataContractSerializer(typeof(Data));
        Data data = new Data 
        { 
            IntValue = 100, 
            IsActivated = true, 
            StringValue = "Hi this is a small string value to check if serialization does work as expected" 
        };

        var sw = Stopwatch.StartNew();
        int Runs = 1000 * 1000;

        for (int i = 0; i < Runs; i++)
        {
            //ser.WriteObject(Stream, data);
            Serializer.Serialize<Data>(Stream, data);
        }
        sw.Stop();
        Console.WriteLine("Did take {0:N0}ms for {1:N0} objects", sw.Elapsed.TotalMilliseconds, Runs);
        Console.ReadLine();
    }
}

The results are indeed promising:

Serializer	Time in ms	N objects
protobuf-net	807	1000000
DataContract	4402	1000000

Nearly a factor 5 faster and a much more compact wire format. Lets use it! After switching over to protbuf-net the transfered wire data has dropped by a factor two (good) and the performance has worsened by nearly a factor two. How is that possible? We have measured it? Protobuf-net is much faster! As it turns out protobuf-net is faster but it has a cost: For the first time a type is de/serialized it does use some very smart code-gen which does not come for free. Lets try to measure this one by setting of our performance test app the Runs value not to one million but to 1.

Serializer	Time in ms	N objects
protobuf-net	85	1
DataContract	24	1

The code-gen overhead is significant and can take up to 200ms for more complex types. The break even point where the code-gen cost is amortized by its faster serialization performance is (assuming small objects) somewhere between 20.000-40.000 serialized objects. As it turned out my specific scenario involved about 100 types and 1000 serializations in total. That explains why the good old DataContractSerializer is not so easy to take out of business. The final approach I ended up was to reduce the number of types and to serialize primitive types via BinaryWriter directly which turned out to be a pretty good alternative.

It sounded good until I measured again and found that my optimizations so far do not help much. After looking more deeper at the profiling data I did found that one of the 1000 calls did take 50% of the time. So how do I find out which call it was? Normal profilers do fail short at this discipline. A (totally undeserved) relatively unknown profiler is SpeedTrace which does unlike normal profilers create traces of your applications by instrumenting your IL code at runtime. This way you can look at the full call stack of the one slow serializer call to find out if this stack was something special.

Unfortunately the call stack showed nothing special. But luckily I have my own tracing as well and I could see that the slow serializer call did happen during the serialization of a bool value. When you encounter after much analysis something unreasonable you cannot explain it then the chances are good that your thread was suspended by the garbage collector. If there is a problem with excessive GCs remains to be investigated but so far the serialization performance seems to be mostly ok.

When you do profile a complex system with many interconnected processes you can never be sure that the timings you just did measure are accurate at all. Some process might be hitting the disc slowing things down for all other processes for some seconds as well. There is a big difference between warm and cold startup. If you restart all processes you can basically forget the first run because of the OS disc cache, JIT and GCs make the measured timings very flexible. When you are in need of a random number generator you should measure cold startup times of a sufficiently complex system. After the first run you can try again getting different and much lower numbers. Now try again at least two times to get some feeling how stable the numbers are.

Oh and try to do the same thing the next day. It might be that the bottleneck you found yesterday is gone today. Thanks to GC and other random stuff it can become pretty hard to find stuff worth optimizing if no big bottlenecks except bloatloads of code are left anymore.

When I have found a spot worth optimizing I do make the code changes and do measure again to check if something has changed. If it has got slower and I am certain that my change should have made it faster I can blame the GC again. The thing is that if you optimize stuff and you allocate less objects the GC times will shift to some other location. If you are unlucky it will make your faster working code slower because you see now GCs at times where none were before. This is where the stuff does get really tricky. A safe escape hatch is to create a repro of the slow code in an isolated application so you can change things fast in a reliable manner. Then the normal profilers do also start working again.

As Vance Morrison does point out it is much more complex to profile a system against the wall clock compared to optimize for CPU time. The reason is that for wall clock time analysis you need to understand how your system does work and which threads (if you have not one but perhaps 20) are causing a visible delay to the end user and which threads can wait a long time without affecting the user experience at all.

Next time: Commercial profiler shootout.

Do Not Optimize Without Measuring

Alois Kraus — Sat, 27 Oct 2012 23:44:00 GMT

Originally posted on: http://geekswithblogs.net/akraus1/archive/2012/10/27/151086.aspx

Recently I had to do some performance work which included reading a lot of code. It is fascinating with what ideas people come up to solve a problem. Especially when there is no problem. When you look at other peoples code you will not be able to tell if it is well performing or not by reading it. You need to execute it with some sort of tracing or even better under a profiler. The first rule of the performance club is not to think and then to optimize but to measure, think and then optimize. The second rule is to do this do this in a loop to prevent slipping in bad things for too long into your code base. If you skip for some reason the measure step and optimize directly it is like changing the wave function in quantum mechanics. This has no observable effect in our world since it does represent only a probability distribution of all possible values. In quantum mechanics you need to let the wave function collapse to a single value. A collapsed wave function has therefore not many but one distinct value. This is what we physicists call a measurement.

If you optimize your application without measuring it you are just changing the probability distribution of your potential performance values. Which performance your application actually has is still unknown. You only know that it will be within a specific range with a certain probability. As usual there are unlikely values within your distribution like a startup time of 20 minutes which should only happen once in 100 000 years. 100 000 years are a very short time when the first customer tries your heavily distributed networking application to run over a slow WIFI network…

What is the point of this? Every programmer/architect has a mental performance model in his head. A model has always a set of explicit preconditions and a lot more implicit assumptions baked into it. When the model is good it will help you to think of good designs but it can also be the source of problems. In real world systems not all assumptions of your performance model (implicit or explicit) hold true any longer. The only way to connect your performance model and the real world is to measure it. In the WIFI example the model did assume a low latency high bandwidth LAN connection. If this assumption becomes wrong the system did have a drastic change in startup time.

Lets look at a example. Lets assume we want to cache some expensive UI resource like fonts objects. For this undertaking we do create a Cache class with the UI themes we want to support. Since Fonts are expensive objects we do create it on demand the first time the theme is requested.

A simple example of a Theme cache might look like this:

using System;
using System.Collections.Generic;
using System.Drawing;

struct Theme
{
    public Color Color;
    public Font Font;
}

static class ThemeCache
{
    static Dictionary<string, Theme> _Cache = new Dictionary<string, Theme>
    {
        {"Default", new Theme { Color = Color.AliceBlue }},
        {"Theme12", new Theme { Color = Color.Aqua }},
    };

    public static Theme Get(string theme)
    {
        Theme cached = _Cache[theme];
        if (cached.Font == null)
        {
            Console.WriteLine("Creating new font");
            cached.Font = new Font("Arial", 8);
        }

        return cached;
    }

}

class Program
{
    static void Main(string[] args)
    {
        Theme item = ThemeCache.Get("Theme12");
        item = ThemeCache.Get("Theme12");
    }
}

This cache does create font objects only once since on first retrieve of the Theme object the font is added to the Theme object. When we let the application run it should print “Creating new font” only once. Right?

Wrong!

The vigilant readers have spotted the issue already. The creator of this cache class wanted to get maximum performance. So he decided that the Theme object should be a value type (struct) to not put too much pressure on the garbage collector.

The code

        Theme cached = _Cache[theme];
        if (cached.Font == null)
        {
            Console.WriteLine("Creating new font");
            cached.Font = new Font("Arial", 8);
        }

does work with a copy of the value stored in the dictionary. This means we do mutate a copy of the Theme object and return it to our caller. But the original Theme object in the dictionary will have always null for the Font field! The solution is to change the declaration of struct Theme to class Theme or to update the theme object in the dictionary. Our cache as it is currently is actually a non caching cache. The funny thing was that I found out with a profiler by looking at which objects where finalized. I found way too many font objects to be finalized. After a bit debugging I found the allocation source for Font objects was this cache. Since this cache was there for years it means that

the cache was never needed since I found no perf issue due to the creation of font objects.
the cache was never profiled if it did bring any performance gain.
to make the cache beneficial it needs to be accessed much more often.

That was the story of the non caching cache. Next time I will write something something about measuring.

Thread.Interrupt Is Evil

Alois Kraus — Mon, 22 Oct 2012 22:04:58 GMT

Originally posted on: http://geekswithblogs.net/akraus1/archive/2012/10/22/151047.aspx

Recently I have found an interesting issue with Thread.Interrupt during application shutdown. Some application was crashing once a week and we had not really a clue what was the issue. Since it happened not very often it was left as is until we have got some memory dumps during the crash. A memory dump usually means WindDbg which I really like to use (I know I am one of the very few fans of it). After a quick analysis I did find that the main thread already had exited and the thread with the crash was stuck in a Monitor.Wait. Strange Indeed. Running the application a few thousand times under the debugger would potentially not have shown me what the reason was so I decided to do what I call constructive debugging. With constructive I mean that I do not try to analyze the running application and try to repro it there. Instead I try to create a synthetic sample application which tries to reproduce the issue. I am done when I get the same crash and callstack as in the production application. This approach is usually quite successful.

I did create a simple Console application project and try to simulate the exact circumstances when the crash did happen from the information I have via memory dump and source code reading. The thread that was crashing was actually MS code from an old version of the Microsoft Caching Application Block. From reading the code I could conclude that the main thread did call the Dispose method on the CacheManger class which did call Thread.Interrupt on the cache scavenger thread which was just waiting for work to do.

My first version of the repro looked like this

    static void Main(string[] args)
    {
        Thread t = new Thread(ThreadFunc)
        {
            IsBackground = true,
            Name = "Test Thread"
        };
        t.Start();

        Console.WriteLine("Interrupt Thread");
        t.Interrupt();
    }

    static void ThreadFunc()
    {
        while (true)
        {
            object value = Dequeue(); // block until unblocked or awaken via ThreadInterruptedException
        }
    }

    static object WaitObject = new object();

    static object Dequeue()
    {
        object lret = "got value";
        try
        {
            lock (WaitObject)
            {
            }
        }
        catch (ThreadInterruptedException)
        {
            Console.WriteLine("Got ThreadInterruptException");
            lret = null;
        }
        return lret;
    }

I do start a background thread and call Thread.Interrupt on it and then directly let the application terminate. The thread in the meantime does plenty of Monitor.Enter/Leave calls to simulate work on it. This first version did not crash. So I need to dig deeper. From the memory dump I did know that the finalizer thread was doing just some critical finalizers which were closing file handles. Ok lets add some long running finalizers to the sample.

class FinalizableObject : CriticalFinalizerObject
{
    ~FinalizableObject()
    {
        Console.WriteLine("Hi we are waiting to finalize now and block the finalizer thread for 5s.");
        Thread.Sleep(5000);
    }
}

class Program
{
    static void Main(string[] args)
    {
        FinalizableObject fin = new FinalizableObject();
        Thread t = new Thread(ThreadFunc)
        {
            IsBackground = true,
            Name = "Test Thread"
        };
        t.Start();

        Console.WriteLine("Interrupt Thread");
        t.Interrupt();
        GC.KeepAlive(fin); // prevent finalizing it too early
        // After leaving main the other thread is woken up via Thread.Abort
        // while we are finalizing. This causes a stackoverflow in the CLR ThreadAbortException handling at this time.
    }

With this changed Main method and a blocking critical finalizer I did get my crash just like the real application. The funny thing is that this is actually a CLR bug. When the main method is left the CLR does suspend all threads except the finalizer thread and declares all objects as garbage. After the normal finalizers were called the critical finalizers are executed to e.g. free OS handles (usually). Remember that I did call Thread.Interrupt as one of the last methods in the Main method. The Interrupt method is actually asynchronous and does wake a thread up and throws a ThreadInterruptedException only once unlike Thread.Abort which does rethrow the exception when an exception handling clause is left.

It seems that the CLR does not expect that a frozen thread does wake up again while the critical finalizers are executed. While trying to raise a ThreadInterrupedException the CLR goes down with an stack overflow. Ups not so nice. Why has this nobody noticed for years is my next question. As it turned out this error does only happen on the CLR for .NET 4.0 (x86 and x64). It does not show up in earlier or later versions of the CLR.

I have reported this issue on connect here but so far it was not confirmed as a CLR bug. But I would be surprised if my console application was to blame for a stack overflow in my test thread in a Monitor.Wait call.

What is the moral of this story? Thread.Abort is evil but Thread.Interrupt is too. It is so evil that even the CLR of .NET 4.0 contains a race condition during the CLR shutdown. When the CLR gurus can get it wrong the chances are high that you get it wrong too when you use this constructs. If you do not believe me see what Patrick Smacchia does blog about Thread.Abort and List.Sort. Not only the CLR creators can get it wrong. The BCL writers do sometimes have a hard time with correct exception handling as well. If you do tell me that you use Thread.Abort frequently and never had problems with it I do suspect that you do not have looked deep enough into your application to find such sporadic errors.

The Truth About .NET Objects And Sharing Them Between AppDomains

Alois Kraus — Wed, 25 Jul 2012 15:11:20 GMT

Originally posted on: http://geekswithblogs.net/akraus1/archive/2012/07/25/150301.aspx

I have written already some time ago how big a .NET object is. John Skeet as also made a very detailed post about object sizes in .NET. I wanted to know if we can deduce the object size not by experiments (measuring) but by looking at the Rotor source code. There is indeed a simple definition in the object headers how big a .NET object minimally can be. A CLR object is still a (sophisticated) structure which is at an address that is changed quite often by the garbage collector.

The picture above shows that every .NET object contains an object header which contains information about which thread in which AppDomain has locked the object (means called Monitor.Enter). Next comes the Method Table Pointer which defines a managed type for one AppDomain. If the assembly is loaded AppDomain neutral this pointer to the type object will have the same value in all AppDomains. This basic building block of the CLR type system is also visible in managed code via Type.TypeHandle.Value which has IntPtr size.

\sscli20\clr\src\vm\object.h

//
// The generational GC requires that every object be at least 12 bytes
// in size.   
#define MIN_OBJECT_SIZE     (2*sizeof(BYTE*) + sizeof(ObjHeader))

A .NET object has basically this layout:

class Object
{
  protected:
    MethodTable*    m_pMethTab;

};

class ObjHeader
{
  private:
    // !!! Notice: m_SyncBlockValue *MUST* be the last field in ObjHeader.
    DWORD  m_SyncBlockValue;      // the Index and the Bits
};

For x86 the minimum size is therefore 12 bytes = 2*4+4. And for x64 it is 24 bytes = 2*8+8. The ObjectHeader struct is padded with another 4 bytes in x64 which does add up to 24 bytes for every object instance. The MIN_OBJECT_SIZE definition has actually a factor two inside it whereas we would expect 8 as minimum empty object size. The previous sentence does contain already the answer to it. It makes little sense to define empty objects. Most meaningful objects have at least one member variable of class type which is indeed another pointer sized member hence the minimum size of 12 bytes (24) bytes in x86/x64.

It is interesting to know that the garbage collector does not know anything about AppDomains. For him the managed heap does only consist of objects which have roots or not and does clean up everything which is not rooted anymore. I found this during the development of WMemoryProfiler which uses DumpHeap of Windbg to get all object references from the managed heap. When I did access all objects found this way I got actually objects from other AppDomains as well. And they did work! It is therefore possible to share objects directly between AppDomains.

Why would you want to do that? Well it is fun and you can do really dirty stuff with that. Do you remember that you cannot unload assemblies from an AppDomain? Yes that is still true but why would you ever want to unload an assembly? Mostly because you were doing some dynamic code generation which will at some point in time dominate your overall memory consumption if you load generated assemblies into your AppDomain. I have seen this stuff many times for dynamic query generation. The problem is that if you load the dynamically created code into another AppDomain you need to serialize the data to the other AppDomain as well because you cannot share plain objects between AppDomains. To serialize potentially much data across AppDomain is prohibitively slow and therefore people live with the restriction that code gen will increase the working set quite a lot. With some tricks you can now share plain objects between AppDomain and get unloadable code as well.

Warning: This following stuff well beyond the specs but it does work since .NET 2.0 up to 4.5.

Do not try this at work!

When you load an assembly into your (default) AppDomain you will load it only for your current AppDomain. The types defined there are not shared anywhere. There is one exception though: The types defined in mscorlib are always shared between all AppDomains. The mscorlib assembly is loaded into a so called Shared Domain. This is not a real AppDomain but simply a placeholder domain where all assemblies are loaded which can be shared between AppDomains. An assembly loaded into the Shared Domain is loaded therefore AppDomain neutral. Assemblies loaded AppDomain neutral have one special behavior:

AppDomain neutral assemblies are never unloaded even when no “real” AppDomain is using them anymore.

The picture below shows in which scenarios assemblies are loaded AppDomain neutral (green) from the Shared Domain.

The first one is the most common one. You load an assembly into the default AppDomain. This defaults to LoaderOptimization.SingleAppDomain where every assembly is compiled from scratch again when other AppDomains with no special flags are created. Only the basic CLR types located in mscorlib are loaded AppDomain neutral and always shared between AppDomains no matter what (with .NET 1.1 this was not the case) flags are used.

If you create e.g. 5 AppDomains with the default settings you will load and JIT every assembly (except mscorlib) again and get different types for each AppDomain although the were all loaded from the same assembly in the same loader context.

The opposite is LoaderOptimization.MultiDomain where every assembly is loaded as AppDomain neutral assembly which ensures that all assemblies loaded in any AppDomain which have this attribute set are loaded and JITed only once and share the types (=Same Method Table pointer) between AppDomains.

An interesting hybrid is LoaderOptimization.MultiDomainHost which does load only these assemblies AppDomain neutral which are loaded from the GAC. That means if you load the same assembly one time from the GAC and a second time the same one unsigned from your probing path you will not get identical types but different Method Table pointers for the types.

Since we know that the GC does not know anything about AppDomains we (at least the managed heap objects do not contain infos in which AppDomain they reside) we should be able to pass object via a pointer to another AppDomain. This could come in handy if we generate a lot of code dynamically for each query which is made against a data source but we want a way to get rid of the compiled code by unloading the Query AppDomain from time to time without the normally required cost to copy the data to be queried every time from the Default AppDomain into the Query AppDomain.

You can see this in action in the sample Application AppDomainTests which is part of the test suite for WMemoryProfiler. Here is the code for the main application which does create AppDomains in a loop send data via an IntPtr to another AppDomain and get the calculated result back without passing the data via Marshalling by value to the other AppDomain.

    class Program
    {
        /// <summary>
        /// Show how to pass an object by reference directly into another appdomain without serializing it at all.
        /// </summary>
        /// <param name="args"></param>
        [LoaderOptimization(LoaderOptimization.MultiDomainHost)]
        static public void Main(string[] args)
        {
            for (int i = 0; i < 10000; i++) // try it often to see how the AppDomains do behave
            { 
            // To load our assembly appdomain neutral we need to use MultiDomainHost on our hosting and child domain
            // If not we would get different Method tables for the same types which would result in InvalidCastExceptions
            // for the same type.
            // Prerequisite for MultiDomainHost is that the assembly we share the data is 
            // a) Installed into the GAC (which requires as strong name as well)
            // If you would use MultiDomain then it would work but all AppDomain neutral assemblies will never be unloaded.
            var other = AppDomain.CreateDomain("Test"+i.ToString(), AppDomain.CurrentDomain.Evidence, new AppDomainSetup
                {
                    LoaderOptimization = LoaderOptimization.MultiDomainHost,
                });

            // Create gate object in other appdomain
            DomainGate gate = (DomainGate)other.CreateInstanceAndUnwrap(Assembly.GetExecutingAssembly().FullName, typeof(DomainGate).FullName);
            

            // now lets create some data
            CrossDomainData data = new CrossDomainData();
            data.Input = Enumerable.Range(0, 10).ToList();

            // process it in other AppDomain
            DomainGate.Send(gate, data);

            // Display result calculated in other AppDomain
            Console.WriteLine("Calculation in other AppDomain got: {0}", data.Aggregate);

            AppDomain.Unload(other);
            // check in debugger now if UnitTests.dll has been unloaded.
            Console.WriteLine("AppDomain unloaded");

            }
        }

To enable code unloading in the other AppDomain I did use LoaderOptimzation.MultiDomainHost which forces all non GAC assemblies to be unloadable. At the same time we must ensure that the assembly that defines CrossDomainData is loaded from the GAC to get an equal MethodTable pointer accross all AppDomains. The actual magic does happen in the DomainGate class which has a method DoSomething which expects not a CLR object but the object address as parameter to weasel a plain CLR reference into another AppDomain. This sounds highly dirty and it certainly is but it is also quite cool ;-).

    /// <summary>
    /// Enables sharing of data between appdomains as plain objects without any marsalling overhead.
    /// </summary>
    class DomainGate : MarshalByRefObject
    {
        /// <summary>
        /// Operate on a plain object which is shared from another AppDomain.
        /// </summary>
        /// <param name="gcCount">Total number of GCs</param>
        /// <param name="objAddress">Address to managed object.</param>
        public void DoSomething(int gcCount, IntPtr objAddress)
        {
            if (gcCount != ObjectAddress.GCCount)
            {
                throw new NotSupportedException("During the call a GC did happen. Please try again.");
            }

            // If you get an exception here disable under Projces/Debugging/Enable Visual Studio Hosting Process
            // The appdomain which is used there seems to use LoaderOptimization.SingleDomain
            CrossDomainData data = (CrossDomainData) PtrConverter<Object>.Default.ConvertFromIntPtr(objAddress);;

            // process input data from other domain
            foreach (var x in data.Input)
            {
                Console.WriteLine(x);
            }

            OtherAssembliesUsage user = new OtherAssembliesUsage();

            // generate output data 
            data.Aggregate = data.Input.Aggregate((x, y) => x + y);
        }

        public static void Send(DomainGate gate, object o)
        {
            var old = GCSettings.LatencyMode;
            try
            {
                GCSettings.LatencyMode = GCLatencyMode.Batch; // try to keep the GC out of our stuff
                var addandGCCount = ObjectAddress.GetAddress(o);
                gate.DoSomething(addandGCCount.Value, addandGCCount.Key);
            }
            finally
            {
                GCSettings.LatencyMode = old;
            }

        }

 
    }

To get an object address I use Marshal.UnsafeAddrOfPinnedArrayElement and then try to work around the many race conditions this does impose. But it is not as bad is it sounds since you do need only to pass an object via a pointer once into the other AppDomain and use this as data gateway to exchange input and output data. This way you can pass data via a pointer to another AppDomain which can be fully unloaded after you are done with it. To make the code unloadable I need to use LoadOptimization.MultiDomainHost for all AppDomains. The data exchange type is located in another assembly which is strong named and you need to put it into the GAC before you let the sample run. Otherwise it will fail with this exception

Unhandled Exception: System.InvalidCastException: [A]AppDomainTests.CrossDomainData cannot be cast to [B]AppDomainTests.CrossDomainData. Type A originates from 'StrongNamedDomainGateDll, Version=1.0.0.0, Culture=neutral, PublicKeyToken=98f280cda3cbf035' in the context 'Default' at location 'C:\Source\WindbgAuto\bin\AnyCPU\Release\StrongNamedDomainGateDll.dll'. Type B originates from 'StrongNamedDomainGateDll, Version=1.0.0.0, Culture=neutral, PublicKeyToken=98f280cda3cbf035' in the context 'Default' at location 'C:\Source\WindbgAuto\bin\AnyCPU\Release\StrongNamedDomainGateDll.dll'.
   at AppDomainTests.DomainGate.DoSomething(Int32 gcCount, IntPtr objAddress) in C:\Source\WindbgAuto\Tests\AppDomainTests\DomainGate.cs:line 24
   at AppDomainTests.DomainGate.DoSomething(Int32 gcCount, IntPtr objAddress)
   at AppDomainTests.DomainGate.Send(DomainGate gate, Object o) in C:\Source\WindbgAuto\Tests\AppDomainTests\DomainGate.cs:line 50
   at AppDomainTests.Program.Main(String[] args) in C:\Source\WindbgAuto\Tests\AppDomainTests\Program.cs:line 41

at first it looks a little pointless to deny a cast to an object which was loaded in the default loader context for the very same assembly. But we do know now that the Method Table pointer for CrossDomainData is different between the two AppDomains. When you install the assembly into the GAC (be sure to use the .NET 4 gacutil!) the error goes away and we then get:

0
1
2
3
4
5
6
7
8
9
Calculation in other AppDomain got: 45

which shows that we can get data and are able to modify it directly between AppDomains. If you use this code in production and it does break. I have warned you. This is far beyond what the MS engineers want us to do and it can break the CLR in subtle unintended ways I have not found yet. Now you have got (hopefully) a much better understanding how the CLR type system and the managed heap does work. If questions are left. Start the application and look at !DumpDomain and !DumpHeap –stat and its related commands to see for yourself.

WMemoryProfiler is Released

Alois Kraus — Sat, 23 Jun 2012 06:46:52 GMT

Originally posted on: http://geekswithblogs.net/akraus1/archive/2012/06/22/150026.aspx

What is it? WMemoryProfiler is a managed profiling Api to aid integration testing. This free library can get managed heap statistics and memory usage for your own process (remember testing) and other processes as well. The best thing is that it does work from .NET 2.0 up to .NET 4.5 in x86 and x64. To make it more interesting it can attach to any running .NET process. The reason why I do mention this is that commercial profilers do support this functionality only for their professional editions. An normally only since .NET 4.0 since the profiling API only since then does support attaching to a running process.

This thing does differ in many aspects from “normal” profilers because while profiling yourself you can get all objects from all managed heaps back as an object array. If you ever wanted to change the state of an object which does only exist a method local in another thread you can get your hands on it now …

Enough theory. Show me some code

        /// <summary>
        /// Show feature to not only get statisics out of a process but also the newly allocated 
        /// instances since the last call to MarkCurrentObjects.
        /// GetNewObjects does return the newly allocated objects as object array
        /// </summary>
        static void InstanceTracking()
        {
            using (var dumper = new MemoryDumper())  // if you have problems use to see the debugger windows true,true))
            {
                dumper.MarkCurrentObjects();
                Allocate();
                ILookup<Type, object> newObjects = dumper.GetNewObjects()
                                                         .ToLookup( x => x.GetType() );

                Console.WriteLine("New Strings:");
                foreach (var newStr in newObjects[typeof(string)] )
                {
                    Console.WriteLine("Str: {0}", newStr);
                }
            }
        }

…

New Strings:
Str: qqd
Str: String data:
Str: String data: 0
Str: String data: 1
…

This is really hot stuff. Not only you can get heap statistics but you can directly examine the new objects and make queries upon them. When I do find more time I can reconstruct the object root graph from it from my own process. It this cool or what? You can also peek into the Finalization Queue to check if you did accidentally forget to dispose a whole bunch of objects …

        /// <summary>
        /// .NET 4.0 or above only. Get all finalizable objects which are ready for finalization and have no other object roots anymore.
        /// </summary>
        static void NotYetFinalizedObjects()
        {
            using (var dumper = new MemoryDumper())
            {
                object[] finalizable = dumper.GetObjectsReadyForFinalization();
                Console.WriteLine("Currently {0} objects of types {1} are ready for finalization. Consider disposing them before.", 
                                  finalizable.Length,
                                   String.Join(",", finalizable.ToLookup( x=> x.GetType() )
                                                               .Select(   x=> x.Key.Name)) 
                                 );
            }

        }

How does it work?

The W of WMemoryProfiler is a good hint. It does employ Windbg and SOS dll to do the heavy lifting and concentrates on an easy to use Api which does hide completely Windbg. If you do not want to see Windbg you will never see it. In my experience the most complex thing is actually to download Windbg from the Windows 8 Stanalone SDK. This is described in the Readme and the exception you are greeted with if it is missing in much greater detail. So I will not go into this here.

What Next?

Depending on the feedback I do get I can imagine some features which might be useful as well

Calculate first order GC Roots from the actual object graph
Identify global statics in Types in object graph
Support read out of finalization queue of .NET 2.0 as well.
Support Memory Dump analysis (again a feature only supported by commercial profilers in their professional editions if it is supported at all)
Deserialize objects from a memory dump into a live process back (this would need some more investigation but it is doable)

The last item needs some explanation. Why on earth would you want to do that? The basic idea is to store in your live process some logging/tracing data which can become quite big but since it is never written to it is very fast to generate. When your process crashes with a memory dump you could transfer this data structure back into a live viewer which can then nicely display your program state at the point it did crash. This is an advanced trouble shooting technique I have not seen anywhere yet but it could be quite useful. You can have here a look at the current feature list of WMemoryProfiler with some examples.

How To Get Started?

First I would download the released source package (it is tiny). And compile the complete project. Then you can compile the Example project (it has this name) and uncomment in the main method the scenario you want to check out. If you are greeted with an exception it is time to install the Windows 8 Standalone SDK which is described in great detail in the exception text.

Thats it for the first round. I have seen something more limited in the Java world some years ago (now I cannot find the link anymore) but anyway. Now we have something much better.

Useful .NET Delegate Internals

Alois Kraus — Sun, 20 May 2012 22:39:11 GMT

Originally posted on: http://geekswithblogs.net/akraus1/archive/2012/05/20/149699.aspx

Delegates in .NET are a very handy addition to the language. With the introduction of LINQ they did become mainstream and everyone is using them or is at least finding them cool. But what the CLR is really doing to them under the covers remains largely unexplored. This is ok as long as you never get any memory dumps from the field with angry customers waiting for a solution. Delegates are heavily used to e.g. send window messages from an arbitrary thread to the main UI thread. Or you have an thread scheduler (TPL anyone?) which does execute delegates from a queue on one or more threads. These things do all work with a custom data structure where besides scheduling information the delegate to be called is stored. When you want to examine a data structure which does contain delegate fields and you need to know to which method this delegate does point to things become less obvious if you do not have the VS debugger on a live process attached. If you dump the contents of a Func<string,bool> delegate you will see in Windbg something like this:

0:000> !DumpObj /d 0272b8d8
Name:        System.Func`2[[System.String, mscorlib],[System.Boolean, mscorlib]]
MethodTable: 6e4edbac
EEClass:     6e211748
Size:        32(0x20) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
      MT    Field   Offset                 Type VT     Attr    Value Name
6e52f744  4000076        4        System.Object  0 instance 0272b8d8 _target  -> Target object to call to
6e52f744  4000077        8        System.Object  0 instance 00000000 _methodBase –> is null except if VS is attached
6e52ab88  4000078        c        System.IntPtr  1 instance   5b0a18 _methodPtr  -> Trampoline code to dispatch the method
6e52ab88  4000079       10        System.IntPtr  1 instance   40c068 _methodPtrAux –> If not null and invocationCount == 0 it does contain the MethodPtr of a static method.
6e52f744  400007a       14        System.Object  0 instance 00000000 _invocationList –> When it is an event there the list of delegates to call are stored
6e52ab88  400007b       18        System.IntPtr  1 instance        0 _invocationCount –> Number of delegates stored in invocationList

We do know the type of the object where one of its methods is called by inspecting the _target field which gives us the instance on which non static methods are called. If the method is static _target does contain only the delegate instance (Func<string,bool>) which is of no help. When a delegate to a static method is declared the value which is normally stored in _methodPtr is stored in _methodPtrAux. This _methodPtrxxxx stuff does not point to data structures but trampolin code that does retrieve the target MethodDescriptor (not via reflection of course). I have found this stuff by creating a little sample app which defines some delegate instances and then goes to sleep to allow me to break into with Windbg quite easy.

using System;
using System.Linq;
using System.Threading;
using System.Runtime.InteropServices;

namespace ConsoleApplication10
{
    class Program
    {
        static void Main(string[] args)
        {
            new Program().Start();
        }

        private void Start()
        {
            Func<string, bool> func = Filter;
            Func<string, bool> staticFunc = FilterStatic;
            Thread.Sleep(5000);
            func("");
        }

        static bool FilterStatic(string str)
        {
            return true;
        }

        bool Filter(string str)
        {
            throw new Exception();
        }

The algorithm how the CLR does retrieve the MethodDescriptor when a delegate has been called is the same since .NET 2.0 up to .NET 4.5. There are even no differences between x86 and x64 (except for the pointer size of a MethodDescriptor). The algorithm can best be seen in x64 assembly code how it does retrieve the method descriptor. The _MethodPtr+5 is the base value in eax.

clr!PrecodeFixupThunk+0x1:
000007fe`edf113f1 4c0fb65002      movzx   r10,byte ptr [rax+2] // load byte from eax+2
000007fe`edf113f6 4c0fb65801      movzx   r11,byte ptr [rax+1] // load byte from eax+1
000007fe`edf113fb 4a8b44d003      mov     rax,qword ptr [rax+r10*8+3] // retrieve base MethodDescriptor
000007fe`edf11400 4e8d14d8        lea     r10,[rax+r11*8] // Add method slot offset to get the right one

From this disassembly we can now create a Windbg script to dump for any MethodPtr the actual method.

0:000> !DumpObj /d 01ca2328
Name:        System.Func`2[[System.String, mscorlib],[System.Boolean, mscorlib]]
MethodTable: 5cf43c6c
EEClass:     5cb73718
Size:        32(0x20) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
      MT    Field   Offset                 Type VT     Attr    Value Name
5cef8194 400002d        4        System.Object 0 instance 01ca231c _target
5cef8194 400002e        8        System.Object 0 instance 00000000 _methodBase
5cefb8fc 400002f        c        System.IntPtr 1 instance   26c048 _methodPtr
5cefb8fc 4000030       10        System.IntPtr 1 instance        0 _methodPtrAux
5cef8194 4000031       14        System.Object 0 instance 00000000 _invocationList
5cefb8fc 4000032       18        System.IntPtr 1 instance        0 _invocationCount
0:000> $$>a< "c:\source\DelegateTest\Resolve.txt" 26c048
Method Name: ConsoleApplication10.Program.Filter(System.String)
Class:        002612fc
MethodTable: 00263784
mdToken:      06000005
Module:       00262e7c
IsJitted:     yes
CodeAddr:     002c05f0
Transparency: Critical

The code for the Resolve.txt Windbg script is

r $t0 = ${$arg1}+5
r $t1 = $t0 + 8*by($t0+2) + 3
r $t2 = 8*by($t0+1)
r $t3 = poi($t1) + $t2
!DumpMD $t3

This does allow you to retrieve the called method from any delegate instance from .NET 2.0-4.5 regardless of its bitness. The offsets used in the script seem to point to IL structures which have the same layout across all platforms. For x86 code there is a even shorter shortcut. It seems that the two offsets are 0 normally which boils the whole calculation down to

!DumpMD poi(_methodPtr+8)

to get the desired information. For x64 though you need the script to get the right infos back. I have tried to load a dump of the short demo application into VS11 to see if VS can resolve the target methods already (would be a fine thing) but nope you will not get much infos out of the dump if you stick to VS. Windbg still remains the (only) one tool of choice to do post mortem debugging with memory dumps. You can either tell your customers that you did not find the bug and you need to install VS on their machines or you take a deep breath and remove they layers of abstractions (C#, IL, Assembler, … Quantum Physics) one by one until you can solve your problem.

If you try this out and come back to me that this script does not work it could be that you did try to dump the _methodPtr from a multicast delegate which has an invocation count > 0. The _methodPtr does then contain the code to loop through the array and calls them one by one. All you need to do is to use the script on one of the delegates contained in the _invocationList array.

To make Windbg more user friendly you should type as first command always

.prefer_dml 1

to enable “hyperlink” support for many commands in WinDbg. With .NET 4.0 the sos.dll does also support this hyperlink syntax which makes it much easier to dump the contents of objects. Whenever you click on one of the blue underlined links with the mouse a useful command like dump object contents is executed.

When you have this enabled it becomes also easier to load the right sos.dll. Many of you know the trick to use the .loadby command to load the sos dll from the same location as the clr.dll (.NET 4.0) or mscorwks (pre .NET 4.0). For some reasons this loadby trick does not work in all cases. Another nearly as fast solution is to use the lm command to display the loaded modules. When you then click on the module where you want to know the path you can then copy it into your command line and append sos.dll to your load command and you are done.

For the ones of you who can remember all shortcuts you can also use

0:000> lm i m clr
Browse full module list
start end module name
5dba0000 5e21f000 clr (export symbols) C:\Windows\Microsoft.NET\Framework\v4.0.30319\clr.dll

to show the full path of all modules which match clr as pattern.

The Return Of FILE And LINE In .NET 4.5

Alois Kraus — Mon, 09 Apr 2012 12:15:59 GMT

Originally posted on: http://geekswithblogs.net/akraus1/archive/2012/04/09/149264.aspx

Good things are hard to kill. One of the most useful predefined compiler macros in C/C++ were __FILE__ and __LINE__ which do expand to the compilation units file name and line number where this value is encountered by the compiler. After 4.5 versions of .NET we are on par with C/C++ again. It is of course not a simple compiler expandable macro it is an attribute but it does serve exactly the same purpose.

Now we do get

CallerLineNumberAttribute == __LINE__
CallerFilePathAttribute == __FILE__
CallerMemberNameAttribute == __FUNCTION__ (MSVC Extension)

The most important one is CallerMemberNameAttribute which is very useful to implement the INotifyPropertyChanged interface without the need to hard code the name of the property anymore. Now you can simply decorate your change method with the new CallerMemberName attribute and you get the property name as string directly inserted by the C# compiler at compile time.

public string UserName
{     
      get {  return _userName;     }     
      set {  _userName=value;        
             RaisePropertyChanged();  // no more RaisePropertyChanged(“UserName”)!   
          }
}

protected void RaisePropertyChanged([CallerMemberName] string member = "")
{   
    var copy = PropertyChanged; 
    if(copy != null)  
    {       
       copy(new PropertyChangedEventArgs(this, member));     
    }
}

Nice and handy. This was obviously the prime reason to implement this feature in the C# 5.0 compiler. You can repurpose this feature for tracing to get your hands on the method name of your caller along other stuff very fast now. All infos are added during compile time which is much faster than other approaches like walking the stack.

The example on MSDN shows the usage of this attribute with an example

public static void TraceMessage(string message, [CallerMemberName] string memberName = "", 
                               [CallerFilePath] string sourceFilePath = "", [CallerLineNumber] int sourceLineNumber = 0) 
{ 
    Console.WriteLine("Hi {0} {1} {2}({3})", message, memberName, sourceFilePath, sourceLineNumber); 
}

When I do think of tracing I do usually want to have a API which allows me to

Trace method enter and leave
Trace messages with a severity like Info, Warning, Error

When I do print a trace message it is very useful to print out method and type name as well. So your API must either be able to pass the method and type name as strings or extract it automatically via walking back one Stackframe and fetch the infos from there. The first glaring deficiency is that there is no CallerTypeAttribute yet because the C# compiler team was not satisfied with its performance.

A usable Trace Api might therefore look like

    enum TraceTypes
    {

        None = 0,
        EnterLeave = 1 << 0,
        Info = 1 << 1,
        Warn = 1 << 2,
        Error = 1 << 3
    }

    class Tracer : IDisposable
    {
        string Type;
        string Method;
            
        public Tracer(string type, string method)
        {
            Type = type;
            Method = method;
            if (IsEnabled(TraceTypes.EnterLeave,Type, Method))
            {
            }
        }

        private bool IsEnabled(TraceTypes traceTypes, string Type, string Method)
        {
           // Do checking here if tracing is enabled
            return false;
        }

        public void Info(string fmt, params object[] args)
        {
        }

        public void Warn(string fmt, params object[] args)
        {
        }

        public void Error(string fmt, params object[] args)
        {
        }

        public static void Info(string type, string method, string fmt, params object[] args)
        {
        }

        public static void Warn(string type, string method, string fmt, params object[] args)
        {
        }

        public static void Error(string type, string method, string fmt, params object[] args)
        {
        }

        public void Dispose()
        {
            // trace method leave
        }
    }

This minimal trace API is very fast but hard to maintain since you need to pass in the type and method name as hard coded strings which can change from time to time. But now we have at least CallerMemberName to rid of the explicit method parameter right? Not really. Since any acceptable usable trace Api should have a method signature like Tracexxx(… string fmt, params [] object args) we not able to add additional optional parameters after the args array. If we would put it before the format string we would need to make it optional as well which would mean the compiler would need to figure out what our trace message and arguments are (not likely) or we would need to specify everything explicitly just like before .

There are ways around this by providing a myriad of overloads which in the end are routed to the very same method but that is ugly. I am not sure if nobody inside MS agrees that the above API is reasonable to have or (more likely) that the whole talk about you can use this feature for diagnostic purposes was not a core feature at all but a simple byproduct of making the life of INotifyPropertyChanged implementers easier.

A way around this would be to allow for variable argument arrays after the params keyword another set of optional arguments which are always filled by the compiler but I do not know if this is an easy one.

The thing I am missing much more is the not provided CallerType attribute. But not in the way you would think of. In the API above I did add some filtering based on method and type to stay as fast as possible for types where tracing is not enabled at all. It should be no more expensive than an additional method call and a bool variable check if tracing for this type is enabled at all. The data is tightly bound to the calling type and method and should therefore become part of the static type instance. Since extending the CLR type system for tracing is not something I do expect to happen I have come up with an alternative approach which allows me basically to attach run time data to any existing type object in super fast way. The key to success is the usage of generics.

    class Tracer<T> : IDisposable
    {
        string Method;

        public Tracer(string method)
        {
            if (TraceData<T>.Instance.Enabled.HasFlag(TraceTypes.EnterLeave))
            {
            }
        }

        public void Dispose()
        {
            if (TraceData<T>.Instance.Enabled.HasFlag(TraceTypes.EnterLeave))
            {
            }
        }

        public static void Info(string fmt, params object[] args)
        {
        }

        /// <summary>
        /// Every type gets its own instance with a fresh set of variables to describe the 
        /// current filter status.
        /// </summary>
        /// <typeparam name="T"></typeparam>
        internal class TraceData<UsingType>
        {
            internal static TraceData<UsingType> Instance = new TraceData<UsingType>();

            public bool IsInitialized = false; // flag if we need to reinit the trace data in case of reconfigured trace settings at runtime
            public TraceTypes Enabled = TraceTypes.None; // Enabled trace levels for this type
        }
    }

We do not need to pass the type as string or Type object to the trace Api. Instead we define a generic Api that accepts the using type as generic parameter. Then we can create a TraceData static instance which is due to the nature of generics a fresh instance for every new type parameter. My tests on my home machine have shown that this approach is as fast as a simple bool flag check. If you have an application with many types using tracing you do not want to bring the app down by simply enabling tracing for one special rarely used type. The trace filter performance for the types which are not enabled must be therefore the fasted code path. This approach has the nice side effect that if you store the TraceData instances in one global list you can reconfigure tracing at runtime safely by simply setting the IsInitialized flag to false. A similar effect can be achieved with a global static Dictionary<Type,TraceData> object but big hash tables have random memory access semantics which is bad for cache locality and you always need to pay for the lookup which involves hash code generation, equality check and an indexed array access.

The generic version is wicked fast and allows you to add more features to your tracing Api with minimal perf overhead. But it is cumbersome to write the generic type argument always explicitly and worse if you do refactor code and move parts of it to other classes it might be that you cannot configure tracing correctly. I would like therefore to decorate my type with an attribute

    [CallerType]
    class Tracer<T> : IDisposable

to tell the compiler to fill in the generic type argument automatically.

    class Program
    {
        static void Main(string[] args)
        {
            using (var t = new Tracer()) // equivalent to new Tracer<Program>()
            {

That would be really useful and super fast since you do not need to pass any type object around but you do have full type infos at hand. This change would be breaking if another non generic type exists in the same namespace where now the generic counterpart would be preferred. But this is an acceptable risk in my opinion since you can today already get conflicts if two generic types of the same name are defined in different namespaces. This would be only a variation of this issue.

When you do think about this further you can add more features like to trace the exception in your Dispose method if the method is left with an exception with that little trick I did write some time ago. You can think of tracing as a super fast and configurable switch to write data to an output destination or to execute alternative actions. With such an infrastructure you can e.g.

Reconfigure tracing at run time.
Take a memory dump when a specific method is left with a specific exception.
Throw an exception when a specific trace statement is hit (useful for testing error conditions).
Execute a passed delegate which e.g. dumps additional state when enabled.
Write data to an in memory ring buffer and dump it when specific events do occur (e.g. method is left with an exception, triggered from outside).
Write data to an output device.
….

This stuff is really useful to have when your code is in production on a mission critical server and you need to find the root cause of sporadic crashes of your application. It could be a buggy graphics card driver which throws access violations into your application (ok with .NET 4 not anymore except if you enable a compatibility flag) where you would like to have a minidump or you have reached after two weeks of operation a state where you need a full memory dump at a specific point in time in the middle of an transaction.

At my older machine I do get with this super fast approach 50 million traces/s when tracing is disabled. When I do know that tracing is enabled for this type I can walk the stack by using StackFrameHelper.GetStackFramesInternal to check further if a specific action or output device is configured for this method which is about 2-3 times faster than the regular StackTrace class. Even with one String.Format I am down to 3 million traces/s so performance is not so important anymore since I do want to do something now.

The CallerMemberName feature of the C# 5 compiler is nice but I would have preferred to get direct access to the MethodHandle and not to the stringified version of it. But I really would like to see a CallerType attribute implemented to fill in the generic type argument of the call site to augment the static CLR type data with run time data.

Alois Kraus

Using WPT For Batch Script Profiling

How To Make Your System Slower With WMI

Profiling Code – The Microsoft Way

Profiling Startup Of VS2012 – SpeedTrace Profiler

Profiling Startup Of VS2012 – JustTrace Profiler

Profiling Startup Of VS2012 – YourKit Profiler

Profiling Startup Of VS2012 – dotTrace Profiler

Profiling Startup Of VS2012 – Ants Profiler

Performance Optimization – It Is Faster When You Can Measure It

Measure with a profiler to get an idea where potential bottlenecks are.

Measure again with tracing only the specific methods to check if this method is really worth optimizing.

Optimize it

Measure again.

Be surprised that your optimization has made things worse.

Think harder

Implement something that really works.

Measure again

Finished! - Or look for the next bottleneck.