From 9b982df4f00477e8a59ad8ff264b69fd98825803 Mon Sep 17 00:00:00 2001 From: Romain Quetiez Date: Tue, 27 Nov 2012 16:53:24 +0000 Subject: [PATCH] New developer tool: set log_queries=1 to enable query logging into data/ The accumulative log data/queries.log can be replayed with test/replay_query_log.php which produces a result file (to check the stability of the results) and a benchmark file (to see the efficiency in CSV) SVN:trunk[2469] --- core/config.class.inc.php | 10 +- core/metamodel.class.php | 116 ++++++++++++++----- core/sqlquery.class.inc.php | 37 +++--- test/replay_query_log.php | 222 ++++++++++++++++++++++++++++++++++++ 4 files changed, 338 insertions(+), 47 deletions(-) create mode 100644 test/replay_query_log.php diff --git a/core/config.class.inc.php b/core/config.class.inc.php index 678eb7dc3..f485d6122 100644 --- a/core/config.class.inc.php +++ b/core/config.class.inc.php @@ -49,7 +49,7 @@ define ('DEFAULT_LOG_ISSUE', true); define ('DEFAULT_LOG_WEB_SERVICE', true); define ('DEFAULT_LOG_KPI_DURATION', false); define ('DEFAULT_LOG_KPI_MEMORY', false); -define ('DEFAULT_DEBUG_QUERIES', false); +define ('DEFAULT_LOG_QUERIES', false); define ('DEFAULT_QUERY_CACHE_ENABLED', true); @@ -641,7 +641,7 @@ class Config protected $m_bLogWebService; protected $m_bLogKPIDuration; // private setting protected $m_bLogKPIMemory; // private setting - protected $m_bDebugQueries; // private setting + protected $m_bLogQueries; // private setting protected $m_bQueryCacheEnabled; // private setting /** @@ -888,7 +888,7 @@ class Config $this->m_bLogWebService = isset($MySettings['log_web_service']) ? (bool) trim($MySettings['log_web_service']) : DEFAULT_LOG_WEB_SERVICE; $this->m_bLogKPIDuration = isset($MySettings['log_kpi_duration']) ? (bool) trim($MySettings['log_kpi_duration']) : DEFAULT_LOG_KPI_DURATION; $this->m_bLogKPIMemory = isset($MySettings['log_kpi_memory']) ? (bool) trim($MySettings['log_kpi_memory']) : DEFAULT_LOG_KPI_MEMORY; - $this->m_bDebugQueries = isset($MySettings['debug_queries']) ? (bool) trim($MySettings['debug_queries']) : DEFAULT_DEBUG_QUERIES; + $this->m_bLogQueries = isset($MySettings['log_queries']) ? (bool) trim($MySettings['log_queries']) : DEFAULT_LOG_QUERIES; $this->m_bQueryCacheEnabled = isset($MySettings['query_cache_enabled']) ? (bool) trim($MySettings['query_cache_enabled']) : DEFAULT_QUERY_CACHE_ENABLED; $this->m_iMinDisplayLimit = isset($MySettings['min_display_limit']) ? trim($MySettings['min_display_limit']) : DEFAULT_MIN_DISPLAY_LIMIT; @@ -1036,9 +1036,9 @@ class Config return $this->m_bLogKPIMemory; } - public function GetDebugQueries() + public function GetLogQueries() { - return $this->m_bDebugQueries; + return $this->m_bLogQueries; } public function GetQueryCacheEnabled() diff --git a/core/metamodel.class.php b/core/metamodel.class.php index 7e11a8b8d..186c2b49c 100644 --- a/core/metamodel.class.php +++ b/core/metamodel.class.php @@ -2090,6 +2090,7 @@ abstract class MetaModel $e->addInfo('OQL', $oFilter->ToOQL()); throw $e; } + self::AddQueryTraceGroupBy($oFilter, $aArgs, $aGroupByExpr, $sRes); return $sRes; } @@ -2138,7 +2139,8 @@ abstract class MetaModel $aScalarArgs = array_merge(self::PrepareQueryArguments($aArgs), $oFilter->GetInternalParams()); try { - $sRes = $oSelect->RenderSelect($aOrderSpec, $aScalarArgs, $iLimitCount, $iLimitStart, $bGetCount); + $bBeautifulSQL = self::$m_bTraceQueries || self::$m_bDebugQuery; + $sRes = $oSelect->RenderSelect($aOrderSpec, $aScalarArgs, $iLimitCount, $iLimitStart, $bGetCount, $bBeautifulSQL); if ($sClassAlias == 'itop') { echo $sRes."
\n"; @@ -2147,9 +2149,10 @@ abstract class MetaModel catch (MissingQueryArgument $e) { // Add some information... - $e->addInfo('OQL', $sOqlQuery); + $e->addInfo('OQL', $oFilter->ToOQL()); throw $e; } + self::AddQueryTraceSelect($oFilter, $aOrderBy, $aArgs, $aAttToLoad, $aExtendedDataSpec, $iLimitCount, $iLimitStart, $bGetCount, $sRes); return $sRes; } @@ -2306,30 +2309,66 @@ abstract class MetaModel $oSelect->AddInnerJoin($oSelectExt, 'id', $aExtendedDataSpec['join_key'] /*, $sTableAlias*/); } + return $oSelect; + } + + protected static function AddQueryTraceSelect($oFilter, $aOrderBy, $aArgs, $aAttToLoad, $aExtendedDataSpec, $iLimitCount, $iLimitStart, $bGetCount, $sSql) + { + $aQueryData = array( + 'type' => 'select', + 'filter' => $oFilter, + 'order_by' => $aOrderBy, + 'args' => $aArgs, + 'att_to_load' => $aAttToLoad, + 'extended_data_spec' => $aExtendedDataSpec, + 'limit_count' => $iLimitCount, + 'limit_start' => $iLimitStart, + 'is_count' => $bGetCount + ); + $sOql = $oFilter->ToOQL(true, $aArgs); + self::AddQueryTrace($aQueryData, $sOql, $sSql); + } + + protected static function AddQueryTraceGroupBy($oFilter, $aArgs, $aGroupByExpr, $sSql) + { + $aQueryData = array( + 'type' => 'group_by', + 'filter' => $oFilter, + 'args' => $aArgs, + 'group_by_expr' => $aGroupByExpr + ); + $sOql = $oFilter->ToOQL(true, $aArgs); + self::AddQueryTrace($aQueryData, $sOql, $sSql); + } + + protected static function AddQueryTrace($aQueryData, $sOql, $sSql) + { if (self::$m_bTraceQueries) { - $sQueryId = md5($sRes); - if(!isset(self::$m_aQueriesLog[$sOqlId])) + $sQueryId = md5(serialize($aQueryData)); + $sMySQLQueryId = md5($sSql); + if(!isset(self::$m_aQueriesLog[$sQueryId])) { - self::$m_aQueriesLog[$sOqlId]['oql'] = $sOqlQuery; - self::$m_aQueriesLog[$sOqlId]['hits'] = 1; + self::$m_aQueriesLog[$sQueryId]['data'] = serialize($aQueryData); + self::$m_aQueriesLog[$sQueryId]['oql'] = $sOql; + self::$m_aQueriesLog[$sQueryId]['hits'] = 1; } else { - self::$m_aQueriesLog[$sOqlId]['hits']++; + self::$m_aQueriesLog[$sQueryId]['hits']++; } - if(!isset(self::$m_aQueriesLog[$sOqlId]['queries'][$sQueryId])) + if(!isset(self::$m_aQueriesLog[$sQueryId]['queries'][$sMySQLQueryId])) { - self::$m_aQueriesLog[$sOqlId]['queries'][$sQueryId]['sql'] = $sRes; - self::$m_aQueriesLog[$sOqlId]['queries'][$sQueryId]['count'] = 1; + self::$m_aQueriesLog[$sQueryId]['queries'][$sMySQLQueryId]['sql'] = $sSql; + self::$m_aQueriesLog[$sQueryId]['queries'][$sMySQLQueryId]['count'] = 1; + $iTableCount = count(CMDBSource::ExplainQuery($sSql)); + self::$m_aQueriesLog[$sQueryId]['queries'][$sMySQLQueryId]['table_count'] = $iTableCount; } else { - self::$m_aQueriesLog[$sOqlId]['queries'][$sQueryId]['count']++; + self::$m_aQueriesLog[$sQueryId]['queries'][$sMySQLQueryId]['count']++; } } - - return $oSelect; } public static function ShowQueryTrace() @@ -2337,34 +2376,55 @@ abstract class MetaModel if (!self::$m_bTraceQueries) return; $iOqlCount = count(self::$m_aQueriesLog); - if ($iOqlCount == 0) - { - echo "

