Adding Query Execution Time to Debug

Discussion regarding Joomla! 1.5 Performance issues.

Moderator: General Support Moderators

Forum rules
Forum Rules
Absolute Beginner's Guide to Joomla! <-- please read before posting, this means YOU.
Security and Performance FAQs
Forum Post Assistant - If you are serious about wanting help, you will use this tool to help you post.
Locked
almooj-craig
Joomla! Guru
Joomla! Guru
Posts: 500
Joined: Mon Aug 11, 2008 3:05 pm

Adding Query Execution Time to Debug

Post by almooj-craig » Sat Aug 13, 2011 3:25 pm

I was thinking that it would be a good idea to have the query execution time displayed for each query that gets listed with the debug plugin. That way it's easier to see what's going on.

In the \libraries\joomla\database\database\mysql.php file change the query function to:

Code: Select all

	function query()
	{
		if (!is_resource($this->_resource)) {
			return false;
		}

		if ($this->_limit > 0 || $this->_offset > 0) {
			$this->_sql .= ' LIMIT '.$this->_offset.', '.$this->_limit;
		}
		if ($this->_debug) {
			$this->_ticker++;
			//$this->_log[] = $this->_sql;
			$t = microtime();
		}
		$this->_errorNum = 0;
		$this->_errorMsg = '';
		$this->_cursor = mysql_query( $this->_sql, $this->_resource );

		if (!$this->_cursor)
		{
			$this->_errorNum = mysql_errno( $this->_resource );
			$this->_errorMsg = mysql_error( $this->_resource )." SQL=$this->_sql";

			if ($this->_debug) {
				JError::raiseError(500, 'JDatabaseMySQL::query: '.$this->_errorNum.' - '.$this->_errorMsg );
			}
			return false;
		}
		if ($this->_debug) {
			$this->_log[] = $this->_sql. '--Time: '.(microtime() - $t);
		}
		return $this->_cursor;
	}
Then in the /plugins/system/debug.php file change the onAfterRender function modify this line:

Code: Select all

			$newlineKeywords = '/<span style="color: #993333; font-weight: bold;">'
				.'(FROM|LEFT|INNER|OUTER|WHERE|SET|VALUES|ORDER|GROUP|HAVING|LIMIT|ON|AND|OR)'
				.'<\\/span>/i'
			;
so that it does a line break for "AND" and "OR".

Then in the same function add a few regexps to the if ($log = $db->getLog()) loop:

Code: Select all

if ($log = $db->getLog())
			{
				echo '<ol>';
				foreach ($log as $k=>$sql)
				{
					$geshi->set_source($sql);
					$text = $geshi->parse_code();
					$text = preg_replace($newlineKeywords, '<br>&nbsp;&nbsp;\\0', $text);
					$text = preg_replace('#(ON|AND|OR)<#', '&nbsp;&nbsp;\\0', $text);
					$text = preg_replace('#&nbsp; #', '', $text);
					$text = preg_replace('#<br />#', '<br>', $text);
					$text = preg_replace('#(&nbsp;)+?<br>#', '<br>', $text);
					$text = preg_replace('#<br>(\W+)?<br>#s', '<br>', $text);
					$text = str_replace('--Time:', '<br>Time:', $text);
					echo '<li>'.$text.'<br></li>';
				}
				echo '</ol>';
			}
Then the debug echo will look somewhat like this:

Code: Select all

SELECT folder AS type, element AS name, params
  FROM jos_plugins
  WHERE published >= 1
    AND access <= 2
  ORDER BY ordering
Time: 0.001047

User avatar
ahmad
Joomla! Guru
Joomla! Guru
Posts: 903
Joined: Fri Apr 07, 2006 4:02 pm
Location: Egypt
Contact:

Re: Adding Query Execution Time to Debug

Post by ahmad » Mon Nov 21, 2011 10:44 am

That's a great snippet, added to my favlist

There's a query time shows "9.8E-5", what does it mean and how can I convert it to seconds?

Thanks a lot

almooj-craig
Joomla! Guru
Joomla! Guru
Posts: 500
Joined: Mon Aug 11, 2008 3:05 pm

Re: Adding Query Execution Time to Debug

Post by almooj-craig » Mon Nov 21, 2011 3:08 pm

If you change all occurrences of microtime() to microtime(true) it should eliminate that problem.

Currently I am using slightly different code that tracks the query execution time (1st time) as well as the running time (2nd time). Then I have an option to toggle on/off the debug_backtrace info. Here is an example.

