Ever tried to browse admin/logs with 586 891 records in the watchdog table? It takes in average about 13.9692559242 seconds on my server. I think it is important to get it lower because everytime you click on "administer" you get that watchdog overview.
My concern is about the watchdog_overview() function and especially about this code
$header = array(
' ',
array('data' => t('Type'), 'field' => 'w.type'),
array('data' => t('Date'), 'field' => 'w.wid', 'sort' => 'desc'),
array('data' => t('Message'), 'field' => 'w.message'),
array('data' => t('User'), 'field' => 'u.name'),
array('data' => t('Operations'))
);
$sql = "SELECT w.*, u.name, u.uid FROM {watchdog} w INNER JOIN {users} u ON w.uid = u.uid";
$tablesort = tablesort_sql($header);
$type = $_SESSION['watchdog_overview_filter'];
if ($type != 'all') {
$result = pager_query($sql ." WHERE w.type = '%s'". $tablesort, 50, 0, NULL, $type);
}
else {
$result = pager_query($sql . $tablesort, 50);
}
while ($watchdog = db_fetch_object($result)) {
$rows[] = array('data' =>
array(
// Cells
$icons[$watchdog->severity],
t($watchdog->type),
format_date($watchdog->timestamp, 'small'),
l(truncate_utf8($watchdog->message, 56, TRUE, TRUE), 'admin/logs/event/'. $watchdog->wid, array(), NULL, NULL, FALSE, TRUE),
theme('username', $watchdog),
$watchdog->link,
),
// Attributes for tr
'class' => "watchdog-". preg_replace('/[^a-z]/i', '-', $watchdog->type) .' '. $classes[$watchdog->severity]
);
}
I tried to optimize the SQL query but had no luck.
So here is one solution to bring it down to a generation time of 0.0609180927275 seconds -- but it does not provide the same functionality because the sorting by username is lost.
// CHANGE: Sorting by username disabled
$header = array(
' ',
array('data' => t('Type'), 'field' => 'type'),
array('data' => t('Date'), 'field' => 'wid', 'sort' => 'desc'),
array('data' => t('Message'), 'field' => 'message'),
array('data' => t('User'), /*'field' => 'u.name'*/),
array('data' => t('Operations'))
);
// CHANGE: Fetch users seperately
$result = db_query("SELECT uid, name FROM {users}");
while ( $user = db_fetch_object($result) ) {
$users[$user->uid] = $user;
}
// CHANGE: Replacing with this simple and fast SELECT
//$sql = "SELECT w.*, u.name, u.uid FROM {watchdog} w INNER JOIN {users} u ON w.uid = u.uid";
$sql = "SELECT * FROM {watchdog}";
$tablesort = tablesort_sql($header);
$type = $_SESSION['watchdog_overview_filter'];
if ($type != 'all') {
$result = pager_query($sql ." WHERE type = '%s'". $tablesort, 50, 0, NULL, $type);
}
else {
$result = pager_query($sql . $tablesort, 50);
}
while ($watchdog = db_fetch_object($result)) {
$rows[] = array('data' =>
array(
// Cells
$icons[$watchdog->severity],
t($watchdog->type),
format_date($watchdog->timestamp, 'small'),
l(truncate_utf8($watchdog->message, 56, TRUE, TRUE), 'admin/logs/event/'. $watchdog->wid, array(), NULL, NULL, FALSE, TRUE),
// CHANGE: Format the username
//theme('username', $watchdog),
theme('username', $users[$watchdog->uid]),
$watchdog->link,
),
// Attributes for tr
'class' => "watchdog-". preg_replace('/[^a-z]/i', '-', $watchdog->type) .' '. $classes[$watchdog->severity]
);
}
Any suggestions? Other ideas?
Comments
Comment #1
dries commentedThe watchdog table does not seems to have an index on uid. Adding an index will likely speed up the query.
Comment #2
dries commentedAlso, changing the w.* to a string of field (w.wid, w.uid, ...) might also reduce execution time as less data needs to be fetched/send.
Comment #3
ebruts commentedFound some time to analyze it more deeply. There was no noticeable increase of the speed as I added the index.
It seems the real impact is the ORDER BY in combination with the two tables.
Using (Note that tablesort is commented out)
I get the average of 2.538157392152 seconds (50 querys).
Further I could optimize it a bit by submitting a fixed $count_query to pager_query().
(The attempt to generate the query on the fly is a bit unlucky).
SELECT COUNT(*) FROM {watchdog} w INNER JOIN {users} u ON w.uid = u.uidSo we just drop the rest starting from INNER JOIN and this
resulted in the average of 0.834068059921 seconds.
That was just a test (as this does not have any sorting capabilities at all), maybe it helps someone to get a solution for this.
Comment #4
ebruts commentedI was wondering why the added INDEX had no impact on the query. Compare this with Dries' comment.
As you see no key is used on my MySQL server (4.0.15-Max). So I've upgraded and yes, got the same result.
Here is some statistics, used admin/logs/hits as I have way more entries there.
Before:
After:
This is great when sorting for timestamp and path but is not quite as fast for user sorting because a temporary table and filesort is used.
To get the same result on MySQL 4.0.x you'll need to add "...LEFT JOIN users u FORCE INDEX (PRIMARY) ON u.uid..."
It's not included as this will break PostgreSQL.
Comment #5
ebruts commentedOn the other side INSERTs will be slower for the accesslog (as for the watchdog, I don't think that matters).
Comment #6
drummNo longger applies.
Comment #7
FiReaNGeL commentedI had fun with this one tonight. Built myself a 500k+ watchdog table. Original query, as people noticed, is dog slow (87 seconds on my machine).
It turns out that we`re doing an INNER JOIN when its really not needed (theres no case where a watchdog log row has no user that I know of - the field is set to 'not null' anyway). For some reason I ignore, the mysql optimizer on inner join is really funky / bad. Doing the exact same query with a LEFT JOIN yields :
Notice that were now using the primary key in both cases, doing an index scan and an eq_ref, which is the best scenario (instead of the worse case scenario we were having).
The query yields the same results as the INNER JOIN one, in 0.0009 seconds (you read that right). Yeah, I had mysql query cache turned off, don't worry :)
I noticed that Drupal has a tendency to abuse INNER JOIN when its not needed. Someone might want to look throught core for these.
Comment #8
RobRoy commentedI suppose you're right as even watchdog entries for Anonymous users correspond to user rows with uid = 0. What about on cron runs or running Drupal from the command line?
Comment #9
FiReaNGeL commentedYou might have missed it in my post, but the uid field in watchdog is set to 'not null' and default to 0. So it just can't be empty.
Comment #10
FiReaNGeL commentedI talked to knowledgeable people on #mysql and it is like I suspected; sometimes, the mysql optimizer is suboptimal (use the wrong indexes or no indexes at all) on inner joins.
Since its not needed in this case AND it brings a nice speed boost for high traffic websites, I'd say that its a good solution.
Comment #11
dmitrig01 commentedDoesn't apply to drupal 5 or 6
Comment #12
killes@www.drop.org commentedthe patch may not apply, but our workflow mandates it has to be in the dev-6 branch.
Comment #13
Wesley Tanaka commenteddelete from watchdog where timestamp < XXX, which is called every time cron is run, is slow without an index on timestamp.
Comment #14
panchoStill to be fixed. For large sites this is a performance bug.
Comment #15
dpearcefl commentedDoes this still need to be fixed in current D6?