Adding Query Execution Time to Debug

[almooj-craig]

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

[ahmad]

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]

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

[ahmad]

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]

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>

[ahmad]

Thanks for sharing almooj-craig

[dristant]

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]

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]

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]

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