From ee8bd63a08b1535c0f30f2eac689e4df0688a755 Mon Sep 17 00:00:00 2001 From: Josh Sherman Date: Wed, 1 Oct 2014 07:41:01 -0400 Subject: [PATCH] Working on that new profiler Gotta figure out what's going on with the database portion, it's going all crazy on me. --- src/Database.php | 16 --- src/Profiler.php | 296 ++++++++++------------------------------------- src/Resource.php | 14 ++- 3 files changed, 72 insertions(+), 254 deletions(-) diff --git a/src/Database.php b/src/Database.php index d4e5ff7..c5a71e8 100644 --- a/src/Database.php +++ b/src/Database.php @@ -311,22 +311,6 @@ class Database extends Object // Checks if the query is blank if ($sql != '') { - // Builds out stack trace for queries - $files = []; - - $backtrace = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS); - krsort($backtrace); - - foreach ($backtrace as $file) - { - if (isset($file['class'], $file['line'])) - { - $files[] = $file['class'] . ':' . $file['line']; - } - } - - $sql .= "\n" . '/* [' . implode('|', $files) . '] */'; - // Establishes if we're working on an EXPLAIN if ($this->config['pickles']['profiler']) { diff --git a/src/Profiler.php b/src/Profiler.php index 9d76d0a..dc7b1fa 100644 --- a/src/Profiler.php +++ b/src/Profiler.php @@ -25,18 +25,13 @@ namespace Pickles; * config.ini for a site. Out of the box the profiler will report on every * class object in the system that extends the code Object class. * - * Note: I really wanted to use PHP Quick Profiler by Ryan Campbell of - * Particletree but it kept barking out errors when I tried to use it with - * E_STRICT turned on. Here's a link anyway since it looks awesome: - * http://particletree.com/features/php-quick-profiler/ - * * @usage Profiler::log('some action you want to track'); * @usage Profiler::log($object, 'methodName'); */ class Profiler { /** - * Profile + * Logs * * Array of logged events * @@ -44,18 +39,7 @@ class Profiler * @access private * @var array */ - private static $profile = []; - - /** - * Queries - * - * Number of queries that have been logged - * - * @static - * @access private - * @var integer - */ - private static $queries = 0; + private static $logs = []; /** * Timers @@ -68,41 +52,6 @@ class Profiler */ private static $timers = []; - /** - * Enabled - * - * Checks if the profiler is set to boolean true or if the passed type is - * specified in the profiler configuration value. - * - * @param array $type type(s) to check - * @return boolean whether or not the type is enabled - */ - public static function enabled(/* polymorphic */) - { - $config = Config::getInstance(); - $config = $config['pickles']['profiler']; - - // Checks if we're set to boolean true - if ($config === true) - { - return true; - } - else - { - $types = func_get_args(); - - foreach ($types as $type) - { - if (stripos($config, $type) !== false) - { - return true; - } - } - } - - return false; - } - /** * Log * @@ -125,21 +74,23 @@ class Profiler switch ($data_type) { case 'array': - $log = '
' . print_r($data, true) . '
'; + $details = print_r($data, true); break; case 'object': - $log = '[' . get_parent_class($data) . '] ' - . '' . get_class($data) . '' - . ($method != '' ? '->' . $method . '()' : ''); + $details['class'] = get_class($data); - $data_type = '' . $data_type . ''; + if ($method != '') + { + $details['method'] = $method . '()'; + } + + $data_type = $data_type; break; case 'timer': - $log = $method; - - $data_type = '' . $data_type . ''; + $details = $method; + $data_type = $data_type; break; case 'string': @@ -149,16 +100,16 @@ class Profiler $data_type = $type; } - $log = $data; + $details = $data; break; } - self::$profile[] = [ - 'log' => $log, - 'type' => $data_type, - 'time' => $time, - 'elapsed' => $time - $_SERVER['REQUEST_TIME_FLOAT'], - 'memory' => memory_get_usage(), + self::$logs[] = [ + 'type' => $data_type, + 'timestamp' => $time, + 'elapsed_time' => $time - $_SERVER['REQUEST_TIME_FLOAT'], + 'memory_usage' => memory_get_usage(), + 'details' => $details, ]; } @@ -175,41 +126,39 @@ class Profiler */ public static function logQuery($query, $input_parameters = false, $explain = false, $duration = false) { - self::$queries++; - - $log = ''; + $log = []; + /* if ($input_parameters != 'false' && is_array($input_parameters)) { - $log .= '
'; - foreach ($input_parameters as $key => $value) { - $log .= '
' . $key . ' => ' . $value . ''; + $log .= $key . ' => ' . $value; - $query = str_replace($key, '' . $key . '', $query); + $query = str_replace($key, $key, $query); } } - $log = '' . $query . '' . $log; + $log = $query . ' ' . $log; if (is_array($explain)) { - $log .= '
'; - foreach ($explain as $table) { - $log .= '
Possible Keys => ' . ($table['possible_keys'] == '' ? 'NONE' : $table['possible_keys']) . '' - . '
Key => ' . ($table['key'] == '' ? 'NONE' : $table['key']) . '' - . '
Type => ' . $table['type'] . '' - . '
Rows => ' . $table['rows'] . '' - . ($table['Extra'] != '' ? '
Extra => ' . $table['Extra'] . '' : ''); + $log .= 'Possible Keys => ' . ($table['possible_keys'] == '' ? 'NONE' : $table['possible_keys']) + . 'Key => ' . ($table['key'] == '' ? 'NONE' : $table['key']) + . 'Type => ' . $table['type'] + . 'Rows => ' . $table['rows'] + . ($table['Extra'] != '' ? 'Extra => ' . $table['Extra'] : ''); } } - $log .= '

