Hi,
After drastically reducing the number of mysql queries, and caching costly-to-compute fragments, I have managed to reduce the execution time of my code, for heavy (i.e. big) pages from about 900-1000 to about 200 milliseconds.
However, the execution time logged on onEndRequest is between 200 and 400 ms more!!
This happens on the online server. However, on my local machine this time is practically zero.
Is it the actual time spent for network I/O (well… network O)? In that case I won’t worry about it. But I thought PHP would just send the output to a buffer and then let Apache send it through. Does PHP block until the output is flushed and only then is onEndRequest called?
I can see how CApplication::run() works, but the question is more about PHP and its interaction with Apache than about the framework.
Here’s how I measure it.
I have extended CController through a class called Controller which overrides processOutput:
public function processOutput($output) {
$r=parent::processOutput($output);
Yii::log(" * Time after processing output: ".Yii::getLogger()->executionTime, 'profile');
return $r;
}
and then I have a "requestEventHandler" application component that just attaches a method of its own as handler to the onEndRequest event (at the beginning of the handler list, because obviously it must be done before logs get processed:
class RequestEventHandler extends CApplicationComponent {
public function init() {
Yii::app()->getEventHandlers('onEndRequest')->insertAt(0,array($this, 'endRequest'));
}
public function endRequest($event) {
Yii::log(" * Total time: ".Yii::getLogger()->executionTime, 'profile');
}
Some example output:
* Time after processing output: 0.26433086395264
* Total time: 0.45684504508972
(this is a very short page)
* Time after processing output: 0.18872690200806
* Total time: 0.75160908699036
(this is a very long page, more than 150k, which takes very little to generate as the biggest chunk is cached)
Though I’m using ‘profile’ as the category, I have nothing else being logged as ‘profile’, no beginProfile or endProfile being executed, and YII_DEBUG is false. There are only very few logs being logged (not that only a few get collected but many get logged, no: just very few get logged at all). I clarify this just to exclude that time may be spent processing logs, which anyway wouldn’t be measured since the above time is obviously measured before processing log (and couldn’t be otherwise).
I really think it’s just the network outputting time, hence not an issue (the fact that on local machine the time becomes close to zero seems to suggest that), but I need to be sure.