Magento SQL Logging – (Part I)

As with any e-commerce solution Magento stores nearly all the data of the online store in a database. To simplify the communication between code and the database Magento provides a number of abstraction functions. The use of abstraction to communicate with the database leads to the question of what queries are being issued to the database to obtain the data. A quick search on Google returns hundreds of forums and blogs that provide different solutions to this question. Summarizing the options available by the time of writing, a Magento developer can choose from the following options:

  1. To see all queries issued to the database
    1. Modify the core Magento code that deals with the database query generation
    2. Enable Magento Pdo MySql debugging
    3. Switch on MySQL logging
  2. To see only a specific query
    1. Modify the file with the collection under debugging

In this article we will take a look at the first option. In the next article we analyse the second option of logging what queries are running under the hood of Magento.

Modify the core Magento code that deals with the database query generation

Magento builds its entire database communication by using an abstraction class defined in \lib\Varien\Db\Adapter\Pdo\Mysql.php. The class provides a number of functions to construct the query and a query() function to execute the constructed database statement. The query() function is an ideal place to place any query logging as it is the method that will actually execute the any database statements.

The following snippet shows how the query method should be modified.

  1. public function query($sql, $bind = array())
  2. {
  3.   $this->_debugTimer();
  4.  
  5.   try {
  6.     $sql = (string)$sql;
  7.     if (strpos($sql, ':') !== false || strpos($sql, '?') !== false) {
  8.       $this->_bindParams = $bind;
  9.       $sql = preg_replace_callback('#(([\'"])((\\2)|((.*?[^\\\\])\\2)))#', array($this, 'proccessBindCallback'), $sql);
  10.       $bind = $this->_bindParams;
  11.     }
  12.  
  13.      // Begin code to insert
  14.     $code = 'SQL: ' . $sql . "\r\n";
  15.     if ($bind) {
  16.       $code .= 'BIND: ' . print_r($bind, true) . "\r\n";
  17.     }
  18.     $this->_debugWriteToFile("[".date('Y-m-d H:i:s')."] ".$code);
  19.      // End code to insert
  20.  
  21.     $result = parent::query($sql, $bind);
  22.   } catch (Exception $e) {
  23.     $this->_debugStat(self::DEBUG_QUERY, $sql, $bind);
  24.     $this->_debugException($e);
  25.   }
  26.   $this->_debugStat(self::DEBUG_QUERY, $sql, $bind, $result);
  27.   return $result;
  28. }

Enable Magento Pdo MySql debugging

As any reader can notice in the previous code, the MySql library provided by Magento already contains a number of debugging information. Magento debugging information is enabled or disabled by setting the protected variable $_debug. When the $_debug variable is set to true, the Pdo MySql class interacts with the database an entry is added inside the file \var\debug\sql.txt. The logging file can be changed by modifying the location defined in the class variable $_debugFile.

Below is a snippet of the Pdo MySql class variables.

  1. /**
  2.      * Write SQL debug data to file
  3.      *
  4.      * @var bool
  5.      */
  6.     protected $_debug               =  false;    // Change to true to enable debugging
  7.  
  8.     /**
  9.      * Minimum query duration time to be logged
  10.      *
  11.      * @var unknown_type
  12.      */
  13.     protected $_logQueryTime        = 0.05;
  14.  
  15.     /**
  16.      * Log all queries (ignored minimum query duration time)
  17.      *
  18.      * @var bool
  19.      */
  20.     protected $_logAllQueries       = false;
  21.  
  22.     /**
  23.      * Add to log call stack data (backtrace)
  24.      *
  25.      * @var bool
  26.      */
  27.     protected $_logCallStack        = false;
  28.  
  29.     /**
  30.      * Path to SQL debug data log
  31.      *
  32.      * @var string
  33.      */
  34.     protected $_debugFile           = 'var/debug/sql.txt';
  35.  
  36.     /**
  37.      * Io File Adapter
  38.      *
  39.      * @var Varien_Io_File
  40.      */
  41.     protected $_debugIoAdapter;
  42.  
  43.     /**
  44.      * Debug timer start value
  45.      *
  46.      * @var float
  47.      */
  48.     protected $_debugTimer          = 0;

Switch on MySQL logging

Magento is normally combined with MySQL as a database. MySQL has the ability to log queries executed on databases inside either a file or table. By default MySQL logging is switched off and set to log into files. To verify the state of MySQL logging issue the following query on any database.

  1. SHOW VARIABLES WHERE variable_name IN ('log', 'log_output', 'log_slow_queries', 'general_log_file', 'slow_query_log_file');

The variables that are returned by this query provide the following information:

  • log – determines if the general logging is switched ON or OFF
  • log_output – determines if the logging mechanism will write into a file  (FILE) or unto a table (TABLE)
  • log_slow_queries – this variable indicates whether slow queries are logged. This is normally used during performance tweaking exercises.
  • general_log_file – defines the file and location where the logs are written when the ‘log’’ variable is set to ON.
  • slow_query_log_file – determines the file and location where slow queries are logged at when the ‘log_output’ variable is set to ‘FILE’.

A complete list of variable can be obtained from MySQL Reference documents.

To change any of the variables listed above the command SET GLOBAL needs to be used. For example, to enable the general logging the log variable is set by calling the command

  1. SET GLOBAL general_log = 'ON';

When log_output is set to TABLE, MySQL uses a set of predefined tables. The tables corresponding to the different logging types are:

  • General logging – MySQL will log all entries into the table mysql.general_log
  • Slow queries – MySQL will log all entries into the table mysql.slow_ log

Articles:

References:

Magento: SQL Debugging Option – Programming Questions
Stackoverflow: How do I print all the queries in Magento
iFuel Interactive: Logging all SQL in Magento
RedLightBlinking: Debugging in Magento – how to find template paths, logging and display errors
MySQL: Server System Variables