Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
27 commits
Select commit Hold shift + click to select a range
7da81b2
fix(serializer): add last_edited timestamp to presentation cache key …
smarcet May 23, 2026
34d39eb
chore(routes): enable server.timing.doctrine on getEvents for profiling
smarcet May 23, 2026
07882a0
chore(profiling): expose per-phase request breakdown via Server-Timin…
smarcet May 23, 2026
d09ff46
fix(profiling): accurate DB time measurement via DBAL Driver Middleware
smarcet May 23, 2026
3c04297
chore(profiling): log top-repeating SQL patterns to identify exact N+…
smarcet May 23, 2026
9a9e23e
fix(member): memoize belongsToGroup() per-instance to eliminate N+1 o…
smarcet May 23, 2026
c6fa4d3
fix(repository): preload PresentationSpeaker + Member in single DQL q…
smarcet May 23, 2026
b3ba482
fix(repository): include root alias 'a' in speaker+member preload SELECT
smarcet May 23, 2026
098d513
chore(debug): instrument preload to confirm what it loads
smarcet May 23, 2026
92596db
chore(debug): capture Member query params to identify which Members a…
smarcet May 23, 2026
0aab8d1
fix(debug): strip backticks before matching Member table name
smarcet May 23, 2026
9883ff4
fix(auth): memoize getCurrentUser() — eliminates ~98 redundant Member…
smarcet May 23, 2026
5043231
fix(repository): batch-preload SummitSelectedPresentation, eliminates…
smarcet May 23, 2026
e49226a
chore(debug): instrument SummitSelectedPresentation preload to find w…
smarcet May 25, 2026
bec63ec
fix(speaker): pre-populate getPresentationAssignmentOrder cache from …
smarcet May 25, 2026
9a40015
fix(repository): preload location (FETCH JOIN), tags and materials in…
smarcet May 25, 2026
1376db2
fix(repository): preload sponsors batch + fetch-join PresentationCate…
smarcet May 25, 2026
e919d1c
chore(cleanup): remove diagnostic logging used to profile the /events…
smarcet May 25, 2026
f6d3997
docs(adr): document /events N+1 elimination work
smarcet May 25, 2026
56610bb
fix(events): correct SummitSelectedPresentation preload DQL and cache…
smarcet May 25, 2026
1506fd1
fix(events): low-severity findings + unit tests from PR #549 review
smarcet May 25, 2026
ad726c4
fix(trait): restore optional afterQuery hook in _getAll
smarcet May 25, 2026
0707b34
fix(timing): replace Session with request attributes for sub-phase ti…
smarcet May 26, 2026
a117437
fix(timing): use import instead of fully qualified class for QueryTim…
smarcet May 26, 2026
96e036a
fix(auth): track side-effects independently in getCurrentUser cache
smarcet May 26, 2026
f29b535
fix(presentation): reset memoizedSelectionStatus on all state-mutatin…
smarcet May 26, 2026
1bfc58c
fix(cache): bump last_edited on association-only mutations to bust Pr…
smarcet May 26, 2026
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
380 changes: 380 additions & 0 deletions adr/002-events-endpoint-n-plus-1-elimination.md

Large diffs are not rendered by default.

