From e645d45c2db0a37237239e2fe2fa72d85621e2fe Mon Sep 17 00:00:00 2001
From: Michael <heluecht@pirati.ca>
Date: Sun, 9 Jun 2024 06:13:20 +0000
Subject: [PATCH] Log the page execution performance

---
 src/App.php                | 35 ++++++++++++++++++++++++++++++++++-
 static/defaults.config.php |  9 +++++++++
 2 files changed, 43 insertions(+), 1 deletion(-)

diff --git a/src/App.php b/src/App.php
index 73fc77a066..da367186ab 100644
--- a/src/App.php
+++ b/src/App.php
@@ -24,6 +24,7 @@ namespace Friendica;
 use Exception;
 use Friendica\App\Arguments;
 use Friendica\App\BaseURL;
+use Friendica\App\Request;
 use Friendica\Capabilities\ICanCreateResponses;
 use Friendica\Content\Nav;
 use Friendica\Core\Config\Factory\Config;
@@ -93,6 +94,9 @@ class App
 	/** @var string The name of the current mobile theme */
 	private $currentMobileTheme;
 
+	/** @var string */
+	private $requestId;
+
 	/** @var Authentication */
 	private $auth;
 
@@ -281,8 +285,9 @@ class App
 	 * @param DbaDefinition               $dbaDefinition
 	 * @param ViewDefinition              $viewDefinition
 	 */
-	public function __construct(Authentication $auth, Database $database, IManageConfigValues $config, App\Mode $mode, BaseURL $baseURL, LoggerInterface $logger, Profiler $profiler, L10n $l10n, Arguments $args, IManagePersonalConfigValues $pConfig, IHandleUserSessions $session, DbaDefinition $dbaDefinition, ViewDefinition $viewDefinition)
+	public function __construct(Request $request, Authentication $auth, Database $database, IManageConfigValues $config, App\Mode $mode, BaseURL $baseURL, LoggerInterface $logger, Profiler $profiler, L10n $l10n, Arguments $args, IManagePersonalConfigValues $pConfig, IHandleUserSessions $session, DbaDefinition $dbaDefinition, ViewDefinition $viewDefinition)
 	{
+		$this->requestId      = $request->getRequestId();
 		$this->auth           = $auth;
 		$this->database       = $database;
 		$this->config         = $config;
@@ -683,9 +688,11 @@ class App
 			}
 
 			$this->logger->debug('Request processed sucessfully', ['response' => $response->getStatusCode(), 'address' => $server['REMOTE_ADDR'] ?? '', 'request' => $requeststring, 'referer' => $server['HTTP_REFERER'] ?? '', 'user-agent' => $server['HTTP_USER_AGENT'] ?? '', 'duration' => number_format(microtime(true) - $request_start, 3)]);
+			$this->logSlowCalls(microtime(true) - $request_start, $response->getStatusCode(), $requeststring, $server['HTTP_USER_AGENT'] ?? '');
 			System::echoResponse($response);
 		} catch (HTTPException $e) {
 			$this->logger->debug('Request processed with exception', ['response' => $e->getCode(), 'address' => $server['REMOTE_ADDR'] ?? '', 'request' => $requeststring, 'referer' => $server['HTTP_REFERER'] ?? '', 'user-agent' => $server['HTTP_USER_AGENT'] ?? '', 'duration' => number_format(microtime(true) - $request_start, 3)]);
+			$this->logSlowCalls(microtime(true) - $request_start, $e->getCode(), $requeststring, $server['HTTP_USER_AGENT'] ?? '');
 			$httpException->rawContent($e);
 		}
 		$page->logRuntime($this->config, 'runFrontend');
@@ -707,4 +714,30 @@ class App
 			$this->baseURL->redirect($toUrl);
 		}
 	}
+
+	/**
+	 * Log slow page executions
+	 *
+	 * @param float $duration
+	 * @param integer $code
+	 * @param string $request
+	 * @param string $agent
+	 * @return void
+	 */
+	private function logSlowCalls(float $duration, int $code, string $request, string $agent)
+	{
+		$logfile  = $this->config->get('system', 'page_execution_logfile');
+		$loglimit = $this->config->get('system', 'page_execution_log_limit');
+		if (empty($logfile) || empty($loglimit) || ($duration < $loglimit)) {
+			return;
+		}
+
+		@file_put_contents(
+			$logfile,
+			DateTimeFormat::utcNow() . "\t" . round($duration, 3) . "\t" .
+			$this->requestId . "\t" . $code . "\t" .
+			$request . "\t" . $agent . "\n",
+			FILE_APPEND
+		);
+	}
 }
diff --git a/static/defaults.config.php b/static/defaults.config.php
index 3988e753c2..ab651b7929 100644
--- a/static/defaults.config.php
+++ b/static/defaults.config.php
@@ -449,6 +449,15 @@ return [
 		// Optimizes all tables instead of only tables like workerqueue or the cache
 		'optimize_all_tables' => false,
 
+		// page_execution_logfile (Path)
+		// Name of a logfile to log slow page executions.
+		'page_execution_logfile' => '',
+
+		// page_execution_log_limit (Integer)
+		// If a page execution lasts longer than this value in seconds it is logged.
+		// Inactive if system => page_execution_logfile is empty.
+		'page_execution_log_limit' => 2,
+
 		// paranoia (Boolean)
 		// Log out users if their IP address changed.
 		'paranoia' => false,