404-solution / includes / diagnostics / QueryBudgetInstrumentation.php

QueryBudgetInstrumentation.php in 404 Solution trunk, at includes/diagnostics/QueryBudgetInstrumentation.php

324 lines 11.7 KB

Raw Download Zip

1	<?php
2
3	if (!defined('ABSPATH')) {
4	exit;
5	}
6
7	/**
8	* Runtime instrumentation for queryAndGetResults() durations and request-level
9	* timeout budgets.
10	*
11	* Implements technique 4 of docs/PROACTIVE_BUG_DISCOVERY.md ("Reverse-proxy
12	* timeout budget audit"). Disabled by default — turned on per-process by
13	* setting either:
14	* - environment variable ABJ404_QUERY_BUDGET_LOG=<directory>
15	* - PHP constant ABJ404_QUERY_BUDGET_LOG (string path to a writable directory)
16	*
17	* When enabled, every queryAndGetResults() call records:
18	* - resolved SQL source identifier (filename, /* abj404:src=ID */ marker,
19	* or backtrace-derived Class::method — see DataAccess::extractSqlFilename)
20	* - elapsed wall-clock ms
21	* - per-query timeout hint actually used (s)
22	* - timestamp + request URI
23	*
24	* On shutdown, if any single query exceeded its per-query budget OR the request's
25	* cumulative DB time exceeded the request budget (default 25s — below the
26	* Cloudflare ~100s and nginx ~60s reverse-proxy cutoffs, with margin for
27	* non-DB request work), one JSONL violation entry is appended to
28	* `<dir>/slow-query-budget-violations.log`.
29	*
30	* The log shape is intentionally append-only JSONL so multiple Playwright
31	* worker processes can write concurrently without coordination, and so
32	* failing E2E runs can attach the file as an artifact for triage.
33	*/
34	class ABJ_404_Solution_QueryBudgetInstrumentation {
35
36	/** Default per-request cumulative budget in milliseconds (admin/AJAX). */
37	const DEFAULT_REQUEST_BUDGET_MS = 25000;
38
39	/** Default per-query budget in milliseconds — same as the cumulative cap. */
40	const DEFAULT_QUERY_BUDGET_MS = 25000;
41
42	/** @var bool\|null Lazily resolved enabled flag. */
43	private static $enabled = null;
44
45	/** @var string\|null Lazily resolved log directory. */
46	private static $logDir = null;
47
48	/** @var bool */
49	private static $shutdownRegistered = false;
50
51	/**
52	* Per-request recording buffer.
53	*
54	* @var array{queries: list<array{sql:string, elapsed_ms:float, timeout_s:int, ts:float}>, request_budget_ms: int, started_at: float}\|null
55	*/
56	private static $state = null;
57
58	/**
59	* Returns true if instrumentation is enabled for this process.
60	*
61	* Reads from the ABJ404_QUERY_BUDGET_LOG environment variable or the same
62	* named PHP constant. The value, if non-empty, is the directory the
63	* violations log is written to. An explicit "0" / "false" / empty value
64	* keeps it disabled.
65	*/
66	public static function isEnabled(): bool {
67	if (self::$enabled !== null) {
68	return self::$enabled;
69	}
70	$dir = self::resolveLogDir();
71	self::$enabled = ($dir !== null && $dir !== '');
72	return self::$enabled;
73	}
74
75	/**
76	* Returns the log directory, or null if instrumentation is disabled or
77	* the directory is unwritable. Result is cached.
78	*/
79	public static function logDir(): ?string {
80	if (self::$logDir !== null) {
81	return self::$logDir === '' ? null : self::$logDir;
82	}
83	$dir = self::resolveLogDir();
84	if ($dir === null \|\| $dir === '') {
85	self::$logDir = '';
86	return null;
87	}
88	if (!is_dir($dir)) {
89	$made = @mkdir($dir, 0755, true);
90	if (!$made && !is_dir($dir)) {
91	self::$logDir = '';
92	return null;
93	}
94	}
95	if (!is_writable($dir)) {
96	self::$logDir = '';
97	return null;
98	}
99	self::$logDir = $dir;
100	return self::$logDir;
101	}
102
103	/** @return string\|null */
104	private static function resolveLogDir(): ?string {
105	$envVal = getenv('ABJ404_QUERY_BUDGET_LOG');
106	if (is_string($envVal) && $envVal !== '' && $envVal !== '0' && strtolower($envVal) !== 'false') {
107	return $envVal;
108	}
109	if (defined('ABJ404_QUERY_BUDGET_LOG')) {
110	$constVal = constant('ABJ404_QUERY_BUDGET_LOG');
111	if (is_string($constVal) && $constVal !== '' && $constVal !== '0' && strtolower($constVal) !== 'false') {
112	return $constVal;
113	}
114	}
115	return null;
116	}
117
118	/**
119	* Path to the violations log inside the configured log directory.
120	*/
121	public static function violationLogPath(): ?string {
122	$dir = self::logDir();
123	if ($dir === null) {
124	return null;
125	}
126	return rtrim($dir, "/\\") . DIRECTORY_SEPARATOR . 'slow-query-budget-violations.log';
127	}
128
129	/**
130	* Per-request cumulative budget in ms. Override by defining
131	* ABJ404_REQUEST_BUDGET_MS as a positive integer.
132	*/
133	public static function requestBudgetMs(): int {
134	if (defined('ABJ404_REQUEST_BUDGET_MS')) {
135	$v = constant('ABJ404_REQUEST_BUDGET_MS');
136	if (is_int($v) && $v > 0) {
137	return $v;
138	}
139	if (is_string($v) && ctype_digit($v) && (int)$v > 0) {
140	return (int)$v;
141	}
142	}
143	return self::DEFAULT_REQUEST_BUDGET_MS;
144	}
145
146	/**
147	* Records a single queryAndGetResults() invocation.
148	*
149	* @param string $sqlInfo Resolved source identifier (NOT raw SQL — keeps log PII-free)
150	* @param float $elapsedMs Wall-clock duration in milliseconds
151	* @param int $timeoutSeconds The per-query timeout hint actually applied
152	* @return void
153	*/
154	public static function recordQuery(string $sqlInfo, float $elapsedMs, int $timeoutSeconds): void {
155	if (!self::isEnabled()) {
156	return;
157	}
158	if (self::$state === null) {
159	self::initState();
160	}
161	// Ensure the shutdown flush is wired even when the early-return paths
162	// in queryAndGetResults() short-circuit before WordPress finishes
163	// booting. register_shutdown_function is idempotent for our purposes
164	// because flushOnShutdown() guards against double-emission.
165	self::ensureShutdownRegistered();
166
167	// Empty input would erase the source attribution that drives triage,
168	// so substitute a stable sentinel. DataAccess::extractSqlFilename
169	// never produces empty strings — this guards against external callers.
170	$sqlInfo = $sqlInfo === '' ? 'unknown-source' : $sqlInfo;
171	if (strlen($sqlInfo) > 200) {
172	$sqlInfo = substr($sqlInfo, 0, 200);
173	}
174	/** @var array{queries: list<array{sql:string, elapsed_ms:float, timeout_s:int, ts:float}>, request_budget_ms: int, started_at: float} $state */
175	$state = self::$state;
176	$state['queries'][] = array(
177	'sql' => $sqlInfo,
178	'elapsed_ms' => max(0.0, $elapsedMs),
179	'timeout_s' => max(0, $timeoutSeconds),
180	'ts' => abj_clock()->nowFloat(),
181	);
182	self::$state = $state;
183	}
184
185	/** @return void */
186	private static function initState(): void {
187	self::$state = array(
188	'queries' => array(),
189	'request_budget_ms' => self::requestBudgetMs(),
190	'started_at' => abj_clock()->nowFloat(),
191	);
192	}
193
194	/** @return void */
195	private static function ensureShutdownRegistered(): void {
196	if (self::$shutdownRegistered) {
197	return;
198	}
199	self::$shutdownRegistered = true;
200	register_shutdown_function(array(__CLASS__, 'flushOnShutdown'));
201	}
202
203	/**
204	* Flush on shutdown: if the request violated the budget, append one JSONL
205	* entry to the violations log.
206	*
207	* @return void
208	*/
209	public static function flushOnShutdown(): void {
210	if (!self::isEnabled() \|\| self::$state === null) {
211	return;
212	}
213	$entry = self::buildViolationEntry();
214	// Reset state so re-flush (e.g. test calling flushOnShutdown() twice)
215	// does not double-emit.
216	$state = self::$state;
217	self::$state = null;
218	if ($entry === null) {
219	return;
220	}
221	$path = self::violationLogPath();
222	if ($path === null) {
223	return;
224	}
225	$line = json_encode($entry, JSON_UNESCAPED_SLASHES);
226	if ($line === false) {
227	return;
228	}
229	// file_put_contents with FILE_APPEND \| LOCK_EX is concurrency-safe
230	// across Playwright worker processes.
231	@file_put_contents($path, $line . "\n", FILE_APPEND \| LOCK_EX);
232	}
233
234	/**
235	* Build a violation entry for the current request, or null if no budget
236	* was exceeded.
237	*
238	* @return array<string,mixed>\|null
239	*/
240	private static function buildViolationEntry(): ?array {
241	if (self::$state === null) {
242	return null;
243	}
244	$budgetMs = self::$state['request_budget_ms'];
245	$totalMs = 0.0;
246	$perQueryViolations = array();
247	foreach (self::$state['queries'] as $q) {
248	$totalMs += $q['elapsed_ms'];
249	// Per-query budget: timeout_s converted to ms, capped at the
250	// request budget (since a single query above the request budget
251	// is by definition a violation).
252	$perQueryBudgetMs = min(self::DEFAULT_QUERY_BUDGET_MS,
253	$q['timeout_s'] > 0 ? $q['timeout_s'] * 1000 : self::DEFAULT_QUERY_BUDGET_MS);
254	if ($q['elapsed_ms'] > $perQueryBudgetMs) {
255	$perQueryViolations[] = array(
256	'sql' => $q['sql'],
257	'elapsed_ms' => round($q['elapsed_ms'], 2),
258	'budget_ms' => $perQueryBudgetMs,
259	'reason' => 'per-query',
260	);
261	}
262	}
263	$cumulativeViolation = $totalMs > $budgetMs;
264	if (empty($perQueryViolations) && !$cumulativeViolation) {
265	return null;
266	}
267	return array(
268	'ts' => gmdate('Y-m-d\TH:i:s\Z', abj_clock()->now()),
269	'uri' => self::currentRequestUri(),
270	'request_total_ms' => round($totalMs, 2),
271	'request_budget_ms' => $budgetMs,
272	'query_count' => count(self::$state['queries']),
273	'cumulative_violation' => $cumulativeViolation,
274	'violations' => $perQueryViolations,
275	);
276	}
277
278	/** @return string */
279	private static function currentRequestUri(): string {
280	$uri = isset($_SERVER['REQUEST_URI']) && is_string($_SERVER['REQUEST_URI']) ? $_SERVER['REQUEST_URI'] : '';
281	if ($uri === '' && isset($_SERVER['SCRIPT_NAME']) && is_string($_SERVER['SCRIPT_NAME'])) {
282	$uri = $_SERVER['SCRIPT_NAME'];
283	}
284	if ($uri === '' && PHP_SAPI === 'cli') {
285	$uri = 'cli://' . (isset($_SERVER['argv'][0]) ? basename((string)$_SERVER['argv'][0]) : 'php');
286	}
287	return $uri === '' ? '(unknown)' : substr($uri, 0, 500);
288	}
289
290	/**
291	* Reset all internal state. Test-only. Production code never calls this.
292	*
293	* @return void
294	*/
295	public static function resetForTests(): void {
296	self::$enabled = null;
297	self::$logDir = null;
298	self::$state = null;
299	self::$shutdownRegistered = false;
300	}
301	}
302
303	/**
304	* Top-level recording entry point — called from queryAndGetResults(). The
305	* indirection through a free function (rather than a direct class method
306	* call) mirrors the existing abj404_benchmark_record_db_query() hook so that
307	* environments without the instrumentation file loaded incur zero cost
308	* (the function_exists() guard at the call site short-circuits).
309	*
310	* @param string $sqlInfo
311	* @param float $elapsedMs
312	* @param int $timeoutSeconds
313	* @return void
314	*/
315	if (!function_exists('abj404_query_budget_record')) {
316	function abj404_query_budget_record(string $sqlInfo, float $elapsedMs, int $timeoutSeconds): void {
317	ABJ_404_Solution_QueryBudgetInstrumentation::recordQuery(
318	$sqlInfo,
319	$elapsedMs,
320	$timeoutSeconds
321	);
322	}
323	}
324