Trace activated, but no query found

\n"; - return; - } - $iSqlCount = 0; - foreach (self::$m_aQueriesLog as $aOqlData) + foreach (self::$m_aQueriesLog as $sQueryId => $aOqlData) { $iSqlCount += $aOqlData['hits']; } - echo "

Stats on SELECT queries: OQL=$iOqlCount, SQL=$iSqlCount

\n"; - - foreach (self::$m_aQueriesLog as $aOqlData) + $sHtml = "

Stats on SELECT queries: OQL=$iOqlCount, SQL=$iSqlCount

\n"; + foreach (self::$m_aQueriesLog as $sQueryId => $aOqlData) { $sOql = $aOqlData['oql']; $sHits = $aOqlData['hits']; - echo "

$sHits hits for OQL query: $sOql

\n"; - echo "\n"; } + + $sLogFile = 'queries.latest'; + file_put_contents(APPROOT.'data/'.$sLogFile.'.html', $sHtml); + + $sLog = " $aOqlData) + { + if (!array_key_exists($sQueryId, $aQueriesLog)) + { + $aQueriesLog[$sQueryId] = $aOqlData; + } + } + } + else + { + $aQueriesLog = self::$m_aQueriesLog; + } + $sLog = "GetDebugQueries(); + self::$m_bTraceQueries = self::$m_oConfig->GetLogQueries(); self::$m_bQueryCacheEnabled = self::$m_oConfig->GetQueryCacheEnabled(); self::$m_bSkipCheckToWrite = self::$m_oConfig->Get('skip_check_to_write'); diff --git a/core/sqlquery.class.inc.php b/core/sqlquery.class.inc.php index 2d45d205b..762f78cdf 100644 --- a/core/sqlquery.class.inc.php +++ b/core/sqlquery.class.inc.php @@ -48,6 +48,7 @@ class SQLQuery private $m_aValues = array(); // Values to set in case of an update query private $m_oSelectedIdField = null; private $m_aJoinSelects = array(); + private $m_bBeautifulQuery = false; public function __construct($sTable, $sTableAlias, $aFields, $bToDelete = true, $aValues = array(), $oSelectedIdField = null) { @@ -293,8 +294,11 @@ class SQLQuery } // Interface, build the SQL query - public function RenderSelect($aOrderBy = array(), $aArgs = array(), $iLimitCount = 0, $iLimitStart = 0, $bGetCount = false) + public function RenderSelect($aOrderBy = array(), $aArgs = array(), $iLimitCount = 0, $iLimitStart = 0, $bGetCount = false, $bBeautifulQuery = false) { + $this->m_bBeautifulQuery = $bBeautifulQuery; + $sLineSep = $this->m_bBeautifulQuery ? "\n" : ''; + // The goal will be to complete the lists as we build the Joins $aFrom = array(); $aFields = array(); @@ -305,7 +309,9 @@ class SQLQuery $aSelectedIdFields = array(); $this->privRender($aFrom, $aFields, $aGroupBy, $oCondition, $aDelTables, $aSetValues, $aSelectedIdFields); - $sFrom = self::ClauseFrom($aFrom); + $sIndent = $this->m_bBeautifulQuery ? " " : null; + $sFrom = self::ClauseFrom($aFrom, $sIndent); + $sWhere = self::ClauseWhere($oCondition, $aArgs); if ($bGetCount) { @@ -317,11 +323,11 @@ class SQLQuery $aCountFields[] = "COALESCE($sFieldExpr, 0)"; // Null values are excluded from the count } $sCountFields = implode(', ', $aCountFields); - $sSQL = "SELECT COUNT(DISTINCT $sCountFields) AS COUNT FROM $sFrom WHERE $sWhere"; + $sSQL = "SELECT$sLineSep COUNT(DISTINCT $sCountFields) AS COUNT$sLineSep FROM $sFrom$sLineSep WHERE $sWhere"; } else { - $sSQL = "SELECT COUNT(*) AS COUNT FROM $sFrom WHERE $sWhere"; + $sSQL = "SELECT$sLineSep COUNT(*) AS COUNT$sLineSep FROM $sFrom$sLineSep WHERE $sWhere"; } } else @@ -340,7 +346,7 @@ class SQLQuery { $sLimit = ''; } - $sSQL = "SELECT DISTINCT $sSelect FROM $sFrom WHERE $sWhere $sOrderBy $sLimit"; + $sSQL = "SELECT$sLineSep DISTINCT $sSelect$sLineSep FROM $sFrom$sLineSep WHERE $sWhere$sLineSep $sOrderBy$sLineSep $sLimit"; } return $sSQL; } @@ -394,27 +400,30 @@ class SQLQuery return $sDelTables; } - private static function ClauseFrom($aFrom) + private static function ClauseFrom($aFrom, $sIndent = null, $iIndentLevel = 0) { + $sLineBreakLong = $sIndent ? "\n".str_repeat($sIndent, $iIndentLevel + 1) : ''; + $sLineBreak = $sIndent ? "\n".str_repeat($sIndent, $iIndentLevel) : ''; + $sFrom = ""; foreach ($aFrom as $sTableAlias => $aJoinInfo) { switch ($aJoinInfo["jointype"]) { case "first": - $sFrom .= "`".$aJoinInfo["tablename"]."` AS `$sTableAlias`"; - $sFrom .= " ".self::ClauseFrom($aJoinInfo["subfrom"]); + $sFrom .= $sLineBreakLong."`".$aJoinInfo["tablename"]."` AS `$sTableAlias`"; + $sFrom .= self::ClauseFrom($aJoinInfo["subfrom"], $sIndent, $iIndentLevel + 1); break; case "inner": case "inner_tree": - $sFrom .= " INNER JOIN (`".$aJoinInfo["tablename"]."` AS `$sTableAlias`"; - $sFrom .= " ".self::ClauseFrom($aJoinInfo["subfrom"]); - $sFrom .= ") ON ".$aJoinInfo["joincondition"]; + $sFrom .= $sLineBreak."INNER JOIN ($sLineBreakLong`".$aJoinInfo["tablename"]."` AS `$sTableAlias`"; + $sFrom .= " ".self::ClauseFrom($aJoinInfo["subfrom"], $sIndent, $iIndentLevel + 1); + $sFrom .= $sLineBreak.") ON ".$aJoinInfo["joincondition"]; break; case "left": - $sFrom .= " LEFT JOIN (`".$aJoinInfo["tablename"]."` AS `$sTableAlias`"; - $sFrom .= " ".self::ClauseFrom($aJoinInfo["subfrom"]); - $sFrom .= ") ON ".$aJoinInfo["joincondition"]; + $sFrom .= $sLineBreak."LEFT JOIN ($sLineBreakLong`".$aJoinInfo["tablename"]."` AS `$sTableAlias`"; + $sFrom .= " ".self::ClauseFrom($aJoinInfo["subfrom"], $sIndent, $iIndentLevel + 1); + $sFrom .= $sLineBreak.") ON ".$aJoinInfo["joincondition"]; break; default: throw new CoreException("Unknown jointype: '".$aJoinInfo["jointype"]."'"); diff --git a/test/replay_query_log.php b/test/replay_query_log.php new file mode 100644 index 000000000..f30a1139e --- /dev/null +++ b/test/replay_query_log.php @@ -0,0 +1,222 @@ + + +/** + * Replay the query log made when log_queries = 1 + * + * @copyright Copyright (C) 2010-2012 Combodo SARL + * @license http://opensource.org/licenses/AGPL-3.0 + */ + + +function LogResult($sString) +{ + file_put_contents(APPROOT.'data/queries.results.log', "\n".$sString, FILE_APPEND); +} + +function LogBenchmarkCSV() +{ + $aValues = array(); + foreach (func_get_args() as $arg) + { + if (is_string($arg)) + { + $aValues[] = '"'.str_replace('"', '\\"', $arg).'"'; + } + else + { + $aValues[] = (string) $arg; + } + } + $sLine = implode(';', $aValues); // the preferred for MS Excel + file_put_contents(APPROOT.'data/queries.benchmark.csv', "\n".$sLine, FILE_APPEND); +} + + +///////////////////////////////////////////////////////////////////////////// +// +// Main program +// +///////////////////////////////////////////////////////////////////////////// + +require_once('../approot.inc.php'); +require_once(APPROOT.'/application/application.inc.php'); +require_once(APPROOT.'/application/ajaxwebpage.class.inc.php'); + +require_once(APPROOT.'/application/startup.inc.php'); +$operation = utils::ReadParam('operation', ''); + +require_once(APPROOT.'/application/loginwebpage.class.inc.php'); +LoginWebPage::DoLogin(); // Check user rights and prompt if needed + +$oP = new WebPage('Replay queries.log'); + + +ini_set('memory_limit', '512M'); + +require_once(APPROOT.'/data/queries.log'); +$iCount = count($aQueriesLog); +$oP->p("Nombre de requêtes: ".$iCount); + +$sOperation = utils::ReadParam('operation', ''); + +switch ($sOperation) +{ +case '': +default: + $oP->add("
    \n"); + foreach ($aQueriesLog as $sQueryId => $aOqlData) + { + $sOql = $aOqlData['oql']; + $sOqlHtml = htmlentities($sOql, ENT_QUOTES, 'UTF-8'); + $oP->add("
  1. $sOqlHtml
    2. \n"); + } + $oP->add("
