diff --git a/application/itopwebpage.class.inc.php b/application/itopwebpage.class.inc.php index 8494f17be..39b5d9677 100644 --- a/application/itopwebpage.class.inc.php +++ b/application/itopwebpage.class.inc.php @@ -820,7 +820,9 @@ EOF if ($this->GetOutputFormat() == 'html') { + $oKPI = new ExecutionKPI(); echo $sHtml; + $oKPI->ComputeAndReport('Echoing ('.round(strlen($sHtml) / 1024).' Kb)'); } else if ($this->GetOutputFormat() == 'pdf' && $this->IsOutputFormatAvailable('pdf') ) { @@ -846,6 +848,7 @@ EOF $oMPDF->Output($sOutputName, 'I'); } MetaModel::RecordQueryTrace(); + ExecutionKPI::ReportStats(); } public function AddTabContainer($sTabContainer) diff --git a/core/config.class.inc.php b/core/config.class.inc.php index d0164d8b0..2da65eb55 100644 --- a/core/config.class.inc.php +++ b/core/config.class.inc.php @@ -47,8 +47,6 @@ define ('DEFAULT_LOG_GLOBAL', true); define ('DEFAULT_LOG_NOTIFICATION', true); 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_LOG_QUERIES', false); define ('DEFAULT_QUERY_CACHE_ENABLED', true); @@ -626,6 +624,33 @@ class Config 'source_of_value' => '', 'show_in_conf_sample' => true, ), + 'log_kpi_duration' => array( + 'type' => 'integer', + 'description' => 'Level of logging for troubleshooting performance issues', + // examples... not used + 'default' => 0, + 'value' => 0, + 'source_of_value' => '', + 'show_in_conf_sample' => false, + ), + 'log_kpi_memory' => array( + 'type' => 'integer', + 'description' => 'Level of logging for troubleshooting memory limit issues', + // examples... not used + 'default' => 0, + 'value' => 0, + 'source_of_value' => '', + 'show_in_conf_sample' => false, + ), + 'log_kpi_user_id' => array( + 'type' => 'string', + 'description' => 'Limit the scope of users to the given user id (* means no limit)', + // examples... not used + 'default' => '*', + 'value' => '*', + 'source_of_value' => '', + 'show_in_conf_sample' => false, + ), ); public function IsProperty($sPropCode) @@ -684,8 +709,6 @@ class Config protected $m_bLogNotification; protected $m_bLogIssue; protected $m_bLogWebService; - protected $m_bLogKPIDuration; // private setting - protected $m_bLogKPIMemory; // private setting protected $m_bLogQueries; // private setting protected $m_bQueryCacheEnabled; // private setting @@ -795,8 +818,6 @@ class Config $this->m_bLogNotification = DEFAULT_LOG_NOTIFICATION; $this->m_bLogIssue = DEFAULT_LOG_ISSUE; $this->m_bLogWebService = DEFAULT_LOG_WEB_SERVICE; - $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; @@ -932,8 +953,6 @@ 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_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_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; @@ -1072,16 +1091,6 @@ class Config return $this->m_bLogWebService; } - public function GetLogKPIDuration() - { - return $this->m_bLogKPIDuration; - } - - public function GetLogKPIMemory() - { - return $this->m_bLogKPIMemory; - } - public function GetLogQueries() { return $this->m_bLogQueries; diff --git a/core/kpi.class.inc.php b/core/kpi.class.inc.php index 38bfca118..8c703b609 100644 --- a/core/kpi.class.inc.php +++ b/core/kpi.class.inc.php @@ -28,34 +28,170 @@ class ExecutionKPI { static protected $m_bEnabled_Duration = false; static protected $m_bEnabled_Memory = false; + static protected $m_sAllowedUser = '*'; - static protected $m_aStats = array(); + static protected $m_aStats = array(); // Recurrent operations + static protected $m_aExecData = array(); // One shot operations protected $m_fStarted = null; protected $m_iInitialMemory = null; - static public function EnableDuration() + static public function EnableDuration($iLevel) { - self::$m_bEnabled_Duration = true; + if ($iLevel > 0) + { + self::$m_bEnabled_Duration = true; + } } - static public function EnableMemory() + static public function EnableMemory($iLevel) { - self::$m_bEnabled_Memory = true; + if ($iLevel > 0) + { + self::$m_bEnabled_Memory = true; + } + } + + /** + * @param string sUser A user login or * for all users + */ + static public function SetAllowedUser($sUser) + { + self::$m_sAllowedUser = $sUser; } static public function ReportStats() { + if (self::$m_sAllowedUser != '*') + { + if (UserRights::GetUser() != self::$m_sAllowedUser) + { + return; + } + } + + global $fItopStarted; + $sExecId = microtime(); // id to differentiate the hrefs! + + $aBeginTimes = array(); + foreach (self::$m_aExecData as $aOpStats) + { + $aBeginTimes[] = $aOpStats['time_begin']; + } + array_multisort($aBeginTimes, self::$m_aExecData); + + $sTableStyle = 'background-color: #ccc; margin: 10px;'; + + self::Report("
"); + self::Report("
"); + self::Report("

