Improved the KPI logging: setting log_kpi_duration to 2 will enable blaming of the FIRST caller (callstack entirely shown in the produced report)

SVN:trunk[2975]

core/MyHelpers.class.inc.php

@@ -219,7 +219,7 @@ class MyHelpers
 		}
 	}
 
-	public static function get_callstack_html($iLevelsToIgnore = 0, $aCallStack = null)
+	public static function get_callstack($iLevelsToIgnore = 0, $aCallStack = null)
 	{
 		if ($aCallStack == null) $aCallStack = debug_backtrace();
 		
@@ -231,6 +231,16 @@ class MyHelpers
 		{
 			$sLine = empty($aCallInfo['line']) ? "" : $aCallInfo['line'];
 			$sFile = empty($aCallInfo['file']) ? "" : $aCallInfo['file'];
+			if ($sFile != '')
+			{
+				$sFile = str_replace('\\', '/', $sFile);
+				$sAppRoot = str_replace('\\', '/', APPROOT);
+				$iPos = strpos($sFile, $sAppRoot);
+				if ($iPos !== false)
+				{
+					$sFile = substr($sFile, strlen($sAppRoot));
+				}
+			}
 			$sClass = empty($aCallInfo['class']) ? "" : $aCallInfo['class'];
 			$sType = empty($aCallInfo['type']) ? "" : $aCallInfo['type'];
 			$sFunction = empty($aCallInfo['function']) ? "" : $aCallInfo['function'];
@@ -259,11 +269,11 @@ class MyHelpers
 						$args .= $a;
 					break;
 						case 'string':
-						$a = Str::pure2html(self::beautifulstr($a, 1024, true, true));
+						$a = Str::pure2html(self::beautifulstr($a, 64, true, false));
 						$args .= "\"$a\"";
 						break;
 					case 'array':
-						$args .= 'Array('.count($a).')';
+						$args .= 'array('.count($a).')';
 						break;
 					case 'object':
 						$args .= 'Object('.get_class($a).')';
@@ -272,19 +282,25 @@ class MyHelpers
 						$args .= 'Resource('.strstr($a, '#').')';
 						break;
 					case 'boolean':
-						$args .= $a ? 'True' : 'False';
+						$args .= $a ? 'true' : 'false';
 						break;
 					case 'NULL':
-						$args .= 'Null';
+						$args .= 'null';
 						break;
 					default:
 						$args .= 'Unknown';
 					}
 				}
-				$sFunctionInfo = "$sClass $sType $sFunction($args)";
+				$sFunctionInfo = "$sClass$sType$sFunction($args)";
 			}
 			$aDigestCallStack[] = array('File'=>$sFile, 'Line'=>$sLine, 'Function'=>$sFunctionInfo);
 		}
+		return $aDigestCallStack;
+	}
+
+	public static function get_callstack_html($iLevelsToIgnore = 0, $aCallStack = null)
+	{
+		$aDigestCallStack = self::get_callstack($iLevelsToIgnore, $aCallStack);
 		return self::make_table_from_assoc_array($aDigestCallStack);
 	}
 
@@ -293,6 +309,17 @@ class MyHelpers
 		return self::get_callstack_html($iLevelsToIgnore, $aCallStack);
 	}
 
+	public static function get_callstack_text($iLevelsToIgnore = 0, $aCallStack = null)
+	{
+		$aDigestCallStack = self::get_callstack($iLevelsToIgnore, $aCallStack);
+		$aRes = array();
+		foreach ($aDigestCallStack as $aCall)
+		{
+			$aRes[] = $aCall['File'].' at '.$aCall['Line'].', '.$aCall['Function'];
+		}
+		return implode("\n", $aRes);
+	}
+
 	///////////////////////////////////////////////////////////////////////////////
 	// Source: New
 	// Last modif: 2004/12/20 RQU

core/cmdbsource.class.inc.php