Code: Select all

/administrator/INDEX.php:65 dispatch
/administrator/includes/application.php:129 renderComponent
/libraries/joomla/application/component/helper.php:162 require_once
/administrator/components/com_cpanel/admin.cpanel.php:25 display
/administrator/components/com_cpanel/admin.cpanel.html.php:34 getModules
/libraries/joomla/application/module/helper.php:89 _load
/libraries/joomla/application/module/helper.php:336 loadObjectList
--
SELECT id, title, module, position, content, showtitle, control, params
  FROM jos_modules AS m
  LEFT JOIN jos_modules_menu AS mm
    ON mm.moduleid = m.id
  WHERE m.published = 1
    AND m.access <= 2
    AND m.client_id = 1
  ORDER BY position, ordering
Time: 0.0013659000396729 -- 0.09226393699646
If you are interested I'll post the code for my new method.
Craig
Last edited by almooj-craig on Mon Nov 21, 2011 4:19 pm, edited 1 time in total.

User avatar
ahmad
Joomla! Guru
Joomla! Guru
Posts: 903
Joined: Fri Apr 07, 2006 4:02 pm
Location: Egypt
Contact:

Re: Adding Query Execution Time to Debug

Post by ahmad » Mon Nov 21, 2011 3:18 pm

Man you're a legend! Thanks for saving my day :)
Sure thing It would be great if you could share the new snippet :)

almooj-craig
Joomla! Guru
Joomla! Guru
Posts: 500
Joined: Mon Aug 11, 2008 3:05 pm

Re: Adding Query Execution Time to Debug

Post by almooj-craig » Mon Nov 21, 2011 4:58 pm

This is the new method that adds the running time and the traceback info.

In the \libraries\joomla\database\database\mysql.php file change the query function to:

Code: Select all

function query()
{
	if (!is_resource($this->_resource)) {
		return false;
	}

	if ($this->_limit > 0 || $this->_offset > 0) {
		$this->_sql .= ' LIMIT '.$this->_offset.', '.$this->_limit;
	}
	if ($this->_debug) {
		$this->_ticker++;
		//$this->_log[] = $this->_sql;
		$t = microtime(true);
	}
	$this->_errorNum = 0;
	$this->_errorMsg = '';
	$this->_cursor = mysql_query( $this->_sql, $this->_resource );

	if (!$this->_cursor)
	{
		$this->_errorNum = mysql_errno( $this->_resource );
		$this->_errorMsg = mysql_error( $this->_resource )." SQL=$this->_sql";

		if ($this->_debug) {
			JError::raiseError(500, 'JDatabaseMySQL::query: '.$this->_errorNum.' - '.$this->_errorMsg );
		}
		return false;
	}
	if ($this->_debug) {
		if (JDEBUG)
		{
			$bcktrc_add='';
			if (JDEBUG==2)
			{
				$backtrace = debug_backtrace();
				if (is_array($backtrace))
				{
					for ($i = 20; $i > 0; $i--) 
					{
						if (isset($backtrace[$i]) and is_array($backtrace[$i]))
						{
							if (isset($backtrace[$i]['file']) and isset($backtrace[$i]['line']))
								$bcktrc_add .= str_replace(JPATH_ROOT, '', $backtrace[$i]['file']).':'.$backtrace[$i]['line'].' '.$backtrace[$i]['function']."\n";
						}
					}	
				}
				$bcktrc_add .= "\n--\n";
			}
			$mt =  microtime(true);
			$this->_log[] = $bcktrc_add . $this->_sql. '--Time: '.($mt - $t) . ' -- '. ($mt - $GLOBALS['dTime']);
		}
		else
			$this->_log[] = $this->_sql;
	}
	return $this->_cursor;
}
if ($this->_debug) {
if (JDEBUG)
seems redundant but some components like virtumart set the _debug without having JDEBUG set. This allows them to set _debug without errors.

In the \administrator\includes\framework.php you need to store the starting time:

Code: Select all

//if ($CONFIG->debug and preg_match('/^('.@$CONFIG->error_ip.')/', $_SERVER['REMOTE_ADDR']))
if ($CONFIG->debug)
{
	$GLOBALS['dTime'] = microtime(true);
	define( 'JDEBUG', $CONFIG->debug );
}
else
	define( 'JDEBUG', 0 );
//error_reporting(0);
Ignore the $CONFIG->error_ip part, I use that to only show debug and errors on my ip address.

Make the same change in the /includes/framework.php file.


Then in the global configuration you simply toggle debug off, on or on with traceback. You need to modify these two configuration files:

administrator\components\com_config\controllers\application.php

Code: Select all

// DEBUG
$debug 				= array (JHTML::_('select.option', 0, JText::_('No')),JHTML::_('select.option', 1, JText::_('Yes')), JHTML::_('select.option', 2, JText::_('With Traceback')));
$lists['debug'] = JHTML::_('select.genericlist',  $debug, 'debug', 'class="inputbox" size="1"', 'value', 'text', $row->debug);
//$lists['debug'] 		= JHTML::_('select.booleanlist', 'debug', 'class="inputbox"', $row->debug);
$lists['debug_lang'] 	= JHTML::_('select.booleanlist', 'debug_lang', 'class="inputbox"', $row->debug_lang);
Then in the \administrator\components\com_config\views\application\tmplfile\config_debug.php file, change the html so that it uses a list. I believe originally it used a boolean radio element.

Code: Select all

<td width="185" class="key">
	<span class="editlinktip hasTip" title="<?php echo JText::_( 'Enable Debugging' ); ?>::Set the IP address on the Server Page. <?php echo JText::_('TIPDEBUGGINGINFO'); ?>">
		<?php echo JText::_( 'Debug System' ); ?>
	</span>
</td>
<td>
	<?php echo $lists['debug']; ?>
</td>

User avatar
ahmad
Joomla! Guru
Joomla! Guru
Posts: 903
Joined: Fri Apr 07, 2006 4:02 pm
Location: Egypt
Contact:

Re: Adding Query Execution Time to Debug

Post by ahmad » Mon Nov 21, 2011 5:09 pm

Thanks for sharing almooj-craig :)

