[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';
+

htdocs/index.php

@@ -34,6 +34,7 @@
 $client = new \NDB_Client;
 $client->initialize();
 
+Profiler::checkpoint("Profiler started");
 // Middleware that happens on every request. This doesn't include
 // any authentication middleware, because that's done dynamically
 // based on the module router, depending on if the module is public.

modules/dataquery/php/endpoints/queries/query/count.class.inc

@@ -58,9 +58,12 @@ class Count extends \LORIS\Http\Endpoint
     public function countResults(\User $user, int $queryID) : ResponseInterface
     {
         try {
+            \Profiler::checkpoint("Creating query");
             $query = new \LORIS\dataquery\Query($this->loris, $queryID);
 
+            \Profiler::checkpoint("Matching candidates");
             $candidates = \iterator_to_array($query->matchCandidates($user));
+            \Profiler::checkpoint("Returning count");
             return new \LORIS\Http\Response\JSON\OK(
                 [
                     'count' => count($candidates),

modules/dataquery/php/query.class.inc

@@ -545,8 +545,10 @@ class Query implements \LORIS\StudyEntities\AccessibleResource,
         $criteria = $this->getCriteria();
 
         if ($criteria) {
+            \Profiler::checkpoint("Matching with criteria");
             $candidates = $this->_candidateMatches($criteria);
         } else {
+            \Profiler::checkpoint("Matching all candidates");
             $candidates = $this->_allCandidates();
         }
         return $this->_filterInaccessibleCandidates($candidates, $user);
@@ -564,6 +566,7 @@ class Query implements \LORIS\StudyEntities\AccessibleResource,
         array $candIDs,
         \User $user,
     ) : iterable {
+        \Profiler::checkpoint("Filtering inaccessible candidates");
         if (count($candIDs) == 0) {
             return [];
         }
@@ -640,6 +643,7 @@ class Query implements \LORIS\StudyEntities\AccessibleResource,
                 yield $canddata->CandID;
             }
         }
+        \Profiler::checkpoint("Finished filtering candidates");
     }
 
     /**
@@ -678,7 +682,9 @@ class Query implements \LORIS\StudyEntities\AccessibleResource,
         }
 
         foreach ($criteria['group'] as $crit) {
+            \Profiler::checkpoint("Checking groups");
             if (isset($crit['group'])) {
+                \Profiler::checkpoint("Subgroup");
                 $subresults = $this->_candidateMatches($crit);
                 if (is_array($subresults)) {
                     $results[] = $subresults;
@@ -747,12 +753,14 @@ class Query implements \LORIS\StudyEntities\AccessibleResource,
                 $visitlist = $query['visits'];
             }
 
+            \Profiler::checkpoint("Calling engine get matches");
             $matches = $engine->getCandidateMatches($term, $visitlist);
             if (is_array($matches)) {
                 $results[] = $matches;
             } else {
                 $results[] = iterator_to_array($matches);
             }
+            \Profiler::checkpoint("Done group");
         }
         $combinedresult = [];
         if (count($results) == 1) {

modules/instruments/php/instrumentqueryengine.class.inc

@@ -104,14 +104,16 @@ class InstrumentQueryEngine implements \LORIS\Data\Query\QueryEngine
             throw new \DomainException("Field for unknown instrument");
         }
 
-        $inst   = \NDB_BVL_Instrument::factory($this->loris, $testname);
+        $inst = \NDB_BVL_Instrument::factory($this->loris, $testname);
+        \Profiler::checkpoint("After NDB_BVL_Instrument::factory for $testname");
         $values = $inst->bulkLoadInstanceData(
             null,
             $term,
         );
         foreach ($values as $match) {
             yield $match->getCandID();
         }
+        \Profiler::checkpoint("Finished bulk load for $testname");
         return;
     }
 

php/libraries/LogSettings.class.inc

@@ -51,4 +51,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['profiler_log_level']  ?? "none";
+    }
 }

php/libraries/NDB_BVL_Instrument.class.inc

@@ -2299,7 +2299,7 @@ abstract class NDB_BVL_Instrument extends NDB_Page
                         JOIN instrument_data ON (flag.DataID=instrument_data.ID)
 			JOIN test_names tn ON (tn.ID=flag.TestID)
 			$where";
-
+            \Profiler::checkpoint("Running query (JSON data): " . $query);
             $jsondata = $db->pselect($query, $params);
             foreach ($jsondata as $row) {
                     $newinst = clone $this;
@@ -2316,6 +2316,7 @@ abstract class NDB_BVL_Instrument extends NDB_Page
                     ) ?? $this->defaultInstanceData();
                     yield $newinst;
             }
+            \Profiler::checkpoint("Finished query");
             return;
         } else {
             $conditions   = ['tn.test_name=:tn'];
@@ -2353,7 +2354,8 @@ abstract class NDB_BVL_Instrument extends NDB_Page
 		    JOIN test_names tn ON (tn.ID=f.TestID)
                     JOIN session ON (f.SessionID=session.ID)
 		 $where";
-            $data  = $db->pselect($query, $params);
+            \Profiler::checkpoint("Running query (table instrument): " . $query);
+            $data = $db->pselect($query, $params);
             foreach ($data as $row) {
                     $newinst = clone $this;
 
@@ -2367,6 +2369,7 @@ abstract class NDB_BVL_Instrument extends NDB_Page
 
                     yield $newinst;
             }
+            \Profiler::checkpoint("Finished query");
             return;
         }
     }

php/libraries/Profiler.php

@@ -0,0 +1,67 @@
+<?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;
+    }
+}