From b7131ba4db0549a19fa6caa6cebad4410becb61f Mon Sep 17 00:00:00 2001 From: Romain Quetiez Date: Mon, 30 Aug 2010 22:14:04 +0000 Subject: [PATCH] Improved the internal KPI reporting tools SVN:trunk[722] --- .../userrightsprofile.class.inc.php | 8 +- core/cmdbobject.class.inc.php | 2 +- core/cmdbsource.class.inc.php | 5 +- core/config.class.inc.php | 21 ++- core/duration.class.inc.php | 82 --------- core/kpi.class.inc.php | 167 ++++++++++++++++++ core/metamodel.class.php | 16 +- core/test.class.inc.php | 2 +- core/userrights.class.inc.php | 4 +- pages/UI.php | 8 +- setup/ajax.dataloader.php | 2 +- setup/index.php | 4 +- setup/xmldataloader.class.inc.php | 2 +- 13 files changed, 213 insertions(+), 110 deletions(-) delete mode 100644 core/duration.class.inc.php create mode 100644 core/kpi.class.inc.php diff --git a/addons/userrights/userrightsprofile.class.inc.php b/addons/userrights/userrightsprofile.class.inc.php index 75e64031b..d2320abeb 100644 --- a/addons/userrights/userrightsprofile.class.inc.php +++ b/addons/userrights/userrightsprofile.class.inc.php @@ -452,7 +452,7 @@ class UserRightsProfile extends UserRightsAddOnAPI { if (!is_null($this->m_aClassActionGrants)) return; - $oDuration = new Duration(); + $oKPI = new ExecutionKPI(); $oFilter = DBObjectSearch::FromOQL_AllData("SELECT URP_ActionGrant AS p WHERE p.permission = 'yes'"); $aGrants = $oFilter->ToDataArray(); @@ -461,7 +461,7 @@ class UserRightsProfile extends UserRightsAddOnAPI $this->m_aClassActionGrants[$aGrant['profileid']][$aGrant['class']][strtolower($aGrant['action'])] = $aGrant['id']; } - $oDuration->Scratch('Load of action grants'); + $oKPI->ComputeAndReport('Load of action grants'); } public function LoadCache() @@ -469,7 +469,7 @@ class UserRightsProfile extends UserRightsAddOnAPI if (!is_null($this->m_aProfiles)) return; // Could be loaded in a shared memory (?) - $oDuration = new Duration(); + $oKPI = new ExecutionKPI(); $oProfileSet = new DBObjectSet(DBObjectSearch::FromOQL_AllData("SELECT URP_Profiles")); $this->m_aProfiles = array(); @@ -505,7 +505,7 @@ class UserRightsProfile extends UserRightsAddOnAPI $this->m_aClassStimulusGrants[$oStimGrant->Get('profileid')][$oStimGrant->Get('class')][$oStimGrant->Get('stimulus')] = $oStimGrant; } - $oDuration->Scratch('Load of user management cache (excepted Action Grants)'); + $oKPI->ComputeAndReport('Load of user management cache (excepted Action Grants)'); /* echo "
\n";
diff --git a/core/cmdbobject.class.inc.php b/core/cmdbobject.class.inc.php
index ecb58ce24..dd3a47428 100644
--- a/core/cmdbobject.class.inc.php
+++ b/core/cmdbobject.class.inc.php
@@ -35,7 +35,7 @@ require_once('coreexception.class.inc.php');
 
 require_once('config.class.inc.php');
 require_once('log.class.inc.php');
-require_once('duration.class.inc.php');
+require_once('kpi.class.inc.php');
 
 require_once('dict.class.inc.php');
 
diff --git a/core/cmdbsource.class.inc.php b/core/cmdbsource.class.inc.php
index e42d66b8d..b72c4bdd8 100644
--- a/core/cmdbsource.class.inc.php
+++ b/core/cmdbsource.class.inc.php
@@ -195,14 +195,13 @@ class CMDBSource
 		//$aTraceInf['file'] = __FILE__;
 		// $sSQLQuery .= MyHelpers::MakeSQLComment($aTraceInf);
 	  
-		$mu_t1 = MyHelpers::getmicrotime();
+		$oKPI = new ExecutionKPI();
 		$result = mysql_query($sSQLQuery, self::$m_resDBLink);
 		if (!$result) 
 		{
 			throw new MySQLException('Failed to issue SQL query', array('query' => $sSQLQuery));
 		}
