cakephp paginator extremely slow

Question

I have a cakephp application, 2.4, and I'm having issues with the Paginator component. First off, it's not the database, it's definitely the execution of parsing the query results. I have DebugKit installed and can see that my mysql query for the paginated data takes a whole 2 ms. The table has 2.5 million records of messages, and 500,000 users. Obviously proper indexing is in place. But, the controller action is taking 6167.82 ms. So, here's my controller action:

$this->Paginator->settings = array(
  'Message' => array(
    'fields' => array(
      'Recipient.username',
      'Recipient.profile_photo',
      'Recipient.id',
      'Message.*'
    ),
    'joins' => array(array(
      'table' => 'users',
      'alias' => 'Recipient',
      'type' => 'LEFT',
      'conditions' => array(
        'Recipient.id = `Message`.`recipient_id`'
      )
    )),
      'conditions' => array( 
      'Message.sender_id' => $this->Auth->user('id'), 
      'Message.deleted_by_sender' => '0' 
    ), 
    'limit' => 10, 
    'order' => 'Message.id DESC', 
    'recursive' => -1 
  )
);
$sents = $this->Paginator->paginate( 'Message' );
$this->set( 'sents', $sents );
$this->view = 'index';

I've google this and searched stack overflow. The majority of the responses are for poor mysql optimization which isn't my case. The other half of the responses suggest containable. So, I tried containable. Using contain was actually slower because it tried to grab even more data from the user's field than just the username, photo, and id. Then when cake built the array from the query results it executed nearly 500 ms slower with containable because of the extra user data I'm assuming.

I'm going to now dig into the cake Paginator component and see why it's taking so long to build the response. I'm hoping someone beats me to it and has a good solution to help speed this up.

My web server is running ubuntu 12.04 with 3gb ram, apache and mod_php with apc installed and working for the model and core cache. The database is on a separate server. I also have a redis server persisting other user data and the cake session data. There is plenty of power here to parse 10 records from a mysql query containing about a dozen rows.

EDIT: ANSWER

As suggested first by Ilie Pandia there was something else happening, such as a callback, that was slowing down the pagination. This was actually unrelated to the pagination component. The Recipient model had a behavior that loaded an sdk in the setup callback for a 3rd party service. That service was taking several seconds to respond. This happened when the linkedModel in the query was loaded to filter the results. Hopefully anyone else looking for reasons why cake might be performing poorly will also look at the callbacks on models in the application and plugins.

the ralationship is just Message belongsTo Recipient or there is more? — arilia, Jan 28 '14 at 19:59
Message belongs to Sender, Recipient, and MassMessage. I've been debugging this for about an hour this morning and have figured out what is taking so long. I have not figured out why yet though. I will update this as soon as I know more. — mneil, Jan 29 '14 at 16:57
I am facing to same issue. I presume it's because Paginator component needs the total count and make the query with `WHERE 1=1` first, then paginate according to `limit` — zeflex, Jan 26 '18 at 21:13

score 0 · Accepted Answer · answered Jan 28 '14 at 19:03

0

I see no reason for this to run slow at all.

So this suggests that there are some callback installed (either in the model or the controller) that do additional processing and inflate the action time so much.

That is assuming that there is nothing else in the controller but what your wrote.

You could actually measure the time of the paginate call itself and I think you will find that it is very fast. So the bottle neck is elsewhere in the code.

PS: You could also try to disable DebugKit for a while. Introspection may take very long for some particular cases.

answered Jan 28 '14 at 19:03

Ilie Pandia

1,829
14
16

"I have DebugKit installed", second sentence in my question. That code is the entirety of the controller action. I didn't write this entire thing and there may be some callbacks hidden somewhere that I'm unaware of though. I will also check for that and update this. Thanks – mneil Jan 29 '14 at 15:34
I've noticed that you have DebugKit installed and that you've measure the query and action time. What I was suggesting was to manually measure the pagination time specifically. You may notice that it is nearly instant so you will know that there are some callbacks involved. And do try to disable DebugKit for a test or two, see how that goes... I am curios what you find! – Ilie Pandia Jan 29 '14 at 15:37
(I suggest this because I do not know how DebugKit actually measures the action time... with or without callbacks?) – Ilie Pandia Jan 29 '14 at 15:38
Just had a quick look at my DebugKit installed and it does not says what "control action" includes? (like any callbacks or not...) – Ilie Pandia Jan 29 '14 at 15:39
I tracked down the issue to the _filterResults method of the DboSource class in /lib/Cake/Model/Datasource/DboSource.php. Amazingly, it's a 1 line conditional causing the issue. if (!isset($model->{$className}) || !is_object($model->{$className})) I started adding output to the debug timer to track down what was happening. I ended up at this line. $model->{$className} is my User class which is just an alias for Recipient. This line is taking up 95% of the execution time for the query. I'm going to try and replicate the issue with a clean install. – mneil Jan 29 '14 at 17:06
what version of CakePHP and what line? [see source file](http://api.cakephp.org/2.3/source-class-DboSource.html#25-3313) – Ilie Pandia Jan 29 '14 at 17:08
Cakephp 2.4.4. Line 1148 in the source file you linked to. Before the conditional I put DebugTimer::start( 'Timer', $message = "Paginator->paginate DboSource Read filterResults filtering $className" ); And after DebugTimer::stop( 'Timer' ); – mneil Jan 29 '14 at 17:16
That is a for loop, I wonder if it affects timing. But I see that the specific method uses the afterFilter callback, so this may be related to a call back after all. – Ilie Pandia Jan 29 '14 at 17:40
Search your project for implementations of "afterFind" and see what comes up. – Ilie Pandia Jan 29 '14 at 17:41
There was a behavior attached to the Recipient model (alias user) which was opening a connection to a 3rd party service in the setup callback. I'm not entirely sure why it happened at that line specifically; but that is when the behavior was loaded. I moved the connection out of the setup. It would be nice if there were a way to stop cake from loading behaviors during associations like this but it's probably not used often. – mneil Jan 29 '14 at 18:10
You can use `$this->Model->Behaviors->disable()/enable()` to wrap that pagination call and temporarily remove the behavior you do not need. (where 'Model' is your Model name, of course) – Ilie Pandia Jan 29 '14 at 18:15

score -1 · Answer 2 · answered Jan 29 '14 at 06:31

-1

Install DebugKit for your application.

And inspect which query is taking too much time. From there, you should be able to track the bottleneck.

answered Jan 29 '14 at 06:31

XuDing

1,982
18
27

DebugKit is installed. I would downvote this but I don't have the reputation yet to do so. The query is NOT SLOW. 2ms. – mneil Jan 29 '14 at 15:31

cakephp paginator extremely slow

2 Answers2