Log the execution time

mod/fbrowser.php

@@ -39,10 +39,12 @@ use Friendica\Util\Strings;
 function fbrowser_content(App $a)
 {
 	if (!local_user()) {
+		DI::page()->logRuntime();
 		exit();
 	}
 
 	if (DI::args()->getArgc() == 1) {
+		DI::page()->logRuntime();
 		exit();
 	}
 

mod/photos.php

@@ -158,6 +158,7 @@ function photos_post(App $a)
 
 	if (!$can_post) {
 		notice(DI::l10n()->t('Permission denied.'));
+		DI::page()->logRuntime();
 		exit();
 	}
 
@@ -166,6 +167,7 @@ function photos_post(App $a)
 	if (!$owner_record) {
 		notice(DI::l10n()->t('Contact information unavailable'));
 		DI::logger()->info('photos_post: unable to locate contact record for page owner. uid=' . $page_owner_uid);
+		DI::page()->logRuntime();
 		exit();
 	}
 

mod/pubsub.php

@@ -38,6 +38,7 @@ function hub_return($valid, $body)
 	} else {
 		throw new \Friendica\Network\HTTPException\NotFoundException();
 	}
+	DI::page()->logRuntime();
 	exit();
 }
 

mod/pubsubhubbub.php

@@ -142,5 +142,6 @@ function pubsubhubbub_init(App $a) {
 
 		throw new \Friendica\Network\HTTPException\AcceptedException();
 	}
+	DI::page()->logRuntime();
 	exit();
 }

mod/share.php

@@ -30,6 +30,7 @@ function share_init(App $a) {
 	$post_id = ((DI::args()->getArgc() > 1) ? intval(DI::args()->getArgv()[1]) : 0);
 
 	if (!$post_id || !local_user()) {
+		DI::page()->logRuntime();
 		exit();
 	}
 
@@ -38,6 +39,7 @@ function share_init(App $a) {
 	$item = Post::selectFirst($fields, ['id' => $post_id]);
 
 	if (!DBA::isResult($item) || $item['private'] == Item::PRIVATE) {
+		DI::page()->logRuntime();
 		exit();
 	}
 
@@ -56,5 +58,6 @@ function share_init(App $a) {
 	}
 
 	echo $o;
+	DI::page()->logRuntime();
 	exit();
 }

mod/tagger.php

@@ -167,6 +167,6 @@ EOT;
 	$post = Post::selectFirst(['uri-id', 'uid'], ['id' => $post_id]);
 
 	Worker::add(PRIORITY_HIGH, "Notifier", Delivery::POST, $post['uri-id'], $post['uid']);
-
+	DI::page()->logRuntime();
 	exit();
 }

mod/wall_attach.php

@@ -67,6 +67,7 @@ function wall_attach_post(App $a) {
 			System::jsonExit(['error' => DI::l10n()->t('Permission denied.')]);
 		}
 		notice(DI::l10n()->t('Permission denied.') . EOL );
+		DI::page()->logRuntime();
 		exit();
 	}
 
@@ -74,6 +75,7 @@ function wall_attach_post(App $a) {
 		if ($r_json) {
 			System::jsonExit(['error' => DI::l10n()->t('Invalid request.')]);
 		}
+		DI::page()->logRuntime();
 		exit();
 	}
 
@@ -97,6 +99,7 @@ function wall_attach_post(App $a) {
 		} else {
 			notice($msg);
 		}
+		DI::page()->logRuntime();
 		exit();
 	}
 
@@ -108,6 +111,7 @@ function wall_attach_post(App $a) {
 		} else {
 			echo $msg . EOL;
 		}
+		DI::page()->logRuntime();
 		exit();
 	}
 
@@ -122,6 +126,7 @@ function wall_attach_post(App $a) {
 		} else {
 			echo $msg . EOL;
 		}
+		DI::page()->logRuntime();
 		exit();
 	}
 
@@ -132,7 +137,7 @@ function wall_attach_post(App $a) {
 	$lf = "\n";
 
 	echo  $lf . $lf . '[attachment]' . $newid . '[/attachment]' . $lf;
-
+	DI::page()->logRuntime();
 	exit();
 	// NOTREACHED
 }

mod/wall_upload.php

@@ -89,6 +89,7 @@ function wall_upload_post(App $a, $desktopmode = true)
 			System::jsonExit(['error' => DI::l10n()->t('Permission denied.')]);
 		}
 		notice(DI::l10n()->t('Permission denied.'));
+		DI::page()->logRuntime();
 		exit();
 	}
 
@@ -96,6 +97,7 @@ function wall_upload_post(App $a, $desktopmode = true)
 		if ($r_json) {
 			System::jsonExit(['error' => DI::l10n()->t('Invalid request.')]);
 		}
+		DI::page()->logRuntime();
 		exit();
 	}
 
