How to determine the (Propel2) cause of a slow query

[murraycollingwood]

Hi

I have a simple query using Propel2:

        time_elapsed("-- -- Prepare the staff query");

        $staffCollection = self::create()
                        ->filterBySchoolid($schoolid)
            ->find();

        time_elapsed("-- -- Executed the staff query");

When I run this the elapsed time is about 9 seconds.

[07-Jan-2023 13:11:33 ] ==!== -- -- Prepare the staff query 0.00016593933105469 ==!==
[07-Jan-2023 13:11:43 ] ==!== -- -- Executed the staff query 9.1365768909454 ==!==

The entire generated query is: SELECT user.id, user.username, user.password, user.schoolid, [skipped a bunch of other fields here] FROM user WHERE user.schoolid=15

I have lots of other queries that run in less than a second on larger tables.

This makes no sense to me. I added logging to my MariaDB 10.10.2 and the database log indicates there is no delay in this query, it is running in less than a second.

When I run the query in a MySQL session it runs within a second.

I duplicated the table and then renamed the duplicate back into the original name - still the same result. I checked the index is in place on 'Schoolid', which it is.

It seems to be something between MySQL and Propel2 that is taking a whole lot longer than it should.

Can anybody suggest any options I should try to identify why this is suddenly performing so badly?

Cheers Murray

[mringler]

How much data is returned by the query? Could it be just transfer time? What does the profiler output say when running Propel in debug mode?

[murraycollingwood]

How much data is returned by the query? Could it be just transfer time? What does the profiler output say when running Propel in debug mode?

The result is 147 rows.

Great idea - Propel debug mode... So now I can see there are two queries being executed in this elapsed time:

[09-Jan-2023 05:42:11 Australia/Queensland] ==!== -- -- Prepare the staff query 0.0050010681152344 ==!==
[2023-01-09T05:42:11.576051+10:00] defaultLogger.INFO: SELECT user.id, user.username, user.password, user.email, user.security, user.name, user.shortcode, user.notes, user.schoolid, user.notifynow, user.notifydaily, user.lastcategory, user.changepw, user.datepwexpires, user.nonldap, user.valtimechart, user.combgen, user.barcode, user.firstname, user.active, user.mobile, user.whsec, user.keepalive, user.digesta1, user.disabled, user.genkey, user.created_at, user.updated_at, user.guestsecurity, user.hideblog, user.appsec, user.yearlevel, user.saschool, user.fte, user.studentlimit, user.extension FROM user WHERE user.schoolid=15 [] []
[2023-01-09T05:42:11.584208+10:00] defaultLogger.INFO: SELECT id, importactive, feature, integrate, apiurl, apiusername, apipassword, multiday, attachable, bookaheadct, osimpdescription, waitconfirm, waitleadhours, waitresponse, delaymins, composite, defaultview, approvalinc, defaultnotify FROM rbschool WHERE id = 15 [] []
[09-Jan-2023 05:42:20 Australia/Queensland] ==!== -- -- Executed the staff query 9.1138670444489 ==!==

The first is the expected one that returns 147 rows. The second returns just a single record.

Running both of these queries within a MySQL session return results instantly. Yet in this script it takes 9 seconds.

This also raises another question, between those two time_elapsed() functions there is no other code. So where is this second query coming from????

[mringler]

Interesting that the second query is executed pretty much at the same time as the first one, and then it takes another 8 seconds to return, which seems to indicate that the time is not spent with the database, but actually on PHP side preparing the result (my guess is the second query is part of that). What happens during instantiation of model objects? Maybe if you log current time in the model constructor, you can see how much is spent between each call?

Btw. if you enable debug mode by calling Propel::getServiceContainer()->useDebugMode(), you should also get profiler information, including how long the query took from Propel side. It looks like this:

[2022-12-14 11:36:20]      Time:  0.219ms | Memory:   4.54MB | Memory Delta:  +17.3kB | Memory Peak:   4.91MB | SELECT ... 

[murraycollingwood]

With profiler information:

[09-Jan-2023 06:22:43 Australia/Queensland] ==!== -- -- Prepare the staff query 3.3855438232422E-5 ==!==
[2023-01-09T06:22:43.096268+10:00] defaultLogger.INFO:      Time: 0.00191ms | Memory:    681kB | Memory Delta:  +2.09kB | Memory Peak:    689kB | Binding 15 at position :p1 w/ PDO type PDO::PARAM_INT [] []
[2023-01-09T06:22:43.098027+10:00] defaultLogger.INFO:      Time:   1.68ms | Memory:    734kB | Memory Delta:  +53.6kB | Memory Peak:    738kB | SELECT user.id, user.username, user.password, user.email, user.security, user.name, user.shortcode, user.notes, user.schoolid, user.notifynow, user.notifydaily, user.lastcategory, user.changepw, user.datepwexpires, user.nonldap, user.valtimechart, user.combgen, user.barcode, user.firstname, user.active, user.mobile, user.whsec, user.keepalive, user.digesta1, user.disabled, user.genkey, user.created_at, user.updated_at, user.guestsecurity, user.hideblog, user.appsec, user.yearlevel, user.saschool, user.fte, user.studentlimit, user.extension FROM user WHERE user.schoolid=15 AND (Disabled IS NULL OR Disabled = 0) ORDER BY user.name ASC,user.firstname ASC [] []
[2023-01-09T06:22:43.098606+10:00] defaultLogger.INFO:      Time: 0.00596ms | Memory:    753kB | Memory Delta:  +2.09kB | Memory Peak:    761kB | Binding 15 at position :p0 w/ PDO type PDO::PARAM_INT [] []
[2023-01-09T06:22:43.098895+10:00] defaultLogger.INFO:      Time:  0.222ms | Memory:    770kB | Memory Delta:  +17.9kB | Memory Peak:    770kB | SELECT id, importactive, feature, integrate, apiurl, apiusername, apipassword, multiday, attachable, bookaheadct, osimpdescription, waitconfirm, waitleadhours, waitresponse, delaymins, composite, defaultview, approvalinc, defaultnotify FROM rbschool WHERE id = 15 [] []
[09-Jan-2023 06:22:52 Australia/Queensland] ==!== -- -- Executed the staff query 9.0515241622925 ==!==

What does it mean???

[murraycollingwood]

Found it!

It is the constructor for the User table.

Hmmm, so now a question. I was using the constructor to set some default values for the new User records. But Propel uses the same constructor when creating the existing objects.

Is there a way to know whether the constructor is being called by Propel to populate an object, verses the actual creation of a new object?

[mringler]

Hey, nice!

Is there a way to know whether the constructor is being called by Propel to populate an object, verses the actual creation of a new object?

No, I don't think so. It sounds like you are not just instantiating a user object, but setting up a whole domain, with default relations and all. I would rather do that in its own function (maybe something like $newUser = User.initNewUser(...)) and use that in the few places (probably just one) where you actually add new users.

[murraycollingwood]

Thanks Moritz, really appreciate your help with this one.