Speed: ' . number_format($duration * 100, 3) . ' ms'; + $log .= 'query_time: ' . $duration; + */ - self::log($log, false, 'database'); + $log = [$query, $input_parameters, $explain, $duration]; + + self::log($log, false, 'database'); } /** @@ -222,26 +171,27 @@ class Profiler */ public static function timer($timer) { - if (self::enabled('timers')) + // Starts the timer + if (!isset(self::$timers[$timer])) { - // Starts the timer - if (!isset(self::$timers[$timer])) - { - self::$timers[$timer] = microtime(true); - self::Log('timer', 'Started timer ' . $timer . ''); - } - // Ends the timer - else - { - self::Log('timer', 'Stopped timer ' . $timer . ' => Time Elapsed: ' . number_format((microtime(true) - self::$timers[$timer]) * 100, 3) . ' ms'); + self::$timers[$timer] = microtime(true); - unset(self::$timers[$timer]); - } - - return true; + self::Log('timer', [ + 'action' => 'start', + 'name' => $timer + ]); } + // Ends the timer + else + { + self::Log('timer', [ + 'action' => 'stop', + 'name' => $timer, + 'elapsed_time' => (microtime(true) - self::$timers[$timer]) + ]); - return false; + unset(self::$timers[$timer]); + } } /** @@ -250,142 +200,24 @@ class Profiler * Generates the Profiler report that is displayed by the Controller. * Contains all the HTML needed to display the data properly inline on the * page. Will generally be displayed after the closing HTML tag. - * - * @todo Thinking this should return the report and not necessarily echo it */ public static function report() { - ?> - -
- PICKLES Profiler

- There is nothing to profile. This often happens when the profiler configuration is set to either "queries" or "explains" and there are no database queries on the page (common on pages that only have a template). You may want to set the profiler to boolean true to ensure you get a profile of the page.'; - } - else - { - $start_time = $_SERVER['REQUEST_TIME_FLOAT']; - $peak_usage = self::formatSize(memory_get_peak_usage()); - $end_time = self::$profile[count(self::$profile) - 1]['time']; // @todo No idea what though? - $duration = ($end_time - $start_time); + $report = [ + 'request_time' => $_SERVER['REQUEST_TIME_FLOAT'], + 'execution_time' => self::$logs[count(self::$logs) - 1]['timestamp'] + - $_SERVER['REQUEST_TIME_FLOAT'], + 'peak_memory_usage' => memory_get_peak_usage(), + 'max_execution_time' => ini_get('max_execution_time'), + 'memory_limit' => ini_get('memory_limit'), + 'included_files' => count(get_included_files()), + 'logs' => self::$logs, + ]; - $logs = count(self::$profile); - $logs .= ' Log' . ($logs == 1 ? '' : 's'); + self::$logs = []; + self::$timers = []; - $files = count(get_included_files()); - $files .= ' File' . ($files == 1 ? '' : 's'); - - $queries = self::$queries . ' Quer'. (self::$queries == 1 ? 'y' : 'ies'); - ?> - - - - - - - - -
- Console -
- 		- Load Time -
- 		- Memory Usage -
- 		- Database -
- 		- Includes -
-
- - - - - - - $entry) - { - ?> - - - - - - - -
ConsoleMemoryTime
ms
- -
-

- config['pickles']['profiler']) { - Profiler::timer('resource ' . $method); + $timer = get_class($this) . '->' . $method . '()'; + Profiler::timer($timer); } - */ $this->response = $this->$method(); - /* // Stops the resource timer if ($this->config['pickles']['profiler']) { - Profiler::timer('resource ' . $method); + Profiler::timer($timer); } - */ } } } @@ -402,6 +399,11 @@ class Resource extends Object } } + if ($this->config['pickles']['profiler']) + { + $response['profiler'] = Profiler::report(); + } + $pretty = isset($_REQUEST['pretty']) ? JSON_PRETTY_PRINT : false; echo json_encode($response, $pretty);