dristant
Joomla! Fledgling
Joomla! Fledgling
Posts: 1
Joined: Wed Feb 13, 2013 6:16 pm

Re: Adding Query Execution Time to Debug

Post by dristant » Wed Feb 13, 2013 6:21 pm

Can Some body post the same code for Joomla 2.5.6, It will be much appreciated...I tried to tweak the things but its not working..

Please find below the Code I tried...

I guess it should be the same function any help much appreciated..

Code: Select all

public function execute()
	{
		if (!is_resource($this->connection))
		{
			// Legacy error handling switch based on the JError::$legacy switch.
			// @deprecated  12.1
			if (JError::$legacy)
			{
				if ($this->debug)
				{
					JError::raiseError(500, 'JDatabaseMySQL::query: ' . $this->errorNum . ' - ' . $this->errorMsg);
				}
				return false;
			}
			else
			{
				JLog::add(JText::sprintf('JLIB_DATABASE_QUERY_FAILED', $this->errorNum, $this->errorMsg), JLog::ERROR, 'database');
				throw new JDatabaseException($this->errorMsg, $this->errorNum);
			}
		}

		// Take a local copy so that we don't modify the original query and cause issues later
		$sql = $this->replacePrefix((string) $this->sql);
		if ($this->limit > 0 || $this->offset > 0)
		{
			$sql .= ' LIMIT ' . $this->offset . ', ' . $this->limit;
		}

		// If debugging is enabled then let's log the query.
		if ($this->debug)
		{
			// Increment the query counter and add the query to the object queue.
			$this->count++;
			
			$t = microtime();
			//$this->log[] = $sql;
			
			JLog::add($sql, JLog::DEBUG, 'databasequery');
		}

		// Reset the error values.
		$this->errorNum = 0;
		$this->errorMsg = '';

		// Execute the query.
		$this->cursor = mysql_query($sql, $this->connection);

		// If an error occurred handle it.
		if (!$this->cursor)
		{
			$this->errorNum = (int) mysql_errno($this->connection);
			$this->errorMsg = (string) mysql_error($this->connection) . ' SQL=' . $sql;

			// Legacy error handling switch based on the JError::$legacy switch.
			// @deprecated  12.1
			if (JError::$legacy)
			{
				if ($this->debug)
				{
					JError::raiseError(500, 'JDatabaseMySQL::query: ' . $this->errorNum . ' - ' . $this->errorMsg);
				}
				return false;
			}
			else
			{
				JLog::add(JText::sprintf('JLIB_DATABASE_QUERY_FAILED', $this->errorNum, $this->errorMsg), JLog::ERROR, 'databasequery');
				throw new JDatabaseException($this->errorMsg, $this->errorNum);
			}
		}
		if ($this->_debug) {
         $this->_log[] = $this->_sql. '--Time: '.(microtime() - $t);
		}
		
		return $this->cursor;
	}
