libertus

Investigating WordPress 2.0.4 Performance

none
~

“Smiley” Peformance Monitor plugin for WordPress

As there have been reports of dramatic slow-downs after upgrading to WordPress 2.0.4, and my blog is still running 2.0.3, naturally I wish to investigate these reports prior to upgrading. I could wait for the WordPress developers to do this, but I’m impatient. WordPress 2.0.4 contains a critical security fix that I wish to apply, among others. I don’t want to sacrifice performance for a tiny amount of extra safety.

I previously investigated the memory use of WordPress 2.0.2. I shall build upon that work to introduce execution timestamps and database queries into the performance graph. I shall then directly compare the performance of 2.0.3 and 2.0.4 on the same dataset – my blog, of course!

Review

My previous work resulted in each execution of WordPress generating and storing a graph of program memory usage. The performance issues reported in WordPress 2.0.4 seem to be related to excessive database queries so I want to probe how many are executed and when. WordPress already tracks this information, so gathering it is easy.

Preparation

I begin afresh with WordPress 2.0.3 and an extraction of the previous memory graph source into a new file named performance-probe.php, as follows:

function performance_probe( $tag )
{
  global $wpdb;
  global $performance_graph;

  $performance_graph[] =
    array(
      $tag,
      memory_get_usage(),
      timer_stop(),
      $wpdb->num_queries
    )
  ;
}

function performance_probe_dump_graph() {
  performance_probe( $_SERVER['REQUEST_URI'] );

  $filename = $basename = ABSPATH . '/wp-content/perfgraph-'.date('Ymd-His');
  while( file_exists( $filename ) and ++$seq < 100 )
    $filename = $basename . '-' . $seq;

  global $performance_graph;
  file_put_contents($filename, gzcompress(serialize($performance_graph)) );
}

register_shutdown_function( 'performance_probe_dump_graph' );

This file is included at the beginning of the WordPress index.php. The probe is invasive in nature, requiring a modification, albeit simple, to the WordPress core, in wp-includes/functions.php, at the top of function do_action().

