Maximum execution time exceeded $query->__debugInfo() in beforefind

[davo3]

Hi,

When trying to get the information about the current query in beforeFind, similar to this

public function beforeFind(Event $event, Query $query, $options, $primary) {
     debug($query->__debugInfo());die;
}

I am getting php error of maximum execution time to be exceeded. It is just a simple test application, nothing fancy: 2 tables (users and posts) baked with standard models, views and controllers. From components only Auth is loaded. There is no any other logic. All works fine, index of posts, adding, editing, deleting, but ASA I put that line in PostsTable.php => beforeFind I get that execution time error. Same thing happens if I put $query->__toString(). I think it is handy to get query's information in callback when making some changes, in cake 2.x $query would contain that info and I had no issues debugging it.

Debian 8.2, Apache/2.4.10, PHP 5.6.13, Cake 3.1.2

[davo3]

Just tried the same thing on Windows 7, xampp 3.2.1, Apache 2.4.16, php 5.6.12

here I am getting Allowed memory size error

Fatal error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 65488 bytes) in D:\xampp\htdocs\cake3\vendor\cakephp\cakephp\src\Event\EventDispatcherTrait.php on line 816

Fatal error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 65488 bytes) in D:\xampp\htdocs\cake3\vendor\cakephp\cakephp\src\Event\EventManager.php on line 78

[rchavik]

AFAIK, you're not supposed to call __debugInfo() yourself.

Just use: debug($query);

See: http://php.net/manual/en/language.oop5.magic.php#object.debuginfo

[davo3]

Ok, I have tried that as well - debug($query); also tried var_dump($query);, both on windows xampp and on debian - either it gives maximum execution error or apache stops working. My other websites work completely fine(on cake 2.x) and I would like to stress that I do not have any other code in cake 3.x, that could possibly cause the issue. There is definitely smth wrong.

Thanks

[dereuromark]

Can you raise the limit to 256+ MB just for trying to find out if that is just a lot of memory needed or some loop thing?

[davo3]

Here are the results: I did both on windows 7 and Debian 8.
php settings - memory limit 1024M, max execution time 60 seconds,

I tried one by one by debug, var_dump and print_r

debug($query); - max execution time exceeded error
var_dump($query); - apache just stopped working, no output in browser
print_r($query); - apache stops working, for windows/xampp browser outputs multiple (like 370 times) "Object Cake\ORM\Query"

[dakota]

Does it do this for any query, or only a specific one?

What happens if you try something like debug(TableRegistry::get('Posts')->find()) without the beforeFind existing?

[davo3]

I had tried for posts index action (btw I have only a few rows in posts table), just tried for posts view action as well, the same thing.

Without beforefind, or with beforefind but without debug($query) inside it, everything works fine and the output of debug(TableRegistry::get('Posts')->find()) is just

/src/Controller/PostsController.php (line 23)
object(Cake\ORM\Query) {

    '(help)' => 'This is a Query object, to get the results execute or iterate it.',
    'sql' => 'SELECT Posts.id AS `Posts__id`, Posts.slug AS `Posts__slug`, Posts.title AS `Posts__title`, Posts.body AS `Posts__body`, Posts.status AS `Posts__status`, Posts.created AS `Posts__created`, Posts.modified AS `Posts__modified` FROM posts Posts',
    'params' => [],
    'defaultTypes' => [
        'Posts.id' => 'integer',
        'id' => 'integer',
        'Posts.slug' => 'string',
        'slug' => 'string',
        'Posts.title' => 'string',
        'title' => 'string',
        'Posts.body' => 'text',
        'body' => 'text',
        'Posts.status' => 'integer',
        'status' => 'integer',
        'Posts.created' => 'datetime',
        'created' => 'datetime',
        'Posts.modified' => 'datetime',
        'modified' => 'datetime'
    ],
    'decorators' => (int) 0,
    'executed' => false,
    'hydrate' => true,
    'buffered' => true,
    'formatters' => (int) 0,
    'mapReducers' => (int) 0,
    'contain' => [],
    'matching' => [],
    'extraOptions' => [],
    'repository' => object(App\Model\Table\PostsTable) {

        'registryAlias' => 'Posts',
        'table' => 'posts',
        'alias' => 'Posts',
        'entityClass' => 'App\Model\Entity\Post',
        'associations' => [],
        'behaviors' => [
            (int) 0 => 'Timestamp'
        ],
        'defaultConnection' => 'default',
        'connectionName' => 'default'

    }

}

Btw, if I put e.g. debug('something');die; in beforefind I can see the output and no problem with that. Also, if I put e.g. debug($query->type());die; that works fine as well and I can see the output - as select

[dakota]

So, just to make 100% I understand. You are only getting the max execution error if you debug($query) inside your beforeFind?

[davo3]

Exactly, with PHP memory limit of 1024M and 60 seconds of max execution time I open the /posts/index or /posts/view/1 page and having this code in PostsTable.php

public function beforeFind(Event $event, Query $query, $options, $primary) {
    debug($query);die;
}

I am getting php error that maximum execution time was exceeded.

However without beforefind (or without debug in it) putting debug(TableRegistry::get('Posts')->find()) in controller I can see the query output as shown above.

[dakota]

I believe I know what's wrong. The ORM in CakePHP 3 is entirely lazily executed. This means that until the point where it is needed, basically is executed including beforeFind.

One of the things that triggers beforeFind is debugging the query object. Reason for this is that the beforeFind is often used to alter the query, and if you are debugging the query object you are probably interested in seeing the entire SQL statement that will be executed.

Now, internally, CakePHP triggers the beforeFind event, then marks the query to ensure that the beforeFind is not repeated. It only changes the flag, after the event has been fired. So, in your case, you are recursively firing beforeFind (Since the ORM doesn't know that beforeFind has already been fired when you call your debug())

@lorenzo Would it be feasible to move https://github.com/cakephp/cakephp/blob/master/src/ORM/Query.php#L817a to above the event dispatch? I'm not sure if that would break anything else.

[lorenzo]

It seems safe to move it there

[dakota]

Will push a PR now.

[dakota]

PR now open.

[davo3]

I just changed in my local files to test. This commit dakota@ec6bec3
fixed the issue. Thanks a lot.