Example log output:

# TIME: 110617 5:04:34
# USER@Host: ---
# Query_time: 14.751956 Lock_time: 0.000148 Rows_sent: 10 Rows_examined: 2040480
SET TIMESTAMP=1308301474;
SELECT pmi.recipient, pmi.TYPE, pmi.mid FROM gac_pm_index pmi WHERE pmi.TYPE NOT IN ('user', 'hidden') AND pmi.is_new = 1 ORDER BY mid ASC LIMIT 0, 10;

Changing the NOT IN to an IN did not help much, removing the ORDER BY did (down to 1.5s). But currently we need that ORDER BY to proceed with the same mid as we eventuelly stopped last time.

Eventually we could consider by doing to ORDERING in PHP or it would probably not even be necessary anymore as we'd need to fetch anything anyway. That might be still much faster than 10+s, because I really don't expect more than some hundred rows to exist in the worst case.

Comments

te-brian’s picture

A better way to say it is that anything approaching 100+ rows is an indication of something unhealthy going on.

berdir’s picture

Status: Active » Needs review
StatusFileSize
new4.87 KB

Oh wow..

I found two totally crazy performance bugs.

The first was this line in privatemsg_message_change_recipient():

$thread_id = db_result(db_query('SELECT thread_id FROM {pm_index} WHERE mid = %d', $mid));

Trivial query, what could be wrong with that..

What's wrong is that there can be a *huge* amount of rows with that mid. Ten thousands, if you have large recipients like large groups/roles.

I was able to replace that query and a second to load the author uid with a call to privatemsg_message_load(), which is now statically cached. Basically 2000 queries less to execute. Yay.

Then, I initially noticed something very weird when switching to privatemsg_message_load(). There were now thousands of queries suddenly in privatemsg_attachments_privatemsg_message_load() when loading a single message. Turns out, there was a very similar problem in the message load query. When not specifying the $account when loading messages (which is always done in the UI), it did join in pm_index with just the mid as the condition, resulting in the same thousands of results. And then, in contrast to above, it loaded *every single one* of them, calling the load hook on each of them. o.0

Additionally, I also rewrote the query as initially discussed.

I'll let the numbers speak.

before patch, with pm_email_notify:
Took 99.635545015335 seconds to add the recipients. Memory consumption: 104.54 MB.

before patch, without pm_email_notify:
Took 96.889940023422 seconds to add the recipients. Memory consumption: 61.17 MB.

with patch and pm_email_notify:
Took 9.1466522216797 seconds to add 1000 recipients. Memory consumption: 66.16 MB.

with patch and without pm_email_notify:
Took 4.2939682006836 seconds to add 1000 recipients. Memory consumption: 59.62 MB.

So, even with pm_email_notify (but sending of mails disabled with devel.module), this is an improvement by a factor of 10 and without it, it is an improvement by the factor of 22! And while doing these tests, I had a lot of ideas on how to improve even further, most of that should be done in follow-up issues:

- Move thread_id to pm_message. There is absuletely no reason for that to be in pm_index and repeated for every single recipient. Will require a lot of work in various queries but might also save a few joins elsewhere, we'll see.
- Right now, we call privatemsg_message_change_recipient() for every recipient seperatly. Before this patch, that resulted in 3 SELECT queries each. Still one with this patch. When we change this function to accept an array of recipients, we can do a single query for them (the query checks if the recipient already exists to avoid adding them twice) and we can also call the hook for all of these together and pass $message in, which is now statically cached anyway.
- I noticed tons of queries to look up the settings with the settings API. When we pass all recipients to a single hook invocation, we might be able to introduce some kind of prefetching API for this (load all settings for uid 1-1000 and setting key A and B in a single query). Again, that will help us to save a few thousand queries per cron/batch run (Yes, this patch will positively affect batch runs too, although I'm not sure in which factor exactly)

Ok, I'm going back to banging my head against a wall, what was I thinking... ;)

Status: Needs review » Needs work

The last submitted patch, 1192250_crazyness.patch, failed testing.

berdir’s picture

Status: Needs work » Needs review
StatusFileSize
new4.98 KB

Added a check to not run the query if there are no types.

berdir’s picture

Title: Slow query in privatemsg_cron() » Slow queries and other performance bugs
te-brian’s picture

Applied this patch and tested in my staging environment. Applies fine and no php errors or warnings yet. I tested a few send-outs to large groups and did not notice quite as staggering a performance improvement (though that could be attributed to custom logic). Definitely not a regression, and it probably was a little faster. I'll see if I can get more scientific results. I have a great query logging module but it does not work in the batches for my site because they are in a modal and ctools exit()'s before hook_footer :(

Please link the other performance issues from here as I am interested in them, especially ones that combine the settings queries and the thread_id moving one. Very interested in those.

berdir’s picture

The easiest way to test the performance is running cron with drush or directly calling privatemsg_cron(). Testing performance on batch runs is tricky I think, because there are so many factors that influence it (time it takes to send a new request, every request just takes up to one second).

The follow-up issues are:

- #1193850: Prefetching of settings for multiple users
- #1193264: Make privatemsg_message_change_recipient() work for multiple recipients
- #1193232: Move thread_id to pm_message

But there's nothing to see yet.

berdir’s picture

Version: 6.x-2.x-dev » 7.x-1.x-dev
StatusFileSize
new3.65 KB

Commited against 6.x-2.x, ported to 7.x-1.x, let's see if the tests pass.

Still interested in performance tests, if you get to it..

berdir’s picture

Status: Needs review » Fixed

Commited to the 7.x branches.

Status: Fixed » Closed (fixed)

Automatically closed -- issue fixed for 2 weeks with no activity.