Skip to main content

This site requires you to update your browser. Your browsing experience maybe affected by not having the most up to date version.

General Questions /

General questions about getting started with SilverStripe that don't fit in any of the categories above.

Moderators: martimiz, Sean, biapar, Willr, Ingo, swaiba, simon_w

What does "all_execution" signify in the profiler?


Reply


5 Posts   1295 Views

Avatar
markguinn

Community Member, 13 Posts

13 January 2010 at 2:57am

I'm doing some work optimizing one of our sites using the profiler (?debug_profile=1) and I've noticed that sometimes "all_execution" is the top entry, sometimes representing 50% or more of the execution time. I've looked at sapphire/main.php so I know technically what "all_execution" is representing, but I'm curious what's actually going on there. Does that mean that the database server is running slow? Does it mean that the controller is taking a long time? If your site is running slowly and all_execution is taking up all the time, where do you look first?

Thanks,
Mark

Avatar
Pigeon

Community Member, 243 Posts

13 January 2010 at 10:59am

I'm not sure; but the name implies to me it is the total execution time to generate the page...

Which might explain why it is 50% (as all the parts will add up to equal the total).

Someone please correct me if I'm wrong.

Avatar
markguinn

Community Member, 13 Posts

14 January 2010 at 1:55am

Thanks for the input, Pigeon. You're right that it encompasses most of the program execution time. The problem is that it's adding up to more than 50%, so there is some missing time in there. I'm just wondering what the missing time normally represents. Looking around on the forums, I've seen at least one other post where that was going on, so I know it's not only me.

Mark

Avatar
Pigeon

Community Member, 243 Posts

14 January 2010 at 1:43pm

Odd, is it a significant amount of time? It could just be that the total timer runs for the entire execution where as the others don't start and stop instantainiously and so the to total time includes the initialisation of the other timers.

Avatar
TotalNet

Community Member, 181 Posts

21 July 2010 at 4:57pm

Edited: 21/07/2010 5:15pm

This has been bugging me so I've just done a little digging into how profiler actually works. If anyone's still interested.

[url=http://www.adepteo.net/profiler/manual.html]Profiler[/url] works by starting and stopping timers around code execution, quite simple really, however, the clever part is that you can have nested timers. When you start a timer within another, the parent timer is suspended.

This is the case with all_execution, which is started in main.php, so essentially the time it reports is really unprofiled time ... i.e. code that does not use profile timers and is not contained within another timer.

To get more detail you really need to dig into the code starting at Director::direct($url); and add timers - although I'm not sure how many levels you can "nest" timers I don't think there's a limit.

Obviously this involves editing core files, however, if you find some code without a profile timer that has a significant chunk of execution time then I'm sure it would be appreciated by the wider community. I'll let you know if I turn up anything.

Cheers,

Rich

EDIT: you can also use profile_trace to see the trace and find potential gaps between all_execution resuming and suspending e.g. ?debug_profile=1&profile_trace=1 at the end of your URL