@@ -148,6 +150,7 @@ function wall_upload_post(App $a, $desktopmode = true)
 			System::jsonExit(['error' => DI::l10n()->t('Invalid request.')]);
 		}
 		notice(DI::l10n()->t('Invalid request.'));
+		DI::page()->logRuntime();
 		exit();
 	}
 
@@ -167,6 +170,7 @@ function wall_upload_post(App $a, $desktopmode = true)
 		} else {
 			echo  $msg. EOL;
 		}
+		DI::page()->logRuntime();
 		exit();
 	}
 
@@ -205,6 +209,7 @@ function wall_upload_post(App $a, $desktopmode = true)
 			} else {
 				echo  $msg. EOL;
 			}
+			DI::page()->logRuntime();
 			exit();
 		}
 	}
@@ -229,6 +234,7 @@ function wall_upload_post(App $a, $desktopmode = true)
 		} else {
 			echo  $msg. EOL;
 		}
+		DI::page()->logRuntime();
 		exit();
 	}
 
@@ -281,6 +287,7 @@ function wall_upload_post(App $a, $desktopmode = true)
 	}
 
 	echo  "\n\n" . '[url=' . DI::baseUrl() . '/photos/' . $page_owner_nick . '/image/' . $resource_id . '][img]' . DI::baseUrl() . "/photo/{$resource_id}-{$smallest}.".$Image->getExt()."[/img][/url]\n\n";
+	DI::page()->logRuntime();
 	exit();
 	// NOTREACHED
 }

src/App.php

@@ -576,6 +576,7 @@ class App
 		$this->profiler->set(microtime(true), 'classinit');
 
 		$moduleName = $this->args->getModuleName();
