CakePHP requestAction

We are currently undergoing another round of site optimization. This time, I used APD to profile our sites. Since the home page is the most important page, I started from profiling it.

Total Elapsed Time = 1.74
Total System Time = 0.51
Total User Time = 1.18


Real User System secs/ cumm
%Time (excl/cumm) (excl/cumm) (excl/cumm) Calls call s/call Memory Usage Name
--------------------------------------------------------------------------------------
77.8 0.00 1.35 0.00 0.89 0.00 0.39 21 0.0000 0.0645 0 View->_render
77.8 0.00 1.35 0.00 0.89 0.00 0.39 23 0.0001 0.0589 0 include
69.1 0.00 1.20 0.00 0.83 0.00 0.36 1 0.0001 1.2032 0 main
64.0 1.11 1.11 0.76 0.76 0.33 0.33 1 1.1136 1.1136 0 apd_set_pprof_trace
48.1 0.00 0.84 0.00 0.55 0.00 0.24 20 0.0001 0.0419 0 View->renderElement
30.4 0.00 0.53 0.00 0.35 0.00 0.15 1 0.0001 0.5289 0 View->renderLayout
27.7 0.00 0.48 0.00 0.31 0.00 0.14 2 0.0001 0.2410 0 View->requestAction
27.7 0.00 0.48 0.00 0.31 0.00 0.14 2 0.0001 0.2407 0 Dispatcher->dispatch
9.4 0.00 0.16 0.00 0.11 0.00 0.05 1 0.0001 0.1636 0 MessagesController->constructClasses
8.7 0.00 0.15 0.00 0.09 0.00 0.06 1 0.0001 0.1513 0 BuddiesController->constructClasses
7.0 0.00 0.12 0.00 0.10 0.00 0.02 6 0.0000 0.0202 0 call_user_func_array
6.8 0.02 0.12 0.01 0.08 0.01 0.04 508 0.0000 0.0002 0 Set->extract
6.2 0.00 0.11 0.00 0.07 0.00 0.01 2 0.0000 0.0543 0 Dispatcher->_invoke
5.9 0.05 0.10 0.03 0.06 0.04 0.04 2242 0.0000 0.0000 0 low
5.9 0.00 0.10 0.00 0.06 0.00 0.04 38 0.0000 0.0027 0 array_map
5.2 0.09 0.09 0.06 0.06 0.02 0.02 1305 0.0001 0.0001 0 handleError
5.0 0.00 0.09 0.00 0.04 0.00 0.00 2 0.0000 0.0433 0 MessagesController->beforeFilter
4.3 0.00 0.08 0.00 0.04 0.00 0.01 2 0.0000 0.0377 0 Dispatcher->start
4.3 0.00 0.07 0.00 0.05 0.00 0.02 125 0.0000 0.0006 0 m
3.5 0.03 0.06 0.00 0.03 0.00 0.00 4 0.0068 0.0154 0 MochaLoggerComponent->debug

The highlighted lines show that the rendering takes a long time. And the time is mostly spent on requestAction. As I recall, CakePHP requestAction is really slow. It's just so happen that we have two requestAction calls in our layout, which is invoked in every single request.

Instead of using requestAction to retreive data in the layout, I added DB call in AppController and pass the data to the layout. The result is stunning.

Total Elapsed Time = 1.29
Total System Time = 0.38
Total User Time = 0.89


Real User System secs/ cumm
%Time (excl/cumm) (excl/cumm) (excl/cumm) Calls call s/call Memory Usage Name
--------------------------------------------------------------------------------------
95.6 0.00 1.23 0.00 0.85 0.00 0.36 1 0.0001 1.2346 0 main
88.6 1.14 1.14 0.79 0.79 0.33 0.33 1 1.1441 1.1441 0 apd_set_pprof_trace
11.4 0.00 0.15 0.00 0.10 0.00 0.04 21 0.0000 0.0070 0 View->_render
10.6 0.00 0.14 0.00 0.09 0.00 0.04 21 0.0001 0.0065 0 include
8.5 0.00 0.11 0.00 0.08 0.00 0.03 20 0.0001 0.0055 0 View->renderElement
5.9 0.00 0.08 0.00 0.05 0.00 0.03 123 0.0000 0.0006 0 m
4.8 0.00 0.06 0.00 0.04 0.01 0.02 123 0.0000 0.0005 0 __
3.7 0.00 0.05 0.00 0.03 0.00 0.02 1 0.0001 0.0484 0 View->renderLayout
2.8 0.00 0.04 0.00 0.02 0.00 0.01 123 0.0000 0.0003 0 I18n::translate
2.3 0.03 0.03 0.02 0.02 0.01 0.01 403 0.0001 0.0001 0 handleError
1.1 0.00 0.01 0.00 0.01 0.00 0.01 27 0.0000 0.0005 0 imgsrc
0.7 0.00 0.01 0.00 0.01 0.00 0.01 27 0.0000 0.0004 0 getUrlHashByte
0.7 0.00 0.01 0.00 0.00 0.00 0.00 2 0.0000 0.0043 0 FormHelper->select
0.6 0.01 0.01 0.01 0.01 0.00 0.00 582 0.0000 0.0000 0 ord
0.6 0.00 0.01 0.00 0.01 0.00 0.00 6 0.0002 0.0013 0 require_once
0.6 0.01 0.01 0.00 0.00 0.00 0.00 123 0.0001 0.0001 0 debug_backtrace
0.6 0.00 0.01 0.00 0.01 0.00 0.00 14 0.0000 0.0005 0 Version::link
0.5 0.00 0.01 0.00 0.00 0.00 0.00 13 0.0000 0.0005 0 VersionHelper->link
0.5 0.00 0.01 0.00 0.01 0.00 0.00 1 0.0000 0.0071 0 LanguageListHelper->nameFromCode
0.5 0.01 0.01 0.01 0.01 0.00 0.00 235 0.0000 0.0000 0 is_array

The first time around, it took 1.74s, excluding the 1.11s on the profiling call, the request was 0.63s.

The second time, it took 1.29s, excluding the 1.14s on the profiling call, the request was 0.15s.

(0.63-0.15)/0.63 = 77%.

Of course, this calculation is not all that scientific. I would have to run a controlled stress time over a long period of time to get an accurate result. However, based on the simple number difference on the render layour call, I think it's safe to say removing requestAction will pay off.