function do_action($tag, $arg = '') {
if(function_exists('performance_probe')) performance_probe($tag);

Finally I import a data dump of my live blog, on which I shall generate the graphs for 2.0.3, upgrade to 2.0.4 and regenerate the graphs.

Ready

The performance testing blog is here.

Taking a Dump

The performance reading dumps to follow were produced using this PHP script.

<?php
$graph = unserialize(gzuncompress(file_get_contents($_SERVER['argv'][1])));
foreach( $graph as $index => $reading ) {
  $tag=$reading[0];
  $memory=$reading[1];
  $timestamp=number_format($reading[2],3);
  $queries = $reading[3];

  $delta = $memory - $delta;
  echo "$index,$tag,$memory,$delta,$timestamp,$queries\\n";
  $delta = $memory;
}
?>

This entry was posted by Libertus on August 6, 2006 at 10:00 am under Education, Plugins, Publicity, Skills, Software, WordPress. You can skip to the end and leave a response. Pinging is currently not allowed. Follow any responses to this entry through the RSS 2.0 feed.

7 Comments

Libertus says:

WordPress 2.0.3 Performance

Non-widget Theme

My first tests with the default, non-widgetized theme, are as follows:

paul@kubuntu ~/p/w/wp-content> php dump.php perfgraph-20060806-114525

0,plugins_loaded,3384120,3384120,0.096,2
1,init,3453264,69144,0.100,2
2,set_current_user,3463160,9896,0.102,4
3,pre_get_posts,3450648,-12512,0.105,4
4,template_redirect,3589808,139160,0.136,8
5,wp_head,3603096,13288,0.139,8
6,loop_start,3594464,-8632,0.142,11
7,loop_end,3618680,24216,0.214,11
8,wp_meta,3754464,135784,0.269,19
9,wp_footer,3746200,-8264,0.270,19
10,/~paul/wp-perftest/,3739408,-6792,0.270,19

paul@kubuntu ~/p/w/wp-content> php dump.php perfgraph-20060806-114529

0,plugins_loaded,3384120,3384120,0.095,2
1,init,3453264,69144,0.099,2
2,set_current_user,3463160,9896,0.101,4
3,pre_get_posts,3450856,-12304,0.106,4
4,template_redirect,3589960,139104,0.112,8
5,wp_head,3603248,13288,0.116,8
6,loop_start,3594616,-8632,0.123,11
7,loop_end,3618752,24136,0.191,11
8,wp_meta,3754536,135784,0.244,19
9,wp_footer,3746272,-8264,0.245,19
10,/~paul/wp-perftest/,3739480,-6792,0.245,19

paul@kubuntu ~/p/w/wp-content> php dump.php perfgraph-20060806-114533

0,plugins_loaded,3384120,3384120,0.094,2
1,init,3453264,69144,0.098,2
2,set_current_user,3463160,9896,0.100,4
3,pre_get_posts,3450648,-12512,0.103,4
4,template_redirect,3589808,139160,0.109,8
5,wp_head,3603096,13288,0.113,8
6,loop_start,3594464,-8632,0.115,11
7,loop_end,3618680,24216,0.187,11
8,wp_meta,3754464,135784,0.240,19
9,wp_footer,3746200,-8264,0.242,19
10,/~paul/wp-perftest/,3739408,-6792,0.242,19

The test homepage uses 19 database queries and renders in roughly 0.25 seconds.

Add Widgets

I use the “Recent Comments” and “Recent Posts” widgets, both of which require database queries, so test with these activated is important.

paul@kubuntu ~/p/w/wp-content> php dump.php perfgraph-20060806-120442

0,plugins_loaded,3635240,3635240,0.121,2
1,init,3719480,84240,0.126,2
2,set_current_user,3719304,-176,0.128,4
3,widgets_init,3737760,18456,0.182,4
4,pre_get_posts,3719808,-17952,0.187,4
5,template_redirect,3854496,134688,0.221,8
6,wp_head,3868008,13512,0.225,8
7,loop_start,3859376,-8632,0.229,11
8,loop_end,3883384,24008,0.316,11
9,wp_meta,3896848,13464,0.322,12
10,parse_query,3910552,13704,0.327,14
11,pre_get_posts,3910968,416,0.327,14
12,loop_start,3954648,43680,0.331,17
13,loop_end,3954672,24,0.349,17
14,wp_footer,4076424,121752,0.408,24
15,/~paul/wp-perftest/,4069184,-7240,0.408,24

paul@kubuntu ~/p/w/wp-content> php dump.php perfgraph-20060806-120449

0,plugins_loaded,3635328,3635328,0.101,2
1,init,3719656,84328,0.105,2
2,set_current_user,3719480,-176,0.107,4
3,widgets_init,3737936,18456,0.147,4
4,pre_get_posts,3719728,-18208,0.151,4
5,template_redirect,3854520,134792,0.157,8
6,wp_head,3868032,13512,0.161,8
7,loop_start,3859400,-8632,0.163,11
8,loop_end,3883488,24088,0.237,11
9,wp_meta,3896952,13464,0.240,12
10,parse_query,3910656,13704,0.244,14
11,pre_get_posts,3911072,416,0.244,14
12,loop_start,3954752,43680,0.250,17
13,loop_end,3954776,24,0.268,17
14,wp_footer,4076528,121752,0.315,24
15,/~paul/wp-perftest/,4069288,-7240,0.315,24

paul@kubuntu ~/p/w/wp-content> php dump.php perfgraph-20060806-120452

0,plugins_loaded,3635328,3635328,0.103,2
1,init,3719656,84328,0.107,2
2,set_current_user,3719480,-176,0.110,4
3,widgets_init,3737936,18456,0.146,4
4,pre_get_posts,3719728,-18208,0.154,4
5,template_redirect,3854520,134792,0.160,8
6,wp_head,3868032,13512,0.164,8
7,loop_start,3859400,-8632,0.167,11
8,loop_end,3883488,24088,0.234,11
9,wp_meta,3896952,13464,0.237,12
10,parse_query,3910656,13704,0.241,14
11,pre_get_posts,3911072,416,0.241,14
12,loop_start,3954752,43680,0.246,17
13,loop_end,3954776,24,0.265,17
14,wp_footer,4076528,121752,0.313,24
15,/~paul/wp-perftest/,4069288,-7240,0.313,24

As expected, Widgets on the homepage cause it to use more queries and load slower, but not by any excessive amount – 5 more queries and 0.06 seconds longer.
August 6, 2006, 12:06 pm
Libertus says:

Upgrade to WordPress 2.0.4

Copy the files, which disables the performance probes. There’s no need to run the upgrade script (the database schema has not changed), and I’m not asked to, but I do anyway.
August 6, 2006, 12:11 pm
Libertus says:

WordPress 2.0.4 Performance

First, I reappy the performance probe change to index.php and wp-includes/functions.php. Next, I view the test site. There is no perceptible performance difference, but I notice the widget changes need to be reapplied to the theme.

That done, and a few more reloads, there is still no perceptible performance difference. Now, I can’t say I’m able to notice differences when performance is already in the sub-second range, so what to the numbers say?

paul@kubuntu ~/p/w/wp-content> php dump.php perfgraph-20060806-122136

0,plugins_loaded,3710856,3710856,0.106,2
1,sanitize_comment_cookies,3715736,4880,0.107,2
2,init,3781672,65936,0.111,2
3,set_current_user,3791112,9440,0.113,4
4,widgets_init,3799880,8768,0.121,4
5,pre_get_posts,3787704,-12176,0.125,4
6,template_redirect,3930560,142856,0.160,8
7,wp_head,3942688,12128,0.163,8
8,loop_start,3936176,-6512,0.165,11
9,loop_end,3959992,23816,0.237,11
10,wp_meta,3972048,12056,0.242,12
11,parse_query,3986528,14480,0.246,14
12,pre_get_posts,3986944,416,0.247,14
13,loop_start,4030936,43992,0.258,17
14,loop_end,4030872,-64,0.273,17
15,wp_footer,4152736,121864,0.322,24
16,/~paul/wp-perftest/,4145304,-7432,0.322,24

paul@kubuntu ~/p/w/wp-content> php dump.php perfgraph-20060806-122145

0,plugins_loaded,3710856,3710856,0.108,2
1,sanitize_comment_cookies,3715736,4880,0.108,2
2,init,3781672,65936,0.112,2
3,set_current_user,3791112,9440,0.114,4
4,widgets_init,3799880,8768,0.122,4
5,pre_get_posts,3787704,-12176,0.126,4
6,template_redirect,3930560,142856,0.137,8
7,wp_head,3942688,12128,0.140,8
8,loop_start,3936176,-6512,0.142,11
9,loop_end,3959992,23816,0.214,11
10,wp_meta,3972048,12056,0.216,12
11,parse_query,3986528,14480,0.225,14
12,pre_get_posts,3986944,416,0.225,14
13,loop_start,4030936,43992,0.231,17
14,loop_end,4030872,-64,0.245,17
15,wp_footer,4152736,121864,0.293,24
16,/~paul/wp-perftest/,4145304,-7432,0.293,24

paul@kubuntu ~/p/w/wp-content> php dump.php perfgraph-20060806-122148

0,plugins_loaded,3710856,3710856,0.106,2
1,sanitize_comment_cookies,3715736,4880,0.107,2
2,init,3781672,65936,0.111,2
3,set_current_user,3791112,9440,0.113,4
4,widgets_init,3799880,8768,0.126,4
5,pre_get_posts,3787704,-12176,0.129,4
6,template_redirect,3930560,142856,0.136,8
7,wp_head,3942688,12128,0.139,8
8,loop_start,3936176,-6512,0.142,11
9,loop_end,3959992,23816,0.220,11
10,wp_meta,3972048,12056,0.223,12
11,parse_query,3986528,14480,0.227,14
12,pre_get_posts,3986944,416,0.227,14
13,loop_start,4030936,43992,0.232,17
14,loop_end,4030872,-64,0.246,17
15,wp_footer,4152736,121864,0.298,24
16,/~paul/wp-perftest/,4145304,-7432,0.298,24

Nothing. The homepage hasn’t slowed down. So, move on to a specific use case.
August 6, 2006, 12:14 pm
Libertus says:
outreach
- none
- ~
Robert Deaton’s Use Case

On the wp-hackers mailing list, 5^th August 2006 at 23:00, Robert Deaton described a particular use case in which slow-down occurs.

I believe I have found part of the cause of the 2.0.4 performance
issues complaints. Somewhere between 2.0.3 and 2.0.4, we did something
that calls get_post tens to hundreds of times depending on the number
of pages when viewing a page with a permalink. This is now completely
reproducable, and is a serious concern as I have one client who is
getting in excess of 300 database queries per page view.

I haven’t yet found the core cause of the issue, but to reproduce,
make sure you have a decent amount of pages (say at least 20 or so),
and fancy permalinks enabled, and likely some sort of menu listing the
pages on the sidebar (I believe this is where the issue is, the new
page walking code perhaps?). You should notice a considerable spike in
query usage, I haven’t had a chance to dig around more, but the rest
of you are welcome to do so, imho this is big enough where it needs to
be fixed and maybe even one last release on the 2.0.x series before
2.1, as this could cause shared hosts to ban users easily for
hammering the db server.

Analysis

The homepage isn’t cited as being slow. This sounds like a single-page view with a sidebar, accessed by permalink.

Checking my test data, I don’t have a decent number of pages (11), so I create 10 more. I do have fancy permalinks enabled and it’s easy to make the Widget sidebar with page listing appear in the single-page view.

First Test

I run the homepage then switch to a single page from the sidebar, which I reload a couple of times, after a bit of wrangling with .htaccess to get the permalinks working. The results are interesting.

Homepage

paul@kubuntu ~/p/w/wp-content> php dump.php perfgraph-20060806-125348

0,plugins_loaded,3727104,3727104,0.138,2
1,sanitize_comment_cookies,3732064,4960,0.139,2
2,init,3798032,65968,0.147,2
3,set_current_user,3807472,9440,0.149,4
4,widgets_init,3816240,8768,0.159,4
5,pre_get_posts,3825864,9624,0.165,4
6,template_redirect,3968440,142576,0.207,8
7,wp_head,3980568,12128,0.210,8
8,loop_start,3974056,-6512,0.215,11
9,loop_end,3996240,22184,0.292,11
10,wp_meta,4008296,12056,0.297,12
11,parse_query,4022776,14480,0.302,14
12,pre_get_posts,4023192,416,0.302,14
13,loop_start,4067184,43992,0.307,17
14,loop_end,4067120,-64,0.321,17
15,wp_footer,4215728,148608,0.383,24
16,/~paul/wp-perftest/,4208296,-7432,0.383,24

Single Page

paul@kubuntu ~/p/w/wp-content> php dump.php perfgraph-20060806-125443

0,plugins_loaded,3727472,3727472,0.104,2
1,sanitize_comment_cookies,3732856,5384,0.104,2
2,init,3798768,65912,0.108,2
3,set_current_user,3808208,9440,0.111,4
4,widgets_init,3816976,8768,0.119,4
5,parse_query,3819184,2208,0.123,4
6,pre_get_posts,3819632,448,0.123,4
7,template_redirect,4013528,193896,0.135,15
8,wp_head,4025792,12264,0.144,15
9,loop_start,4019304,-6488,0.146,18
10,loop_end,4028888,9584,0.194,18
11,wp_meta,4040152,11264,0.196,18
12,parse_query,4065184,25032,0.201,21
13,pre_get_posts,4065600,416,0.201,21
14,loop_start,4105600,40000,0.207,24
15,loop_end,4105704,104,0.220,24
16,wp_footer,4254632,148928,0.280,31
17,/~paul/wp-perftest/zeitgeist/,4249616,-5016,0.280,31

Observations

The number of queries for the page view is 7 more than for the homepage, for no obvious reason, which deserves further investigation. The page load time is not affected.

Investigation

The extra 7 queries occur between action pre_get_posts and action template_redirect. Why does a single page view need so many more queries than the homepage? At a guess, I’d say security (there’s an “Edit this page” link), but I can’t account for 7 queries with that alone. Time to look in the code, down the is_single(), is_page() and !is_home() paths, starting from wp-includes/classes.php, function WP_Query::get_posts().

This yields a block of code, conditional on query parameter pagename, containing a call to get_all_page_ids() and a loop calling get_page(). This loop appears to be the means by which the ID of the required single page is found. I can prove this by choosing a different page, perhaps one of the test pages I added, and see how many queries are performed, betting that it’s no longer 7 more than the homepage.

paul@kubuntu ~/p/w/wp-content> php dump.php perfgraph-20060806-132515

0,plugins_loaded,3727424,3727424,0.102,2
1,sanitize_comment_cookies,3732736,5312,0.102,2
2,init,3798672,65936,0.106,2
3,set_current_user,3808112,9440,0.108,4
4,widgets_init,3816880,8768,0.117,4
5,parse_query,3814704,-2176,0.119,4
6,pre_get_posts,3815248,544,0.119,4
7,template_redirect,4068240,252992,0.151,30
8,wp_head,4078784,10544,0.154,30
9,loop_start,4071592,-7192,0.156,33
10,loop_end,4071640,48,0.157,33
11,wp_meta,4083384,11744,0.159,33
12,parse_query,4116720,33336,0.165,36
13,pre_get_posts,4117136,416,0.165,36
14,loop_start,4158400,41264,0.199,39
15,loop_end,4158504,104,0.213,39
16,wp_footer,4303872,145368,0.277,46
17,/~paul/wp-perftest/performance-test-rd-usecase-page-7/performance-test-rd-usecase-page-8/performance-test-rd-usecase-page-9/performance-test-rd-usecase-page-10/,4298856,-5016,0.277,46

I think this illustrates the problem nicely. The linear page ID search algorithm is rather inefficient.
August 6, 2006, 12:29 pm
Libertus says:
outreach
- none
- ~
Upgrade Problem or Not?

This probably isn’t the upgrade problem, but it is certainly a problem one might encounter upon upgrade to a version that contains this inefficient search code. Using the WordPress Trac I can browse the source looking back through the versions to find out in which the offending code was introduced.

2.0.4

Contains at line 379

2.0.3

Contains at line 378

2.0.2

Contains at line 378

2.0.1

Contains at line 378

No, this isn’t an upgrade problem at all. It’s just a problem my blog already has.
August 6, 2006, 2:06 pm
Libertus says:

The “Smiley” Performance Monitor Plugin for WordPress

Just for fun. Whilst activated, it puts a couple of smilies at the top-left of the page to indicate how hard WordPress had to work to make the page.

“Smiley” Peformance Monitor plugin for WordPress
August 6, 2006, 5:05 pm
Libertus says:

Performance Probe Plugin

Thanks to MarkJaquith on #wordpress for this freaky idea, which works! With a different one-line change to do_action(), the performance probe becomes a plugin.
```
function do_action($tag, $arg = '') {
  if( $tag != 'do_action' ) do_action( 'do_action', $tag );
```
I also experimented with a non-invasive plugin using add_action( 'all', 'performance_probe' ); but this gets called for all filters too and so generates too much information to be useful.
August 12, 2006, 12:21 pm

You must be logged in to post a comment.

Investigating WordPress 2.0.4 Performance

Review

Preparation

Ready

Taking a Dump

7 Comments

Libertus says:

WordPress 2.0.3 Performance

Non-widget Theme

Add Widgets

Libertus says:

Upgrade to WordPress 2.0.4

Libertus says:

WordPress 2.0.4 Performance

Libertus says:

Robert Deaton’s Use Case

Analysis

First Test

Homepage

Single Page

Observations

Investigation

Libertus says:

Upgrade Problem or Not?

Libertus says:

The “Smiley” Performance Monitor Plugin for WordPress

Libertus says:

Performance Probe Plugin

Leave a Reply

Pages

Recent Posts

Categories

Archives