I’m trying to understand a profile showing a lot of CPU usage underneath ServeHTTP, where HTTP serving is supposed to be a small part of the overall program’s profile. I can see that a few expensive database calls are being made, but these can be called from several handlers and I’m not able to figure out which handlers are responsible. Using the “web” command, I get this:
where the part of the call stack I’m actually interested in is somewhere in the dotted line I’ve pointed to - I know withNeed() is expensive, but I need to know which request handler called it. I’ve tried playing around with focus=..., edgefraction=0, nodefraction=0 and various web calls that should focus on the stuff that should be in there, but it doesn’t affect this part of the graph.
The actual code for this part is here - all the handlers are method values, does that make them unprofileable here or something? Perhaps they are the loose main.func·007 and so on referred to above?
Edit: If anyone’s interested in taking a look for themselves, the profile and accompanying binary is here.
Not sure if I should be impressed that I apparently understand the profiler as well as anyone, or sad that apparently nobody really understands the profiler…
I think you need to keep following the trace down further, those functions don’t account for much time by themselves. Looking at the profile, most of the time is being spent in leveldb.
So (part of) the problem is that there are a lot of closures on the way to the actual HTTP handler, adding things like authentication, debugging, CSRF checks and so on. These are the main.func·003 etc in the list above. The solution turned out to be not to use the web view (awesome as it is), but do what @dfc suggests. Using lines (to see what the closures represented) and sorting by ■■■ makes it easy to track down the first “interesting” hit: