Add slow remote requests to debug content

This commit is contained in:
Kijin Sung 2016-06-08 16:15:32 +09:00
parent 1f86ae7883
commit 2d54687a52
11 changed files with 148 additions and 1 deletions

View file

@ -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)

View file

@ -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))
{

View file

@ -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(),

View file

@ -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)
{

View file

@ -173,6 +173,22 @@ $(function() {
}
}
// Add slow remote requests.
if (data.slow_remote_requests && data.slow_remote_requests.length) {
page_body.append($('<h4></h4>').text('Slow Remote Requests (' + data.slow_remote_requests.length + ')'));
for (i in data.slow_remote_requests) {
entry = $('<div class="debug_entry"></div>').appendTo(page_body);
num = parseInt(i) + 1; if (num < 10) num = "0" + num;
entry.text(num + ". " + data.slow_remote_requests[i].url);
description = $('<ul class="debug_backtrace"></ul>').appendTo(entry);
if (data.slow_remote_requests[i].file && data.slow_remote_requests[i].line) {
description.append($('<li></li>').text("Caller: " + data.slow_remote_requests[i].file + ":" + data.slow_remote_requests[i].line).append("<br>(" + data.slow_remote_requests[i].method + ")"));
description.append($('<li></li>').text("Elapsed Time: " + (data.slow_remote_requests[i].elapsed_time ? (data.slow_remote_requests[i].elapsed_time.toFixed(4) + " sec") : "")));
}
description.append($('<li></li>').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");

View file

@ -21,6 +21,7 @@ DB Query Time: <?php echo $data->timing->db_query . "\n"; ?>
DB Processing Time: <?php echo $data->timing->db_class . "\n"; ?>
Layout Processing Time: <?php echo $data->timing->layout . "\n"; ?>
Widget Processing Time: <?php echo $data->timing->widget . "\n"; ?>
Remote Request Time: <?php echo $data->timing->remote . "\n"; ?>
Content Transform Time: <?php echo $data->timing->trans . "\n"; ?>
Resource Usage
@ -157,3 +158,23 @@ Slow Widgets
}
?>
<?php endif; ?>
<?php if (!count($display_content) || isset($display_content['slow_remote_requests'])): ?>
Slow Remote Requests
====================
<?php
$request_count = 0;
if (!count($data->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";
}
?>
<?php endif; ?>

View file

@ -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');

View file

@ -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'));

View file

@ -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';

View file

@ -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의 방문자에게만 표시';

View file

@ -35,6 +35,13 @@
&nbsp;{$lang->debug_seconds}
</div>
</div>
<div class="x_control-group">
<label class="x_control-label" for="debug_log_slow_remote_requests">{$lang->debug_log_slow_remote_requests}</label>
<div class="x_controls">
<input type="text" name="debug_log_slow_remote_requests" id="debug_log_slow_remote_requests" size="5" value="{$debug_log_slow_remote_requests}" style="width:60px" />
&nbsp;{$lang->debug_seconds}
</div>
</div>
<div class="x_control-group">
<label class="x_control-label" for="debug_log_slow_widgets">{$lang->debug_display_type}</label>
<div class="x_controls">
@ -53,6 +60,7 @@
<label for="debug_display_content_slow_queries" class="x_inline"><input type="checkbox" name="debug_display_content[]" id="debug_display_content_slow_queries" value="slow_queries" checked="checked"|cond="!count($debug_display_content) || in_array('slow_queries', $debug_display_content)" /> {$lang->debug_display_content_slow_queries}</label>
<label for="debug_display_content_slow_triggers" class="x_inline"><input type="checkbox" name="debug_display_content[]" id="debug_display_content_slow_triggers" value="slow_triggers" checked="checked"|cond="!count($debug_display_content) || in_array('slow_triggers', $debug_display_content)" /> {$lang->debug_display_content_slow_triggers}</label>
<label for="debug_display_content_slow_widgets" class="x_inline"><input type="checkbox" name="debug_display_content[]" id="debug_display_content_slow_widgets" value="slow_widgets" checked="checked"|cond="!count($debug_display_content) || in_array('slow_widgets', $debug_display_content)" /> {$lang->debug_display_content_slow_widgets}</label>
<label for="debug_display_content_slow_remote_requests" class="x_inline"><input type="checkbox" name="debug_display_content[]" id="debug_display_content_slow_remote_requests" value="slow_remote_requests" checked="checked"|cond="!count($debug_display_content) || in_array('slow_remote_requests', $debug_display_content)" /> {$lang->debug_display_content_slow_remote_requests}</label>
</div>
</div>
<div class="x_control-group">