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

@@ -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()

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."<br/>\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);
+			$sQueryId = md5(serialize($aQueryData));
-			if(!isset(self::$m_aQueriesLog[$sOqlId]))
+			$sMySQLQueryId = md5($sSql);
+			if(!isset(self::$m_aQueriesLog[$sQueryId]))
 			{
-				self::$m_aQueriesLog[$sOqlId]['oql'] = $sOqlQuery;
+				self::$m_aQueriesLog[$sQueryId]['data'] = serialize($aQueryData);
-				self::$m_aQueriesLog[$sOqlId]['hits'] = 1;
+				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[$sQueryId]['queries'][$sMySQLQueryId]['sql'] = $sSql;
-				self::$m_aQueriesLog[$sOqlId]['queries'][$sQueryId]['count'] = 1;
+				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 "<p>Trace activated, but no query found</p>\n";
-			return;
-		}
-
 		$iSqlCount = 0;
-		foreach (self::$m_aQueriesLog as $aOqlData)
+		foreach (self::$m_aQueriesLog as $sQueryId => $aOqlData)
 		{
 			$iSqlCount += $aOqlData['hits'];
 		}
-		echo "<h2>Stats on SELECT queries: OQL=$iOqlCount, SQL=$iSqlCount</h2>\n";
+		$sHtml = "<h2>Stats on SELECT queries: OQL=$iOqlCount, SQL=$iSqlCount</h2>\n";
-
+		foreach (self::$m_aQueriesLog as $sQueryId => $aOqlData)
-		foreach (self::$m_aQueriesLog as $aOqlData)
 		{
 			$sOql = $aOqlData['oql'];
 			$sHits = $aOqlData['hits'];
 
-			echo "<p><b>$sHits</b> hits for OQL query: $sOql</p>\n";
+			$sHtml .= "<p><b>$sHits</b> hits for OQL query: $sOql</p>\n";
-			echo "<ul id=\"ClassesRelationships\" class=\"treeview\">\n";
+			$sHtml .= "<ul id=\"ClassesRelationships\" class=\"treeview\">\n";
 			foreach($aOqlData['queries'] as $aSqlData)
 			{
 				$sQuery = $aSqlData['sql'];
 				$sSqlHits = $aSqlData['count'];
-				echo "<li><b>$sSqlHits</b> hits for SQL: <span style=\"font-size:60%\">$sQuery</span><li>\n";
+				$iTableCount = $aSqlData['table_count'];
+				$sHtml .= "<li><b>$sSqlHits</b> hits for SQL ($iTableCount tables): <pre style=\"font-size:60%\">$sQuery</pre></li>\n";
 			}
-			echo "</ul>\n";
+			$sHtml .= "</ul>\n";
 		}
+
+		$sLogFile = 'queries.latest';
+		file_put_contents(APPROOT.'data/'.$sLogFile.'.html', $sHtml);
+
+		$sLog = "<?php\n\$aQueriesLog = ".var_export(self::$m_aQueriesLog, true).";";
+		file_put_contents(APPROOT.'data/'.$sLogFile.'.log', $sLog);
+
+		// Cumulate the queries
+		$sAllQueries = APPROOT.'data/queries.log';
+		if (file_exists($sAllQueries))
+		{
+			// Merge the new queries into the existing log
+			include($sAllQueries);
+			foreach (self::$m_aQueriesLog as $sQueryId => $aOqlData)
+			{
+				if (!array_key_exists($sQueryId, $aQueriesLog))
+				{
+					$aQueriesLog[$sQueryId] = $aOqlData;
+				}
+			}
+		}
+		else
+		{
+			$aQueriesLog = self::$m_aQueriesLog;
+		}
+		$sLog = "<?php\n\$aQueriesLog = ".var_export($aQueriesLog, true).";";
+		file_put_contents($sAllQueries, $sLog);
 	}
 
 	protected static function MakeModifierProperties($oFilter)
@@ -4430,7 +4490,7 @@ abstract class MetaModel
 			ExecutionKPI::EnableMemory();
 		}
 
-		self::$m_bTraceQueries = self::$m_oConfig->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');

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 .= $sLineBreakLong."`".$aJoinInfo["tablename"]."` AS `$sTableAlias`";
-					$sFrom .= " ".self::ClauseFrom($aJoinInfo["subfrom"]);
+					$sFrom .= self::ClauseFrom($aJoinInfo["subfrom"], $sIndent, $iIndentLevel + 1);
 					break;
 				case "inner":
 				case "inner_tree":
-					$sFrom .= " INNER JOIN (`".$aJoinInfo["tablename"]."` AS `$sTableAlias`";
+					$sFrom .= $sLineBreak."INNER JOIN ($sLineBreakLong`".$aJoinInfo["tablename"]."` AS `$sTableAlias`";
-					$sFrom .= " ".self::ClauseFrom($aJoinInfo["subfrom"]);
+					$sFrom .= " ".self::ClauseFrom($aJoinInfo["subfrom"], $sIndent, $iIndentLevel + 1);
-					$sFrom .= ") ON ".$aJoinInfo["joincondition"];
+					$sFrom .= $sLineBreak.") ON ".$aJoinInfo["joincondition"];
 					break;
 				case "left":
-					$sFrom .= " LEFT JOIN (`".$aJoinInfo["tablename"]."` AS `$sTableAlias`";
+					$sFrom .= $sLineBreak."LEFT JOIN ($sLineBreakLong`".$aJoinInfo["tablename"]."` AS `$sTableAlias`";
-					$sFrom .= " ".self::ClauseFrom($aJoinInfo["subfrom"]);
+					$sFrom .= " ".self::ClauseFrom($aJoinInfo["subfrom"], $sIndent, $iIndentLevel + 1);
-					$sFrom .= ") ON ".$aJoinInfo["joincondition"];
+					$sFrom .= $sLineBreak.") ON ".$aJoinInfo["joincondition"];
 					break;
 				default:
 					throw new CoreException("Unknown jointype: '".$aJoinInfo["jointype"]."'");

test/replay_query_log.php

@@ -0,0 +1,222 @@
+<?php
+// Copyright (C) 2010-2012 Combodo SARL
+//
+//   This file is part of iTop.
+//
+//   iTop is free software; you can redistribute it and/or modify	
+//   it under the terms of the GNU Affero General Public License as published by
+//   the Free Software Foundation, either version 3 of the License, or
+//   (at your option) any later version.
+//
+//   iTop is distributed in the hope that it will be useful,
+//   but WITHOUT ANY WARRANTY; without even the implied warranty of
+//   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+//   GNU Affero General Public License for more details.
+//
+//   You should have received a copy of the GNU Affero General Public License
+//   along with iTop. If not, see <http://www.gnu.org/licenses/>
+
+/**
+ * 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("<ol>\n");
+	foreach ($aQueriesLog as $sQueryId => $aOqlData)
+	{
+		$sOql = $aOqlData['oql'];
+		$sOqlHtml = htmlentities($sOql, ENT_QUOTES, 'UTF-8');
+		$oP->add("<li>$sOqlHtml</li>\n");
+	}
+	$oP->add("</ol>\n");
+	
+	$oP->add("<form action=\"?operation=benchmark\" method=\"post\">\n");
+	$oP->add("<input type=\"submit\" value=\"Benchmark!\">\n");
+	$oP->add("</form>\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();
+?>