-		$mu_t2 = MyHelpers::getmicrotime();
-		// #@# todo - query_trace($sSQLQuery, $mu_t2 - $mu_t1);
+		$oKPI->ComputeStats('Query exec (mySQL)', $sSQLQuery);
 	
 		return $result;
 	}
diff --git a/core/config.class.inc.php b/core/config.class.inc.php
index f11c35fa0..4c8ea89b5 100644
--- a/core/config.class.inc.php
+++ b/core/config.class.inc.php
@@ -37,7 +37,8 @@ define ('DEFAULT_LOG_GLOBAL', true);
 define ('DEFAULT_LOG_NOTIFICATION', true);
 define ('DEFAULT_LOG_ISSUE', true);
 define ('DEFAULT_LOG_WEB_SERVICE', true);
-define ('DEFAULT_LOG_DURATION', false);
+define ('DEFAULT_LOG_KPI_DURATION', false);
+define ('DEFAULT_LOG_KPI_MEMORY', false);
 
 define ('DEFAULT_MIN_DISPLAY_LIMIT', 10);
 define ('DEFAULT_MAX_DISPLAY_LIMIT', 15);
@@ -80,7 +81,8 @@ class Config
 	protected $m_bLogNotification;
 	protected $m_bLogIssue;
 	protected $m_bLogWebService;
