Posted by Amazon on June 18, 2007 at 4:02am
Hi, if you want to tune your database, a good place to start is finding out what the slowest queries are by total time spent.
Here's a nice tool from the MySQL performance blog.
Add this line to your my.cnf and restart your database server:
log-slow-queries = /var/log/mysql/mysql-slow.log
Add execute permissions to mysql_slow_log_parser, it's a perl script.
Here's an example:
Starting...
2818 Queries
Total time: 2821, Average time: 1.00106458481192
Taking 1 to 2 seconds to complete
Rows analyzed 0 - 0
DELETE FROM watchdog WHERE timestamp < XXX;
DELETE FROM watchdog WHERE timestamp < 1181389779;
This means we might want to take a look at how big the watchdog is getting.
Comments
Replace MUL index with UNIQUE/PRI on search_index.word
Can I replace the multiple column index in search_index with a primary or unique index on search_index.word? Add a new index?
I have 48050 distinct words in the index, and 788374 words total. I am wondering if an additional index or making words distinct would help reduce slow queries like:
EXPLAIN of slow query:
mysql> explain extended SELECT t.word AS realword, i.word FROM search_total t LEFT JOIN search_index i ON t.word = i.word WHERE i.word IS NULL;
+----+-------------+-------+-------+---------------+---------+---------+---------------------------+-------+--------------------------------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+-------------+-------+-------+---------------+---------+---------+---------------------------+-------+--------------------------------------+
| 1 | SIMPLE | t | index | NULL | PRIMARY | 152 | NULL | 48050 | Using index |
| 1 | SIMPLE | i | ref | word | word | 152 | civicspacelabs_org.t.word | 16 | Using where; Using index; Not exists |
+----+-------------+-------+-------+---------------+---------+---------+---------------------------+-------+--------------------------------------+
2 rows in set, 1 warning (0.02 sec)
As you can see the join type is 'ref' which is less than optimal. Opinions? This is for Drupal 4.7.
Kieran
To seek, to strive, to find, and not to yield
New Drupal career! Drupal profile builders.
Try pre-configured and updatable profiles on CivicSpaceOnDemand
I found the same, cron was
I found the same, cron was dominating my slow-query-log with the watchdog cleanup.
Admittedly there was a module that was being very noisy and writing to it all the time, but still...
My cron was cleaning hourly, and the logs rolled out if older than a week.
mysql> explain SELECT count(*) FROM watchdog WHERE timestamp <1185951442;+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
| 1 | SIMPLE | watchdog | ALL | NULL | NULL | NULL | NULL | 62032 | Using where |
+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
As an experiment,
mysql> create index timestamp_ix on watchdog (timestamp);mysql> explain SELECT count(*) FROM watchdog WHERE timestamp <1185951442;
+----+-------------+----------+-------+---------------+--------------+---------+------+-------+--------------------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+-------------+----------+-------+---------------+--------------+---------+------+-------+--------------------------+
| 1 | SIMPLE | watchdog | range | timestamp_ix | timestamp_ix | 4 | NULL | 57277 | Using where; Using index |
+----+-------------+----------+-------+---------------+--------------+---------+------+-------+--------------------------+
Isn't less rows looked at in the EXPLAIN a good thing?
Or have I got the wrong end of the stick?
Am I causing all writes to be a little longer (as the index is rebuilt?) and slowing down real service, for the sake of saving a few seconds during admin? Which would be silly.
.dan.
Interesting
I have been meaning to try this, what kind of information does the slow query log really show?
vision media
350designs
Tj Holowaychuk
Vision Media - Victoria BC Web Design
Victoria British Columbia Web Design School
If you get a segfault...
I tried this script on a recently launched site, after a few million queries, and it segfaulted. It /seems/ this is due to some query strings being really too long for the Perl regex engine, on cache-related queries (does that tell us something about the cache functions, BTW ?), on this expression
$query_string =~ s/'([^'\](\.[^'\])*)'/'XXX'/g;.You can work around the problem by truncating the query string: after
$orig_query = $query_string;near line 104, just truncate the query string to some sane length, sufficient to still differentiate queries, like:if ( /^\#/ && $query_string ) { if (($time > $min_time) && ($rows >= $min_rows)) { $orig_query = $query_string; $query_string = substr($query_string, 0, 100); # this is the fix $query_string =~ s/\d+/XXX/g;After that the regex engine no longer crashes, and you can obtain your results.
Thanks fgm - that worked for
Thanks fgm - that worked for me!
Nicholas Cottrell
Transmachina AB
Stockholm, Sweden
Sprawk - translating the web, your way
mysqlsla
I am using mysqlsla for slow log analysis. it is great and flexible at giving reports based on total time per query, total count per query etc. It is great that it identifies query patterns, and not individual queries (i.e. "WHERE uid=9" and "WHERE uid=2" become "WHERE uid=N".
Sample run:
$ ./mysqlsla-2.03 -lt slow --sort t_sum --top 5 /var/log/mysql/mysqld.slow
Report for slow logs: /var/log/mysql/mysqld.slow
12.18k queries total, 526 unique
Sorted by 't_sum'
Grand Totals: Time 1.08M s, Lock 10.26k s, Rows sent 752.62M, Rows Examined 2.47G
______________________________________________________________________ 001 ___
Count : 61 (0.50%)
Time : 175557 s total, 2877.983607 s avg, 4 s to 52890 s max (16.21%)
95% of Time : 26490 s total, 464.736842 s avg, 4 s to 25764 s max
Lock Time (s) : 68 s total, 1.114754 s avg, 0 to 12 s max (0.66%)
95% of Lock : 25 s total, 438.596 ms avg, 0 to 9 s max
Rows sent : 0 avg, 0 to 0 max (0.00%)
Rows examined : 0 avg, 0 to 0 max (0.00%)
Database : db1
Users :
user@localhost : 100.00% (61) of query, 34.23% (4170) of all users
Query abstract:
INSERT INTO accesslog (title, path, url, hostname, uid, sid, timer, timestamp) VALUES('S', 'S', 'S', 'S', N, 'S', N, N)1;
Query sample:
INSERT INTO accesslog (title, path, url, hostname, uid, sid, timer, timestamp) values('', 'node/114', '', '222.222.222.222', 0, 'f8ae10e1637046c65d42ee16e0827b87', 9990, 1232983435);
______________________________________________________________________ 002 ___
Count : 28 (0.23%)
Time : 134021 s total, 4786.464286 s avg, 4 s to 52918 s max (12.38%)
95% of Time : 37207 s total, 1431.038462 s avg, 4 s to 25879 s max
Lock Time (s) : 145 s total, 5.178571 s avg, 0 to 34 s max (1.41%)
95% of Lock : 83 s total, 3.192308 s avg, 0 to 21 s max
Rows sent : 0 avg, 0 to 0 max (0.00%)
Rows examined : 0 avg, 0 to 0 max (0.00%)
Database : db1
Users :
user@localhost : 82.14% (23) of query, 34.23% (4170) of all users
user2@localhost : 17.86% (5) of query, 52.78% (6430) of all users
Query abstract:
UPDATE cache SET data = 'S', created = N, expire = N, headers = 'S', serialized = N WHERE cid = 'S';
Query sample:
UPDATE cache SET data = 'a:2:{i:0;s:24:\"Content-type: image/jpeg\";i:1;s:1996:\".../o/WSbfWUXXpcG6BrYDZE/64o1JUqrkrXOcAxU7qXP/9k=\";}', created = 1233598486, expire = 1233857686, headers = '', serialized = 0 WHERE cid = 'bg_3b6ac8411a306870392951e5ab6faa5c';
______________________________________________________________________ 003 ___
Count : 31 (0.25%)
Time : 97067 s total, 3131.193548 s avg, 4 s to 52896 s max (8.97%)
95% of Time : 268 s total, 9.241379 s avg, 4 s to 38 s max
Lock Time (s) : 8 s total, 258.065 ms avg, 0 to 5 s max (0.08%)
95% of Lock : 2 s total, 68.966 ms avg, 0 to 1 s max
Rows sent : 0 avg, 0 to 0 max (0.00%)
Rows examined : 0 avg, 0 to 0 max (0.00%)
Database : db2
Users :
user@localhost : 100.00% (31) of query, 34.23% (4170) of all users
Query abstract:
DELETE FROM sessions WHERE timestamp < N;
Query sample:
DELETE FROM sessions WHERE timestamp < 1232784725;
______________________________________________________________________ 004 ___
Count : 32 (0.26%)
Time : 81199 s total, 2537.46875 s avg, 4 s to 43889 s max (7.50%)
95% of Time : 10980 s total, 366 s avg, 4 s to 7743 s max
Lock Time (s) : 63 s total, 1.96875 s avg, 0 to 60 s max (0.61%)
95% of Lock : 0 total, 0 avg, 0 to 0 max
Rows sent : 0 avg, 0 to 0 max (0.00%)
Rows examined : 0 avg, 0 to 0 max (0.00%)
Database : wpdb
Users :
naama@localhost : 100.00% (32) of query, 12.21% (1487) of all users
Query abstract:
UPDATE wp_options SET option_value = 'S' WHERE option_name = 'S';
Query sample:
UPDATE wp_options SET option_value = '1237881554' WHERE option_name = 'doing_cron';
______________________________________________________________________ 005 ___
Count : 22 (0.18%)
Time : 61344 s total, 2788.363636 s avg, 4 s to 52877 s max (5.67%)
95% of Time : 423 s total, 21.15 s avg, 4 s to 246 s max
Lock Time (s) : 26 s total, 1.181818 s avg, 0 to 9 s max (0.25%)
95% of Lock : 11 s total, 550 ms avg, 0 to 5 s max
Rows sent : 0 avg, 0 to 0 max (0.00%)
Rows examined : 0 avg, 0 to 0 max (0.00%)
Database : db3
Users :
user@localhost : 68.18% (15) of query, 34.23% (4170) of all users
user2@localhost : 31.82% (7) of query, 52.78% (6430) of all users
Query abstract:
INSERT INTO watchdog (uid, type, message, variables, severity, link, location, referer, hostname, timestamp) VALUES (N, 'S', 'S', 'S', N, 'S', 'S', 'S', 'S', N)1;
Query sample:
INSERT INTO watchdog
(uid, type, message, variables, severity, link, location, referer, hostname, timestamp)
VALUES
(0, 'update', 'Fetched information about all available new releases and updates.', 'a:0:{}', 5, '<a href=\"/admin/reports/updates\">view</a>', 'http://example.com/cron.php', '', '111.111.111.111', 1230077284);
@yhager: I tried 'mysqlsla',
@yhager: I tried 'mysqlsla', but I'm not getting those nice query abstracts which point to Drupal modules like in your examples.
How do I read (interpret) query abstracts like this:
Query abstract:
SELECT SUM(i.score * t.COUNT) AS score FROM search_index i INNER JOIN search_total t ON i.word = t.word INNER JOIN node n ON n.nid = i.sid LEFT JOIN node i18n ON n.tnid > N AND n.tnid = i18n.tnid AND i18n.language = 'S' WHERE n.status =
N AND (n.language ='S' OR n.language ='S' OR n.language IS NULL OR n.language = 'S' AND i18n.nid IS NULL) AND (i.word = 'S' OR i.word = 'S' OR i.word = 'S' OR i.word = 'S' OR i.word = 'S' OR i.word = 'S' OR i.word = 'S') AND i.type = 'S'
GROUP BY i.type, i.sid HAVING COUNT() >= N ORDER BY score DESC LIMIT N, N;
Query abstract:
SELECT COUNT() FROM (SELECT i.type, i.sid, N * (N.N * SUM(i.score * t.COUNT)) + N * pow(N, (greatest(MAX(n.created), MAX(n.changed), coalesce(MAX(c.last_comment_timestamp), N)) - N) * N.43e-N) + N * (N.N - N.N / (N.N + MAX(c.comment_cou
nt) * N.N)) + N * (N.N - N.N / (N.N + MAX(nc.totalcount) * N.N)) AS score FROM search_index i INNER JOIN search_total t ON i.word = t.word INNER JOIN node n ON n.nid = i.sid LEFT JOIN node i18n ON n.tnid > N AND n.tnid = i18n.tnid AND i1
8n.language = 'S' LEFT JOIN node_comment_statistics c ON c.nid = i.sid LEFT JOIN node_counter nc ON nc.nid = i.sid WHERE n.status = N AND (n.language ='S' OR n.language ='S' OR n.language IS NULL OR n.language = 'S' AND i18n.nid IS NULL)
AND (i.word = 'S' OR i.word = 'S' OR i.word = 'S' OR i.word = 'S' OR i.word = 'S' OR i.word = 'S' OR i.word = 'S') AND i.type = 'S' GROUP BY i.type, i.sid HAVING COUNT(*) >= N) n1;
I see that both queries somehow involve 'search_index' and 'i18n', and both involve some SUM() or COUNT() operations. OK, I've already seen that in 'mytop', but I still have no idea where this comes from (Views?)
Thanks for any suggestions!
PS: Currently, http://www.mysqlperformanceblog.com/files/utils/mysql_slow_log_parser is down. Does anyone know an alternative source?
Indexing
@asb - those come from the search module indexing your site. If they significantly slowing things down, maybe you should consider using an index external to Drupal, like Solr.