Skip to content

Commit

Permalink
feature(profiler): allow capture/display of crude profiling data
Browse files Browse the repository at this point in the history
Via `$CONFIG` options, sites can enable the display of profiling data in
the console. Data is available as a tree or a flattened list sorted by
duration.

Refs Elgg#9293
  • Loading branch information
mrclay committed Jan 29, 2016
1 parent 9928c45 commit c01dcc9
Show file tree
Hide file tree
Showing 14 changed files with 271 additions and 5 deletions.
17 changes: 17 additions & 0 deletions elgg-config/settings.example.php
Expand Up @@ -216,3 +216,20 @@
* @global string $CONFIG->exception_include
*/
$CONFIG->exception_include = '';

/**
* To enable profiling, uncomment the following lines, and replace __some_secret__ with a
* secret key. When enabled, profiling data will show in the JS console.
*/
//if (isset($_REQUEST['__some_secret__'])) {
//
// // send profiling data to the JS console?
// $CONFIG->enable_profiling = true;
//
// // profile all queries? A page with a ton of queries could eat up memory.
// $CONFIG->profiling_sql = false;
//
// // in the list, don't include times that don't contribute at least this much to the
// // total time captured. .1% by default
// $CONFIG->profiling_minimum_percentage = .1;
//}
4 changes: 4 additions & 0 deletions engine/classes/Elgg/Application.php
Expand Up @@ -71,6 +71,10 @@ public function __construct(ServiceProvider $services) {
$GLOBALS['START_MICROTIME'] = microtime(true);
}

if (!isset($GLOBALS['_ELGG_MICROTIMES'])) {
$GLOBALS['_ELGG_MICROTIMES'][':begin'] = microtime();
}