KPIs - ".$_SERVER['REQUEST_URI']." (".$_SERVER['REQUEST_METHOD'].")

"); + self::Report("

".date('Y-m-d H:i:s', $fItopStarted)."

"); + self::Report("

log_kpi_user_id: ".MetaModel::GetConfig()->Get('log_kpi_user_id')."

"); + self::Report("
"); + self::Report(""); + self::Report(""); + self::Report(" "); + self::Report(""); + foreach (self::$m_aExecData as $aOpStats) + { + $sOperation = $aOpStats['op']; + $sBegin = $sEnd = $sDuration = $sMemBegin = $sMemEnd = $sMemPeak = '?'; + + $sBegin = round($aOpStats['time_begin'], 3); + $sEnd = round($aOpStats['time_end'], 3); + $fDuration = $aOpStats['time_end'] - $aOpStats['time_begin']; + $sDuration = round($fDuration, 3); + + if (isset($aOpStats['mem_begin'])) + { + $sMemBegin = self::MemStr($aOpStats['mem_begin']); + $sMemEnd = self::MemStr($aOpStats['mem_end']); + if (isset($aOpStats['mem_peak'])) + { + $sMemPeak = self::MemStr($aOpStats['mem_peak']); + } + } + + self::Report(""); + self::Report(" "); + self::Report(""); + } + self::Report("
OperationBeginEndDurationMemory startMemory endMemory peak
$sOperation$sBegin$sEnd$sDuration$sMemBegin$sMemEnd$sMemPeak
"); + self::Report("
"); + + $aConsolidatedStats = array(); foreach (self::$m_aStats as $sOperation => $aOpStats) { - echo "

KPIs for $sOperation

\n"; $fTotalOp = 0; $iTotalOp = 0; $fMinOp = null; $fMaxOp = 0; - echo "
"); + + // Report operation details + foreach (self::$m_aStats as $sOperation => $aOpStats) + { + $sOperationHtml = ''.$sOperation.''; + self::Report("

$sOperationHtml

"); + self::Report("

Back to page stats

