/** * Measures operations duration, memory usage, etc. (and some other KPIs) * * @copyright Copyright (C) 2010-2021 Combodo SARL * @license http://opensource.org/licenses/AGPL-3.0 */ class ExecutionKPI { static protected $m_bEnabled_Duration = false; static protected $m_bEnabled_Memory = false; static protected $m_bBlameCaller = false; static protected $m_sAllowedUser = '*'; static protected $m_aStats = []; // Recurrent operations static protected $m_aExecData = []; // One shot operations /** * @var array[ExecutionKPI] */ static protected $m_aExecutionStack = []; // embedded execution stats protected $m_fStarted = null; protected $m_fChildrenDuration = 0; // Count embedded protected $m_iInitialMemory = null; static public function EnableDuration($iLevel) { if ($iLevel > 0) { self::$m_bEnabled_Duration = true; if ($iLevel > 1) { self::$m_bBlameCaller = true; } else { self::$m_bBlameCaller = false; } } else { self::$m_bEnabled_Duration = false; self::$m_bBlameCaller = false; } } static public function EnableMemory($iLevel) { if ($iLevel > 0) { self::$m_bEnabled_Memory = true; } else { self::$m_bEnabled_Memory = false; } } /** * @param string sUser A user login or * for all users */ static public function SetAllowedUser($sUser) { self::$m_sAllowedUser = $sUser; } static public function IsEnabled() { if (self::$m_bEnabled_Duration || self::$m_bEnabled_Memory) { if ((self::$m_sAllowedUser == '*') || (UserRights::GetUser() == trim(self::$m_sAllowedUser))) { return true; } } return false; } static public function GetDescription() { $aFeatures = array(); if (self::$m_bEnabled_Duration) $aFeatures[] = 'Duration'; if (self::$m_bEnabled_Memory) $aFeatures[] = 'Memory usage'; $sFeatures = implode(', ', $aFeatures); $sFor = self::$m_sAllowedUser == '*' ? 'EVERYBODY' : "'".trim(self::$m_sAllowedUser)."'"; return "KPI logging is active for $sFor. Measures: $sFeatures"; } static public function ReportStats() { if (!self::IsEnabled()) 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;'; $sHtml = "
"; $sHtml .= "
"; $sHtml .= "

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

"; $oStarted = DateTime::createFromFormat('U.u', $fItopStarted); $sHtml .= "

".$oStarted->format('Y-m-d H:i:s.u')."

"; $sHtml .= "

log_kpi_user_id: ".UserRights::GetUserId()."

"; $sHtml .= "
"; $sHtml .= ""; $sHtml .= ""; $sHtml .= " "; $sHtml .= ""; foreach (self::$m_aExecData as $aOpStats) { $sOperation = $aOpStats['op']; $sBegin = round($aOpStats['time_begin'], 3); $sEnd = round($aOpStats['time_end'], 3); $fDuration = $aOpStats['time_end'] - $aOpStats['time_begin']; $sDuration = round($fDuration, 3); $sMemBegin = 'n/a'; $sMemEnd = 'n/a'; $sMemPeak = 'n/a'; 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']); } } $sHtml .= ""; $sHtml .= " "; $sHtml .= ""; } $sHtml .= "
OperationBeginEndDurationMemory startMemory endMemory peak
$sOperation$sBegin$sEnd$sDuration$sMemBegin$sMemEnd$sMemPeak
"; $sHtml .= "
"; $aConsolidatedStats = array(); foreach (self::$m_aStats as $sOperation => $aOpStats) { $fTotalOp = 0; $iTotalOp = 0; $fMinOp = null; $fMaxOp = 0; $sMaxOpArguments = null; foreach ($aOpStats as $sArguments => $aEvents) { foreach ($aEvents as $aEventData) { $fDuration = $aEventData['time']; $fTotalOp += $fDuration; $iTotalOp++; $fMinOp = is_null($fMinOp) ? $fDuration : min($fMinOp, $fDuration); if ($fDuration > $fMaxOp) { $sMaxOpArguments = $sArguments; $fMaxOp = $fDuration; } } } $aConsolidatedStats[$sOperation] = array( 'count' => $iTotalOp, 'duration' => $fTotalOp, 'min' => $fMinOp, 'max' => $fMaxOp, 'avg' => $fTotalOp / $iTotalOp, 'max_args' => $sMaxOpArguments ); } $sHtml .= "
"; $sHtml .= ""; $sHtml .= ""; $sHtml .= " "; $sHtml .= ""; foreach ($aConsolidatedStats as $sOperation => $aOpStats) { $sOperation = ''.$sOperation.''; $sCount = $aOpStats['count']; $sDuration = round($aOpStats['duration'], 3); $sMin = round($aOpStats['min'], 3); $sMax = ''.round($aOpStats['max'], 3).''; $sAvg = round($aOpStats['avg'], 3); $sHtml .= ""; $sHtml .= " "; $sHtml .= ""; } $sHtml .= "
OperationCountDurationMinMaxAvg
$sOperation$sCount$sDuration$sMin$sMax$sAvg
"; $sHtml .= "
"; $sHtml .= "
"; $sHtml .= "

Next page stats

"; $fSlowQueries = MetaModel::GetConfig()->Get('log_kpi_slow_queries'); self::Report($sHtml); // Report operation details foreach (self::$m_aStats as $sOperation => $aOpStats) { $sHtml = ''; $bDisplayHeader = true; foreach ($aOpStats as $sArguments => $aEvents) { $sHtmlArguments = '
'.$sArguments.'
'; if ($aConsolidatedStats[$sOperation]['max_args'] == $sArguments) { $sHtmlArguments = ''.$sHtmlArguments.''; } if (isset($aEvents[0]['callers'])) { $sHtmlArguments .= '
'; $sHtmlArguments .= ''; $sHtmlArguments .= ''; foreach ($aEvents[0]['callers'] as $aCall) { $sHtmlArguments .= ''; $sHtmlArguments .= ''; $sHtmlArguments .= ''; $sHtmlArguments .= ''; } $sHtmlArguments .= '
Call stack for the FIRST caller
'.$aCall['Function'].''.$aCall['File'].':'.$aCall['Line'].'
'; $sHtmlArguments .= '
'; } $fTotalInter = 0; $fMinInter = null; $fMaxInter = 0; foreach ($aEvents as $aEventData) { $fDuration = $aEventData['time']; $fTotalInter += $fDuration; $fMinInter = is_null($fMinInter) ? $fDuration : min($fMinInter, $fDuration); $fMaxInter = max($fMaxInter, $fDuration); } $iCountInter = count($aEvents); $sTotalInter = round($fTotalInter, 3); $sMinInter = round($fMinInter, 3); $sMaxInter = round($fMaxInter, 3); if (($fTotalInter >= $fSlowQueries)) { if ($bDisplayHeader) { $sOperationHtml = ''.$sOperation.''; $sHtml .= "

$sOperationHtml

"; $sHtml .= ""; $sHtml .= ""; $sHtml .= " "; $sHtml .= ""; $bDisplayHeader = false; } $sHtml .= ""; $sHtml .= " "; $sHtml .= ""; } } if (!$bDisplayHeader) { $sHtml .= "
Operation details (+ blame caller if log_kpi_duration = 2)CountDurationMinMax
$sHtmlArguments$iCountInter$sTotalInter$sMinInter$sMaxInter
"; $sHtml .= "

Back to page stats

"; } self::Report($sHtml); } $sHtml = ' '; self::Report($sHtml); } public function __construct() { $this->ResetCounters(); self::Push($this); } /** * Stack executions to remove children duration from stats * * @param \ExecutionKPI $oExecutionKPI */ private static function Push(ExecutionKPI $oExecutionKPI) { self::$m_aExecutionStack[] = $oExecutionKPI; } /** * Pop current child and count its duration in its parent * * @param float|int $fChildDuration */ private static function Pop(float $fChildDuration = 0) { array_pop(self::$m_aExecutionStack); // Update the parent's children duration $oPrevExecutionKPI = end(self::$m_aExecutionStack); if ($oPrevExecutionKPI) { $oPrevExecutionKPI->m_fChildrenDuration += $fChildDuration; } } // Get the duration since startup, and reset the counter for the next measure // public function ComputeAndReport($sOperationDesc) { global $fItopStarted; $aNewEntry = null; if (self::$m_bEnabled_Duration) { $fStopped = MyHelpers::getmicrotime(); $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) { $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')) { $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(); } public function ComputeStats($sOperation, $sArguments) { $fDuration = 0; if (self::$m_bEnabled_Duration) { $fStopped = MyHelpers::getmicrotime(); $fDuration = $fStopped - $this->m_fStarted; $fSelfDuration = $fDuration - $this->m_fChildrenDuration; if (self::$m_bBlameCaller) { self::$m_aStats[$sOperation][$sArguments][] = array( 'time' => $fSelfDuration, 'callers' => MyHelpers::get_callstack(1), ); } else { self::$m_aStats[$sOperation][$sArguments][] = array( 'time' => $fSelfDuration, ); } } self::Pop($fDuration); } protected function ResetCounters() { if (self::$m_bEnabled_Duration) { $this->m_fStarted = microtime(true); } if (self::$m_bEnabled_Memory) { $this->m_iInitialMemory = self::memory_get_usage(); } } const HTML_REPORT_FILE = 'log/kpi.html'; static protected function Report($sText) { file_put_contents(APPROOT.self::HTML_REPORT_FILE, "$sText\n", FILE_APPEND | LOCK_EX); } 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; } } static public function memory_get_peak_usage($bRealUsage = false) { if (function_exists('memory_get_peak_usage')) { return memory_get_peak_usage($bRealUsage); } // PHP > 5.2.1 - this verb depends on a compilation option return 0; } }