\n"); + + $oP->add("
\n"); + $oP->add("\n"); + $oP->add("
\n"); + break; + +case 'benchmark': + // Reset the log contents + file_put_contents(APPROOT.'data/queries.results.log', date('Y-m-d H:i:s')."\n"); + file_put_contents(APPROOT.'data/queries.benchmark.csv', ''); + LogBenchmarkCSV('oql', 'type', 'properties', 'make duration', 'tables', 'query length', 'exec duration', 'rows'); + + foreach ($aQueriesLog as $sQueryId => $aOqlData) + { + $sOql = $aOqlData['oql']; + $sOqlHtml = htmlentities($sOql, ENT_QUOTES, 'UTF-8'); + $aQueryData = unserialize($aOqlData['data']); + + $oFilter = $aQueryData['filter']; + $aArgs = $aQueryData['args']; + + if ($aQueryData['type'] == 'select') + { + $aOrderBy = $aQueryData['order_by']; + $aAttToLoad = $aQueryData['att_to_load']; + $aExtendedDataSpec = $aQueryData['extended_data_spec']; + $iLimitCount = $aQueryData['limit_count']; + $iLimitStart = $aQueryData['limit_start']; + $bGetCount = $aQueryData['is_count']; + + if ($bGetCount) + { + $sQueryType = 'COUNT'; + $sQueryDesc = ''; + } + else + { + $sQueryType = 'LIST'; + $sQueryDesc = "limit count: $iLimitCount"; + $sQueryDesc .= "; limit start: $iLimitStart"; + if (count($aOrderBy) > 0) + { + $sQueryDesc .= "; order by: ".implode(',', array_keys($aOrderBy)); + } + if (is_array($aAttToLoad)) + { + $sQueryDesc .= "; attributes: ".implode(',', array_keys($aAttToLoad)); + } + } + + $fRefTime = MyHelpers::getmicrotime(); + try + { + $sSql = MetaModel::MakeSelectQuery($oFilter, $aOrderBy, $aArgs, $aAttToLoad, $aExtendedDataSpec, $iLimitCount, $iLimitStart, $bGetCount); + } + catch(Exception $e) + { + LogResult("Failed to create the SQL:".$e->getMessage()); + $sSql = ''; + } + $fMakeDuration = MyHelpers::getmicrotime() - $fRefTime; + } + elseif ($aQueryData['type'] == 'group_by') + { + $aGroupByExpr = $aQueryData['group_by_expr']; + + $sQueryType = 'GROUP BY'; + $sQueryDesc = 'expr: '.serialize($aGroupByExpr); + + $fRefTime = MyHelpers::getmicrotime(); + try + { + $sSql = MetaModel::MakeGroupByQuery($oFilter, $aArgs, $aGroupByExpr); + } + catch(Exception $e) + { + LogResult("Failed to create the SQL:".$e->getMessage()); + $sSql = ''; + } + $fMakeDuration = MyHelpers::getmicrotime() - $fRefTime; + } + else + { + // unsupported + $sQueryType = 'ERROR'; + $sQueryDesc = "Unkown type of query: ".$aQueryData['type']; + $fMakeDuration = 0; + } + + LogResult($sOql); + LogResult($sQueryType); + if (strlen($sQueryDesc) > 0) + { + LogResult($sQueryDesc); + } + + if ($sSql != '') + { + try + { + $fRefTime = MyHelpers::getmicrotime(); + $resQuery = CMDBSource::Query($sSql); + $fExecDuration = MyHelpers::getmicrotime() - $fRefTime; + + $iTableCount = count(CMDBSource::ExplainQuery($sSql)); + } + catch (Exception $e) + { + LogResult("Failed to execute the SQL:".$e->getMessage()); + LogResult("The failing SQL:\n".$sSql); + $resQuery = null; + $fExecDuration = 0; + $iTableCount = 0; + } + $iRowCount = 0; + if ($resQuery) + { + while ($aRow = CMDBSource::FetchArray($resQuery)) + { + LogResult("row: ".serialize($aRow)); + $iRowCount++; + } + CMDBSource::FreeResult($resQuery); + } + LogResult("row count = ".$iRowCount); + + LogBenchmarkCSV($sOql, $sQueryType, $sQueryDesc, round($fMakeDuration, 3), $iTableCount, strlen($sSql), round($fExecDuration, 3), $iRowCount); + } + } +} + +$oP->output(); +?> \ No newline at end of file