Thanks

almooj-craig
Joomla! Guru
Joomla! Guru
Posts: 500
Joined: Mon Aug 11, 2008 3:05 pm

Re: Adding Query Execution Time to Debug

Post by almooj-craig » Sun Feb 17, 2013 12:13 pm

I don't use 2.5 but reading through the code you posted, this is what I would try.

Code: Select all

public function execute()
   {
      if (!is_resource($this->connection))
      {
         // Legacy error handling switch based on the JError::$legacy switch.
         // @deprecated  12.1
         if (JError::$legacy)
         {
            if ($this->debug)
            {
               JError::raiseError(500, 'JDatabaseMySQL::query: ' . $this->errorNum . ' - ' . $this->errorMsg);
            }
            return false;
         }
         else
         {
            JLog::add(JText::sprintf('JLIB_DATABASE_QUERY_FAILED', $this->errorNum, $this->errorMsg), JLog::ERROR, 'database');
            throw new JDatabaseException($this->errorMsg, $this->errorNum);
         }
      }

      // Take a local copy so that we don't modify the original query and cause issues later
      $sql = $this->replacePrefix((string) $this->sql);
      if ($this->limit > 0 || $this->offset > 0)
      {
         $sql .= ' LIMIT ' . $this->offset . ', ' . $this->limit;
      }

      // If debugging is enabled then let's log the query.
      if ($this->debug)
      {
         // Increment the query counter and add the query to the object queue.
         $this->count++;
         
         $t = microtime(true);
		 //1.5 version $this->log[] = $sql;		  
         //JLog::add($sql, JLog::DEBUG, 'databasequery');
      }

      // Reset the error values.
      $this->errorNum = 0;
      $this->errorMsg = '';

      // Execute the query.
      $this->cursor = mysql_query($sql, $this->connection);

      // If an error occurred handle it.
      if (!$this->cursor)
      {
         $this->errorNum = (int) mysql_errno($this->connection);
         $this->errorMsg = (string) mysql_error($this->connection) . ' SQL=' . $sql;

         // Legacy error handling switch based on the JError::$legacy switch.
         // @deprecated  12.1
         if (JError::$legacy)
         {
            if ($this->debug)
            {
               JError::raiseError(500, 'JDatabaseMySQL::query: ' . $this->errorNum . ' - ' . $this->errorMsg);
            }
            return false;
         }
         else
         {
            JLog::add(JText::sprintf('JLIB_DATABASE_QUERY_FAILED', $this->errorNum, $this->errorMsg), JLog::ERROR, 'databasequery');
            throw new JDatabaseException($this->errorMsg, $this->errorNum);
         }
      }
      if ($this->_debug) {
         $sql .= '--Time: '.(microtime(true) - $t);
		 JLog::add($sql, JLog::DEBUG, 'databasequery');
         //1.5 version $this->_log[] = $this->_sql. '--Time: '.(microtime(true) - $t);
      }
      
      return $this->cursor;
   }

almooj-craig
Joomla! Guru
Joomla! Guru
Posts: 500
Joined: Mon Aug 11, 2008 3:05 pm

Re: Adding Query Execution Time to Debug

Post by almooj-craig » Sun Feb 17, 2013 12:42 pm

Another option that I added to debug was to list all of the files that have been opened to generate a page. That way you can use traceback, the list of all opened files or grep to find something more easily.

In the onAfterRender function from /plugins/system/debug.php I added the JDEBUG==3 code.

Code: Select all

		echo '<style>';
		echo '#system-debug{color: #000000;}</style>';
		echo '<div id="system-debug" class="profiler">';
		if (JDEBUG==3)
		{
			echo '<ol>';
			foreach (get_included_files() as $f)
			{
				echo '<li>'. str_replace(JPATH_ROOT, '', $f);
			}
			echo '</ol><hr>';
		}
Then in the administrator\components\com_config\controllers\application.php file I added a list option with a value of 3.

SForsgren
Joomla! Enthusiast
Joomla! Enthusiast
Posts: 156
Joined: Fri May 12, 2006 2:46 am

Re: Adding Query Execution Time to Debug

Post by SForsgren » Fri Apr 19, 2013 5:48 pm

Is there a version of this that works with Joomla 3.0.3? I don't see the same files anymore on 3.0.3. Thanks


Locked

Return to “Performance - Joomla! 1.5”