Hourly Cleanup #2 - V3.8.4 taking a *long* time to execute. PMs unusable

محروم.كوم · #1 06-20-2010, 03:00 AM

Our PM system is unusable for 3 to 9 minute every time the Hourly Cleanup #2 is running, which can take 3 to 9 minutes.

Any ideas how to make things better? I'm stumped.

Similar to this persons problem:
http://www.vbulletin.com/forum/showt...y+cleanup+%232

In the ./includes/cron/cleanup2.php file is this part that is taking 3.5 to 9 minutes to execute:
Code:
// Orphaned pmtext records are removed after one hour.
// When we delete PMs we only delete the pm record, leaving
// the pmtext record alone for this script to clean up
$pmtexts = $vbulletin->db->query_read("
SELECT pmtext.pmtextid
FROM " . TABLE_PREFIX . "pmtext AS pmtext
LEFT JOIN " . TABLE_PREFIX . "pm AS pm USING(pmtextid)
WHERE pm.pmid IS NULL");
Here is the process it produces when it is running, here is shows it has been running for 425 seconds:
Code:
mysql> show full processlist;
+--------+-----------------+-----------+--------------------+---------+------+--------------+----------------------------------------------------------------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+--------+-----------------+-----------+--------------------+---------+------+--------------+----------------------------------------------------------------------------------------------------------+
| 873254 | root | localhost | NULL | Query | 0 | NULL | show full processlist |
| 875770 | db_username | localhost | database_name | Query | 425 | Sending data | SELECT pmtext.pmtextid
FROM pmtext AS pmtext
LEFT JOIN pm AS pm USING(pmtextid)
WHERE pm.pmid IS NULL |
+--------+-----------------+-----------+--------------------+---------+------+--------------+----------------------------------------------------------------------------------------------------------+
2 rows in set (0.05 sec)
If there is anything regarding PMs that needs to be attended to while that process is running they are marked as 'locked' and will not run. People cannot even view their PM inbox or open a PM while this is happening. The little thingy in the browsers tab spins and spins until this process has completed, which can be up to 9 minutes.

I went into the phpmyadmin and see there are less than 20K PMs in the entire database (we are a small forum).

Attachment 45963

Then I query for pm.pmtextid == NULL for all 20k PMs and that takes less than a millisecond (as you can see)
Attachment 45962

Then I run this command from within the phpmyadmin, and as you can see it takes 331 seconds to execute.
Code:
SELECT pmtext.pmtextid
FROM pmtext AS pmtext
LEFT JOIN pm AS pm USING(pmtextid)
WHERE pm.pmid IS NULL
;
Attachment 45961

More info:
I am not that technical, it has taken me a while to get to this point.

While I understand the concept of what the script is trying to accomplish, I do not understand the syntax of the mysql commands.

I have disabled hooks in the config.php (define('DISABLE_HOOKS', true); ) and it makes no difference at all.

Removed the few pugins / modifications we did have.

I clicked repair database and there were no issues found

Contacted our hosting provider and they confirmed the issue, then said because it came back with "Empty set (9 min 31.63 sec)", that although the command took over 9 minutes for them, it did not return an error.

While this is happening the MySQL is using 100% of the time it can (as far as I can tell). We are on a vps and of course limited to our share of cpu time. Here is part of a top command output while the issue is occurring. Normally our load averages are about 0.10, when this is occurring it goes up to almost 2:

Code:
top - 22:22:52 up 26 days, 22:31, 1 user, load average: 1.28, 0.63, 0.34
Tasks: 64 total, 1 running, 62 sleeping, 0 stopped, 1 zombie
Cpu(s): 3.0%us, 5.3%sy, 0.0%ni, 91.6%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 1572864k total, 428912k used, 1143952k free, 0k buffers
Swap: 0k total, 0k used, 0k free, 0k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
24052 mysql 15 0 78492 40m 3688 S 100.2 2.6 4633:02 mysqld
7172 myforum 16 0 0 0 0 Z 5.0 0.0 0:00.15 php
1 root 15 0 2148 668 580 S 0.0 0.0 0:05.73 init
3881 root 15 0 16732 14m 1376 S 0.0 0.9 0:15.00 lfd
5776 root 18 0 4700 3000 1664 S 0.0 0.2 0:02.67 authProg
5961 nobody 15 0 9136 2148 680 S 0.0 0.1 0:00.00 httpd
6127 nobody 18 0 9136 2144 676 S 0.0 0.1 0:00.00 httpd
6128 nobody 18 0 9136 2144 676 S 0.0 0.1 0:00.00 httpd
11568 named 18 0 192m 7260 2092 S 0.0 0.5 2:26.27 named
11976 root 15 0 4700 2996 1664 S 0.0 0.2 0:02.80 authProg
13482 root 18 0 1660 428 360 S 0.0 0.0 0:00.00 courierlogger
13535 root 18 0 2000 628 516 S 0.0 0.0 0:00.01 authdaemond
14142 root 15 0 2000 372 256 S 0.0 0.0 0:00.75 authdaemond
14143 root 15 0 2000 372 256 S 0.0 0.0 0:00.82 authdaemond
16279 nobody 18 0 9272 2864 1280 S 0.0 0.2 0:00.00 httpd
16370 root 18 0 7808 5164 1744 S 0.0 0.3 0:16.65 tailwatchd
16380 root 18 0 6728 3676 1380 S 0.0 0.2 0:00.17 cphulkd
17468 root 19 0 14080 7892 1388 S 0.0 0.5 0:00.00 cpdavd
17474 root 15 0 5320 3628 1280 S 0.0 0.2 0:37.59 queueprocd
17501 root 33 18 3800 1528 608 S 0.0 0.1 0:00.18 cpanellogd
17553 nobody 18 0 9272 2816 1268 S 0.0 0.2 0:00.00 httpd
17604 root 18 0 15828 8056 1288 S 0.0 0.5 0:15.86 cpsrvd-ssl
18308 root 15 0 24764 1136 816 S 0.0 0.1 0:40.88 rsyslogd
18325 nobody 15 0 9272 2840 1280 S 0.0 0.2 0:00.01 httpd
19592 root 18 0 9136 4072 2628 S 0.0 0.3 1:27.25 httpd
19621 root 18 0 5272 1452 1104 S 0.0 0.1 0:00.00 pure-ftpd
19623 root 16 0 4976 1144 900 S 0.0 0.1 0:00.00 pure-authd
19892 root 15 0 10036 2788 2212 S 0.0 0.2 0:00.05 sshd
Any input would greatly be appreciated
Attached Images
LONG query.JPG&lrm; (54.7 KB)

quiry of NULL.JPG&lrm; (87.7 KB)

number of pms.JPG&lrm; (23.2 KB)

__DEFINE_LIKE_SHARE__