Wall clock time analysis using PerfView
By default when you collect data using PerfView you are collecting the right events to do a CPU time investigation. However there are other things that can slow your program down beside using too much CPU time. It is not uncommon to be disk bound (startup scenario are often like this), or network bound, or are waiting on other external programs. For cases like this, a CPU investigation is inappropriate.
In fact when people want to do time investigations, they typically want to do wall clock time investigations (that is the time you can measure by observing the external behavior of the program). Thus people really want to measure wall clock time, so why does PerfView concentrate on CPU time?
There is a reason. Wall clock time investigations are significantly more complex than CPU investigations. The fundamental reason is in most applications your CPU usage TENDS to be on your 'critical path'. That is MOST CPU time IS important to your end-to-end time. This is because programs TEND not to have 'background' CPU activity that is 'uninteresting'. Thus all CPU time TENDS too be important and so you can simply go after ANY CPU waste. However for wall clock time this is RARELY true. Most programs have threads that spend much of their time blocked waiting for work (and that time is NOT on anyone's critical path'), but these threads MIGHT wake up and perform a critical service. Thus PARTS of SOME threads wall clock time is important but much of it is unimportant. This is the key difference that is at the heart of what makes wall clock investigations hard. You now have to think about 'critical paths', and you must be much more careful about segregating 'uninteresting' wall clock time' from 'critical path' wall clock time'.
PerfView has been able to collect and present data associated with wall clock for a while, but recently I added documentation about how to use it. You can get at this documentation by clicking on the 'Wall Clock' hyperlink in PerfView's main 'Welcome page'. You can also simply search for 'Wall Clock' in the documentation.
I have also started to add series of videos on wall clock time investigations to the Channel 9 PerfView Videos. The first of these is Wall Clock Time Basics. There will shortly be several more.
These videos use a 'BlockedTime' application. I have included the source code for this application as well as the data files I used in these videos in the link below. To use the attachment, simply open the ZIP file, and then drag the folder inside it to your desktop or other location. The directory include the EXE as well as the PDB (symbols) for it, and the complete VS 2012 source code (in the src directory, the Program.cs file has all the code). Also included are BlockedTimesync.ETL.ZIP (the run where all activity is on a single thread) and BlockedTimeParallel.ETL.ZIP (the run where the search is done in parallel). These ETL.ZIP files do NOT need to be unzipped, simply open them in PerfView and they will implicitly be uncompressed.
Update: There are now more videos on wall clock time analysis
- Wall Clock Time Basics (the first which I talk about above (and uses the BlockedTimeSync.ETL.ZIP data))
- Leveraging Tasks make sense of Parallel/Asynchronous programs this one uses the BlockedTimeParallel.ETL.ZIP data)
- Investigating Wall Clock Response Time of ASP.NET scenarios which I talk about in this blog entry.