MyBB Community Forums

For debugging purposes, I wrote a small profiler that shows timestamps of queries and hook calls of a request. If time is being wasted somewhere during a request, this can help pinpoint the culprit. Unfortunately it has to be patched in, since it can't be done easily in a plugin.

Output looks like this:

　  [0.0913179] => hook_by_ref my_date
    [0.0918109] => hook_by_ref my_date
    [0.0922251] => hook global_end
    [0.0973320] => before query SELECT title,cache FROM mybb_datacache WHERE title='forumpermissions'
    [0.0974650] => after query SELECT title,cache FROM mybb_datacache WHERE title='forumpermissions'
    [0.0976849] => before query SELECT threads, unapprovedthreads FROM mybb_forums WHERE fid = '478' LIMIT 1
    [0.0977879] => after query SELECT threads, unapprovedthreads FROM mybb_forums WHERE fid = '478' LIMIT 1
    [0.0978410] => before query SELECT COUNT(tid) as threads FROM mybb_threads WHERE fid = '478' AND (lastpost >= '1293742791' OR sticky=1)  AND (visible='1' OR visible='0')  ORDER BY lastpost DESC
    [0.0979369] => after query SELECT COUNT(tid) as threads FROM mybb_threads WHERE fid = '478' AND (lastpost >= '1293742791' OR sticky=1)  AND (visible='1' OR visible='0')  ORDER BY lastpost DESC
    [0.1016750] => hook showthread_start
    [0.1130099] => before query 
					REPLACE INTO mybb_threadsread (tid, uid, dateline)
					VALUES('514213', '100001', '1298493236')
				
    [0.1132450] => after query 
					REPLACE INTO mybb_threadsread (tid, uid, dateline)
					VALUES('514213', '100001', '1298493236')

Patch can be applied with my Patches plugin (import the attachment) or manually. [attachment=21723]

inc/class_plugins.php:

/* + */ global $maintimer, $profiler;
/* + */ $profiler[$maintimer->stop()] = "before load {$plugin}";
				if($plugin != "" && file_exists(MYBB_ROOT."inc/plugins/".$plugin.".php"))
				{
					require_once MYBB_ROOT."inc/plugins/".$plugin.".php";
				}
/* + */ $profiler[$maintimer->stop()] = "after load {$plugin}";

/* + */ global $maintimer, $profiler;
/* + */ $profiler[$maintimer->stop()] = "hook {$hook}";
		if(!is_array($this->hooks[$hook]))
		{
			return $arguments;
		}
		$this->current_hook = $hook;
		ksort($this->hooks[$hook]);
		foreach($this->hooks[$hook] as $priority => $hooks)
		{
			if(is_array($hooks))
			{
				foreach($hooks as $hook)
				{
					if($hook['file'])
					{
						require_once $hook['file'];
					}
					$oldreturnargs = $returnargs; // why is this line of code here?
					
					$returnargs = call_user_func_array($hook['function'], array(&$arguments));
					
					
					if($returnargs)
					{
						$arguments = $returnargs;
					}
/* + */ $profiler[$maintimer->stop()] = "after {$this->current_hook} {$hook['function']}";

/* + */ global $maintimer, $profiler;
/* + */ $profiler[$maintimer->stop()] = "hook_by_ref {$hook}";
		if(empty($this->hooks[$hook]) && !is_array($this->hooks[$hook]))
		{
			return $arguments;
		}
		$this->current_hook = $hook;
		ksort($this->hooks[$hook]);
		foreach($this->hooks[$hook] as $priority => $hooks)
		{
			if(is_array($hooks))
			{
				foreach($hooks as $hook)
				{
					if($hook['file'])
					{
						require_once $hook['file'];
					}
					
					call_user_func_array($hook['function'], array(&$arguments));				
/* + */ $profiler[$maintimer->stop()] = "after {$this->current_hook} {$hook['function']}";

inc/db_mysqli.php:

	function query($string, $hide_errors=0, $write_query=0)
	{
/* + */ global $profiler, $maintimer;
/* + */ $profiler[$maintimer->stop()] = "before query {$string}";

/* + */ $profiler[$maintimer->stop()] = "after query {$string}";
		return $query;

inc/functions.php:

			$debugstuff = "Generated in $totaltime seconds 
($percentphp% PHP / $percentsql% MySQL)<br />
SQL Queries: $db->query_count /  Global Parsing Time: $globaltime$memory_usage<br />
$other<br />[<a href=\"$debuglink\" target=\"_blank\">advanced details</a>]<br />";
/* + */ global $profiler;
/* + */ $debugstuff .= "<pre style=\"float: left; text-align: left; overflow: auto; width: 1000px;\">".htmlspecialchars(print_r($profiler, true))."</pre>";

This looks good, thanks for sharing.

how is this different than the debug output mod I posted before?

A single edit the debug code gives the hook name and functions being used for each query.

http://community.mybb.com/thread-88358-p...#pid646406

and the debug pages already give you time per query. So i suppose your edit gives you the time between queries (PHP processing), but actual query time is already available.

The query output by itself is useless if it's PHP taking a long time, not MySQL.

If you have a page generation time 95% PHP and 5% MySQL, all the MySQL debug will show you is that all queries were fast. To locate the culprit on the PHP side (loop, or blocking network I/O, ...), you need to find out where the time is lost, and that's what this profiler does... it shows what is called when, so if you have a huge time gap between two calls, whatever is being done between those calls is where you can find your culprit...

I'm sure there are better ways to do this, but I needed something quick & dirty and since I made it anyway, I shared it.

Its a good idea, I was just asking. Most folks seem to have SQL issues and PHP runs fast, but as I posted and you confirmed, your setup will catch the PHP slow downs

I really do need to start using your patches plugin. It will help me keep track of changes I make a lot better than I have been. This is a good reminder of that