diff --git a/classes/display/DisplayHandler.class.php b/classes/display/DisplayHandler.class.php index bffe15e19..32410803e 100644 --- a/classes/display/DisplayHandler.class.php +++ b/classes/display/DisplayHandler.class.php @@ -189,6 +189,10 @@ class DisplayHandler extends Handler { unset($data->slow_widgets); } + if (count($display_content) && !isset($display_content['slow_remote_requests'])) + { + unset($data->slow_remote_requests); + } if ($data->entries) { foreach ($data->entries as &$entry) diff --git a/classes/file/FileHandler.class.php b/classes/file/FileHandler.class.php index f435a4e47..6698ce3ea 100644 --- a/classes/file/FileHandler.class.php +++ b/classes/file/FileHandler.class.php @@ -389,7 +389,39 @@ class FileHandler } $url = str_replace('&', '&', $url); + $start_time = microtime(true); $response = Requests::request($url, $request_headers, $body ?: $post_data, $method, $request_options); + $elapsed_time = microtime(true) - $start_time; + $GLOBALS['__remote_request_elapsed__'] += $elapsed_time; + + $log = array(); + $log['url'] = $url; + $log['status'] = $response ? $response->status_code : 0; + $log['elapsed_time'] = $elapsed_time; + + if (config('debug.enabled') && in_array('slow_remote_requests', config('debug.display_content'))) + { + $bt = defined('DEBUG_BACKTRACE_IGNORE_ARGS') ? debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS) : debug_backtrace(); + foreach($bt as $no => $call) + { + if(strncasecmp($call['function'], 'getRemote', 9) === 0) + { + $call_no = $no + 1; + $log['called_file'] = $bt[$call_no]['file']; + $log['called_line'] = $bt[$call_no]['line']; + $call_no++; + $log['called_method'] = $bt[$call_no]['class'].$bt[$call_no]['type'].$bt[$call_no]['function']; + $log['backtrace'] = array_slice($bt, $call_no, 1); + break; + } + } + } + else + { + $log['called_file'] = $log['called_line'] = $log['called_method'] = null; + $log['backtrace'] = array(); + } + Rhymix\Framework\Debug::addRemoteRequest($log); if(count($response->cookies)) { diff --git a/common/defaults/config.php b/common/defaults/config.php index 76eb59109..533aaaf4c 100644 --- a/common/defaults/config.php +++ b/common/defaults/config.php @@ -83,6 +83,7 @@ return array( 'log_slow_queries' => 0, 'log_slow_triggers' => 0, 'log_slow_widgets' => 0, + 'log_slow_remote_requests' => 0, 'log_filename' => null, 'display_type' => 'comment', 'display_content' => array(), diff --git a/common/framework/debug.php b/common/framework/debug.php index 75d96d523..9f77ee086 100644 --- a/common/framework/debug.php +++ b/common/framework/debug.php @@ -19,6 +19,8 @@ class Debug protected static $_slow_triggers = array(); protected static $_widgets = array(); protected static $_slow_widgets = array(); + protected static $_remote_requests = array(); + protected static $_slow_remote_requests = array(); /** * Also write to error log. @@ -105,6 +107,26 @@ class Debug return self::$_slow_widgets; } + /** + * Get all remote requests. + * + * @return array + */ + public static function getRemoteRequests() + { + return self::$_remote_requests; + } + + /** + * Get all slow remote requests. + * + * @return array + */ + public static function getSlowRemoteRequests() + { + return self::$_slow_remote_requests; + } + /** * Add a filename alias. * @@ -284,6 +306,33 @@ class Debug } } + /** + * Add a remote request to the log. + * + * @return bool + */ + public static function addRemoteRequest($request) + { + $request_object = (object)array( + 'type' => 'Remote Request', + 'time' => microtime(true), + 'message' => null, + 'url' => $request['url'], + 'status' => $request['status'], + 'file' => $request['called_file'], + 'line' => $request['called_line'], + 'method' => $request['called_method'], + 'backtrace' => $request['backtrace'], + 'elapsed_time' => $request['elapsed_time'], + ); + + self::$_remote_requests[] = $request_object; + if ($request_object->elapsed_time && $request_object->elapsed_time >= config('debug.log_slow_remote_requests')) + { + self::$_slow_remote_requests[] = $request_object; + } + } + /** * The default handler for catching exceptions. * @@ -504,6 +553,7 @@ class Debug 'db_class' => sprintf('%0.4f sec', $GLOBALS['__dbclass_elapsed_time__'] - $GLOBALS['__db_elapsed_time__']), 'layout' => sprintf('%0.4f sec', $GLOBALS['__layout_compile_elapsed__']), 'widget' => sprintf('%0.4f sec', $GLOBALS['__widget_excute_elapsed__']), + 'remote' => sprintf('%0.4f sec', $GLOBALS['__remote_request_elapsed__']), 'trans' => sprintf('%0.4f sec', $GLOBALS['__trans_content_elapsed__']), ), 'entries' => self::$_entries, @@ -512,10 +562,11 @@ class Debug 'slow_queries' => self::$_slow_queries, 'slow_triggers' => self::$_slow_triggers, 'slow_widgets' => self::$_slow_widgets, + 'slow_remote_requests' => self::$_slow_remote_requests, ); // Clean up the backtrace. - foreach (array('entries', 'errors', 'queries', 'slow_queries') as $key) + foreach (array('entries', 'errors', 'queries', 'slow_queries', 'remote_requests', 'slow_remote_requests') as $key) { if (!$data->$key) { diff --git a/common/js/debug.js b/common/js/debug.js index 5b1fef0e4..6798b9c71 100644 --- a/common/js/debug.js +++ b/common/js/debug.js @@ -173,6 +173,22 @@ $(function() { } } + // Add slow remote requests. + if (data.slow_remote_requests && data.slow_remote_requests.length) { + page_body.append($('

').text('Slow Remote Requests (' + data.slow_remote_requests.length + ')')); + for (i in data.slow_remote_requests) { + entry = $('
').appendTo(page_body); + num = parseInt(i) + 1; if (num < 10) num = "0" + num; + entry.text(num + ". " + data.slow_remote_requests[i].url); + description = $('').appendTo(entry); + if (data.slow_remote_requests[i].file && data.slow_remote_requests[i].line) { + description.append($('
  • ').text("Caller: " + data.slow_remote_requests[i].file + ":" + data.slow_remote_requests[i].line).append("
    (" + data.slow_remote_requests[i].method + ")")); + description.append($('
  • ').text("Elapsed Time: " + (data.slow_remote_requests[i].elapsed_time ? (data.slow_remote_requests[i].elapsed_time.toFixed(4) + " sec") : ""))); + } + description.append($('
  • ').text("Status Code: " + data.slow_remote_requests[i].status)); + } + } + // If there are errors, turn the button text red. if (data.errors && data.errors.length) { button_link.addClass("has_errors"); diff --git a/common/tpl/debug_comment.html b/common/tpl/debug_comment.html index 3e9741aee..e3213c2ba 100644 --- a/common/tpl/debug_comment.html +++ b/common/tpl/debug_comment.html @@ -21,6 +21,7 @@ DB Query Time: timing->db_query . "\n"; ?> DB Processing Time: timing->db_class . "\n"; ?> Layout Processing Time: timing->layout . "\n"; ?> Widget Processing Time: timing->widget . "\n"; ?> +Remote Request Time: timing->remote . "\n"; ?> Content Transform Time: timing->trans . "\n"; ?> Resource Usage @@ -157,3 +158,23 @@ Slow Widgets } ?> + + +Slow Remote Requests +==================== +slow_remote_requests)) + { + echo 'None'. "\n"; + } + foreach ($data->slow_remote_requests as $request) + { + $request_caller = sprintf('%s line %d (%s)', $request->file, $request->line, $request->method); + echo sprintf('%02d. %s', ++$request_count, $request->url) . "\n"; + echo sprintf(' - Caller: %s', $request_caller) . "\n"; + echo sprintf(' - Elapsed Time: %0.4f sec', $request->elapsed_time) . "\n"; + echo sprintf(' - Status Code: %d', $request->status) . "\n"; + } +?> + diff --git a/modules/admin/admin.admin.controller.php b/modules/admin/admin.admin.controller.php index 8bbbd3467..a4006bdee 100644 --- a/modules/admin/admin.admin.controller.php +++ b/modules/admin/admin.admin.controller.php @@ -734,6 +734,7 @@ class adminAdminController extends admin Rhymix\Framework\Config::set('debug.log_slow_queries', max(0, floatval($vars->debug_log_slow_queries))); Rhymix\Framework\Config::set('debug.log_slow_triggers', max(0, floatval($vars->debug_log_slow_triggers))); Rhymix\Framework\Config::set('debug.log_slow_widgets', max(0, floatval($vars->debug_log_slow_widgets))); + Rhymix\Framework\Config::set('debug.log_slow_remote_requests', max(0, floatval($vars->debug_log_slow_remote_requests))); Rhymix\Framework\Config::set('debug.display_type', strval($vars->debug_display_type) ?: 'comment'); Rhymix\Framework\Config::set('debug.display_to', strval($vars->debug_display_to) ?: 'admin'); diff --git a/modules/admin/admin.admin.view.php b/modules/admin/admin.admin.view.php index 74e1e6d02..b9b91b764 100644 --- a/modules/admin/admin.admin.view.php +++ b/modules/admin/admin.admin.view.php @@ -554,6 +554,7 @@ class adminAdminView extends admin Context::set('debug_log_slow_queries', Rhymix\Framework\Config::get('debug.log_slow_queries')); Context::set('debug_log_slow_triggers', Rhymix\Framework\Config::get('debug.log_slow_triggers')); Context::set('debug_log_slow_widgets', Rhymix\Framework\Config::get('debug.log_slow_widgets')); + Context::set('debug_log_slow_remote_requests', Rhymix\Framework\Config::get('debug.log_slow_remote_requests')); Context::set('debug_log_filename', Rhymix\Framework\Config::get('debug.log_filename') ?: 'files/debug/YYYYMMDD.php'); Context::set('debug_display_type', Rhymix\Framework\Config::get('debug.display_type')); Context::set('debug_display_content', Rhymix\Framework\Config::get('debug.display_content')); diff --git a/modules/admin/lang/en.php b/modules/admin/lang/en.php index c548c4a8c..fcafa0fa9 100644 --- a/modules/admin/lang/en.php +++ b/modules/admin/lang/en.php @@ -139,11 +139,21 @@ $lang->debug_log_queries = 'Log Queries'; $lang->debug_log_slow_queries = 'Log Slow Queries'; $lang->debug_log_slow_triggers = 'Log Slow Triggers'; $lang->debug_log_slow_widgets = 'Log Slow Widgets'; +$lang->debug_log_slow_remote_requests = 'Log Slow Remote Requests'; $lang->debug_seconds = 'seconds or longer'; $lang->debug_display_type = 'Display Debug Info As'; $lang->debug_display_type_comment = 'HTML source comment'; $lang->debug_display_type_panel = 'On-screen panel'; $lang->debug_display_type_file = 'Write to file'; +$lang->debug_display_content = 'Display Debug Content'; +$lang->debug_display_content_request_info = 'Request/Response information'; +$lang->debug_display_content_entries = 'Debug messages'; +$lang->debug_display_content_errors = 'Errors'; +$lang->debug_display_content_queries = 'Queries'; +$lang->debug_display_content_slow_queries = 'Slow queries'; +$lang->debug_display_content_slow_triggers = 'Slow triggers'; +$lang->debug_display_content_slow_widgets = 'Slow widgets'; +$lang->debug_display_content_slow_remote_requests = 'Slow remote requests'; $lang->debug_display_to = 'Display Debug Info To'; $lang->debug_display_to_admin = 'Administrator only'; $lang->debug_display_to_ip = 'Visitors from IP adresses listed below'; diff --git a/modules/admin/lang/ko.php b/modules/admin/lang/ko.php index d7c602e5a..e236e0dce 100644 --- a/modules/admin/lang/ko.php +++ b/modules/admin/lang/ko.php @@ -134,6 +134,7 @@ $lang->debug_enabled = '디버그 기능 사용'; $lang->debug_log_slow_queries = '느린 쿼리 기록'; $lang->debug_log_slow_triggers = '느린 트리거 기록'; $lang->debug_log_slow_widgets = '느린 위젯 기록'; +$lang->debug_log_slow_remote_requests = '느린 외부 요청 기록'; $lang->debug_seconds = '초 이상 소요시 기록'; $lang->debug_display_type = '디버그 정보 표시 방법'; $lang->debug_display_type_comment = 'HTML 소스에 표시 (주석)'; @@ -147,6 +148,7 @@ $lang->debug_display_content_queries = '쿼리'; $lang->debug_display_content_slow_queries = '느린 쿼리'; $lang->debug_display_content_slow_triggers = '느린 트리거'; $lang->debug_display_content_slow_widgets = '느린 위젯'; +$lang->debug_display_content_slow_remote_requests = '느린 외부 요청'; $lang->debug_display_to = '디버그 정보 표시 대상'; $lang->debug_display_to_admin = '관리자에게만 표시'; $lang->debug_display_to_ip = '아래 IP의 방문자에게만 표시'; diff --git a/modules/admin/tpl/config_debug.html b/modules/admin/tpl/config_debug.html index 7a9e68969..7ca92e55b 100644 --- a/modules/admin/tpl/config_debug.html +++ b/modules/admin/tpl/config_debug.html @@ -35,6 +35,13 @@  {$lang->debug_seconds} +
    + +
    + +  {$lang->debug_seconds} +
    +
    @@ -53,6 +60,7 @@ +