@@ -255,12 +255,6 @@ class CMDBSource
 
 	public static function Query($sSQLQuery)
 	{
-		// Add info into the query as a comment, for easier error tracking
-	  	// disabled until we need it really!
-		//
-		//$aTraceInf['file'] = __FILE__;
-		// $sSQLQuery .= MyHelpers::MakeSQLComment($aTraceInf);
-	  
 		$oKPI = new ExecutionKPI();
 		$result = mysqli_query(self::$m_resDBLink, $sSQLQuery);
 		if (!$result) 
@@ -307,7 +301,9 @@ class CMDBSource
 
 	public static function QueryToScalar($sSql)
 	{
+		$oKPI = new ExecutionKPI();
 		$result = mysqli_query(self::$m_resDBLink, $sSql);
+		$oKPI->ComputeStats('Query exec (mySQL)', $sSql);
 		if (!$result)
 		{
 			throw new MySQLException('Failed to issue SQL query', array('query' => $sSql));
@@ -328,7 +324,9 @@ class CMDBSource
 	public static function QueryToArray($sSql)
 	{
 		$aData = array();
+		$oKPI = new ExecutionKPI();
 		$result = mysqli_query(self::$m_resDBLink, $sSql);
+		$oKPI->ComputeStats('Query exec (mySQL)', $sSql);
 		if (!$result)
 		{
 			throw new MySQLException('Failed to issue SQL query', array('query' => $sSql));

core/config.class.inc.php

@@ -626,7 +626,7 @@ class Config
 		),
 		'log_kpi_duration' => array(
 			'type' => 'integer',
-			'description' => 'Level of logging for troubleshooting performance issues',
+			'description' => 'Level of logging for troubleshooting performance issues (1 to enable, 2 +blame callers)',
 			// examples... not used
 			'default' => 0,
 			'value' => 0,

core/kpi.class.inc.php

@@ -28,6 +28,7 @@ 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 = array(); // Recurrent operations
@@ -41,6 +42,10 @@ class ExecutionKPI
 		if ($iLevel > 0)
 		{
 			self::$m_bEnabled_Duration = true;
+			if ($iLevel > 1)
+			{
+				self::$m_bBlameCaller = true;
+			}
 		}
 	}
 
@@ -145,8 +150,9 @@ class ExecutionKPI
 			$sMaxOpArguments = null;
 			foreach ($aOpStats as $sArguments => $aEvents)
 			{
-				foreach ($aEvents as $fDuration)
+				foreach ($aEvents as $aEventData)
 				{
+					$fDuration = $aEventData['time'];
 					$fTotalOp += $fDuration;
 					$iTotalOp++;
 
@@ -199,20 +205,38 @@ class ExecutionKPI
 			self::Report("<p><a href=\"#".md5($sExecId)."\">Back to page stats</a></p>");
 			self::Report("<table border=\"1\" style=\"$sTableStyle\">");
 			self::Report("<thead>");
-			self::Report("   <th>Operation details</th><th>Count</th><th>Duration</th><th>Min</th><th>Max</th>");
+			self::Report("   <th>Operation details (+ blame caller if log_kpi_duration = 2)</th><th>Count</th><th>Duration</th><th>Min</th><th>Max</th>");
 			self::Report("</thead>");
 			foreach ($aOpStats as $sArguments => $aEvents)
 			{
-				$sHtmlArguments = '<a name="'.md5($sExecId.$sArguments).'">'.$sArguments.'</a>';
+				$sHtmlArguments = '<a name="'.md5($sExecId.$sArguments).'"><div style="white-space: pre-wrap;">'.$sArguments.'</div></a>';
 				if ($aConsolidatedStats[$sOperation]['max_args'] == $sArguments)
 				{
 					$sHtmlArguments = '<span style="color: red;">'.$sHtmlArguments.'</span>';
 				}
+				if (isset($aEvents[0]['callers']))
+				{
+					$sHtmlArguments .= '<div style="padding: 10px;">';
+					$sHtmlArguments .= '<table border="1" bgcolor="#cfc">';
+					$sHtmlArguments .= '<tr><td colspan="2" bgcolor="#e9b96">Call stack for the <b>FIRST</b> caller</td></tr>';
+
+					foreach ($aEvents[0]['callers'] as $aCall)
+					{
+						$sHtmlArguments .= '<tr>';
+						$sHtmlArguments .= '<td>'.$aCall['Function'].'</td>';
+						$sHtmlArguments .= '<td>'.$aCall['File'].':'.$aCall['Line'].'</td>';
+						$sHtmlArguments .= '</tr>';
+					}
+					$sHtmlArguments .= '</table>';
+					$sHtmlArguments .= '</div>';
+				}
+
 				$fTotalInter = 0;
 				$fMinInter = null;
 				$fMaxInter = 0;
-				foreach ($aEvents as $fDuration)
+				foreach ($aEvents as $aEventData)
 				{
+					$fDuration = $aEventData['time'];
 					$fTotalInter += $fDuration;
 					$fMinInter = is_null($fMinInter) ? $fDuration : min($fMinInter, $fDuration);
 					$fMaxInter = max($fMaxInter, $fDuration);
@@ -286,7 +310,19 @@ class ExecutionKPI
 		{
 			$fStopped = MyHelpers::getmicrotime();
 			$fDuration = $fStopped - $this->m_fStarted;
-			self::$m_aStats[$sOperation][$sArguments][] = $fDuration;
+			if (self::$m_bBlameCaller)
+			{
+				self::$m_aStats[$sOperation][$sArguments][] = array(
+					'time' => $fDuration,
+					'callers' => MyHelpers::get_callstack(1),
+				);
+			}
+			else
+			{
+				self::$m_aStats[$sOperation][$sArguments][] = array(
+					'time' => $fDuration
+				);
+			}
 		}
 	}