How to profile all assemblies including BCL

icelava

We have a WCF/IIS service with manual clockings for the begin and end of operation calls. From the logs, we observe the execution time of the app code per operation can be reasonably fast - tens of milliseconds. However, the client making the calls can take hundreds of milliseconds to even seconds to get back the complete response depending on the load.

We are puzzled by this "transmission lag", and would like to know the amount of time the framework code is spending before pushing the data out the wire.

Visual Studio profiler makes it exceedingly hard to include framework assemblies for profiling and instrumentation, and I was hoping ANTS Performance Profiler can shed some light into those activities.

Sadly, on attempting an ASP.NET/IIS 7 profiling session, it appears to only focus on our app code. How can we possibly profile the activities of system.servicemodel, system.web.mvc and the likes?

icelava

Hmmm it looks like if i test with another operation, the system.servicemodel call stack do appear.

I am guessing whether they appear or not is relative to the duration and intensity of other executing code?

icelava

Ok i am perplexed on how to obtain consistent execution timelines of all methods (including BCL) ?

For example when we call a WCF service operation, how is it possible to show the execution durations from first time the ASP.NET runtime picks up the request from IIS all the way to our service app code, and then back?

The Call tree seems to be selectively in what it shows with its stacks of methods and difficult to make out a chronological flow of method calls...

Jessica R

Hi Aaron,

Thanks for your post!

Can I please check--are you using sampling mode of profiling? Or do you have Tools>Options>'Avoid profiling extremely trivial methods' enabled?

So long as you have one of the "all methods inc. framework" profiling modes selected and have enabled profiling of trivial methods, you should see every single managed method call that your application makes, including those from framework DLLs. (You'll also want to make sure to display 'All methods')

Just a few notes:
- The profiler sorts methods in the call tree in order execution time (it's not possible to sort them chronologically)
- The area you have selected on the timeline will also affect what you see in the call tree, so it may be worth selecting the entire timeline to check for the methods you're interested in

I'm also not sure if you are looking for line-level timings of the frameworks DLLs, but if you are, you could try downloading a trial of .NET Reflector - http://www.red-gate.com/products/dotnet ... reflector/ and generating pdb files for the framework DLLs you're interested in. You can then place these in your application directory so that the profiler will find them and give line-level timings for those DLLs.

Hope this helps!

icelava

Hey Jessica, sorry i couldn't get back to this matter as there were a ton of other issues to attend to.

The thing is even as [Avoid profiling extremely trivial methods] and [Simplify very complex stack traces to save memory] are unchecked I do not see, or see very inconsistent displays of call trees that sometimes show up BCL method call stacks, and sometimes not - for the same functionality i am attempting to test for.

Furthermore, even with the presence of my own app .pdb files it does not appear to be able to dig into the source code.

Another big confusion I have has been the lengthy duration of time spent in the thread (Waiting for synchronization) and (Sleeping) categories that I wish could be expanded to figure out which points of code contribute to them.

At the end i am filled with confusion what are the exact contributions to the latency of our service app, as it sometimes report our app code, and sometimes report BCL (i.e. WCF serialisation etc) code. It is difficult to judge without having an absolute timeline picture, instead of visualising preferentially based on relative scales.

Jessica R

Hi there,

No worries!

Hm can I just make sure--which edition of the profiler are you using and what profiling mode? I recall you had another post asking about the differences between pro and standard. (If you are using a trial edition, that is the professional edition.) It does sound as though you might have the standard edition, as that only offers two modes of profiling - "sampling" and "line-level & method-level timings - only methods with source".

The "Sampling" mode will only show a sampling of the methods called in the call tree. This could include both BCL methods and your methods with source, but not every single method that is called will be shown and the methods shown may be different for each profiling session. If you are using this mode, that might explain the inconsistencies.

On the other hand, if you use the "line-level & method-level timings - only methods with source" profiling mode, that could explain when you don't see any BCL calls at all since there's no pdb files for them.

That is strange that you're not able to dig into your methods with source though. Can I please check--are these at least showing up in bold? And is there any sort of error message in the source view window when you try to drill down into the line-level timings?

Regarding "waiting for synchronization" and "sleeping"..
Waiting for synchronization is effectively trapping the WaitforsingleObject calls and some others like socket.receive. Basically it means a thread is sitting there waiting for an AsyncResult from another thread via a WaitOne() method, etc. Sleeping is similar, only one thread is involved. The thread has been told to wait by a Thread.Sleep call.

Thanks!