From 516479cf207aadc04a0b7f3805311356641746dc Mon Sep 17 00:00:00 2001 From: Kijin Sung Date: Tue, 16 Feb 2016 11:01:45 +0900 Subject: [PATCH] Migrate addon, trigger, and widget logging functions to Debug class --- classes/db/DB.class.php | 7 -- classes/display/DisplayHandler.class.php | 7 +- classes/module/ModuleHandler.class.php | 51 +++++++++-- common/framework/debug.php | 84 +++++++++++++---- common/legacy.php | 67 +------------- modules/addon/addon.controller.php | 110 ++++++++++++++--------- modules/widget/widget.controller.php | 9 +- 7 files changed, 188 insertions(+), 147 deletions(-) diff --git a/classes/db/DB.class.php b/classes/db/DB.class.php index 2d0d016ad..695e0fd45 100644 --- a/classes/db/DB.class.php +++ b/classes/db/DB.class.php @@ -396,13 +396,6 @@ class DB } $this->setQueryLog($log); - - $log_args = new stdClass; - $log_args->query = $this->query; - $log_args->query_id = $this->query_id; - $log_args->caller = $log['called_method'] . '() in ' . $log['called_file']; - $log_args->connection = $log['connection']; - writeSlowlog('query', $elapsed_time, $log_args); } /** diff --git a/classes/display/DisplayHandler.class.php b/classes/display/DisplayHandler.class.php index bab8e6c67..80026a860 100644 --- a/classes/display/DisplayHandler.class.php +++ b/classes/display/DisplayHandler.class.php @@ -122,12 +122,13 @@ class DisplayHandler extends Handler self::$response_size = $this->content_size = strlen($output); ModuleHandler::triggerCall('display', 'after', $output); - // debugOutput output + // Output the page content and debug data. $debug = $this->getDebugInfo($output); print $output; print $debug; - - flushSlowlog(); + + // Flush the slow query/trigger/widget log. + ModuleHandler::triggerCall('common.flushDebugInfo', 'after', new stdClass); } /** diff --git a/classes/module/ModuleHandler.class.php b/classes/module/ModuleHandler.class.php index 30fa1410e..80b565d9e 100644 --- a/classes/module/ModuleHandler.class.php +++ b/classes/module/ModuleHandler.class.php @@ -1200,17 +1200,20 @@ class ModuleHandler extends Handler } $before_each_trigger_time = microtime(true); - $output = $oModule->{$called_method}($obj); - $after_each_trigger_time = microtime(true); - $elapsed_time_trigger = $after_each_trigger_time - $before_each_trigger_time; - $slowlog = new stdClass; - $slowlog->caller = $trigger_name . '.' . $called_position; - $slowlog->called = $module . '.' . $called_method; - $slowlog->called_extension = $module; - if($trigger_name != 'XE.writeSlowlog') writeSlowlog('trigger', $elapsed_time_trigger, $slowlog); + if ($trigger_name !== 'common.flushDebugInfo') + { + $trigger_target = $module . ($type === 'class' ? '' : $type) . '.' . $called_method; + + Rhymix\Framework\Debug::addTrigger(array( + 'name' => $trigger_name . '.' . $called_position, + 'target' => $trigger_target, + 'target_plugin' => $module, + 'elapsed_time' => $after_each_trigger_time - $before_each_trigger_time, + )); + } if(is_object($output) && method_exists($output, 'toBool') && !$output->toBool()) { @@ -1222,7 +1225,39 @@ class ModuleHandler extends Handler $trigger_functions = $oModuleModel->getTriggerFunctions($trigger_name, $called_position); foreach($trigger_functions as $item) { + $before_each_trigger_time = microtime(true); $item($obj); + $after_each_trigger_time = microtime(true); + + if ($trigger_name !== 'common.writeSlowlog') + { + if (is_string($item)) + { + $trigger_target = $item; + } + elseif (is_array($item) && count($item)) + { + if (is_object($item[0])) + { + $trigger_target = get_class($item[0]) . '.' . strval($item[1]); + } + else + { + $trigger_target = implode('.', $item); + } + } + else + { + $trigger_target = 'closure'; + } + + Rhymix\Framework\Debug::addTrigger(array( + 'name' => $trigger_name . '.' . $called_position, + 'target' => $trigger_target, + 'target_plugin' => null, + 'elapsed_time' => $after_each_trigger_time - $before_each_trigger_time, + )); + } if(is_object($output) && method_exists($output, 'toBool') && !$output->toBool()) { diff --git a/common/framework/debug.php b/common/framework/debug.php index fe19869ab..6c8ff7120 100644 --- a/common/framework/debug.php +++ b/common/framework/debug.php @@ -15,7 +15,9 @@ class Debug protected static $_errors = array(); protected static $_queries = array(); protected static $_slow_queries = array(); + protected static $_triggers = array(); protected static $_slow_triggers = array(); + protected static $_widgets = array(); protected static $_slow_widgets = array(); /** @@ -63,6 +65,16 @@ class Debug return self::$_slow_queries; } + /** + * Get all triggers. + * + * @return array + */ + public static function getTriggers() + { + return self::$_triggers; + } + /** * Get all slow triggers. * @@ -73,6 +85,16 @@ class Debug return self::$_slow_triggers; } + /** + * Get all widgets. + * + * @return array + */ + public static function getWidgets() + { + return self::$_widgets; + } + /** * Get all slow widgets. * @@ -80,7 +102,7 @@ class Debug */ public static function getSlowWidgets() { - return self::$_slow_triggers; + return self::$_slow_widgets; } /** @@ -188,7 +210,7 @@ class Debug */ public static function addQuery($query) { - self::$_queries[] = (object)array( + $query_object = (object)array( 'type' => 'Query', 'time' => microtime(true), 'message' => $query['result'] === 'success' ? 'success' : $query['errstr'], @@ -202,36 +224,64 @@ class Debug 'method' => $query['called_method'], 'backtrace' => $query['backtrace'], ); + + self::$_queries[] = $query_object; + if ($query_object->query_time && $query_object->query_time >= config('debug.log_slow_queries')) + { + self::$_slow_queries[] = $query_object; + } } /** - * Add a slow query to the log. + * Add a trigger to the log. * * @return bool */ - public static function addSlowQuery() + public static function addTrigger($trigger) { + $trigger_object = (object)array( + 'type' => 'Trigger', + 'time' => microtime(true), + 'message' => null, + 'file' => null, + 'line' => null, + 'backtrace' => array(), + 'trigger_name' => $trigger['name'], + 'trigger_target' => $trigger['target'], + 'trigger_plugin' => $trigger['target_plugin'], + 'trigger_time' => $trigger['elapsed_time'], + ); + self::$_triggers[] = $trigger_object; + if ($trigger_object->trigger_time && $trigger_object->trigger_time >= config('debug.log_slow_triggers')) + { + self::$_slow_triggers[] = $trigger_object; + } } /** - * Add a slow trigger to the log. + * Add a widget to the log. * * @return bool */ - public static function addSlowTrigger() - { - - } - - /** - * Add a slow widget to the log. - * - * @return bool - */ - public static function addSlowWidget() + public static function addWidget($widget) { + $widget_object = (object)array( + 'type' => 'Widget', + 'time' => microtime(true), + 'message' => null, + 'file' => null, + 'line' => null, + 'backtrace' => array(), + 'widget_name' => $widget['name'], + 'widget_time' => $widget['elapsed_time'], + ); + self::$_widgets[] = $widget_object; + if ($widget_object->widget_time && $widget_object->widget_time >= config('debug.log_slow_widgets')) + { + self::$_slow_widgets[] = $widget_object; + } } /** @@ -240,7 +290,7 @@ class Debug * @param Exception $e * @return void */ - public static function exceptionHandler(\Exception $e) + public static function exceptionHandler($e) { // Find out the file where the error really occurred. $errfile = self::translateFilename($e->getFile()); diff --git a/common/legacy.php b/common/legacy.php index 908f7262b..b53f2285b 100644 --- a/common/legacy.php +++ b/common/legacy.php @@ -712,67 +712,7 @@ function debugPrint($entry = null) */ function writeSlowlog($type, $elapsed_time, $obj) { - static $config = null; - if (!$config) - { - $config = config('debug'); - } - if (!Rhymix\Framework\Debug::isEnabledForCurrentUser()) - { - return; - } - if (!$config['log_slow_queries'] && !$config['log_slow_triggers'] && !$config['log_slow_widgets']) - { - return; - } - - static $log_filename = array( - 'query' => 'files/_slowlog_query.php', - 'trigger' => 'files/_slowlog_trigger.php', - 'widget' => 'files/_slowlog_widget.php' - ); - $log_file = RX_BASEDIR . $log_filename[$type]; - $write_file = true; - - $buff = array(); - $buff[] = ''; - $buff[] = date('c'); - - if ($type == 'query' && $config['log_slow_queries'] > 0 && $elapsed_time > $config['log_slow_queries']) - { - $buff[] = $obj->query; - $buff[] = "\tQuery ID : " . $obj->query_id; - $buff[] = "\tCaller : " . $obj->caller; - $buff[] = "\tConnection : " . $obj->connection; - } - elseif ($type == 'trigger' && $config['log_slow_triggers'] > 0 && $elapsed_time > $config['log_slow_triggers']) - { - $buff[] = "\tCaller : " . $obj->caller; - $buff[] = "\tCalled : " . $obj->called; - } - elseif ($type == 'widget' && $config['log_slow_widgets'] > 0 && $elapsed_time > $config['log_slow_widgets']) - { - $buff[] = "\tWidget : " . $obj->called; - } - else - { - $write_file = false; - } - - if($write_file) - { - $buff[] = sprintf("\t%0.6f sec", $elapsed_time); - $buff[] = PHP_EOL . PHP_EOL; - file_put_contents($log_file, implode(PHP_EOL, $buff), FILE_APPEND); - } - - if($type != 'query') - { - $trigger_args = $obj; - $trigger_args->_log_type = $type; - $trigger_args->_elapsed_time = $elapsed_time; - ModuleHandler::triggerCall('XE.writeSlowlog', 'after', $trigger_args); - } + // no-op } /** @@ -780,10 +720,7 @@ function writeSlowlog($type, $elapsed_time, $obj) */ function flushSlowlog() { - $trigger_args = new stdClass(); - $trigger_args->_log_type = 'flush'; - $trigger_args->_elapsed_time = 0; - ModuleHandler::triggerCall('XE.writeSlowlog', 'after', $trigger_args); + // no-op } /** diff --git a/modules/addon/addon.controller.php b/modules/addon/addon.controller.php index 241d10534..d647f62a2 100644 --- a/modules/addon/addon.controller.php +++ b/modules/addon/addon.controller.php @@ -34,8 +34,8 @@ class addonController extends addon $site_module_info = Context::get('site_module_info'); $site_srl = $site_module_info->site_srl; - $addon_path = _XE_PATH_ . 'files/cache/addons/'; - $addon_file = $addon_path . $site_srl . $type . '.acivated_addons.cache.php'; + $addon_path = RX_BASEDIR . 'files/cache/addons/'; + $addon_file = $addon_path . 'addons.' . intval($site_srl) . '.' . $type . '.php'; if($this->addon_file_called) { @@ -46,7 +46,7 @@ class addonController extends addon FileHandler::makeDir($addon_path); - if(!file_exists($addon_file)) + if(!file_exists($addon_file) || filemtime($addon_file) < filemtime(__FILE__)) { $this->makeCacheFile($site_srl, $type); } @@ -88,57 +88,78 @@ class addonController extends addon || ($type == "pc" && $val->is_used != 'Y') || ($type == "mobile" && $val->is_used_m != 'Y') || ($gtype == 'global' && $val->is_fixed != 'Y') - || !is_dir(_XE_PATH_ . 'addons/' . $addon)) + || !is_dir(RX_BASEDIR . 'addons/' . $addon)) { continue; } - + $extra_vars = unserialize($val->extra_vars); + if(!$extra_vars) + { + $extra_vars = new stdClass; + } + $mid_list = $extra_vars->mid_list; - if(!is_array($mid_list) || count($mid_list) < 1) + if(!is_array($mid_list)) { - $mid_list = NULL; + $mid_list = array(); } - + + // Initialize $buff[] = '$before_time = microtime(true);'; - $buff[] = '$rm = \'' . $extra_vars->xe_run_method . "';"; - $buff[] = '$ml = array('; - if($mid_list) + + // Run method and mid list + $run_method = $extra_vars->xe_run_method ?: 'run_selected'; + $buff[] = '$rm = \'' . $run_method . "';"; + $buff[] = '$ml = ' . var_export(array_fill_keys($mid_list, true), true) . ';'; + + // Addon filename + $buff[] = sprintf('$addon_file = RX_BASEDIR . \'addons/%s/%s.addon.php\';', $addon, $addon); + + // Addon configuration + $buff[] = '$addon_info = unserialize(' . var_export(serialize($extra_vars), true) . ');'; + + // Decide whether to run in this mid + if ($run_method === 'no_run_selected') { - foreach($mid_list as $mid) - { - $buff[] = "'$mid' => 1,"; - } + $buff[] = '$run = !isset($ml[$_m]);'; } - $buff[] = ');'; - $buff[] = sprintf('$addon_file = \'./addons/%s/%s.addon.php\';', $addon, $addon); - - if($val->extra_vars) + elseif (!count($mid_list)) { - unset($extra_vars); - $extra_vars = base64_encode($val->extra_vars); + $buff[] = '$run = true;'; } - $addon_include = sprintf('unset($addon_info); $addon_info = unserialize(base64_decode(\'%s\')); @include($addon_file);', $extra_vars); - - $buff[] = 'if(file_exists($addon_file)){'; - $buff[] = 'if($rm === \'no_run_selected\'){'; - $buff[] = 'if(!isset($ml[$_m])){'; - $buff[] = $addon_include; - $buff[] = '}}else{'; - $buff[] = 'if(isset($ml[$_m]) || count($ml) === 0){'; - $buff[] = $addon_include; - $buff[] = '}}}'; - $buff[] = '$after_time = microtime(true);'; - $buff[] = '$addon_time_log = new stdClass();'; - $buff[] = '$addon_time_log->caller = $called_position;'; - $buff[] = '$addon_time_log->called = "' . $addon . '";'; - $buff[] = '$addon_time_log->called_extension = "' . $addon . '";'; - $buff[] = 'writeSlowlog("addon",$after_time-$before_time,$addon_time_log);'; + else + { + $buff[] = '$run = isset($ml[$_m]);'; + } + + // Write debug info + $buff[] = 'if ($run && file_exists($addon_file)):'; + $buff[] = ' include($addon_file);'; + $buff[] = ' $after_time = microtime(true);'; + $buff[] = ' if (class_exists("Rhymix\\\\Framework\\\\Debug")):'; + $buff[] = ' Rhymix\\Framework\\Debug::addTrigger(array('; + $buff[] = ' "name" => "addon." . $called_position,'; + $buff[] = ' "target" => "' . $addon . '",'; + $buff[] = ' "target_plugin" => "' . $addon . '",'; + $buff[] = ' "elapsed_time" => $after_time - $before_time,'; + $buff[] = ' ));'; + $buff[] = ' endif;'; + $buff[] = 'endif;'; + $buff[] = ''; } - $addon_path = _XE_PATH_ . 'files/cache/addons/'; - FileHandler::makeDir($addon_path); - $addon_file = $addon_path . ($gtype == 'site' ? $site_srl : '') . $type . '.acivated_addons.cache.php'; + + // Write file in new location + $addon_path = RX_BASEDIR . 'files/cache/addons/'; + $addon_file = $addon_path . 'addons.' . ($gtype == 'site' ? intval($site_srl) : 'G') . '.' . $type . '.php'; FileHandler::writeFile($addon_file, join(PHP_EOL, $buff)); + + // Remove file from old location + $old_addon_file = $addon_path . ($gtype == 'site' ? $site_srl : '') . $type . '.acivated_addons.cache.php'; + if (file_exists($old_addon_file)) + { + FileHandler::removeFile($old_addon_file); + } } /** @@ -176,12 +197,17 @@ class addonController extends addon */ function removeAddonConfig($site_srl) { - $addon_path = _XE_PATH_ . 'files/cache/addons/'; - $addon_file = $addon_path . $site_srl . '.acivated_addons.cache.php'; + $addon_path = RX_BASEDIR . 'files/cache/addons/'; + $addon_file = $addon_path . 'addons.' . intval($site_srl) . '.' . $type . '.php'; if(file_exists($addon_file)) { FileHandler::removeFile($addon_file); } + $old_addon_file = $addon_path . ($gtype == 'site' ? $site_srl : '') . $type . '.acivated_addons.cache.php'; + if (file_exists($old_addon_file)) + { + FileHandler::removeFile($old_addon_file); + } $args = new stdClass(); $args->site_srl = $site_srl; diff --git a/modules/widget/widget.controller.php b/modules/widget/widget.controller.php index f13141365..1cd42c78c 100644 --- a/modules/widget/widget.controller.php +++ b/modules/widget/widget.controller.php @@ -644,11 +644,10 @@ class widgetController extends widget // Debug widget creation time information added to the results $elapsed_time = microtime(true) - $start; $GLOBALS['__widget_excute_elapsed__'] += $elapsed_time; - $slowlog = new stdClass; - $slowlog->caller = "widget.execute"; - $slowlog->called = $widget; - $slowlog->called_extension = $widget; - writeSlowlog('widget', $elapsed_time, $slowlog); + Rhymix\Framework\Debug::addWidget(array( + 'name' => $widget, + 'elapsed_time' => $elapsed_time, + )); // Return result return $output;