vb.org Archive - How To Check Your Plugins For Performance

Warning: Advanced tutorial - for developers only.

We all love the new product & plugins system that was introduced in vbulletin. No more doing file modifications, no more writing a lot of instructions in a long txt and following them for an hour to install a hack, just upload the product, run.. ready (with some exceptions, of course).

I found myself trying to find a "good" method for checking my plugins for performance. After all, I don't want a hack or modification going wild and slowing my whole forum. I seriously needed to find a way to find out how much resources my plugins were using. And, while developing, I wanted to make sure that I didn't have "bad code" that used too many resources.

We already had the solution, for logging the page load time, a microtime() is used. Why not do it with every hook as well, then we could check the statistics and if a hook is taking too much time to execute, disable it, or reprogram it.

Gettings these statistics is a simple modification.

1) We'll need to create a new table, run the following query (add your table prefix if necessary):

Code:

CREATE TABLE hookstats (

  hookid int auto_increment primary key,

  hookname varchar(250) not null,

  start varchar(30) not null,

  end varchar(30) null

  );

2) Open class_hook.php (in the includes directory), and find:

PHP Code:


		
			
return $this->pluginlist["$hookname"];

Change it to:

PHP Code:


		
			
        return

            "

            global \$db;

            \$db->query_write(\"INSERT INTO ".TABLE_PREFIX."hookstats (hookname, start) VALUES ('".$hookname."', '\".microtime(true).\"')\");

            \$hookid = \$db->insert_id();

            

            ".

            $this->pluginlist["$hookname"].

            "

            \$db->query_write(\"UPDATE ".TABLE_PREFIX."hookstats SET end='\".microtime(true).\"' WHERE hookid=\$hookid\");

            "

            ;

Curious? I just added to every hook some lines to insert into the database the start and end time, the microtime. Now all the hook execution time is logged into the database.

3) Open a couple pages on which the plugins are used. Browse a while. We need the plugins to be executed before checking the stats!

4) Run the following query on your favorite sql client, phpmyadmin, the console, or wherever you want to check the stats (add the table prefix if necessary):

Code:

SELECT

    hookname,avg(end-start) runtime

FROM hookstats

WHERE end > 0

GROUP BY hookname

ORDER BY runtime DESC;

You will get something like this:

Code:

+-------------------------------+---------------------+

| hookname                      | runtime             |

+-------------------------------+---------------------+

| forumhome_complete            |    0.54312801516406 | 

| newpost_process               |   0.020376857913686 | 

| editpost_edit_complete        |   0.014933427174886 | 

| profile_editusergroups_start  |  0.0098423132529626 | 

| profile_updateavatar_complete |  0.0098001956939697 | 

| global_shutdown               |  0.0080306405620168 | 

+-------------------------------+---------------------+

This means that forumhome_complete, on average, takes 0.5 seconds to execute. Depending on your server that could be ok, or very bad. newpost_process takes 0.02 seconds to execute (that's better).

You can check the average execution time for every hook.

These are the average execution times for each hook on your forum. Of course, what you probably needed was the execution time for a plugin, or a product, not the whole hook. Doing so is out of the scope of this tutorial, this technique shouldn't be so difficult to extend for logging the time per plugin or per product. For now, seeing the information per hook is useful and a good start.

The irony? Try not to use this on a production environment since logging in the database takes some resources. You are adding a lot of queries, 2 per hook. This should be used whenever you need to benchmark performance, test your mod, and disabled after.

X vBulletin 3.8.12 by vBS Debug Information
Page Generation 0.02440 seconds Memory Usage 1,729KB Queries Executed 10 (?)
More Information
Template Usage: (1)ad_footer_end (1)ad_footer_start (1)ad_header_end (1)ad_header_logo (1)ad_navbar_below (3)bbcode_code_printable (2)bbcode_php_printable (1)footer (1)gobutton (1)header (1)headinclude (6)option (1)post_thanks_navbar_search (1)printthread (3)printthreadbit (1)spacer_close (1)spacer_open Phrase Groups Available: global postbit showthread	Included Files: ./printthread.php ./global.php ./includes/init.php ./includes/class_core.php ./includes/config.php ./includes/functions.php ./includes/class_hook.php ./includes/modsystem_functions.php ./includes/class_bbcode_alt.php ./includes/class_bbcode.php ./includes/functions_bigthree.php Hooks Called: init_startup init_startup_session_setup_start init_startup_session_setup_complete cache_permissions fetch_threadinfo_query fetch_threadinfo fetch_foruminfo style_fetch cache_templates global_start parse_templates global_setup_complete printthread_start bbcode_fetch_tags bbcode_create bbcode_parse_start bbcode_parse_complete_precache bbcode_parse_complete printthread_post printthread_complete
Messages: