4

I'm trying to profile a .NET application in Visual Studio using the build-in profiler. Tracking CPU samples, I come across something weird. In a part of the application I have the following (simplified for clarity):

var requestObject = new RequestObject(parameters);
var result = GetResult(requestObject,"stringvalue");

I see that the second row uses about 10% of the samples. However, the method ´GetResult()´ only uses about 7%, the rest seems to be in [clr.dll]. I know clr.dll is responsible for garbage collection, JIT compiling, context switching etc, and the ´GetResult()´ method is fairly complex (spanning multiple assemblies, possibly using multiple threads) so it's not implausible that some of these actions need to be taken once the method returns. The ´RequestObject´ is also a bit complex so that might have something to do with it.

My question is: Can I track down exactly what happens here, and what can I do to make it faster? Note that 3% does not sound much, but ´GetResult()´ will be called a lot of times during the programs lifespan, even though when testing it is only run once. And it is very important that I can reduce the response time of the application.

Thanks a lot in advance for any answers!

Kristof U.
  • 1,263
  • 10
  • 17
DukeOf1Cat
  • 1,087
  • 15
  • 34
  • You have to pick the right fight. Assuming you *could* make GetResult take 1% instead of 10% then you've only made your program 9% faster. You've got another 90% as a potential optimization target, code that you actually may have source for. You cannot optimize code buried in clr.dll – Hans Passant Nov 14 '12 at 12:04
  • 1
    @HansPassant As I wrote, GetResult() is only a small part of execution when testing, because there is an initiation phase that is quite intense. Over time, when GetResult() has been called a few thousand times, I think it will make up almost 100% of CPU time. To clarify, the response time of the application is almost 100% dependent on GetResult(). So is there potential to optimize up to 30% without even touching GetResult()? – DukeOf1Cat Nov 14 '12 at 12:38

3 Answers3

3

You're not alone in trying to figure out what the profiler output means. SO has many questions like that. I work in a big .net app, and I've tried various profilers, and I know it's not what people are taught, but what actually works is this method. For one thing, you can take some samples during initialization, and other samples during basic run time. You don't have to pile the two together and try to guess what the load would be like in each phase without the other.

Also, if you look only at CPU time, you will miss any speedup opportunities due to extra I/O. You should not assume there isn't any, or that it's insignificant. If you do manage to find a CPU-only speedup opportunity, and fix it, then the part you didn't find becomes a larger fraction of the whole. You could get to a point where if you can't find anything else to fix, you might assume there is nothing else, when in fact there is, and it could be large. If you take samples yourself, you get a clear view of what's costing time.

You might want to say "But that's not accurate!" Well, OK, if there's something you could fix, and fixing it would save 90% of the time, but your inquiry is inaccurate and says it's taking 80%, or 95%, does that prevent you from fixing it and getting the 10-times speedup? The fact is, when your goal is to actually find problems, rather than just measure them, the bigger they are, the fewer samples it takes.

Community
  • 1
  • 1
Mike Dunlavey
  • 40,059
  • 14
  • 91
  • 135
  • Yes, I read about this solution in a related post. The whole cyckle takes about 500 milliseconds to run, so I think it would be difficult to collect the samples manually with an even spread across the time spectrum. If I manually trigger the cycle (by connecting to the application and calling a method) and then hit pause, chances are I will always hit it at the same spot since there are reaction times etc to weigh in. Do you have a suggestion for automating this? – DukeOf1Cat Nov 14 '12 at 16:35
  • Also, what if the stuff done i clr.dll is not one thing, but many different? Then they will likely only show once each in my samples, so how do I know if I've found anything? – DukeOf1Cat Nov 14 '12 at 16:36
  • 2
    @Joel: First question: A couple answers: 1) try it and see, and 2) put a temporary loop of like 100 times around your half-second process. Second question: Chances are it is in the clr.dll, but the stack tells you what in your code is requesting it. So, for example, if you see it doing a lot of `new GetResult`, you can check if maybe you could re-use old ones - stuff like that. The point is, you can use your whole brain to understand what's going on, rather than just puzzling over some numbers coming out. – Mike Dunlavey Nov 14 '12 at 16:42
  • 1
    @Joel: If you're up for a little math, [*this explains it.*](http://scicomp.stackexchange.com/a/2719/1262) – Mike Dunlavey Nov 14 '12 at 16:46
2

You may be interested in using the PerfView tool that is available for free download. I agree with Mike that in this scenario (of a web-request) CPU might not be the dominate factor, so using a CPU profiler could easily be inaccurate. PerfView can do CPU analsysis, but it has the ability to do 'wall clock' analysis too (see the 'Wall Clock / Blocked time' link on PerfView's welcome page). This view shows BOTH CPU and blocking but takes more care in interpreting the data (you have to find the right thread and include the segment of thread of interest). If this is an ASP.NET application there is a special view (the ASP.NET Thread Time Stacks), that is of particular interest (also in the docs).

The bad news is that there is no substitute for understanding what your profiler is telling you, so you will have to spend some time learning what this tool is showing you. I think it is more then worth it and there are PerfView Videos, and reasonably good documentation built into the tool to help you out, but you have to be willing to invest some time (e.g an hour).

The good news is that the payoff is for your investment is non-trivial. You should be able to figure out your particular problem within an hour, and with a few hours of investment you will be able to figure a broad variety of issues in pretty much any application (even ones you did not build). The tool is very powerful, but with power comes lots of potential avenues of investigation, and with it the ability to misuse the data and become confused.

Vance Morrison
  • 146
  • 1
  • 2
1

this post is old but I wanted to clarify a few things. In the current implementation of the profiler whenever you see [], it means we know the name of the dll but were unable to resolve symbols for it. One reason is that you did not select the microsoft symbol servers in your sysmbol settings. Another possibility is that the module was ngen (wherein you will see []). In that case you will need to generate the ngen pdb to actually get symbols resolved. Once that occurs you should be able to see exacly what functions are using what fraction of the cpu.

Andre Hamilton
  • 236
  • 1
  • 3