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?

CommentFileSizeAuthor
#4 drupal_62.patch5.93 KBebruts

Comments

dries’s picture

The watchdog table does not seems to have an index on uid. Adding an index will likely speed up the query.

mysql> EXPLAIN SELECT w.*, u.name, u.uid FROM watchdog w INNER JOIN users u ON w.uid = u.uid LIMIT 0, 50;
+-------+--------+---------------+---------+---------+-------+--------+-------------+
| table | type   | possible_keys | key     | key_len | ref   | rows   | Extra       |
+-------+--------+---------------+---------+---------+-------+--------+-------------+
| w     | ALL    | NULL          | NULL    |    NULL | NULL  | 142429 |             |
| u     | eq_ref | PRIMARY       | PRIMARY |       4 | w.uid |      1 | Using where |
+-------+--------+---------------+---------+---------+-------+--------+-------------+
dries’s picture

Also, 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.

ebruts’s picture

Found 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)

  $sql = "SELECT w.uid, w.severity, w.type, w.timestamp, w.message, w.link, u.name, u.uid FROM {watchdog} w INNER JOIN {users} u ON w.uid = u.uid";
  //$tablesort = tablesort_sql($header);

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.uid

So we just drop the rest starting from INNER JOIN and this

  // Added a fixed $count_query
  if ($type != 'all') {
    $result = pager_query($sql ." WHERE w.type = '%s'". $tablesort, 50, 0, "SELECT COUNT(*) FROM {watchdog} WHERE type = '". db_escape_string($type) ."'", $type);
  }
  else {
    $result = pager_query($sql . $tablesort, 50, 0, NULL, "SELECT COUNT(*) FROM {watchdog}");
  }

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.

ebruts’s picture

Title: Improve watchdog overview speed » Improve watchdog/statistics query speed
Status: Active » Needs review
StatusFileSize
new5.93 KB

I was wondering why the added INDEX had no impact on the query. Compare this with Dries' comment.

mysql> EXPLAIN SELECT w.*, u.name, u.uid FROM watchdog w INNER JOIN users u ON w.uid = u.uid LIMIT 0, 50;
+-------+------+---------------+------+---------+------+--------+-------------+
| table | type | possible_keys | key  | key_len | ref  | rows   | Extra       |
+-------+------+---------------+------+---------+------+--------+-------------+
| u     | ALL  | PRIMARY       | NULL |    NULL | NULL |   3275 |             |
| w     | ALL  | NULL          | NULL |    NULL | NULL | 936189 | Using where |
+-------+------+---------------+------+---------+------+--------+-------------+

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:

SELECT a.aid, a.path, a.title, a.uid, u.name, a.timestamp FROM accesslog a LEFT JOIN users u ON u.uid = a.uid ORDER BY  a.path ASC LIMIT 0, 30
Time: 22.4348480701 seconds

After:

SELECT a.aid, a.path, a.title, a.uid, u.name, a.timestamp FROM accesslog a LEFT JOIN users u ON u.uid = a.uid ORDER BY  a.path ASC LIMIT 0, 30
Time: 0.000720024108887 seconds

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.

ebruts’s picture

On the other side INSERTs will be slower for the accesslog (as for the watchdog, I don't think that matters).

drumm’s picture

Version: x.y.z » 6.x-dev
Status: Needs review » Needs work

No longger applies.

FiReaNGeL’s picture

I 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 :

Generated by: phpMyAdmin 2.9.0.3 / MySQL 5.0.27-community-nt
SQL query: EXPLAIN SELECT w.*, u.name, u.uid FROM watchdog w LEFT JOIN users u ON w.uid = u.uid ORDER BY w.wid DESC LIMIT 0, 50;
id 	select_type 	table 	type 	possible_keys   	key 	      key_len 	  ref 	rows 	Extra
1 	SIMPLE 	           w 	 index 	     NULL 	         PRIMARY 	  4 	    NULL 	500031 	 
1 	SIMPLE 	           u 	  eq_ref   PRIMARY 	       PRIMARY 	        4 	drupal.w.uid 	1 	  

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.

RobRoy’s picture

(theres no case where a watchdog log row has no user that I know of -
the field is set to 'not null' anyway)

I 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?

FiReaNGeL’s picture

You 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.

FiReaNGeL’s picture

I 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.

dmitrig01’s picture

Version: 6.x-dev » 4.7.x-dev

Doesn't apply to drupal 5 or 6

killes@www.drop.org’s picture

Version: 4.7.x-dev » 6.x-dev

the patch may not apply, but our workflow mandates it has to be in the dev-6 branch.

Wesley Tanaka’s picture

delete from watchdog where timestamp < XXX, which is called every time cron is run, is slow without an index on timestamp.

pancho’s picture

Title: Improve watchdog/statistics query speed » watchdog_overview() is terribly slow
Category: task » bug

Still to be fixed. For large sites this is a performance bug.

dpearcefl’s picture

Does this still need to be fixed in current D6?

Status: Needs work » Closed (outdated)

Automatically closed because Drupal 6 is no longer supported. If the issue verifiably applies to later versions, please reopen with details and update the version.