Log the page execution performance

diff --git a/src/App.php b/src/App.php
index 73fc77a0668b19828ad68886ccaac3c0c75a66c5..da367186ab84f46b801bece43146764f4d814883 100644 (file)
--- 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 3988e753c22246785ee665734ce41f01f307cd1d..ab651b79299c832eeddbbb634c3e47d1cbe526dc 100644 (file)
--- 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,