-	protected $m_bLogDuration; // private setting
+	protected $m_bLogKpiDuration; // private setting
+	protected $m_bLogKpiMemory; // private setting
 
 	/**
 	 * @var integer Number of elements to be displayed when there are more than m_iMaxDisplayLimit elements
@@ -178,7 +180,8 @@ class Config
 		$this->m_bLogNotification = DEFAULT_LOG_NOTIFICATION;
 		$this->m_bLogIssue = DEFAULT_LOG_ISSUE;
 		$this->m_bLogWebService = DEFAULT_LOG_WEB_SERVICE;
-		$this->m_bLogDuration = DEFAULT_LOG_DURATION;
+		$this->m_bLogKPIDuration = DEFAULT_LOG_KPI_DURATION;
+		$this->m_bLogKPIDuration = DEFAULT_LOG_KPI_DURATION;
 		$this->m_iMinDisplayLimit = DEFAULT_MIN_DISPLAY_LIMIT;
 		$this->m_iMaxDisplayLimit = DEFAULT_MAX_DISPLAY_LIMIT;
 		$this->m_iStandardReloadInterval = DEFAULT_STANDARD_RELOAD_INTERVAL;
@@ -278,7 +281,8 @@ class Config
 		$this->m_bLogNotification = isset($MySettings['log_notification']) ? (bool) trim($MySettings['log_notification']) : DEFAULT_LOG_NOTIFICATION;
 		$this->m_bLogIssue = isset($MySettings['log_issue']) ? (bool) trim($MySettings['log_issue']) : DEFAULT_LOG_ISSUE;
 		$this->m_bLogWebService = isset($MySettings['log_web_service']) ? (bool) trim($MySettings['log_web_service']) : DEFAULT_LOG_WEB_SERVICE;
-		$this->m_bLogDuration = isset($MySettings['log_duration']) ? (bool) trim($MySettings['log_duration']) : DEFAULT_LOG_DURATION;
+		$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_iMinDisplayLimit = isset($MySettings['min_display_limit']) ? trim($MySettings['min_display_limit']) : DEFAULT_MIN_DISPLAY_LIMIT;
 		$this->m_iMaxDisplayLimit = isset($MySettings['max_display_limit']) ? trim($MySettings['max_display_limit']) : DEFAULT_MAX_DISPLAY_LIMIT;
 		$this->m_iStandardReloadInterval = isset($MySettings['standard_reload_interval']) ? trim($MySettings['standard_reload_interval']) : DEFAULT_STANDARD_RELOAD_INTERVAL;
@@ -409,9 +413,14 @@ class Config
 		return $this->m_bLogWebService;
 	}
 
-	public function GetLogDuration()
+	public function GetLogKPIDuration()
 	{
-		return $this->m_bLogDuration;
+		return $this->m_bLogKPIDuration;
+	}
+
+	public function GetLogKPIMemory()
+	{
+		return $this->m_bLogKPIMemory;
 	}
 
 	public function GetMinDisplayLimit()
diff --git a/core/duration.class.inc.php b/core/duration.class.inc.php
deleted file mode 100644
index c02745526..000000000
--- a/core/duration.class.inc.php
+++ /dev/null
@@ -1,82 +0,0 @@
-
- * @author      Romain Quetiez 
- * @author      Denis Flaven 
- * @license     http://www.opensource.org/licenses/gpl-3.0.html LGPL
- */
-
-class Duration
-{
-	static $m_bEnabled = false;
-
-	static public function Enable()
-	{
-		self::$m_bEnabled = true;
-	}
-
-	protected $m_fStarted = null;
-
-	public function __construct()
-	{
-		if (!self::$m_bEnabled) return;
-
-		$this->m_fStarted = MyHelpers::getmicrotime();
-	}
-
-	// Get the duration since startup, and reset the counter for the next measure
-	//
-	public function Scratch($sMeasure)
-	{
-		if (!self::$m_bEnabled) return;
-
-		$fStopped = MyHelpers::getmicrotime();
-		$fDuration = $fStopped - $this->m_fStarted;
-		$this->Report($sMeasure.': '.round($fDuration, 3));
-
-		$this->m_fStarted = MyHelpers::getmicrotime();
-	}
-
-	protected function Report($sText)
-	{
-		echo "DURATION... $sText
\n"; - } -} - -// Prototype, to be finalized later -// Reports the function duration -// One single thing to do: construct it -class FunctionDuration -{ - protected $m_sFunction = null; - - public function __construct() - { - $this->m_sFunction = 'my_function_name_in_call_stack'; - $this->m_fStarted = MyHelpers::getmicrotime(); - } - - public function __destruct() - { - $this->Scratch('Exiting '); - } -} - -?> diff --git a/core/kpi.class.inc.php b/core/kpi.class.inc.php new file mode 100644 index 000000000..4f3dec552 --- /dev/null +++ b/core/kpi.class.inc.php @@ -0,0 +1,167 @@ + + * @author Romain Quetiez + * @author Denis Flaven + * @license http://www.opensource.org/licenses/gpl-3.0.html LGPL + */ + +class ExecutionKPI +{ + static protected $m_bEnabled_Duration = false; + static protected $m_bEnabled_Memory = false; + + static protected $m_aStats = array(); + + protected $m_fStarted = null; + protected $m_iInitialMemory = null; + + static public function EnableDuration() + { + self::$m_bEnabled_Duration = true; + } + + static public function EnableMemory() + { + self::$m_bEnabled_Memory = true; + } + + static public function ReportStats() + { + foreach (self::$m_aStats as $sOperation => $aOpStats) + { + echo "====================
\n"; + echo "KPIs for $sOperation
\n"; + echo "====================
\n"; + $fTotalOp = 0; + $iTotalOp = 0; + foreach ($aOpStats as $sArguments => $aEvents) + { + $fTotalInter = 0; + $iTotalInter = 0; + foreach ($aEvents as $fDuration) + { + $fTotalInter += $fDuration; + $iTotalInter++; + } + $fTotalOp += $fTotalInter; + $iTotalOp++; + echo "$sArguments: $iTotalInter (".round($fTotalInter, 3).")
\n"; + } + echo "Total: $iTotalOp (".round($fTotalOp, 3).")
\n"; + echo "====================
\n"; + } + } + + + public function __construct() + { + $this->ResetCounters(); + } + + // Get the duration since startup, and reset the counter for the next measure + // + public function ComputeAndReport($sOperationDesc) + { + if (self::$m_bEnabled_Duration) + { + $fStopped = MyHelpers::getmicrotime(); + $fDuration = $fStopped - $this->m_fStarted; + $this->Report($sOperationDesc.' / duration: '.round($fDuration, 3)); + } + + if (self::$m_bEnabled_Memory) + { + $iMemory = self::memory_get_usage(); + $iMemoryUsed = $iMemory - $this->m_iInitialMemory; + $this->Report($sOperationDesc.' / memory: '.self::MemStr($iMemoryUsed).' (Total: '.self::MemStr($iMemory).')'); + } + + $this->ResetCounters(); + } + + public function ComputeStats($sOperation, $sArguments) + { + if (self::$m_bEnabled_Duration) + { + $fStopped = MyHelpers::getmicrotime(); + $fDuration = $fStopped - $this->m_fStarted; + self::$m_aStats[$sOperation][$sArguments][] = $fDuration; + } + } + + protected function ResetCounters() + { + if (self::$m_bEnabled_Duration) + { + $this->m_fStarted = MyHelpers::getmicrotime(); + } + + if (self::$m_bEnabled_Memory) + { + $this->m_iInitialMemory = self::memory_get_usage(); + } + } + + protected function Report($sText) + { + echo "$sText
\n"; + } + + static protected function MemStr($iMemory) + { + return round($iMemory / 1024).' Kb'; + } + + static protected function memory_get_usage() + { + if (function_exists('memory_get_usage')) + { + return memory_get_usage(true); + } + + // Copied from the PHP manual + // + //If its Windows + //Tested on Win XP Pro SP2. Should work on Win 2003 Server too + //Doesn't work for 2000 + //If you need it to work for 2000 look at http://us2.php.net/manual/en/function.memory-get-usage.php#54642 + if (substr(PHP_OS,0,3) == 'WIN') + { + $output = array(); + exec('tasklist /FI "PID eq ' . getmypid() . '" /FO LIST', $output); + + return preg_replace( '/[\D]/', '', $output[5] ) * 1024; + } + else + { + //We now assume the OS is UNIX + //Tested on Mac OS X 10.4.6 and Linux Red Hat Enterprise 4 + //This should work on most UNIX systems + $pid = getmypid(); + exec("ps -eo%mem,rss,pid | grep $pid", $output); + $output = explode(" ", $output[0]); + //rss is given in 1024 byte units + return $output[1] * 1024; + } + } +} + +?> diff --git a/core/metamodel.class.php b/core/metamodel.class.php index d50970728..763ca5ffe 100644 --- a/core/metamodel.class.php +++ b/core/metamodel.class.php @@ -1534,9 +1534,9 @@ abstract class MetaModel // Query caching // $bQueryCacheEnabled = true; - $sOqlQuery = $oFilter->ToOql(); if ($bQueryCacheEnabled) { + $sOqlQuery = $oFilter->ToOql(); // Warning: using directly the query string as the key to the hash array can FAIL if the string // is long and the differences are only near the end... so it's safer (but not bullet proof?) // to use a hash (like md5) of the string as the key ! @@ -1565,7 +1565,9 @@ abstract class MetaModel $aTableAliases = array(); $oConditionTree = $oFilter->GetCriteria(); + $oKPI = new ExecutionKPI(); $oSelect = self::MakeQuery($oFilter->GetSelectedClasses(), $oConditionTree, $aClassAliases, $aTableAliases, $aTranslation, $oFilter); + $oKPI->ComputeStats('MakeQuery (select)', $sOqlQuery); self::$m_aQueryStructCache[$sOqlQuery] = clone $oSelect; } @@ -3169,9 +3171,13 @@ abstract class MetaModel self::$m_bLogWebService = false; } - if (self::$m_oConfig->GetLogDuration()) + if (self::$m_oConfig->GetLogKPIDuration()) { - Duration::Enable(); + ExecutionKPI::EnableDuration(); + } + if (self::$m_oConfig->GetLogKPIMemory()) + { + ExecutionKPI::EnableMemory(); } // Note: load the dictionary as soon as possible, because it might be @@ -3206,13 +3212,13 @@ abstract class MetaModel $sSource = self::$m_oConfig->GetDBName(); $sTablePrefix = self::$m_oConfig->GetDBSubname(); - $oDuration = new Duration(); + $oKPI = new ExecutionKPI(); // The include have been included, let's browse the existing classes and // develop some data based on the proposed model self::InitClasses($sTablePrefix); - $oDuration->Scratch('Initialization of Data model structures'); + $oKPI->ComputeAndReport('Initialization of Data model structures'); self::$m_sDBName = $sSource; self::$m_sTablePrefix = $sTablePrefix; diff --git a/core/test.class.inc.php b/core/test.class.inc.php index eaebc80af..67e8e184f 100644 --- a/core/test.class.inc.php +++ b/core/test.class.inc.php @@ -35,7 +35,7 @@ require_once('cmdbsource.class.inc.php'); require_once('sqlquery.class.inc.php'); require_once('log.class.inc.php'); -require_once('duration.class.inc.php'); +require_once('kpi.class.inc.php'); require_once('dbobject.class.php'); require_once('dbobjectsearch.class.php'); diff --git a/core/userrights.class.inc.php b/core/userrights.class.inc.php index 91c63a65a..e247ea685 100644 --- a/core/userrights.class.inc.php +++ b/core/userrights.class.inc.php @@ -131,7 +131,7 @@ abstract class User extends cmdbAbstractObject return; } - $oDuration = new Duration(); + $oKPI = new ExecutionKPI(); $aDisplayData = array(); foreach (MetaModel::GetClasses($sClassCategory) as $sClass) @@ -167,7 +167,7 @@ abstract class User extends cmdbAbstractObject ); } - $oDuration->Scratch('Computation of user rights'); + $oKPI->ComputeAndReport('Computation of user rights'); $aDisplayConfig = array(); $aDisplayConfig['class'] = array('label' => Dict::S('UI:UserManagement:Class'), 'description' => Dict::S('UI:UserManagement:Class+')); diff --git a/pages/UI.php b/pages/UI.php index c2570fb5e..66698c9ee 100644 --- a/pages/UI.php +++ b/pages/UI.php @@ -455,15 +455,18 @@ try require_once('../application/itopwebpage.class.inc.php'); require_once('../application/wizardhelper.class.inc.php'); - $oDuration = new Duration(); require_once('../application/startup.inc.php'); $oAppContext = new ApplicationContext(); $currentOrganization = utils::ReadParam('org_id', ''); $operation = utils::ReadParam('operation', ''); + $oKPI = new ExecutionKPI(); + require_once('../application/loginwebpage.class.inc.php'); LoginWebPage::DoLogin(); // Check user rights and prompt if needed + $oKPI->ComputeAndReport('User login'); + $oP = new iTopWebPage(Dict::S('UI:WelcomeToITop'), $currentOrganization); switch($operation) @@ -1390,7 +1393,8 @@ EOF $oP->set_title($oMenuNode->GetLabel()); } } - $oDuration->Scratch('Total page execution time'); + $oKPI->ComputeAndReport('GUI creation before output'); + ExecutionKPI::ReportStats(); ////MetaModel::ShowQueryTrace(); $oP->output(); } diff --git a/setup/ajax.dataloader.php b/setup/ajax.dataloader.php index c1db84a5d..6ddf3b35d 100644 --- a/setup/ajax.dataloader.php +++ b/setup/ajax.dataloader.php @@ -89,7 +89,7 @@ ob_start('FatalErrorCatcher'); // Start capturing the output, and pass it throug require_once('../core/config.class.inc.php'); require_once('../core/log.class.inc.php'); -require_once('../core/duration.class.inc.php'); +require_once('../core/kpi.class.inc.php'); require_once('../core/cmdbsource.class.inc.php'); require_once('./xmldataloader.class.inc.php'); diff --git a/setup/index.php b/setup/index.php index 309ce4144..59b8fa6a4 100644 --- a/setup/index.php +++ b/setup/index.php @@ -26,7 +26,7 @@ require_once('../application/utils.inc.php'); require_once('../core/config.class.inc.php'); require_once('../core/log.class.inc.php'); -require_once('../core/duration.class.inc.php'); +require_once('../core/kpi.class.inc.php'); require_once('../core/cmdbsource.class.inc.php'); require_once('./setuppage.class.inc.php'); @@ -376,7 +376,7 @@ function CheckServerConnection(SetupWebPage $oP, $sDBServer, $sDBUser, $sDBPwd) function InitDataModel(SetupWebPage $oP, $sConfigFileName, $bModelOnly = true) { require_once('../core/log.class.inc.php'); - require_once('../core/duration.class.inc.php'); + require_once('../core/kpi.class.inc.php'); require_once('../core/coreexception.class.inc.php'); require_once('../core/dict.class.inc.php'); require_once('../core/attributedef.class.inc.php'); diff --git a/setup/xmldataloader.class.inc.php b/setup/xmldataloader.class.inc.php index f874d9e5f..de28bfb4f 100644 --- a/setup/xmldataloader.class.inc.php +++ b/setup/xmldataloader.class.inc.php @@ -88,7 +88,7 @@ class XMLDataLoader protected function InitDataModel($sConfigFileName) { require_once('../core/log.class.inc.php'); - require_once('../core/duration.class.inc.php'); + require_once('../core/kpi.class.inc.php'); require_once('../core/coreexception.class.inc.php'); require_once('../core/dict.class.inc.php'); require_once('../core/attributedef.class.inc.php');