tags:

views:

294

answers:

2

A particular UPDATE query on our website sometimes runs extremely slow, and examines a lot more rows than necessary. It filters by the primary key, so I would expect that MySQL would always just need to examine one row.

Here's some examples from MySQL's slow-query log:

# Time: 090702 12:59:06
# User@Host: XXX[XXX] @ XXX [XXX]
# Query_time: 21  Lock_time: 0  Rows_sent: 0  Rows_examined: 500500
SET timestamp=1246532346;
UPDATE `folders` SET `folder_id` = '1705641', `updated_at` = now() WHERE `folders`.`id` = '1682995';
# Time: 090702 14:13:44
# User@Host: XXX[XXX] @ XXX [XXX]
# Query_time: 17  Lock_time: 0  Rows_sent: 0  Rows_examined: 16816745
SET timestamp=1246536824;
UPDATE `folders` SET `folder_id` = '417997', `updated_at` = now() WHERE `folders`.`id` = '1705956';
# Time: 090702 14:15:42
# User@Host: XXX[XXX] @ XXX [XXX]
# Query_time: 13  Lock_time: 0  Rows_sent: 0  Rows_examined: 16816719
SET timestamp=1246536942;
UPDATE `folders` SET `folder_id` = '1706267', `updated_at` = now() WHERE `folders`.`id` = '1705956';
# Time: 090702 16:07:43
# User@Host: XXX[XXX] @ XXX [XXX]
# Query_time: 499  Lock_time: 0  Rows_sent: 0  Rows_examined: 88668449
SET timestamp=1246543663;
UPDATE `folders` SET `folder_id` = '1707407', `updated_at` = now() WHERE `folders`.`id` = '1706992';

The query is run more often than that, though, so it doesn't always expose this behaviour. Also if I run the same queries manually, they run just fine and return immediately.

I also verified the table and as far as I can see it should be fine:

mysql> describe folders;
+------------------+-----------------------+------+-----+---------------------+----------------+
| Field            | Type                  | Null | Key | Default             | Extra          |
+------------------+-----------------------+------+-----+---------------------+----------------+
| id               | mediumint(8) unsigned | NO   | PRI | NULL                | auto_increment | 
| user_id          | mediumint(8) unsigned | NO   | MUL | NULL                |                | 
| folder_id        | mediumint(8) unsigned | YES  | MUL | NULL                |                | 
| created_at       | timestamp             | NO   |     | CURRENT_TIMESTAMP   |                | 
| updated_at       | timestamp             | NO   |     | 0000-00-00 00:00:00 |                | 
| modified_at      | timestamp             | NO   |     | 0000-00-00 00:00:00 |                | 
| name             | varchar(255)          | NO   |     | NULL                |                | 
| guest_permission | tinyint(3) unsigned   | NO   |     | 1                   |                | 
+------------------+-----------------------+------+-----+---------------------+----------------+
8 rows in set (0.00 sec)

mysql> show index from folders;
+---------+------------+-----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+
| Table   | Non_unique | Key_name  | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment |
+---------+------------+-----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+
| folders |          0 | PRIMARY   |            1 | id          | A         |      760318 |     NULL | NULL   |      | BTREE      |         | 
| folders |          1 | user_id   |            1 | user_id     | A         |       69119 |     NULL | NULL   |      | BTREE      |         | 
| folders |          1 | folder_id |            1 | folder_id   | A         |      380159 |     NULL | NULL   | YES  | BTREE      |         | 
+---------+------------+-----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+
3 rows in set (0.00 sec)

Another thing is that the MySQL server sometimes locks up and stops accepting connections, and every time this happens I usually find one of these slow queries in the logfile, immediately before the failure. I can't see any relevant error messages in other logfiles, but a MySQL restart makes it responsive again.

Does anybody have an idea what's going on, or what things I could check to narrow the problem down?

EDIT: We're using MySQL 5.0.51a on a dedicated server, and currently 6 webservers running PHP 5.2.6 and connecting via PDO to the MySQL server. All servers are running Debian Lenny. The slow query happens on all webservers.

EDIT: Here's an EXPLAIN for a related query, with and without quotes:

mysql> explain SELECT * FROM `folders` WHERE `folders`.`id` = '1682995';
+----+-------------+---------+-------+---------------+---------+---------+-------+------+-------+
| id | select_type | table   | type  | possible_keys | key     | key_len | ref   | rows | Extra |
+----+-------------+---------+-------+---------------+---------+---------+-------+------+-------+
|  1 | SIMPLE      | folders | const | PRIMARY       | PRIMARY | 3       | const |    1 |       | 
+----+-------------+---------+-------+---------------+---------+---------+-------+------+-------+
1 row in set (0.00 sec)

mysql> explain SELECT * FROM `folders` WHERE `folders`.`id` = 1682995;
+----+-------------+---------+-------+---------------+---------+---------+-------+------+-------+
| id | select_type | table   | type  | possible_keys | key     | key_len | ref   | rows | Extra |
+----+-------------+---------+-------+---------------+---------+---------+-------+------+-------+
|  1 | SIMPLE      | folders | const | PRIMARY       | PRIMARY | 3       | const |    1 |       | 
+----+-------------+---------+-------+---------------+---------+---------+-------+------+-------+
1 row in set (0.00 sec)
+1  A: 

That is weird, but my guess is it could be because your id field is int but you're passing a string (quoted). Try not using a string and see if it helps.

To help figure out exactly what's going on, change the query to a SELECT with the same WHERE clause and run it through EXPLAIN. Like this:

EXPLAIN SELECT * FROM `folders` WHERE `folders`.`id` = '1682995';
EXPLAIN SELECT * FROM `folders` WHERE `folders`.`id` = 1682995;

See if there is a difference.

More info on EXPLAIN.

Artem Russakovskii
No difference. Also, if that really was the cause I would expect the query to ALWAYS be this slow. But thanks for the help, anyway!
toupeira
A: 

Silly me. I forgot that there were some triggers on the folders table, and of course it was a query inside one of these triggers which caused my problems...

There's an additional table tree which maintains the associations between the folders, and the triggers update these associations when a folder is deleted or moved in the hierarchy. In the UPDATE trigger, it has to delete all existing references to the folder, before adding the new references. The relevant DELETE query began as follows:

DELETE FROM `tree`
  WHERE `folder_id` IN (
    SELECT `folder_id` FROM `children`
  )
  AND ...

children is a temporary table where I previously store the folder ID's I need. Now for some reason MySQL can't optimize this query, but if I use a RIGHT JOIN instead it works perfectly fine:

DELETE `tree`.* FROM `tree`
  RIGHT JOIN children USING (folder_id)
  WHERE ...

Since I've changed this query MySQL's slow-query log remains blissfully empty, and we haven't experienced any MySQL lockups.

toupeira