Original file line number Diff line number Diff line change
Expand Up @@ -170,24 +170,28 @@ private function getSerializerType(): string
*/
public function getEvents($summit_id)
{
return $this->processRequest(function () use ($summit_id) {
$req = request();
$req->attributes->set('timing.controller_start', microtime(true));
return $this->processRequest(function () use ($summit_id, $req) {
$current_user = $this->resource_server_context->getCurrentUser(true);
return $this->withReplica(function() use ($summit_id, $current_user) {
return $this->withReplica(function() use ($summit_id, $current_user, $req) {
$strategy = new RetrieveAllSummitEventsBySummitStrategy($this->repository, $this->event_repository, $this->resource_server_context);
$response = $strategy->getEvents(['summit_id' => $summit_id]);
return $this->ok
$req->attributes->set('timing.serializer_start', microtime(true));
$data = $response->toArray
(
$response->toArray
(
SerializerUtils::getExpand(),
SerializerUtils::getFields(),
SerializerUtils::getRelations(),
[
'current_user' => $current_user
SerializerUtils::getExpand(),
SerializerUtils::getFields(),
SerializerUtils::getRelations(),
[
'current_user' => $current_user
],
$this->getSerializerType()
)
$this->getSerializerType()
);
$req->attributes->set('timing.serializer_end', microtime(true));
$result = $this->ok($data);
$req->attributes->set('timing.controller_end', microtime(true));
return $result;
});

});
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -82,7 +82,8 @@ public function _getAll
callable $defaultOrderRules = null,
callable $defaultPageSize = null,
callable $queryCallable = null,
array $serializerParams = []
array $serializerParams = [],
callable $afterQuery = null
)
{
return $this->processRequest(function () use (
Expand All @@ -94,7 +95,8 @@ public function _getAll
$defaultOrderRules,
$defaultPageSize,
$queryCallable,
$serializerParams
$serializerParams,
$afterQuery
) {
$values = Request::all();

Expand Down Expand Up @@ -139,6 +141,14 @@ public function _getAll
$applyExtraFilters
);
$dbEnd = (microtime(true)-$dbStart)*1000;

// Optional post-load hook so callers can pre-populate caches /
// batch-load related entities before serialization runs. Receives
// the PagingResponse so it can inspect items.
if (is_callable($afterQuery)) {
$afterQuery($data);
}

$transformStart = microtime(true);
$serializerParams['filter'] = $filter;
$res = $data->toArray
Expand Down
29 changes: 29 additions & 0 deletions app/Http/Middleware/Doctrine/QueryTimingCollector.php
Original file line number Diff line number Diff line change
@@ -0,0 +1,29 @@
<?php

namespace App\Http\Middleware\Doctrine;

/**
* Request-scoped accumulator for SQL execution times.
*
* Static so that the DBAL Driver Middleware (instantiated by Doctrine on
* connection creation) and the request lifecycle middleware (ServerTimingDoctrine)
* can share state without needing dependency injection through Doctrine's
* internals. Reset at request start by ServerTimingDoctrine.
*/
class QueryTimingCollector
{
public static float $totalMs = 0.0;
public static int $count = 0;

public static function record(float $startedAt): void
{
self::$totalMs += (microtime(true) - $startedAt) * 1000.0;
self::$count++;
}

public static function reset(): void
{
self::$totalMs = 0.0;
self::$count = 0;
}
}
77 changes: 77 additions & 0 deletions app/Http/Middleware/Doctrine/QueryTimingMiddleware.php
Original file line number Diff line number Diff line change
@@ -0,0 +1,77 @@
<?php

namespace App\Http\Middleware\Doctrine;

use Doctrine\DBAL\Driver as DBALDriver;
use Doctrine\DBAL\Driver\Connection as DBALConnection;
use Doctrine\DBAL\Driver\Middleware as DBALMiddleware;
use Doctrine\DBAL\Driver\Middleware\AbstractConnectionMiddleware;
use Doctrine\DBAL\Driver\Middleware\AbstractDriverMiddleware;
use Doctrine\DBAL\Driver\Middleware\AbstractStatementMiddleware;
use Doctrine\DBAL\Driver\Result as DBALResult;
use Doctrine\DBAL\Driver\Statement as DBALStatement;

/**
* DBAL Driver Middleware that records SQL execution duration into
* QueryTimingCollector. Registered globally via config/doctrine.php so it
* times every query in every request; the request-scoped accumulator is
* reset at the top of each request by ServerTimingDoctrine.
*
* Per-query overhead is two microtime(true) calls — negligible.
*/
class QueryTimingMiddleware implements DBALMiddleware
{
public function wrap(DBALDriver $driver): DBALDriver
{
return new QueryTimingDriver($driver);
}
}

class QueryTimingDriver extends AbstractDriverMiddleware
{
public function connect(array $params): DBALConnection
{
return new QueryTimingConnection(parent::connect($params));
}
}

class QueryTimingConnection extends AbstractConnectionMiddleware
{
public function query(string $sql): DBALResult
{
$start = microtime(true);
try {
return parent::query($sql);
} finally {
QueryTimingCollector::record($start);
}
}

public function exec(string $sql): int
{
$start = microtime(true);
try {
return parent::exec($sql);
} finally {
QueryTimingCollector::record($start);
}
}

public function prepare(string $sql): DBALStatement
{
return new QueryTimingStatement(parent::prepare($sql));
}
}

class QueryTimingStatement extends AbstractStatementMiddleware
{
public function execute($params = null): DBALResult
{
$start = microtime(true);
try {
return parent::execute($params);
} finally {
QueryTimingCollector::record($start);
}
}
}
110 changes: 31 additions & 79 deletions app/Http/Middleware/ServerTimingDoctrine.php
Original file line number Diff line number Diff line change
Expand Up @@ -2,101 +2,53 @@

namespace App\Http\Middleware;

use App\Http\Middleware\Doctrine\QueryTimingCollector;
use Closure;
use Doctrine\ORM\EntityManagerInterface;
use Illuminate\Support\Facades\Session;
use LaravelDoctrine\ORM\Facades\Registry;
use models\utils\SilverstripeBaseModel;
use Psr\Log\LoggerInterface;
use Symfony\Component\HttpFoundation\Response;

class ServerTimingDoctrine
{
/** @var EntityManagerInterface */
private EntityManagerInterface $em;


public function __construct()
{
$this->em = Registry::getManager(SilverstripeBaseModel::EntityManager);
}

public function handle($request, Closure $next): Response
{
$start = microtime(true);
$conn = $this->em->getConnection();
$cfg = $conn->getConfiguration();

$dbMs = 0.0;

// --- DBAL 2.x: DebugStack ---
if (class_exists(\Doctrine\DBAL\Logging\DebugStack::class) && method_exists($cfg, 'setSQLLogger')) {
$debugStack = new \Doctrine\DBAL\Logging\DebugStack();
$prevLogger = $cfg->getSQLLogger() ?? null;
$cfg->setSQLLogger($debugStack);
// Reset the request-scoped SQL timing accumulator. The actual per-query
// timing is done by QueryTimingMiddleware, a DBAL Driver Middleware
// registered globally in config/doctrine.php. That gives accurate
// per-statement durations under DBAL 3.x prepared statements, which
// the deprecated SQLLogger / Logging\Middleware paths do not.
QueryTimingCollector::reset();

try {
/** @var Response $response */
$response = $next($request);
} finally {
foreach ($debugStack->queries as $q) {
$dbMs += isset($q['executionMS']) ? (float) $q['executionMS'] : 0.0;
}
$cfg->setSQLLogger($prevLogger);
}
/** @var Response $response */
$response = $next($request);

// --- DBAL 3.x: Logging\Middleware (PSR-3) ---
} elseif (class_exists(\Doctrine\DBAL\Logging\Middleware::class) && method_exists($cfg, 'setMiddlewares')) {
$dbMs = QueryTimingCollector::$totalMs;
$dbCount = QueryTimingCollector::$count;

$end = microtime(true);
$totalMs = ($end - $start) * 1000.0;
$bootMs = defined('LARAVEL_START') ? max(($start - LARAVEL_START) * 1000.0, 0.0) : 0.0;
$appMs = max($totalMs - $dbMs, 0.0);

$collector = new class implements LoggerInterface {
public float $dbMs = 0.0;
public function log($level, $message, array $context = []): void {
if (isset($context['duration_ms'])) {
$this->dbMs += (float) $context['duration_ms'];
} elseif (isset($context['executionMS'])) {
$this->dbMs += (float) $context['executionMS'];
} elseif (isset($context['duration'])) {
$this->dbMs += (float) $context['duration'];
}
}
public function emergency($m, array $c = []):void { $this->log('emergency', $m, $c); }
public function alert($m, array $c = []):void { $this->log('alert', $m, $c); }
public function critical($m, array $c = []):void { $this->log('critical', $m, $c); }
public function error($m, array $c = []):void { $this->log('error', $m, $c); }
public function warning($m, array $c = []):void { $this->log('warning', $m, $c); }
public function notice($m, array $c = []) :void { $this->log('notice', $m, $c); }
public function info($m, array $c = []):void { $this->log('info', $m, $c); }
public function debug($m, array $c = []):void { $this->log('debug', $m, $c); }
};

$mw = new \Doctrine\DBAL\Logging\Middleware($collector);
$prev = method_exists($cfg, 'getMiddlewares') ? $cfg->getMiddlewares() : [];
$cfg->setMiddlewares(array_merge($prev, [$mw]));

try {
/** @var Response $response */
$response = $next($request);
} finally {
$dbMs = $collector->dbMs;
$cfg->setMiddlewares($prev);
}
// Read controller-level timing markers (set by the controller via $request->attributes).
// If the controller didn't set them, these phases are reported as 0.
$attrs = $request->attributes;
$cStart = $attrs->has("timing.controller_start") ? (float) $attrs->get("timing.controller_start") : null;
$cEnd = $attrs->has("timing.controller_end") ? (float) $attrs->get("timing.controller_end") : null;
$sStart = $attrs->has("timing.serializer_start") ? (float) $attrs->get("timing.serializer_start") : null;
$sEnd = $attrs->has("timing.serializer_end") ? (float) $attrs->get("timing.serializer_end") : null;

// --- Fallback
} else {
/** @var Response $response */
$response = $next($request);
}
$preMs = ($cStart !== null) ? max(($cStart - $start) * 1000.0, 0.0) : 0.0;
$controllerMs = ($cStart !== null && $cEnd !== null) ? max(($cEnd - $cStart) * 1000.0, 0.0) : 0.0;
$serializerMs = ($sStart !== null && $sEnd !== null) ? max(($sEnd - $sStart) * 1000.0, 0.0) : 0.0;
$postMs = ($cEnd !== null) ? max(($end - $cEnd) * 1000.0, 0.0) : 0.0;

$totalMs = (microtime(true) - $start) * 1000.0;
$bootMs = defined('LARAVEL_START') ? max(($start - LARAVEL_START) * 1000.0, 0.0) : 0.0;
$appMs = max($totalMs - $dbMs, 0.0);
$dbMs = Session::has("db_time") ? (float) Session::get("db_time") : $dbMs;
$transformMs = Session::has("transform_time") ? (float) Session::get("transform_time") : 0.0;
$encodeMs = Session::has("encode_time") ? (float) Session::get("encode_time") : 0.0;
$response->headers->set('Server-Timing',
sprintf('boot;dur=%.1f,db;dur=%.1f,transform;dur=%.1f,encode;dur=%.1f,app;dur=%.1f,total;dur=%.1f',
$bootMs,$dbMs,$transformMs,$encodeMs,$appMs,$totalMs));
sprintf(
'boot;dur=%.1f,pre;dur=%.1f,controller;dur=%.1f,db;dur=%.1f;desc="%d queries",serializer;dur=%.1f,post;dur=%.1f,app;dur=%.1f,total;dur=%.1f',
$bootMs, $preMs, $controllerMs, $dbMs, $dbCount, $serializerMs, $postMs, $appMs, $totalMs
)
);
$response->headers->set('Timing-Allow-Origin', '*');

return $response;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -104,11 +104,14 @@ public function serialize($expand = null, array $fields = [], array $relations =
$presentation = $this->object;
if(!$presentation instanceof Presentation) return [];

// Include last_edited timestamp so a presentation update naturally busts the cache
// without needing an explicit Cache::forget — the old key just ages out via TTL.
$key =
sprintf
(
"public_presentation_%s_%s_%s_%s",
"public_presentation_%s_%s_%s_%s_%s",
$presentation->getId(),
$presentation->getLastEditedUTC()?->getTimestamp() ?? 0,
$expand ?? "",
implode(",",$fields),
implode(",", $relations)
Expand Down
23 changes: 20 additions & 3 deletions app/Models/Foundation/Main/Member.php
Original file line number Diff line number Diff line change
Expand Up @@ -1041,12 +1041,29 @@ public function getGroupByCode(string $code): ?Group
return $res === false ? null : $res;
}

/**
* Request-scoped cache for group membership lookups. The current-user
* Member instance is shared across the whole request, and the same group
* codes are checked many times by serializers (isAdmin, memberCanEdit,
* etc.) — typical /events request fires this ~80 times for ~8 unique codes.
* Property is unannotated so Doctrine ignores it; resets naturally when
* the entity is re-hydrated on a new request.
*
* @var array<string, bool>
*/
private array $groupMembershipCache = [];

/**
* @param string $code
* @return bool
*/
public function belongsToGroup(string $code): bool
{
$code = trim($code);
if (array_key_exists($code, $this->groupMembershipCache)) {
return $this->groupMembershipCache[$code];
}

try {
$sql = <<<SQL
SELECT COUNT(MemberID)
Expand All @@ -1057,15 +1074,15 @@ public function belongsToGroup(string $code): bool

$stmt = $this->prepareRawSQL($sql, [
'member_id' => $this->getId(),
'code' => trim($code),
'code' => $code,
]);
$res = $stmt->executeQuery();
$res = $res->fetchFirstColumn();
return intval($res[0]) > 0;
return $this->groupMembershipCache[$code] = (intval($res[0]) > 0);
} catch (\Exception $ex) {

}
return false;
return $this->groupMembershipCache[$code] = false;

}

Expand Down
Loading
Loading