fixed debug logger performance

SE/se-lib/AclQueryBuilder.php

@@ -51,11 +51,11 @@ class AclQueryBuilder {
 	}
 
 	public function from($from, $prefix = 't') {
-		DBG::log([
-			'from instanceof Core_AclBase' => ($from instanceof Core_AclBase),
-			'from instanceof AntAclBase' => ($from instanceof AntAclBase),
-			'from instanceof TableAcl' => ($from instanceof TableAcl),
-		], 'array', "\$from class(".get_class($from).")");
+		// DBG::log([
+		// 	'from instanceof Core_AclBase' => ($from instanceof Core_AclBase),
+		// 	'from instanceof AntAclBase' => ($from instanceof AntAclBase),
+		// 	'from instanceof TableAcl' => ($from instanceof TableAcl),
+		// ], 'array', "\$from class(".get_class($from).")");
 		if ($this->from) throw new Exception("Duplicate FROM");
 		$this->from = $from;
 		$this->_fromPrefix = $prefix;
@@ -289,8 +289,9 @@ class AclQueryBuilder {
 	}
 
 	public function fetchAll() {
+		DBG::log("AclQueryBuilder::fetchAll - generateSql... ns(".$this->from->getNamespace().")");
 		$sql = $this->generateSql();
-		DBG::log((array)$this, 'array', "AclQueryBuilder::fetchAll");
+		DBG::log("AclQueryBuilder::fetchAll - generateSql end ns(".$this->from->getNamespace().")");
 		return $this->getPDO()->fetchAll($sql);
 	}
 
@@ -371,6 +372,7 @@ class AclQueryBuilder {
 			'is_string'
 		);
 		$sqlWhere = (!empty($sqlWhere)) ? "where " . implode("\n\t and ", $sqlWhere) : '';
+		DBG::log($sqlWhere, 'array', "generateSql \$sqlWhere");
 
 		$limit = ($this->limit < 0) ? 0 : $this->limit;
 		$offset = ($this->offset < 0) ? 0 : $this->offset;

SE/se-lib/DBG.php

@@ -3,6 +3,7 @@
 Lib::loadClass('User');
 Lib::loadClass('UI');
 Lib::loadClass('Request');
+Lib::loadClass('DebugLazyLogger');
 
 class DBG {
 
@@ -256,20 +257,13 @@ class DBG {
 		if (!self::isActive() && !self::isLogActiveByAdmin()) return;
 		if ('Debug' == V::get('_route', '', $_REQUEST) && !V::get('DBG', '', $_REQUEST)) return;
 		static $_firstRun = true;
-		$prefix = ('production' == V::get('P5_ENV', 'production', $_SERVER)) ? "" : "dev-";
-		$logFileName = "/tmp/{$prefix}se-debug-" . implode('-', [
-			date("Y-m-d"),
-			User::getLogin(),
-			Request::getUserIp(),
-			substr(session_id(), 0, 6),
-			V::get('REQUEST_TIME', '', $_SERVER)// [REQUEST_TIME] => 1485770466
-		]) . '.log';
 		if ($_firstRun) {
 			$_firstRun = false;
 			$firstMsg = V::get('REQUEST_METHOD', '', $_SERVER) . " " . V::get('REQUEST_URI', '', $_SERVER);
-			self::_log([ 'POST' => $_POST, 'GET' => $_GET, 'POST_BODY' => Request::getRequestBody() ], 'array', $firstMsg, $logFileName);
+			DebugLazyLogger::log([ 'POST' => $_POST, 'GET' => $_GET, 'POST_BODY' => Request::getRequestBody() ], 'array', $firstMsg);
 		}
-		self::_log($mixedArg, $type, $msg, $logFileName);
+		$mixedArg = (is_scalar($mixedArg)) ? substr((string)$mixedArg, 0, 50) : substr(var_export($mixedArg, true), 0, 50);// TODO: DBG
+		DebugLazyLogger::log($mixedArg, $type, $msg);
 	}
 	public static function logAuth($mixedArg, $msg = '') {
 		if ('Debug' == V::get('_route', '', $_REQUEST) && !V::get('DBG', '', $_REQUEST)) return;

SE/se-lib/DebugLazyLogger.php

@@ -0,0 +1,138 @@
+<?php
+
+class DebugLazyLogger {
+
+	function __construct() {
+		$this->_items = [];
+		$prefix = ('production' == V::get('P5_ENV', 'production', $_SERVER)) ? "" : "dev-";
+		$this->_logFileName = "/tmp/{$prefix}se-debug-" . implode('-', [
+			date("Y-m-d"),
+			User::getLogin(),
+			Request::getUserIp(),
+			substr(session_id(), 0, 6),
+			V::get('REQUEST_TIME', '', $_SERVER)// [REQUEST_TIME] => 1485770466
+		]) . '.log';
+	}
+
+	static function getInstance() {
+		static $instance;
+		if (!$instance) $instance = new DebugLazyLogger();
+		return $instance;
+	}
+
+	// DebugLazyLogger::log($mixedArg, $type, $msg, $logFileName);
+	static function log($mixedArg, $type, $msg) {
+		$logger = self::getInstance();
+		$logger->addLog($mixedArg, $type, $msg);
+	}
+
+	function addLog($mixedArg, $type, $msg) {
+		$microTime = date("Y-m-d H:i:s") . substr((string)microtime(), 1, 6);
+		$this->_items[] = [ $microTime, $mixedArg, $type, $msg ];
+	}
+
+	function __destruct() {
+		$startSaveLog = date("Y-m-d H:i:s") . substr((string)microtime(), 1, 6);
+		$firstItem = reset($this->_items);
+		foreach ($this->_items as $logItem) { // $logItem: [ $mixedArg, $type, $msg, $logFileName ]
+			list($microTime, $mixedArg, $type, $msg) = $logItem;
+			self::_log($microTime, $mixedArg, $type, $msg, $this->_logFileName);
+		}
+		$endSaveLog = date("Y-m-d H:i:s") . substr((string)microtime(), 1, 6);
+		self::_log($startSaveLog, $mixedArg = null, $type = 'string', $msg = "Start saving log", $this->_logFileName);
+		self::_log($endSaveLog,   $mixedArg = null, $type = 'string', $msg = "End saving log", $this->_logFileName);
+		self::_log($endSaveLog,   $mixedArg = [
+			"{$firstItem[0]} diff(-----) - first log entry",
+			"{$startSaveLog} diff(" . V::milisecondsStringDiff($startSaveLog, $firstItem[0]) . ") - start saving log to file",
+			"{$endSaveLog} diff(" . V::milisecondsStringDiff($endSaveLog, $startSaveLog) . ") - end saving log to file",
+		], $type = 'array', $msg = "Summary", $this->_logFileName);
+	}
+
+	public static function _log($microTime ,$mixedArg, $type, $msg, $logFileName) {
+		$logInfo = [
+			'date' => $microTime,
+			'type' => $type,
+			'msg' => $msg,
+			'log' => '',
+			'trace' => '',
+		];
+		if ($mixedArg instanceof Exception) {
+			$logInfo['type'] = 'Exception';
+			if (!empty($logInfo['msg'])) $logInfo['msg'] .= ". ";
+			$logInfo['msg'] .= $mixedArg->getMessage();
+			$logInfo['log'] = [
+				'code' => $mixedArg->getCode(),
+				'line' => $mixedArg->getLine(),
+				'file' => str_replace(APP_PATH_ROOT, 'SE', $mixedArg->getFile()),
+			];
+			$logInfo['trace'] = $mixedArg->getTraceAsString();// getTrace
+		} else if (is_string($mixedArg)) {
+			if ('sql' == $type) {
+				if (!$logInfo['type']) $logInfo['type'] = 'sql';
+				if (empty($logInfo['msg'])) $logInfo['msg'] = "sql";
+				$logInfo['log'] = $mixedArg;
+			} else {
+				if (empty($logInfo['type'])) $logInfo['type'] = 'string';
+				if (empty($msg)) {
+					$logInfo['msg'] = $mixedArg;
+					$logInfo['log'] = '';
+				} else {
+					$logInfo['msg'] = $msg;
+					$logInfo['log'] = $mixedArg;
+				}
+			}
+			ob_start();
+			debug_print_backtrace();
+			$logInfo['trace'] = ob_get_clean();
+		} else if ('array' == $type || is_array($mixedArg)) {
+			$mixedArg = (array)$mixedArg;
+			if (!$logInfo['type']) $logInfo['type'] = 'array';
+			if (!empty($logInfo['msg']) && !empty($mixedArg['msg'])) $logInfo['msg'] .= ". {$mixedArg['msg']}";
+			else if (empty($logInfo['msg']) && !empty($mixedArg['msg'])) $logInfo['msg'] = $mixedArg['msg'];
+			if (!empty($mixedArg['msg'])) unset($mixedArg['msg']);
+			$logInfo['log'] = $mixedArg;
+			ob_start();
+			debug_print_backtrace();
+			$logInfo['trace'] = ob_get_clean();
+		}
+		if (!empty($logInfo['trace']) && 'Exception' !== $logInfo['type']) {// remove #0 and #1 (DBG::log and DBG::_log)
+			$pos = strpos($logInfo['trace'], "\n#2");
+			// if (false !== $pos) $logInfo['trace'] = substr($logInfo['trace'], $pos + 1); // TODO
+		}
+		$logInfo['trace'] = str_replace(APP_PATH_ROOT, 'SE', $logInfo['trace']);
+		$logInfo['trace'] .= (("\n" == substr($logInfo['trace'], -1)) ? '' :  "\n") . "#URI: " . V::get('REQUEST_URI', '', $_SERVER);
+		if (!$logInfo['type']) $logInfo['type'] = 'unknown';
+
+		if (!empty($logInfo['trace'])) {
+			$trace = array_map(function ($part) {
+				if ('URI: ' === substr($part, 0, strlen('URI: '))) return "#{$part}";
+				if ($pos = strpos($part, '{closure}')) {
+					// #10 Route_Storage_AclStruct->{closure}(Array ([namespace] => default_db/BI_audit_ENERGA_PRAC ... )
+					return "#" . substr($part, 0, 200) . ( strlen($part) > 200 ? '...' : '' );
+				}
+				if ($pos = strrpos($part, ' called at [')) {
+					$spacePos = strpos($part, ' ');
+					$spacePos = (' ' === $part[$spacePos + 1]) ? $spacePos + 1 : $spacePos;
+					$spacePos = (' ' === $part[$spacePos + 1]) ? $spacePos + 1 : $spacePos;
+					$spacePos += 1;
+					$called = substr($part, $pos + strlen(' called at ['), -1);
+					$nr = substr($part, 0, $spacePos);
+					$line = substr($part, $spacePos, ($pos > 200) ? 200 : $pos - $spacePos);
+					if ($pos > 200) $line .= "...";
+					$line = str_replace("\n", '\\n', $line);
+					return "#{$nr}{$called}: {$line}";
+				}
+				return "#" . substr($part, 0, 200) . ( strlen($part) > 200 ? '...' : '' );
+			}, explode("\n#", $logInfo['trace']));
+			array_shift($trace);
+			$logInfo['trace'] = implode("\n", $trace);
+		}
+
+		error_log(
+			json_encode($logInfo) . "\n"
+			, 3
+			, $logFileName
+		);
+	}
+
+}