/**
* This was introduced in 2.0 in order to remove all internal non-API state from $CONFIG. This will
* be a breaking change, but frees us to refactor in 2.x without fear of plugins depending on
Expand Down
4 changes: 4 additions & 0 deletions engine/classes/Elgg/Cache/SystemCache.php
Expand Up @@ -134,6 +134,8 @@ function disable() {
* @access private
*/
function loadAll() {
$GLOBALS['_ELGG_MICROTIMES'][__METHOD__][':begin'] = microtime();

$this->CONFIG->system_cache_loaded = false;

if (!_elgg_services()->views->configureFromCache($this)) {
Expand All @@ -149,6 +151,8 @@ function loadAll() {
// Note: We don't need view_overrides for operation. Inspector can pull this from the cache

$this->CONFIG->system_cache_loaded = true;

$GLOBALS['_ELGG_MICROTIMES'][__METHOD__][':end'] = microtime();
}

/**
Expand Down
14 changes: 13 additions & 1 deletion engine/classes/Elgg/Database.php
Expand Up @@ -408,7 +408,19 @@ protected function executeQuery($query, Connection $connection) {
$this->queryCount++;

try {
return $connection->query($query);
// don't want to eat memory. need to opt-in to this by setting
// $GLOBALS['_ELGG_MICROTIMES']['SQL'] to empty array.
if (!isset($GLOBALS['_ELGG_MICROTIMES']['SQL'])) {
return $connection->query($query);
}

$timer_key = preg_replace('~\\s+~', ' ', trim($query));

$GLOBALS['_ELGG_MICROTIMES']['SQL'][$timer_key][':begin'] = microtime();
$value = $connection->query($query);
$GLOBALS['_ELGG_MICROTIMES']['SQL'][$timer_key][':end'] = microtime();

return $value;
} catch (\Exception $e) {
throw new \DatabaseException($e->getMessage() . "\n\n QUERY: $query");
}
Expand Down
4 changes: 4 additions & 0 deletions engine/classes/Elgg/Database/Plugins.php
Expand Up @@ -307,6 +307,8 @@ function isActive($plugin_id, $site_guid = null) {
* @access private
*/
function load() {
$GLOBALS['_ELGG_MICROTIMES'][__METHOD__][':begin'] = microtime();

$plugins_path = elgg_get_plugins_path();
$start_flags = ELGG_PLUGIN_INCLUDE_START |
ELGG_PLUGIN_REGISTER_VIEWS |
Expand Down Expand Up @@ -354,6 +356,8 @@ function load() {
}

$this->active_ids_known = true;

$GLOBALS['_ELGG_MICROTIMES'][__METHOD__][':end'] = microtime();
return $return;
}

Expand Down
3 changes: 3 additions & 0 deletions engine/classes/Elgg/Di/ServiceProvider.php
Expand Up @@ -134,6 +134,9 @@ public function __construct(\Elgg\Config $config) {
});

$this->setFactory('db', function(ServiceProvider $c) {
if ($c->config->getVolatile('profiling_sql')) {
$GLOBALS['_ELGG_MICROTIMES']['SQL'] = [];
}
$db_config = new \Elgg\Database\Config($c->config->getStorageObject());

// we inject the logger in _elgg_engine_boot()
Expand Down
18 changes: 16 additions & 2 deletions engine/classes/Elgg/EventsService.php
Expand Up @@ -25,6 +25,11 @@ class EventsService extends \Elgg\HooksRegistrationService {
* @access private
*/
public function trigger($event, $type, $object = null, array $options = array()) {
static $inspector;
if ($inspector === null) {
$inspector = new Inspector();
}

$options = array_merge(array(
self::OPTION_STOPPABLE => true,
self::OPTION_DEPRECATION_MESSAGE => '',
Expand All @@ -46,14 +51,23 @@ public function trigger($event, $type, $object = null, array $options = array())
foreach ($events as $callback) {
if (!is_callable($callback)) {
if ($this->logger) {
$inspector = new Inspector();
$this->logger->warn("handler for event [$event, $type] is not callable: "
. $inspector->describeCallable($callback));
}
continue;
}

$return = call_user_func_array($callback, $args);

if ($type === 'system' && $event !== 'shutdown') {
$callback_as_string = $inspector->describeCallable($callback) . "()";

$GLOBALS['_ELGG_MICROTIMES']["[$event,$type]"][$callback_as_string][':begin'] = microtime();
$return = call_user_func_array($callback, $args);
$GLOBALS['_ELGG_MICROTIMES']["[$event,$type]"][$callback_as_string][':end'] = microtime();
} else {
$return = call_user_func_array($callback, $args);
}

if (!empty($options[self::OPTION_STOPPABLE]) && ($return === false)) {
return false;
}
Expand Down
6 changes: 6 additions & 0 deletions engine/classes/Elgg/I18n/Translator.php
Expand Up @@ -182,6 +182,8 @@ function getLanguage() {
* @access private
*/
function loadTranslations($language = null) {
$GLOBALS['_ELGG_MICROTIMES'][__METHOD__][':begin'] = microtime();

if ($this->CONFIG->system_cache_enabled) {
$loaded = true;

Expand All @@ -204,6 +206,8 @@ function loadTranslations($language = null) {
$GLOBALS['_ELGG']->i18n_loaded_from_cache = true;
// this is here to force
$GLOBALS['_ELGG']->language_paths[$this->defaultPath] = true;

$GLOBALS['_ELGG_MICROTIMES'][__METHOD__][':end'] = microtime();
return;
}
}
Expand All @@ -217,6 +221,8 @@ function loadTranslations($language = null) {
if ($language) {
$this->loadPluginTranslations($language);
}

$GLOBALS['_ELGG_MICROTIMES'][__METHOD__][':end'] = microtime();
}

/**
Expand Down
171 changes: 171 additions & 0 deletions engine/classes/Elgg/Profiler.php
@@ -0,0 +1,171 @@
<?php
namespace Elgg;

/**
* Analyzes duration of functions, queries, and processes
*
* @access private
*/
class Profiler {

public $percentage_format = "%01.2f";
public $duration_format = "%01.6f";
public $minimum_percentage = 0.2;

private $total;

public function buildTree($times = null) {
if ($times === null) {
$times = $GLOBALS['_ELGG_MICROTIMES'];
}

if (!isset($times[':end'])) {
$times[':end'] = microtime();
}

$begin = $this->findBeginTime($times);
$end = $this->findEndTime($times);
$this->total = $this->diffMicrotime($begin, $end);

return $this->analyzePeriod('', $times);
}

public function flattenTree(array &$list = [], array $tree, $prefix = '') {
$is_root = empty($list);

if (isset($tree['periods'])) {
foreach ($tree['periods'] as $period) {
$this->flattenTree($list, $period, "{$prefix} {$period['name']}");
}
unset($tree['periods']);
}
$tree['name'] = trim($prefix);
$list[] = $tree;

if ($is_root) {
usort($list, function ($a, $b) {
if ($a['duration'] == $b['duration']) {
return 0;
}
return ($a['duration'] > $b['duration']) ? -1 : 1;
});
}
}

public function formatTree(array $tree) {
$tree['duration'] = sprintf($this->duration_format, $tree['duration']);
if (isset($tree['percentage'])) {
$tree['percentage'] = sprintf($this->percentage_format, $tree['percentage']);
}
if (isset($tree['periods'])) {
$tree['periods'] = array_map([$this, 'formatTree'], $tree['periods']);
}
return $tree;
}

public static function handlePageOutput($hook, $type, $html, $params) {
$profiler = new self();
$min_percentage = elgg_get_config('profiling_minimum_percentage');
if ($min_percentage !== null) {
$profiler->minimum_percentage = $min_percentage;
}

$tree = $profiler->buildTree();
$tree = $profiler->formatTree($tree);
$data['tree'] = $tree;
$data['total'] = $tree['duration'] . " seconds";

$list = [];
$profiler->flattenTree($list, $tree);

$list = array_map(function ($period) {
return "{$period['percentage']}% ({$period['duration']}) {$period['name']}";
}, $list);

$data['list'] = $list;

$html .= "<script>";
$html .= "console.log(" . json_encode($data) . ");";
$html .= "</script>";
return $html;
}

private function analyzePeriod($name, array $times) {
$begin = $this->findBeginTime($times);
$end = $this->findEndTime($times);
if ($begin === false || $end === false) {
return false;
}
unset($times[':begin'], $times[':end']);

$total = $this->diffMicrotime($begin, $end);
$ret = [
'name' => $name,
'percentage' => 100, // may be overwritten by parent
'duration' => $total,
];

foreach ($times as $times_key => $period) {
$period = $this->analyzePeriod($times_key, $period);
if ($period === false) {
continue;
}
$period['percentage'] = 100 * $period['duration'] / $this->total;
if ($period['percentage'] < $this->minimum_percentage) {
continue;
}
$ret['periods'][] = $period;
}

if (isset($ret['periods'])) {
usort($ret['periods'], function ($a, $b) {
if ($a['duration'] == $b['duration']) {
return 0;
}
return ($a['duration'] > $b['duration']) ? -1 : 1;
});
}

return $ret;
}

private function findBeginTime(array $times) {
if (isset($times[':begin'])) {
return $times[':begin'];
}
unset($times[':begin'], $times[':end']);
$first = reset($times);
if (is_array($first)) {
return $this->findBeginTime($first);
}
return false;
}

private function findEndTime(array $times) {
if (isset($times[':end'])) {
return $times[':end'];
}
unset($times[':begin'], $times[':end']);
$last = end($times);
if (is_array($last)) {
return $this->findEndTime($last);
}
return false;
}

/**
* Calculate a precise time difference.
*
* @param string $start result of microtime()
* @param string $end result of microtime()
*
* @return float difference in seconds, calculated with minimum precision loss
*/
private function diffMicrotime($start, $end) {
list($start_usec, $start_sec) = explode(" ", $start);
list($end_usec, $end_sec) = explode(" ", $end);
$diff_sec = (int)$end_sec - (int)$start_sec;
$diff_usec = (float)$end_usec - (float)$start_usec;
return (float)$diff_sec + $diff_usec;
}
}
3 changes: 3 additions & 0 deletions engine/classes/Elgg/Router.php
Expand Up @@ -61,6 +61,9 @@ public function route(\Elgg\Http\Request $request) {
'handler' => $identifier, // backward compatibility
'segments' => $segments,
);

$GLOBALS['_ELGG_MICROTIMES']['build page'][':begin'] = microtime();

$result = $this->hooks->trigger('route', $identifier, $result, $result);
if ($result === false) {
return true;
Expand Down
8 changes: 8 additions & 0 deletions engine/lib/configuration.php
Expand Up @@ -262,6 +262,8 @@ function get_config($name, $site_guid = 0) {
* @access private
*/
function _elgg_load_site_config() {
$GLOBALS['_ELGG_MICROTIMES'][__FUNCTION__][':begin'] = microtime();

global $CONFIG;

$CONFIG->site_guid = (int) datalist_get('default_site');
Expand All @@ -286,6 +288,8 @@ function _elgg_load_site_config() {
_elgg_services()->logger->setLevel($CONFIG->debug);
_elgg_services()->logger->setDisplay(true);
}

$GLOBALS['_ELGG_MICROTIMES'][__FUNCTION__][':end'] = microtime();
}

/**
Expand Down Expand Up @@ -325,6 +329,8 @@ function _elgg_configure_cookies($CONFIG) {
* @access private
*/
function _elgg_load_application_config() {
$GLOBALS['_ELGG_MICROTIMES'][__FUNCTION__][':begin'] = microtime();

global $CONFIG;

$install_root = Directory\Local::root();
Expand Down Expand Up @@ -371,6 +377,8 @@ function _elgg_load_application_config() {

// this must be synced with the enum for the entities table
$CONFIG->entity_types = array('group', 'object', 'site', 'user');

$GLOBALS['_ELGG_MICROTIMES'][__FUNCTION__][':end'] = microtime();
}

/**
Expand Down
4 changes: 4 additions & 0 deletions engine/lib/elgglib.php
Expand Up @@ -1990,6 +1990,10 @@ function _elgg_init() {

return $result;
});

if (_elgg_services()->config->getVolatile('enable_profiling')) {
elgg_register_plugin_hook_handler('output', 'page', [\Elgg\Profiler::class, 'handlePageOutput'], 999);
}
}

/**
Expand Down

0 comments on commit c01dcc9

Please sign in to comment.