[Core] Add performance profiler logger

This adds a new Profiler class that can be used for logging performance
bottlenecks in LORIS. To use it, add a call to Profiler::checkpoint("message")
and if the profiler is enabled in the configuration module (default, disabled)
it will print to the error logs a timestamp, how long the request has taken
so far, the message, max memory usage, and any new memory usage since the last
checkpoint call.

This can be used to debug where requests are slowing down. The checkpoints added
in this PR are the places that I used to optimize the dataquery module.

SQL/0000-00-03-ConfigTables.sql

@@ -169,6 +169,7 @@ INSERT INTO ConfigSettings (Name, Description, Visible, AllowMultiple, Label, Or
 INSERT INTO ConfigSettings (Name, Description, Visible, AllowMultiple, DataType, Parent, Label, OrderNumber) SELECT 'database_log_level', 'Verbosity of database logging', 1, 0, 'log_level', ID, 'Database Log Level', 3 FROM ConfigSettings WHERE Name='logs';
 INSERT INTO ConfigSettings (Name, Description, Visible, AllowMultiple, DataType, Parent, Label, OrderNumber) SELECT 'request_log_level', 'Verbosity of HTTP request logs', 1, 0, 'log_level', ID, 'HTTP Request Log Level', 3 FROM ConfigSettings WHERE Name='logs';
 INSERT INTO ConfigSettings (Name, Description, Visible, AllowMultiple, DataType, Parent, Label, OrderNumber) SELECT 'exception_log_level', 'Verbosity of PHP exception logging', 1, 0, 'log_level', ID, 'Exception Log Level', 3 FROM ConfigSettings WHERE Name='logs';
+INSERT INTO ConfigSettings (Name, Description, Visible, AllowMultiple, DataType, Parent, Label, OrderNumber) SELECT 'profiler_log_level', 'Verbosity of performance profiler logging', 1, 0, 'log_level', ID, 'Profiler Log Level', 3 FROM ConfigSettings WHERE Name='logs';
 
 INSERT INTO ConfigSettings (Name, Description, Visible, AllowMultiple, Label, OrderNumber) VALUES ('aws', 'Settings related to AWS services', 1, 0, 'AWS Settings', 13);
 INSERT INTO ConfigSettings (Name, Description, Visible, AllowMultiple, DataType, Parent, Label, OrderNumber) SELECT 'AWS_S3_Endpoint', 'Endpoint to use for accessing files stored in S3. Endpoint or region are required for S3 support.', 1, 0, 'text', ID, 'AWS S3 Endpoint', 3 FROM ConfigSettings WHERE Name='aws';

SQL/New_patches/2024-profiler_log.sql

@@ -0,0 +1,2 @@
+INSERT INTO ConfigSettings (Name, Description, Visible, AllowMultiple, DataType, Parent, Label, OrderNumber) SELECT 'profiler_log_level', 'Verbosity of performance profiler logging', 1, 0, 'log_level', ID, 'Profiler Log Level', 3 FROM ConfigSettings WHERE Name='logs';
+

php/libraries/LogSettings.class.inc

@@ -50,4 +50,14 @@ class LogSettings
     {
         return $this->levels['exception_log_level']  ?? "none";
     }
+
+    /**
+     * Get the current verbosity level for performance profile logging
+     *
+     * @return string
+     */
+    function getProfilerLogLevel() : string
+    {
+        return $this->levels['profile_log_level']  ?? "none";
+    }
 }

php/libraries/Profiler.php

@@ -0,0 +1,65 @@
+<?php declare(strict_types=1);
+
+use \Psr\Log\LoggerInterface;
+
+/**
+ * Class to consistently log profiling related information to LORIS
+ * logs so that performance issues can be more easily debugged.
+ *
+ * @license http://www.gnu.org/licenses/gpl-3.0.txt GPLv3
+ */
+class Profiler
+{
+    protected \DateTimeImmutable $startTime;
+    protected ?\DateTimeImmutable $lastCheckpoint;
+    protected int $lastMemory;
+    protected LoggerInterface $logger;
+
+    /**
+     * Private constructor that is only called from checkpoint, so
+     * that a singleton is used.
+     */
+    private function __construct()
+    {
+
+        $this->startTime  = new \DateTimeImmutable();
+        $this->lastMemory = memory_get_peak_usage();
+
+	$loglevel = \NDB_Config::singleton()->getLogSettings()->getProfilerLogLevel();
+	if ($loglevel !== "none") {
+		$this->logger     = new \LORIS\Log\ErrorLogLogger(\Psr\Log\LogLevel::DEBUG);
+	} else {
+		$this->logger = new \Psr\Log\NullLogger();
+	}
+    }
+
+    /**
+     * Adds a checkpoint to the error logs that displays the timing since
+     * the initial checkpoint, and any increase in the PHP max memory usage
+     * since the last checkpoint.
+     *
+     * @param string $msg - A message to display with the stats in the log
+     *
+     * @return void
+     */
+    public static function checkpoint(string $msg) : void
+    {
+        static $profiler = new Profiler();
+        $currentMemory   = memory_get_peak_usage();
+        $now = new \DateTimeImmutable();
+        $profiler->logger->debug(
+            "["
+            . $now->format("U")
+            . " ("
+            . $now->diff($profiler->startTime)->format("%s") . "s)] "
+            . $msg
+            . ' (Max memory: '
+            . $currentMemory
+            . ', since last checkpoint: '
+            . ($currentMemory - $profiler->lastMemory)
+            . ')'
+        );
+        $profiler->lastCheckpoint = new \DateTimeImmutable();
+        $profiler->lastMemory     = $currentMemory;
+    }
+}