"); + self::Report(""); + self::Report(""); + self::Report(" "); + self::Report(""); + foreach ($aOpStats as $sArguments => $aEvents) + { + $sHtmlArguments = ''.$sArguments.''; + if ($aConsolidatedStats[$sOperation]['max_args'] == $sArguments) + { + $sHtmlArguments = ''.$sHtmlArguments.''; + } $fTotalInter = 0; $fMinInter = null; $fMaxInter = 0; @@ -64,34 +200,17 @@ class ExecutionKPI $fTotalInter += $fDuration; $fMinInter = is_null($fMinInter) ? $fDuration : min($fMinInter, $fDuration); $fMaxInter = max($fMaxInter, $fDuration); - - $fMinOp = is_null($fMinOp) ? $fDuration : min($fMinOp, $fDuration); - $fMaxOp = max($fMaxOp, $fDuration); } - $fTotalOp += $fTotalInter; - $iTotalOp++; $iCountInter = count($aEvents); - $sTotalInter = round($fTotalInter, 3)."s"; - if ($iCountInter > 1) - { - $sMinInter = round($fMinInter, 3)."s"; - $sMaxInter = round($fMaxInter, 3)."s"; - $sTimeDesc = "$sTotalInter (from $sMinInter to $sMaxInter) in $iCountInter times"; - } - else - { - $sTimeDesc = "$sTotalInter"; - } - echo "
  • Spent $sTimeDesc, on: $sArguments
  • \n"; + $sTotalInter = round($fTotalInter, 3); + $sMinInter = round($fMinInter, 3); + $sMaxInter = round($fMaxInter, 3); + self::Report(""); + self::Report(" "); + self::Report(""); } - echo "\n"; - echo "\n"; + self::Report("
    Operation detailsCountDurationMinMax
    $sHtmlArguments$iCountInter$sTotalInter$sMinInter$sMaxInter
    "); } } @@ -105,25 +224,43 @@ class ExecutionKPI // public function ComputeAndReport($sOperationDesc) { + global $fItopStarted; + + $aNewEntry = null; + if (self::$m_bEnabled_Duration) { $fStopped = MyHelpers::getmicrotime(); - $fDuration = $fStopped - $this->m_fStarted; - $this->Report($sOperationDesc.' / duration: '.round($fDuration, 3)); + $aNewEntry = array( + 'op' => $sOperationDesc, + 'time_begin' => $this->m_fStarted - $fItopStarted, + 'time_end' => $fStopped - $fItopStarted, + ); + // Reset for the next operation (if the object is recycled) + $this->m_fStarted = $fStopped; } 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).')'); + $iCurrentMemory = self::memory_get_usage(); + if (is_null($aNewEntry)) + { + $aNewEntry = array('op' => $sOperationDesc); + } + $aNewEntry['mem_begin'] = $this->m_iInitialMemory; + $aNewEntry['mem_end'] = $iCurrentMemory; if (function_exists('memory_get_peak_usage')) { - $iMemoryPeak = memory_get_peak_usage(); - $this->Report($sOperationDesc.' / memory peak: '.self::MemStr($iMemoryPeak)); + $aNewEntry['mem_peak'] = memory_get_peak_usage(); } + // Reset for the next operation (if the object is recycled) + $this->m_iInitialMemory = $iCurrentMemory; } + if (!is_null($aNewEntry)) + { + self::$m_aExecData[] = $aNewEntry; + } $this->ResetCounters(); } @@ -150,9 +287,11 @@ class ExecutionKPI } } - protected function Report($sText) + const HtmlReportFile = 'log/kpi.html'; + + static protected function Report($sText) { - echo "$sText
    \n"; + file_put_contents(APPROOT.self::HtmlReportFile, "$sText\n", FILE_APPEND | LOCK_EX); } static protected function MemStr($iMemory) @@ -204,13 +343,3 @@ class ExecutionKPI } } -class ApplicationStartupKPI extends ExecutionKPI -{ - public function __construct() - { - global $fItopStarted; - $this->m_fStarted = $fItopStarted; - } -} - -?> diff --git a/core/metamodel.class.php b/core/metamodel.class.php index 87ed1d53e..3f2bf2418 100644 --- a/core/metamodel.class.php +++ b/core/metamodel.class.php @@ -4531,14 +4531,9 @@ abstract class MetaModel self::$m_bLogWebService = false; } - if (self::$m_oConfig->GetLogKPIDuration()) - { - ExecutionKPI::EnableDuration(); - } - if (self::$m_oConfig->GetLogKPIMemory()) - { - ExecutionKPI::EnableMemory(); - } + ExecutionKPI::EnableDuration(self::$m_oConfig->Get('log_kpi_duration')); + ExecutionKPI::EnableMemory(self::$m_oConfig->Get('log_kpi_memory')); + ExecutionKPI::SetAllowedUser(self::$m_oConfig->Get('log_kpi_user_id')); self::$m_bTraceQueries = self::$m_oConfig->GetLogQueries(); self::$m_bIndentQueries = self::$m_oConfig->Get('query_indentation_enabled'); diff --git a/pages/UI.php b/pages/UI.php index c8b186eab..84e7889ca 100644 --- a/pages/UI.php +++ b/pages/UI.php @@ -374,8 +374,8 @@ try require_once(APPROOT.'/application/startup.inc.php'); $operation = utils::ReadParam('operation', ''); - $oKPI = new ApplicationStartupKPI(); - $oKPI->ComputeAndReport('Load of data model and all includes'); + $oKPI = new ExecutionKPI(); + $oKPI->ComputeAndReport('Data model loaded'); $oKPI = new ExecutionKPI(); @@ -1650,10 +1650,6 @@ EOF /////////////////////////////////////////////////////////////////////////////////////////// } - $oKPI->ComputeAndReport('GUI creation before output'); - - ExecutionKPI::ReportStats(); - DisplayWelcomePopup($oP); $oP->output(); } diff --git a/pages/run_query.php b/pages/run_query.php index 218b05d51..55603d025 100644 --- a/pages/run_query.php +++ b/pages/run_query.php @@ -224,7 +224,6 @@ catch(Exception $e) { $oP->p(''.Dict::Format('UI:RunQuery:Error', $e->getMessage()).''); } -ExecutionKPI::ReportStats(); $oP->output(); ?> diff --git a/test/benchmark.php b/test/benchmark.php index 67ad9d7a3..ae987983e 100644 --- a/test/benchmark.php +++ b/test/benchmark.php @@ -866,7 +866,6 @@ catch(ZZCoreException $e) $oP->error("Error: '".$e->getHtmlDesc()."'"); } $oKPI->ComputeAndReport('Total execution'); -// too big (showing all queries) ExecutionKPI::ReportStats(); //MetaModel::RecordQueryTrace(); $oP->output(); ?>