feature(profiler): allow capture/display of crude profiling data

Via `$CONFIG` options, sites can enable the display of profiling data in
the JavaScript console. Data is available as a tree or a flattened list
sorted by duration. Times available:

- each callable in system events (e.g. `file_init` and `aalborg_theme_pagesetup`)
- total time to run start.php for all plugins
- from routing to `elgg_view_page` ("how long to generate the body of the page")
- `elgg_view_page`
- `elgg_view_layout`
- various boot functions
- (optional) timing each query

Fixes #9293

elgg-config/settings.example.php

@@ -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;
+//}

engine/classes/Elgg/Application.php

@@ -71,6 +71,8 @@ public function __construct(ServiceProvider $services) {
 			$GLOBALS['START_MICROTIME'] = microtime(true);
 		}
 
+		$services->timer->begin([]);
+
 		/**
 		 * 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

engine/classes/Elgg/Cache/SystemCache.php

@@ -1,6 +1,8 @@
 <?php
 namespace Elgg\Cache;
 
+use Elgg\Profilable;
+
 /**
  * WARNING: API IN FLUX. DO NOT USE DIRECTLY.
  *
@@ -11,6 +13,8 @@
  * @since      1.10.0
  */
 class SystemCache {
+	use Profilable;
+
 	/**
 	 * Global Elgg configuration
 	 * 
@@ -134,6 +138,10 @@ function disable() {
 	 * @access private
 	 */
 	function loadAll() {
+		if ($this->timer) {
+			$this->timer->begin([__METHOD__]);
+		}
+
 		$this->CONFIG->system_cache_loaded = false;
 
 		if (!_elgg_services()->views->configureFromCache($this)) {
@@ -149,6 +157,10 @@ function loadAll() {
 		// Note: We don't need view_overrides for operation. Inspector can pull this from the cache
 
 		$this->CONFIG->system_cache_loaded = true;
+
+		if ($this->timer) {
+			$this->timer->end([__METHOD__]);
+		}
 	}
 
 	/**

engine/classes/Elgg/Database.php

@@ -17,6 +17,7 @@
  * @subpackage Database
  */
 class Database {
+	use Profilable;
 
 	const DELAYED_QUERY = 'q';
 	const DELAYED_TYPE = 't';
@@ -408,7 +409,17 @@ protected function executeQuery($query, Connection $connection) {
 		$this->queryCount++;
 
 		try {
-			return $connection->query($query);
+			if (!$this->timer) {
+				return $connection->query($query);
+			}
+
+			$timer_key = preg_replace('~\\s+~', ' ', trim($query));
+
+			$this->timer->begin(['SQL', $timer_key]);
+			$value = $connection->query($query);
+			$this->timer->end(['SQL', $timer_key]);
+
+			return $value;
 		} catch (\Exception $e) {
 			throw new \DatabaseException($e->getMessage() . "\n\n QUERY: $query");
 		}

engine/classes/Elgg/Database/Plugins.php

@@ -2,6 +2,7 @@
 namespace Elgg\Database;
 
 use Elgg\Cache\Pool;
+use Elgg\Profilable;
 use Exception;
 
 /**
@@ -21,6 +22,7 @@
  * @since 1.10.0
  */
 class Plugins {
+	use Profilable;
 
 	/**
 	 * @var string[] Active plugin IDs with IDs as the array keys. Missing keys imply inactive plugins.
@@ -307,6 +309,10 @@ function isActive($plugin_id, $site_guid = null) {
 	 * @access private
 	 */
 	function load() {
+		if ($this->timer) {
+			$this->timer->begin([__METHOD__]);
+		}
+
 		$plugins_path = elgg_get_plugins_path();
 		$start_flags = ELGG_PLUGIN_INCLUDE_START |
 						ELGG_PLUGIN_REGISTER_VIEWS |
@@ -354,6 +360,11 @@ function load() {
 		}
 
 		$this->active_ids_known = true;
+
+		if ($this->timer) {
+			$this->timer->end([__METHOD__]);
+		}
+
 		return $return;
 	}
 

engine/classes/Elgg/Di/ServiceProvider.php

@@ -58,6 +58,7 @@
  * @property-read \Elgg\Database\SubtypeTable              $subtypeTable
  * @property-read \Elgg\Cache\SystemCache                  $systemCache
  * @property-read \Elgg\SystemMessagesService              $systemMessages
+ * @property-read \Elgg\Timer                              $timer
  * @property-read \Elgg\I18n\Translator                    $translator
  * @property-read \Elgg\UpgradeService                     $upgrades
  * @property-read \Elgg\Database\UsersTable                $usersTable
@@ -137,7 +138,13 @@ public function __construct(\Elgg\Config $config) {
 			$db_config = new \Elgg\Database\Config($c->config->getStorageObject());
 
 			// we inject the logger in _elgg_engine_boot()
-			return new \Elgg\Database($db_config);
+			$db = new \Elgg\Database($db_config);
+
+			if ($c->config->getVolatile('profiling_sql')) {
+				$db->setTimer($c->timer);
+			}
+
+			return $db;
 		});
 
 		$this->setFactory('deprecation', function(ServiceProvider $c) {
@@ -218,7 +225,11 @@ public function __construct(\Elgg\Config $config) {
 		});
 
 		$this->setFactory('plugins', function(ServiceProvider $c) {
-			return new \Elgg\Database\Plugins(new Pool\InMemory());
+			$plugins = new \Elgg\Database\Plugins(new Pool\InMemory());
+			if ($c->config->getVolatile('enable_profiling')) {
+				$plugins->setTimer($c->timer);
+			}
+			return $plugins;
 		});
 
 		$this->setFactory('privateSettings', function(ServiceProvider $c) {
@@ -237,7 +248,11 @@ public function __construct(\Elgg\Config $config) {
 
 		$this->setFactory('router', function(ServiceProvider $c) {
 			// TODO(evan): Init routes from plugins or cache
-			return new \Elgg\Router($c->hooks);
+			$router = new \Elgg\Router($c->hooks);
+			if ($c->config->getVolatile('enable_profiling')) {
+				$router->setTimer($c->timer);
+			}
+			return $router;
 		});
 
 		$this->setFactory('session', function(ServiceProvider $c) {
@@ -271,12 +286,20 @@ public function __construct(\Elgg\Config $config) {
 
 		$this->setClassName('subtypeTable', \Elgg\Database\SubtypeTable::class);
 
-		$this->setClassName('systemCache', \Elgg\Cache\SystemCache::class);
+		$this->setFactory('systemCache', function (ServiceProvider $c) {
+			$cache = new \Elgg\Cache\SystemCache();
+			if ($c->config->getVolatile('enable_profiling')) {
+				$cache->setTimer($c->timer);
+			}
+			return $cache;
+		});
 
 		$this->setFactory('systemMessages', function(ServiceProvider $c) {
 			return new \Elgg\SystemMessagesService($c->session);
 		});
 
+		$this->setClassName('timer', \Elgg\Timer::class);
+
 		$this->setClassName('translator', \Elgg\I18n\Translator::class);
 
 		$this->setFactory('upgrades', function(ServiceProvider $c) {
@@ -309,10 +332,15 @@ public function __construct(\Elgg\Config $config) {
 	 */
 	protected function resolveLoggerDependencies($service_needed) {
 		$svcs['hooks'] = new \Elgg\PluginHooksService();
+
 		$svcs['logger'] = new \Elgg\Logger($svcs['hooks'], $this->config, $this->context);
 		$svcs['hooks']->setLogger($svcs['logger']);
+
 		$svcs['events'] = new \Elgg\EventsService();
 		$svcs['events']->setLogger($svcs['logger']);
+		if ($this->config->getVolatile('enable_profiling')) {
+			$svcs['events']->setTimer($this->timer);
+		}
 
 		foreach ($svcs as $key => $service) {
 			$this->setValue($key, $service);

engine/classes/Elgg/EventsService.php

@@ -12,11 +12,29 @@
  * @since      1.9.0
  */
 class EventsService extends \Elgg\HooksRegistrationService {
+	use Profilable;
 
 	const OPTION_STOPPABLE = 'stoppable';
 	const OPTION_DEPRECATION_MESSAGE = 'deprecation_message';
 	const OPTION_DEPRECATION_VERSION = 'deprecation_version';
 
+	/**
+	 * @var Inspector
+	 */
+	private $inspector;
+
+	/**
+	 * Constructor
+	 *
+	 * @param Inspector $inspector Inspector
+	 */
+	public function __construct(Inspector $inspector = null) {
+		if (!$inspector) {
+			$inspector = new Inspector();
+		}
+		$this->inspector = $inspector;
+	}
+
 	/**
 	 * Triggers an Elgg event.
 	 * 
@@ -46,14 +64,22 @@ 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));
+										. $this->inspector->describeCallable($callback));
 				}
 				continue;
 			}
 
-			$return = call_user_func_array($callback, $args);
+			if ($this->timer && $type === 'system' && $event !== 'shutdown') {
+				$callback_as_string = $this->inspector->describeCallable($callback) . "()";
+
+				$this->timer->begin(["[$event,$type]", $callback_as_string]);
+				$return = call_user_func_array($callback, $args);
+				$this->timer->end(["[$event,$type]", $callback_as_string]);
+			} else {
+				$return = call_user_func_array($callback, $args);
+			}
+
 			if (!empty($options[self::OPTION_STOPPABLE]) && ($return === false)) {
 				return false;
 			}

engine/classes/Elgg/Profilable.php

@@ -0,0 +1,25 @@
+<?php
+namespace Elgg;
+
+/**
+ * Make an object accept a timer.
+ *
+ * @access private
+ */
+trait Profilable {
+
+	/**
+	 * @var Timer|null
+	 */
+	private $timer;
+
+	/**
+	 * Set a timer that should collect begin/end times for events
+	 *
+	 * @param Timer $timer Timer
+	 * @return void
+	 */
+	public function setTimer(Timer $timer) {
+		$this->timer = $timer;
+	}
+}