+		$page->setLogging($moduleName, $this->args->getMethod());
 
 		try {
 			// Missing DB connection: ERROR
@@ -712,6 +713,7 @@ class App
 			$this->profiler->set(microtime(true) - $timestamp, 'content');
 			if ($response->getHeaderLine(ICanCreateResponses::X_HEADER) === ICanCreateResponses::TYPE_HTML) {
 				$page->run($this, $this->baseURL, $this->args, $this->mode, $response, $this->l10n, $this->profiler, $this->config, $pconfig);
+				$page->logRuntime();
 			} else {
 				$page->exit($response);
 			}

src/App/Page.php

@@ -30,6 +30,7 @@ use Friendica\Core\Config\Capability\IManageConfigValues;
 use Friendica\Core\PConfig\Capability\IManagePersonalConfigValues;
 use Friendica\Core\Hook;
 use Friendica\Core\L10n;
+use Friendica\Core\Logger;
 use Friendica\Core\Renderer;
 use Friendica\Core\System;
 use Friendica\Core\Theme;
@@ -78,14 +79,31 @@ class Page implements ArrayAccess
 	 */
 	private $basePath;
 
+	private $timestamp  = 0;
+	private $moduleName = '';
+	private $method     = '';
+
 	/**
 	 * @param string $basepath The Page basepath
 	 */
 	public function __construct(string $basepath)
 	{
+		$this->timestamp = microtime(true);
 		$this->basePath = $basepath;
 	}
 
+	public function setLogging(string $moduleName, string $method)
+	{
+		$this->moduleName = $moduleName;
+		$this->method     = $method;
+	}
+
+	public function logRuntime()
+	{
+		$runtime = number_format(microtime(true) - $this->timestamp, 3);
+		Logger::debug('Runtime', ['method' => $this->method, 'module' => $this->moduleName, 'runtime' => $runtime]);
+	}
+
 	/**
 	 * Whether a offset exists
 	 *
@@ -401,6 +419,7 @@ class Page implements ArrayAccess
 		}
 
 		echo $response->getBody();
+		$this->logRuntime();
 	}
 
 	/**
@@ -421,6 +440,9 @@ class Page implements ArrayAccess
 	{
 		$moduleName = $args->getModuleName();
 
+		$this->moduleName = $moduleName;
+		$this->method     = $args->getMethod();
+
 		/* Create the page content.
 		 * Calls all hooks which are including content operations
 		 *

src/Core/System.php

@@ -448,7 +448,7 @@ class System
 			case 307:
 				throw new TemporaryRedirectException();
 		}
-
+		DI::page()->logRuntime();
 		exit();
 	}
 
@@ -522,6 +522,7 @@ class System
 		echo str_replace("\t", "       ", $o);
 		echo "</section>";
 		echo "</body></html>\r\n";
+		DI::page()->logRuntime();
 		exit();
 	}
 

src/Module/Admin/PhpInfo.php

@@ -30,6 +30,7 @@ class PhpInfo extends BaseAdmin
 		self::checkAdminAccess();
 
 		phpinfo();
+		DI::page()->logRuntime();
 		exit();
 	}
 }

src/Module/Attach.php

@@ -72,6 +72,7 @@ class Attach extends BaseModule
 		}
 
 		echo $data;
+		DI::page()->logRuntime();
 		exit();
 		// NOTREACHED
 	}

src/Module/Contact/Hovercard.php

@@ -107,6 +107,7 @@ class Hovercard extends BaseModule
 		]);
 
 		echo $o;
+		DI::page()->logRuntime();
 		exit();
 	}
 }

src/Module/Debug/ItemBody.php

@@ -48,6 +48,7 @@ class ItemBody extends BaseModule
 		if (!empty($item)) {
 			if (DI::mode()->isAjax()) {
 				echo str_replace("\n", '<br />', $item['body']);
+				DI::page()->logRuntime();
 				exit();
 			} else {
 				return str_replace("\n", '<br />', $item['body']);

src/Module/Group.php

@@ -360,6 +360,7 @@ class Group extends BaseModule
 		if ($change) {
 			$tpl = Renderer::getMarkupTemplate('groupeditor.tpl');
 			echo Renderer::replaceMacros($tpl, $context);
+			DI::page()->logRuntime();
 			exit();
 		}
 

src/Module/HTTPException/PageNotFound.php

@@ -47,6 +47,7 @@ class PageNotFound extends BaseModule
 		$queryString = $this->server['QUERY_STRING'];
 		// Stupid browser tried to pre-fetch our Javascript img template. Don't log the event or return anything - just quietly exit.
 		if (!empty($queryString) && preg_match('/{[0-9]}/', $queryString) !== 0) {
+			DI::page()->logRuntime();
 			exit();
 		}
 

src/Module/Oembed.php

@@ -43,6 +43,7 @@ class Oembed extends BaseModule
 		if (DI::args()->getArgv()[1] == 'b2h') {
 			$url = ["", trim(hex2bin($_REQUEST['url']))];
 			echo Content\OEmbed::replaceCallback($url);
+			DI::page()->logRuntime();
 			exit();
 		}
 
@@ -50,6 +51,7 @@ class Oembed extends BaseModule
 		if (DI::args()->getArgv()[1] == 'h2b') {
 			$text = trim(hex2bin($_REQUEST['text']));
 			echo Content\OEmbed::HTML2BBCode($text);
+			DI::page()->logRuntime();
 			exit();
 		}
 
@@ -68,6 +70,7 @@ class Oembed extends BaseModule
 			echo $j->html;
 			echo '</body></html>';
 		}
+		DI::page()->logRuntime();
 		exit();
 	}
 }

src/Module/PermissionTooltip.php

@@ -164,7 +164,7 @@ class PermissionTooltip extends \Friendica\BaseModule
 		} else {
 			echo $o . $receivers;
 		}
-
+		DI::page()->logRuntime();
 		exit();
 	}
 

src/Module/Photo.php

@@ -224,6 +224,7 @@ class Photo extends BaseModule
 				'output' => number_format($output, 3), 'rest' => number_format($rest, 3)]);
 		}
 
+		DI::page()->logRuntime();
 		exit();
 	}
 

src/Module/Proxy.php

@@ -202,6 +202,7 @@ class Proxy extends BaseModule
 		header('Expires: ' . gmdate('D, d M Y H:i:s', time() + (31536000)) . ' GMT');
 		header('Cache-Control: max-age=31536000');
 		echo $img->asString();
+		DI::page()->logRuntime();
 		exit();
 	}
 }

src/Module/RobotsTxt.php

@@ -44,6 +44,7 @@ class RobotsTxt extends BaseModule
 		foreach ($allDisalloweds as $disallowed) {
 			echo 'Disallow: ' . $disallowed . PHP_EOL;
 		}
+		DI::page()->logRuntime();
 		exit();
 	}
 }

src/Module/Settings/UserExport.php

@@ -112,7 +112,7 @@ class UserExport extends BaseSettings
 					self::exportContactsAsCSV(local_user());
 					break;
 			}
-
+			DI::page()->logRuntime();
 			exit();
 		}
 	}

src/Module/Theme.php

@@ -45,7 +45,7 @@ class Theme extends BaseModule
 		if (file_exists("view/theme/$theme/style.php")) {
 			require_once "view/theme/$theme/style.php";
 		}
-
+		DI::page()->logRuntime();
 		exit();
 	}
 }

src/Module/ThemeDetails.php

@@ -48,6 +48,7 @@ class ThemeDetails extends BaseModule
 				'credits' => $credits,
 			]);
 		}
+		DI::page()->logRuntime();
 		exit();
 	}
 }

src/Module/Update/Network.php

@@ -31,6 +31,7 @@ class Network extends NetworkModule
 	protected function rawContent(array $request = [])
 	{
 		if (!isset($_GET['p']) || !isset($_GET['item'])) {
+			DI::page()->logRuntime();
 			exit();
 		}
 

src/Util/JsonLD.php

@@ -69,6 +69,7 @@ class JsonLD
 
 		if ($recursion > 5) {
 			Logger::error('jsonld bomb detected at: ' . $url);
+			DI::page()->logRuntime();
 			exit();
 		}