Merge pull request #11416 from owncloud/eventlogger

Allow apps to gather performance diagnistics

17 files changed, 524 insertions, 10 deletions

diff --git a/lib/base.php b/lib/base.php
index 5ba8d3829ca..23f0e594510 100644
--- a/lib/base.php
+++ b/lib/base.php
@@ -444,6 +444,7 @@ class OC {
 
 	public static function init() {
 		// register autoloader
+		$loaderStart = microtime(true);
 		require_once __DIR__ . '/autoloader.php';
 		self::$loader = new \OC\Autoloader();
 		self::$loader->registerPrefix('Doctrine\\Common', 'doctrine/common/lib');
@@ -453,6 +454,13 @@ class OC {
 		self::$loader->registerPrefix('Patchwork', '3rdparty');
 		self::$loader->registerPrefix('Pimple', '3rdparty/Pimple');
 		spl_autoload_register(array(self::$loader, 'load'));
+		$loaderEnd = microtime(true);
+
+		// setup the basic server
+		self::initPaths();
+		self::$server = new \OC\Server();
+		\OC::$server->getEventLogger()->log('autoloader', 'Autoloader', $loaderStart, $loaderEnd);
+		\OC::$server->getEventLogger()->start('boot', 'Initialize');
 
 		// set some stuff
 		//ob_start();
@@ -469,7 +477,6 @@ class OC {
 		if (get_magic_quotes_gpc() == 1) {
 			ini_set('magic_quotes_runtime', 0);
 		}
-
 		//try to configure php to enable big file uploads.
 		//this doesn´t work always depending on the webserver and php configuration.
 		//Let´s try to overwrite some defaults anyways
@@ -485,9 +492,9 @@ class OC {
 		@ini_set('file_uploads', '50');
 
 		self::handleAuthHeaders();
-		self::initPaths();
 		self::registerAutoloaderCache();
 
+
 		OC_Util::isSetLocaleWorking();
 
 		// setup 3rdparty autoloader
@@ -516,9 +523,8 @@ class OC {
 		stream_wrapper_register('quota', 'OC\Files\Stream\Quota');
 		stream_wrapper_register('oc', 'OC\Files\Stream\OC');
 
-		// setup the basic server
-		self::$server = new \OC\Server();
 
+		\OC::$server->getEventLogger()->start('init_session', 'Initialize session');
 		self::initTemplateEngine();
 		OC_App::loadApps(array('session'));
 		if (self::$CLI) {
@@ -526,6 +532,7 @@ class OC {
 		} else {
 			self::initSession();
 		}
+		\OC::$server->getEventLogger()->end('init_session');
 		self::checkConfig();
 		self::checkInstalled();
 		self::checkSSL();
@@ -612,6 +619,7 @@ class OC {
 
 			exit();
 		}
+		\OC::$server->getEventLogger()->end('boot');
 	}
 
 	private static function registerLocalAddressBook() {
@@ -701,6 +709,7 @@ class OC {
 	 * Handle the request
 	 */
 	public static function handleRequest() {
+		\OC::$server->getEventLogger()->start('handle_request', 'Handle request');
 		// load all the classpaths from the enabled apps so they are available
 		// in the routing files of each app
 		OC::loadAppClassPaths();
diff --git a/lib/private/app.php b/lib/private/app.php
index a97db7b5e53..8fcffbad950 100644
--- a/lib/private/app.php
+++ b/lib/private/app.php
@@ -89,6 +89,7 @@ class OC_App {
 	 */
 	public static function loadApp($app, $checkUpgrade = true) {
 		if (is_file(self::getAppPath($app) . '/appinfo/app.php')) {
+			\OC::$server->getEventLogger()->start('load_app_' . $app, 'Load app: ' . $app);
 			if ($checkUpgrade and self::shouldUpgrade($app)) {
 				throw new \OC\NeedsUpdateException();
 			}
@@ -100,6 +101,7 @@ class OC_App {
 				// enabled for groups
 				self::$enabledAppsCache = array();
 			}
+			\OC::$server->getEventLogger()->end('load_app_' . $app);
 		}
 	}
 
diff --git a/lib/private/db.php b/lib/private/db.php
index 80163415a90..ba069977d35 100644
--- a/lib/private/db.php
+++ b/lib/private/db.php
@@ -91,6 +91,7 @@ class OC_DB {
 
 		try {
 			self::$connection = $factory->getConnection($type, $connectionParams);
+			self::$connection->getConfiguration()->setSQLLogger(\OC::$server->getQueryLogger());
 		} catch(\Doctrine\DBAL\DBALException $e) {
 			OC_Log::write('core', $e->getMessage(), OC_Log::FATAL);
 			OC_User::setUserId(null);
diff --git a/lib/private/diagnostics/event.php b/lib/private/diagnostics/event.php
new file mode 100644
index 00000000000..af5d2ff8840
--- /dev/null
+++ b/lib/private/diagnostics/event.php
@@ -0,0 +1,89 @@
+<?php
+/**
+ * Copyright (c) 2014 Robin Appelman <icewind@owncloud.com>
+ * This file is licensed under the Affero General Public License version 3 or
+ * later.
+ * See the COPYING-README file.
+ */
+
+namespace OC\Diagnostics;
+
+use OCP\Diagnostics\IEvent;
+
+class Event implements IEvent {
+	/**
+	 * @var string
+	 */
+	protected $id;
+
+	/**
+	 * @var float
+	 */
+	protected $start;
+
+	/**
+	 * @var float
+	 */
+	protected $end;
+
+	/**
+	 * @var string
+	 */
+	protected $description;
+
+	/**
+	 * @param string $id
+	 * @param string $description
+	 * @param float $start
+	 */
+	public function __construct($id, $description, $start) {
+		$this->id = $id;
+		$this->description = $description;
+		$this->start = $start;
+	}
+
+	/**
+	 * @param float $time
+	 */
+	public function end($time) {
+		$this->end = $time;
+	}
+
+	/**
+	 * @return float
+	 */
+	public function getStart() {
+		return $this->start;
+	}
+
+	/**
+	 * @return string
+	 */
+	public function getId() {
+		return $this->id;
+	}
+
+	/**
+	 * @return string
+	 */
+	public function getDescription() {
+		return $this->description;
+	}
+
+	/**
+	 * @return float
+	 */
+	public function getEnd() {
+		return $this->end;
+	}
+
+	/**
+	 * @return float
+	 */
+	public function getDuration() {
+		if (!$this->end) {
+			$this->end = microtime(true);
+		}
+		return $this->end - $this->start;
+	}
+}
diff --git a/lib/private/diagnostics/eventlogger.php b/lib/private/diagnostics/eventlogger.php
new file mode 100644
index 00000000000..9e557ebd304
--- /dev/null
+++ b/lib/private/diagnostics/eventlogger.php
@@ -0,0 +1,41 @@
+<?php
+/**
+ * Copyright (c) 2014 Robin Appelman <icewind@owncloud.com>
+ * This file is licensed under the Affero General Public License version 3 or
+ * later.
+ * See the COPYING-README file.
+ */
+
+namespace OC\Diagnostics;
+
+use OCP\Diagnostics\IEventLogger;
+
+class EventLogger implements IEventLogger {
+	/**
+	 * @var \OC\Diagnostics\Event[]
+	 */
+	private $events = array();
+
+	public function start($id, $description) {
+		$this->events[$id] = new Event($id, $description, microtime(true));
+	}
+
+	public function end($id) {
+		if (isset($this->events[$id])) {
+			$timing = $this->events[$id];
+			$timing->end(microtime(true));
+		}
+	}
+
+	public function log($id, $description, $start, $end) {
+		$this->events[$id] = new Event($id, $description, $start);
+		$this->events[$id]->end($end);
+	}
+
+	/**
+	 * @return \OCP\Diagnostics\IEvent[]
+	 */
+	public function getEvents() {
+		return $this->events;
+	}
+}
diff --git a/lib/private/diagnostics/nulleventlogger.php b/lib/private/diagnostics/nulleventlogger.php
new file mode 100644
index 00000000000..bf203cbfefd
--- /dev/null
+++ b/lib/private/diagnostics/nulleventlogger.php
@@ -0,0 +1,43 @@
+<?php
+/**
+ * Copyright (c) 2014 Robin Appelman <icewind@owncloud.com>
+ * This file is licensed under the Affero General Public License version 3 or
+ * later.
+ * See the COPYING-README file.
+ */
+
+namespace OC\Diagnostics;
+
+use OCP\Diagnostics\IEventLogger;
+
+/**
+ * Dummy event logger that doesn't actually log anything
+ */
+class NullEventLogger implements IEventLogger {
+	/**
+	 * Mark the start of an event
+	 *
+	 * @param $id
+	 * @param $description
+	 */
+	public function start($id, $description) {
+	}
+
+	/**
+	 * Mark the end of an event
+	 *
+	 * @param $id
+	 */
+	public function end($id) {
+	}
+
+	public function log($id, $description, $start, $end) {
+	}
+
+	/**
+	 * @return \OCP\Diagnostics\IEvent[]
+	 */
+	public function getEvents() {
+		return array();
+	}
+}
diff --git a/lib/private/diagnostics/nullquerylogger.php b/lib/private/diagnostics/nullquerylogger.php
new file mode 100644
index 00000000000..8467b4dd26c
--- /dev/null
+++ b/lib/private/diagnostics/nullquerylogger.php
@@ -0,0 +1,31 @@
+<?php
+/**
+ * Copyright (c) 2014 Robin Appelman <icewind@owncloud.com>
+ * This file is licensed under the Affero General Public License version 3 or
+ * later.
+ * See the COPYING-README file.
+ */
+
+namespace OC\Diagnostics;
+
+use OCP\Diagnostics\IQueryLogger;
+
+class NullQueryLogger implements IQueryLogger {
+	/**
+	 * @param string $sql
+	 * @param array $params
+	 * @param array $types
+	 */
+	public function startQuery($sql, array $params = null, array $types = null) {
+	}
+
+	public function stopQuery() {
+	}
+
+	/**
+	 * @return \OCP\Diagnostics\IQuery[]
+	 */
+	public function getQueries() {
+		return array();
+	}
+}
diff --git a/lib/private/diagnostics/query.php b/lib/private/diagnostics/query.php
new file mode 100644
index 00000000000..d50d7592636
--- /dev/null
+++ b/lib/private/diagnostics/query.php
@@ -0,0 +1,57 @@
+<?php
+/**
+ * Copyright (c) 2014 Robin Appelman <icewind@owncloud.com>
+ * This file is licensed under the Affero General Public License version 3 or
+ * later.
+ * See the COPYING-README file.
+ */
+
+namespace OC\Diagnostics;
+
+use OCP\Diagnostics\IQuery;
+
+class Query implements IQuery {
+	private $sql;
+
+	private $params;
+
+	private $start;
+
+	private $end;
+
+	/**
+	 * @param string $sql
+	 * @param array $params
+	 * @param int $start
+	 */
+	public function __construct($sql, $params, $start) {
+		$this->sql = $sql;
+		$this->params = $params;
+		$this->start = $start;
+	}
+
+	public function end($time) {
+		$this->end = $time;
+	}
+
+	/**
+	 * @return array
+	 */
+	public function getParams() {
+		return $this->params;
+	}
+
+	/**
+	 * @return string
+	 */
+	public function getSql() {
+		return $this->sql;
+	}
+
+	/**
+	 * @return int
+	 */
+	public function getDuration() {
+		return $this->end - $this->start;
+	}
+}
diff --git a/lib/private/diagnostics/querylogger.php b/lib/private/diagnostics/querylogger.php
new file mode 100644
index 00000000000..1f80f907173
--- /dev/null
+++ b/lib/private/diagnostics/querylogger.php
@@ -0,0 +1,47 @@
+<?php
+/**
+ * Copyright (c) 2014 Robin Appelman <icewind@owncloud.com>
+ * This file is licensed under the Affero General Public License version 3 or
+ * later.
+ * See the COPYING-README file.
+ */
+
+namespace OC\Diagnostics;
+
+use OCP\Diagnostics\IQueryLogger;
+
+class QueryLogger implements IQueryLogger {
+	/**
+	 * @var \OC\Diagnostics\Query
+	 */
+	protected $activeQuery;
+
+	/**
+	 * @var \OC\Diagnostics\Query[]
+	 */
+	protected $queries = array();
+
+	/**
+	 * @param string $sql
+	 * @param array $params
+	 * @param array $types
+	 */
+	public function startQuery($sql, array $params = null, array $types = null) {
+		$this->activeQuery = new Query($sql, $params, microtime(true));
+	}
+
+	public function stopQuery() {
+		if ($this->activeQuery) {
+			$this->activeQuery->end(microtime(true));
+			$this->queries[] = $this->activeQuery;
+			$this->activeQuery = null;
+		}
+	}
+
+	/**
+	 * @return \OCP\Diagnostics\IQuery[]
+	 */
+	public function getQueries() {
+		return $this->queries;
+	}
+}
diff --git a/lib/private/route/router.php b/lib/private/route/router.php
index aa3d05dcb85..645d6141964 100644
--- a/lib/private/route/router.php
+++ b/lib/private/route/router.php
@@ -106,6 +106,7 @@ class Router implements IRouter {
 	 * @return void
 	 */
 	public function loadRoutes($app = null) {
+		$requestedApp = $app;
 		if ($this->loaded) {
 			return;
 		}
@@ -123,6 +124,7 @@ class Router implements IRouter {
 				$routingFiles = array();
 			}
 		}
+		\OC::$server->getEventLogger()->start('loadroutes' . $requestedApp, 'Loading Routes');
 		foreach ($routingFiles as $app => $file) {
 			if (!isset($this->loadedApps[$app])) {
 				$this->loadedApps[$app] = true;
@@ -145,6 +147,7 @@ class Router implements IRouter {
 			$collection->addPrefix('/ocs');
 			$this->root->addCollection($collection);
 		}
+		\OC::$server->getEventLogger()->end('loadroutes' . $requestedApp);
 	}
 
 	/**
@@ -236,6 +239,7 @@ class Router implements IRouter {
 			}
 		}
 
+		\OC::$server->getEventLogger()->start('run_route', 'Run route');
 		if (isset($parameters['action'])) {
 			$action = $parameters['action'];
 			if (!is_callable($action)) {
@@ -249,6 +253,7 @@ class Router implements IRouter {
 		} else {
 			throw new \Exception('no action available');
 		}
+		\OC::$server->getEventLogger()->end('run_route');
 	}
 
 	/**
diff --git a/lib/private/server.php b/lib/private/server.php
index d2728d2b6ef..f7ffee484ea 100644
--- a/lib/private/server.php
+++ b/lib/private/server.php
@@ -6,12 +6,16 @@ use OC\AppFramework\Http\Request;
 use OC\AppFramework\Db\Db;
 use OC\AppFramework\Utility\SimpleContainer;
 use OC\Cache\UserCache;
+use OC\Diagnostics\NullQueryLogger;
+use OC\Diagnostics\EventLogger;
+use OC\Diagnostics\QueryLogger;
 use OC\Security\CertificateManager;
 use OC\DB\ConnectionWrapper;
 use OC\Files\Node\Root;
 use OC\Files\View;
 use OC\Security\Crypto;
 use OC\Security\SecureRandom;
+use OC\Diagnostics\NullEventLogger;
 use OCP\IServerContainer;
 use OCP\ISession;
 use OC\Tagging\TagMapper;
@@ -24,7 +28,6 @@ use OC\Tagging\TagMapper;
  * TODO: hookup all manager classes
  */
 class Server extends SimpleContainer implements IServerContainer {
-
 	function __construct() {
 		$this->registerService('ContactsManager', function ($c) {
 			return new ContactsManager();
@@ -59,8 +62,8 @@ class Server extends SimpleContainer implements IServerContainer {
 					'env' => $_ENV,
 					'cookies' => $_COOKIE,
 					'method' => (isset($_SERVER) && isset($_SERVER['REQUEST_METHOD']))
-							? $_SERVER['REQUEST_METHOD']
-							: null,
+						? $_SERVER['REQUEST_METHOD']
+						: null,
 					'urlParams' => $urlParams,
 					'requesttoken' => $requestToken,
 				), $stream
@@ -208,10 +211,10 @@ class Server extends SimpleContainer implements IServerContainer {
 		$this->registerService('Search', function ($c) {
 			return new Search();
 		});
-		$this->registerService('SecureRandom', function($c) {
+		$this->registerService('SecureRandom', function ($c) {
 			return new SecureRandom();
 		});
-		$this->registerService('Crypto', function($c) {
+		$this->registerService('Crypto', function ($c) {
 			return new Crypto(\OC::$server->getConfig(), \OC::$server->getSecureRandom());
 		});
 		$this->registerService('Db', function ($c) {
@@ -221,6 +224,21 @@ class Server extends SimpleContainer implements IServerContainer {
 			$config = $c->query('AllConfig');
 			return new HTTPHelper($config);
 		});
+		$this->registerService('EventLogger', function ($c) {
+			/** @var Server $c */
+			if (defined('DEBUG') and DEBUG) {
+				return new EventLogger();
+			} else {
+				return new NullEventLogger();
+			}
+		});
+		$this->registerService('QueryLogger', function ($c) {
+			if (defined('DEBUG') and DEBUG) {
+				return new QueryLogger();
+			} else {
+				return new NullQueryLogger();
+			}
+		});
 	}
 
 	/**
@@ -285,7 +303,7 @@ class Server extends SimpleContainer implements IServerContainer {
 	 * @return \OCP\Files\Folder
 	 */
 	function getUserFolder($userId = null) {
-		if($userId === null) {
+		if ($userId === null) {
 			$user = $this->getUserSession()->getUser();
 			if (!$user) {
 				return null;
@@ -528,6 +546,7 @@ class Server extends SimpleContainer implements IServerContainer {
 
 	/**
 	 * Returns an instance of the HTTP helper class
+	 *
 	 * @return \OC\HTTPHelper
 	 */
 	function getHTTPHelper() {
@@ -559,4 +578,26 @@ class Server extends SimpleContainer implements IServerContainer {
 	function createEventSource() {
 		return new \OC_EventSource();
 	}
+
+	/**
+	 * Get the active event logger
+	 *
+	 * The returned logger only logs data when debug mode is enabled
+	 *
+	 * @return \OCP\Diagnostics\IEventLogger
+	 */
+	function getEventLogger() {
+		return $this->query('EventLogger');
+	}
+
+	/**
+	 * Get the active query logger
+	 *
+	 * The returned logger only logs data when debug mode is enabled
+	 *
+	 * @return \OCP\Diagnostics\IQueryLogger
+	 */
+	function getQueryLogger() {
+		return $this->query('QueryLogger');
+	}
 }
diff --git a/lib/private/util.php b/lib/private/util.php
index d6515872c5a..858138f58fe 100755
--- a/lib/private/util.php
+++ b/lib/private/util.php
@@ -64,6 +64,8 @@ class OC_Util {
 			return false;
 		}
 
+		\OC::$server->getEventLogger()->start('setup_fs', 'Setup filesystem');
+
 		// If we are not forced to load a specific user we load the one that is logged in
 		if ($user == "" && OC_User::isLoggedIn()) {
 			$user = OC_User::getUser();
@@ -88,6 +90,7 @@ class OC_Util {
 		}
 
 		if ($user != '' && !OCP\User::userExists($user)) {
+			\OC::$server->getEventLogger()->end('setup_fs');
 			return false;
 		}
 
@@ -128,6 +131,7 @@ class OC_Util {
 
 			OC_Hook::emit('OC_Filesystem', 'setup', array('user' => $user, 'user_dir' => $userDir));
 		}
+		\OC::$server->getEventLogger()->end('setup_fs');
 		return true;
 	}
 
diff --git a/lib/public/diagnostics/ievent.php b/lib/public/diagnostics/ievent.php
new file mode 100644
index 00000000000..a2a3461f68a
--- /dev/null
+++ b/lib/public/diagnostics/ievent.php
@@ -0,0 +1,36 @@
+<?php
+/**
+ * Copyright (c) 2014 Robin Appelman <icewind@owncloud.com>
+ * This file is licensed under the Affero General Public License version 3 or
+ * later.
+ * See the COPYING-README file.
+ */
+
+namespace OCP\Diagnostics;
+
+interface IEvent {
+	/**
+	 * @return string
+	 */
+	public function getId();
+
+	/**
+	 * @return string
+	 */
+	public function getDescription();
+
+	/**
+	 * @return float
+	 */
+	public function getStart();
+
+	/**
+	 * @return float
+	 */
+	public function getEnd();
+
+	/**
+	 * @return float
+	 */
+	public function getDuration();
+}
diff --git a/lib/public/diagnostics/ieventlogger.php b/lib/public/diagnostics/ieventlogger.php
new file mode 100644
index 00000000000..cd9f2768ca3
--- /dev/null
+++ b/lib/public/diagnostics/ieventlogger.php
@@ -0,0 +1,39 @@
+<?php
+/**
+ * Copyright (c) 2014 Robin Appelman <icewind@owncloud.com>
+ * This file is licensed under the Affero General Public License version 3 or
+ * later.
+ * See the COPYING-README file.
+ */
+
+namespace OCP\Diagnostics;
+
+interface IEventLogger {
+	/**
+	 * Mark the start of an event
+	 *
+	 * @param string $id
+	 * @param string $description
+	 */
+	public function start($id, $description);
+
+	/**
+	 * Mark the end of an event
+	 *
+	 * @param string $id
+	 */
+	public function end($id);
+
+	/**
+	 * @param string $id
+	 * @param string $description
+	 * @param float $start
+	 * @param float $end
+	 */
+	public function log($id, $description, $start, $end);
+
+	/**
+	 * @return \OCP\Diagnostics\IEvent[]
+	 */
+	public function getEvents();
+}
diff --git a/lib/public/diagnostics/iquery.php b/lib/public/diagnostics/iquery.php
new file mode 100644
index 00000000000..f1111e069bb
--- /dev/null
+++ b/lib/public/diagnostics/iquery.php
@@ -0,0 +1,26 @@
+<?php
+/**
+ * Copyright (c) 2014 Robin Appelman <icewind@owncloud.com>
+ * This file is licensed under the Affero General Public License version 3 or
+ * later.
+ * See the COPYING-README file.
+ */
+
+namespace OCP\Diagnostics;
+
+interface IQuery {
+	/**
+	 * @return string
+	 */
+	public function getSql();
+
+	/**
+	 * @return array
+	 */
+	public function getParams();
+
+	/**
+	 * @return float
+	 */
+	public function getDuration();
+}
diff --git a/lib/public/diagnostics/iquerylogger.php b/lib/public/diagnostics/iquerylogger.php
new file mode 100644
index 00000000000..0fba9eb8b10
--- /dev/null
+++ b/lib/public/diagnostics/iquerylogger.php
@@ -0,0 +1,27 @@
+<?php
+/**
+ * Copyright (c) 2014 Robin Appelman <icewind@owncloud.com>
+ * This file is licensed under the Affero General Public License version 3 or
+ * later.
+ * See the COPYING-README file.
+ */
+
+namespace OCP\Diagnostics;
+
+use Doctrine\DBAL\Logging\SQLLogger;
+
+interface IQueryLogger extends SQLLogger {
+	/**
+	 * @param string $sql
+	 * @param array $params
+	 * @param array $types
+	 */
+	public function startQuery($sql, array $params = null, array $types = null);
+
+	public function stopQuery();
+
+	/**
+	 * @return \OCP\Diagnostics\IQuery[]
+	 */
+	public function getQueries();
+}
diff --git a/lib/public/iservercontainer.php b/lib/public/iservercontainer.php
index a093ff3a640..55c2c89b710 100644
--- a/lib/public/iservercontainer.php
+++ b/lib/public/iservercontainer.php
@@ -248,4 +248,20 @@ interface IServerContainer {
 	 * @return \OC\HTTPHelper
 	 */
 	function getHTTPHelper();
+
+	/**
+	 * Get the active event logger
+	 *
+	 * @return \OCP\Diagnostics\IEventLogger
+	 */
+	function getEventLogger();
+
+	/**
+	 * Get the active query logger
+	 *
+	 * The returned logger only logs data when debug mode is enabled
+	 *
+	 * @return \OCP\Diagnostics\IQueryLogger
+	 */
+	function getQueryLogger();
 }