Elgg: profile MySQL queries on Elgg 1.10 - 1.x

elgg-profile-queries.php

<?php
/**
 * Query profiler for Elgg 1.10-1.12
 *
 * Require this script inside settings.php and the JavaScript console will report all
 * queries with their time in seconds, and the total time spent in mysql_query().
 *
 * This will not include queries performed after the "output", "page" hook.
 *
 * On production you could include this only if a particular query string is set:
 *
 *   if (isset($_GET['<secret_string>'])) {
 *      require __DIR__ . '/elgg-profile-queries.php';
 *   }
 *
 * On Elgg 1.9 and 2.0, you can alter the core Database::executeQuery() method to
 * call \Elgg\_elgg_profile_mysql_query() if it exists.
 */

namespace Elgg;

global $_ELGG_QUERIES;
$_ELGG_QUERIES = array();

/**
 * @param string $query      SQL query
 * @param string $start_time Output of microtime() before query
 */
function _elgg_profile_mysql_query($query, $start_time) {
	global $_ELGG_QUERIES;

	if (empty($_ELGG_QUERIES) && function_exists('elgg_register_plugin_hook_handler')) {
		profile_setup_reporting();
	}

	$_ELGG_QUERIES[] = array(
		_microtime_diff($start_time, microtime()),
		trim($query),
	);
}

/**
 * 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
 */
function _microtime_diff($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;
}

// Inside the Elgg namespace, this hijacks calls to the global function. Namely,
// the Elgg\Database class will use this.
function mysql_query($query, $link_identifier = null) {
	global $_ELGG_QUERIES;

	if (empty($_ELGG_QUERIES) && function_exists('elgg_register_plugin_hook_handler')) {
		profile_setup_reporting();
	}

	$before = microtime();

	$res = \mysql_query($query, $link_identifier);

	$_ELGG_QUERIES[] = array(
		_microtime_diff($before, microtime()),
		trim($query),
	);

	return $res;
}

function profile_get_queries($slowest_first = false, $format = '% 3.4F | %s') {
	global $_ELGG_QUERIES;

	$queries = $_ELGG_QUERIES;

	if ($slowest_first) {
		usort($queries, function ($a, $b) {
			if ($a[0] == $b[0]) {
				return 0;
			}
			return ($a[0] > $b[0]) ? -1 : 1;
		});
	}

	return array_map(function ($query) use ($format) {
		return sprintf($format, $query[0], $query[1]);
	}, $queries);
}

function profile_get_total_query_time() {
	global $_ELGG_QUERIES;

	return array_reduce($_ELGG_QUERIES, function ($carry, $item) {
		return $carry + $item[0];
	}, 0);
}

function profile_setup_reporting() {
	elgg_register_plugin_hook_handler('output', 'page', function ($h, $t, $v, $p) {
		$time = sprintf("Total query time: %.3F", profile_get_total_query_time());
		$queries = array(
			'slowest_first' => profile_get_queries(true),
			'chronological' => profile_get_queries(),
		);

		$v .= "<script>";
		$v .= "console.log(" . json_encode($queries) . ");";
		$v .= "console.log(" . json_encode($time) . ");";
		$v .= "</script>";
		return $v;
	}, 999);
}