Results profiling CakePHP event system
Written by @ChrisTitos, @erik-am, @ntimal and @wilcowisse.
We did a small profiling on some small CakePHP applications with XDebug with profiling turned on. The read the profiling log files we used Webgrind. In order to get reliable results we turned caching off.
The first application we constructed only consists of a Controller and a view. There are no database operations done. The following figure shows the invocation count and the total self cost in percent (%) of the 10 most time consuming components.
The App:load() methods is far the most time consuming. This is probably the case because it contains many file includes (not shown in the figure). And indeed, we observe that there are 2 methods within the CakeEventManager which appear in the top 10. Although the application has a limited number of user classes, there are 32 events dispatched. The following picture shows the methods which the CakeEventManager->dispatch() method is called from and the total call cost.
Also the _attachSubscriber() function is quite time consuming. The following figure shows the internal calls and their cost.
We are also able to show what the php function call_user_func(), which is called from the dispatch method, calls.
The second application is an extension of the first application. The controller has in this case 7 Components, which are, according to the sequence diagrams called. The following figure shows the top 10 most consuming parts of this application.
We did not see a high increase in the time complexity of the methods in the CakeEventManager. The fact that, for example, _attachSubscriber() is called the same number of times with the same cost, is easily explained: in all cases there is only one ComponentsCollection that is attached to the CakeEventManager. This is true even if there are no components at all.
So the cost of having many components (or behaviours or helpers) is never in attaching the listeners. There is a slight increase in the cost of dispatches comparing application 1 and 2 and that confirms expectations. If a dispatched event triggers the ComponentCollection, it calls methods on all its Components.
The important point is that CakeEventManager->dispatch() consumes a lot of unneccessary time if there are no Behaviors/Components/etc. and the callbacks are empty. For example, there is always a ComponentCollection as a listener, and when an event is fired, then ComponentCollection->trigger() is called in the dispatch method, but it is unnecessary if are no Components.
CakePHP 2.1.x was the first release which had the new Event system. The profiling results are roughly the same as for version 2.3.x. We performed the profiling with Application 2.
In version 2.0.x we see some differences with respect to newer versions. Logically, because the event subsystem had not been introduced yet, the CakeEventManager is absent. However, it is remarkable that ObjectCollection->trigger() appears in the list now.
The trigger() method spends most of its time on the php::call_user_func_array() function, as we see in the next figure.
Within the whole application ObjectCollection->trigger() is the only method which calls this php function. It is used to call the right listener method. So the problem seems not to be new since CakePHP 2.1, but only be replaced to other methods. This sheds some new light on the performance issues of the events. It could be that the architecture isn't the bottleneck but that the internal functionality should be revised.
The previous experiments were performed on a small example application. Now we will consider a large application, a Content Management System, that is actually used in production. When a certain page is viewed, several Model classes are involved: Page, MenuItem and Section. A Page belongs to a Section of the website and a Section defines which MenuItems should appear in the sidebar. Furthermore, multiple Components are used, such as a MenuBuilder for constructing the menu, HitsLogger for logging visitor counts and a Component provided by the HTMLPurifier plug-in. Also, many Model classes have the ContainableBehavior. Therefore, quite some callbacks (both empty and non-empty ones) are involved.
The application was written for CakePHP 2.0. We performed an upgrade to CakePHP 2.1.5 and measured the performance of requesting a single page before and afterwards. The results are shown in the table below. The times are averages over 7 trials. We also included a list of calls to php::call_user_func_array() in version 2.1.5.
| v2.0 | v2.1 | |||
|---|---|---|---|---|
| Function call | Time | #invocations | Time | #invocations |
| ObjectCollection->trigger | 61 ms | 22 | 59 ms | 28 |
| php::call_user_func_array | 60 ms | 48 | 55 ms | 80 |
What we expected was that call_user_func_array() would be invoked more often, which was confirmed. However, we expected ObjectCollection->trigger() to take much more time, but it did not. In fact, the time decreased. Of course, an explanation for the decrease is that between version 2.0 and 2.1 more things were changed than just the events system. Therefore, it is possible that the logic that is actually inside the callbacks performs better. Having said that, if the fact that callbacks were incorporated into the events system had been a major performancy penalty, we surely would have expected to see that in the results. Therefore, we conclude that the change has not seriously impacted the performance.