404-solution / includes / diagnostics / AjaxQueryTimeline.php

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

463 lines 19.7 KB

Raw Download Zip

1	<?php
2
3	if (!defined('ABSPATH')) {
4	exit;
5	}
6
7	/**
8	* Per-query attribution INSIDE an instrumented admin-AJAX work stage
9	* (Bruno timeout cause matrix, cause class F; gap-hunt iteration 1, gap G5).
10	*
11	* A stage boundary can only say "the request stopped somewhere inside
12	* table_redirects". That one stage covers SQL execution, the row-formatting
13	* loop, URL parsing and normalization, locale handling, and every foreign
14	* callback other plugins attached to the filters our render path runs. Those
15	* are different causes with different fixes, and a stage name cannot separate
16	* them. This class splits the DATABASE half of that window off from the PHP
17	* half; ABJ_404_Solution_AjaxRowLoopProgress splits the row-formatting half.
18	*
19	* ABJ_404_Solution_QueryBudgetInstrumentation already watches the same seam,
20	* and is deliberately left alone: it answers a different question (did this
21	* request blow a reverse-proxy timeout budget?) on a different trigger, with a
22	* different gate and a different sink -- a side file that nothing in the
23	* support or feedback path ever reads. Three properties are what make it
24	* unusable for the one session this investigation gets, and are therefore the
25	* three properties this class is built around:
26	*
27	* - ARMED BY THE LEDGER, NOT BY AN ENVIRONMENT VARIABLE. Recording is on for
28	* exactly the requests ABJ_404_Solution_AjaxRequestLedger already scopes
29	* its checkpoints to -- the admin table AJAX endpoint -- and off everywhere
30	* else, so the hot front-end 404 path pays nothing and a beta build needs
31	* no server-side configuration to produce evidence.
32	*
33	* - RECORDED BEFORE THE QUERY RUNS, NOT AFTER IT. A query that blocks and
34	* never returns writes nothing at all if the record is emitted on
35	* completion: the last line on disk would describe the PREVIOUS query, and
36	* the shape of the one that actually hung -- the single most decisive fact
37	* about a stall inside a stage -- would be exactly what is missing. Each
38	* probe therefore names the query that is about to execute and carries the
39	* PRECEDING query's duration, so the full timeline is still reconstructable
40	* while the in-flight query is always named. The final query's own duration
41	* arrives with the summary emitted at response time.
42	*
43	* - ALWAYS, NOT ONLY ON A BUDGET VIOLATION. A stall assembled from two
44	* hundred individually-fast queries never crosses a slow-query threshold,
45	* and that shape is one of the live hypotheses. Recording only violations
46	* is structurally blind to it.
47	*
48	* Records go through ABJ_404_Solution_AjaxCheckpointLogger's high-frequency
49	* envelope, which means they are joined to the ledger request ID, ranked by
50	* ABJ_404_Solution_DiagnosticEvidencePriority, and carried by the support
51	* payload and the developer log archive with no extra plumbing.
52	*
53	* SQL is recorded as a SHAPE only, through the existing redaction helper:
54	* quoted literals and numbers become `?` before anything is written, so a
55	* user's URLs never reach the journal.
56	*
57	* @phpstan-type AbjOpenQuery array{q: int, started_at: float\|null,
58	* breadcrumb: array<string, mixed>\|null}
59	* @phpstan-type AbjSlowestQuery array{q: int, ms: float}
60	* @phpstan-type AbjTimelineState array{request_id: string, count: int, recorded: int,
61	* db_ms: float, last_ms: float\|null, open: AbjOpenQuery\|null,
62	* slowest: AbjSlowestQuery\|null, capped: bool, summarized: bool}
63	*/
64	final class ABJ_404_Solution_AjaxQueryTimeline {
65
66	/**
67	* Probe records emitted per request before recording stops.
68	*
69	* Chosen as a cost ceiling, not as an expected count: a table request
70	* issues well under this, so the cap only ever binds on a pathological
71	* request -- and on such a request the query COUNT is itself the finding,
72	* which the summary still reports truthfully. The transition is announced
73	* with its own record rather than happening silently, because an evidence
74	* channel that quietly stops is the failure mode this whole subsystem
75	* exists to prevent.
76	*/
77	const MAX_RECORDED_QUERIES = 60;
78
79	/**
80	* Bytes of redacted SQL shape kept per probe.
81	*
82	* The redaction helper's own 4000-character ceiling is sized for a single
83	* fatal-error report; at up to 60 probes per request it would let one
84	* request eat the entire support excerpt. The leading clauses are what
85	* identify a query, so the head is what is kept, and `sql_len` states the
86	* true length so truncation is never mistaken for a short query.
87	*/
88	const MAX_SHAPE_LENGTH = 400;
89
90	/** Marker for "no query has completed yet", kept distinct from a zero duration. */
91	const PREV_NONE = 'none';
92
93	/** The preceding query returned normally and its duration is trustworthy. */
94	const PREV_COMPLETE = 'complete';
95
96	/**
97	* The preceding query never reported a completion. Either it threw past
98	* the executor's recording call or a nested recovery query interleaved
99	* with it; in both cases `prev_ms` is withheld rather than guessed.
100	*/
101	const PREV_UNFINISHED = 'unfinished';
102
103	/**
104	* @var AbjTimelineState\|null
105	* @phpstan-var AbjTimelineState\|null
106	*/
107	private static $state = null;
108
109	/** @var ABJ_404_Solution_AjaxFailureLogger\|null Cached; redaction is stateless. */
110	private static $redactor = null;
111
112	/**
113	* The ledger ID of the request whose queries are being attributed, or ''
114	* when this request is out of scope.
115	*
116	* Delegated to the ledger rather than re-deriving the scope here, so the
117	* per-query channel can never drift out of step with the boundary
118	* checkpoints it has to be read alongside.
119	*/
120	public static function armedRequestId(): string {
121	return ABJ_404_Solution_AjaxDiagnosticRequestPolicy::instrumentedRequestIdFromGlobalContext();
122	}
123
124	/** Whether this request records per-query attribution at all. */
125	public static function isArmed(): bool {
126	return self::armedRequestId() !== '';
127	}
128
129	/**
130	* Record that a query is ABOUT to execute. Never throws.
131	*
132	* @param string $preparedQuery The final SQL, after table-name replacement,
133	* parameter binding, and timeout wrapping -- i.e. exactly the bytes the
134	* server will see. Redacted to a shape here; never stored raw.
135	* @param string $sourceLabel Stable call-site identifier resolved by
136	* ABJ_404_Solution_DatabaseQueryDiagnostics (SQL filename, `abj404:src`
137	* marker, or Class::method), which is what makes a shape actionable.
138	* @param int $timeoutSeconds The per-query timeout hint actually applied.
139	* @param string $preflightId The completed preflight that led here.
140	* @return array{q:int,sql_id:string}\|null
141	*/
142	public static function beginQuery(
143	string $preparedQuery,
144	string $sourceLabel,
145	int $timeoutSeconds,
146	string $preflightId = ''
147	): ?array {
148	$identity = null;
149	try {
150	$requestId = self::armedRequestId();
151	if ($requestId === '') {
152	return null;
153	}
154	$state = self::stateFor($requestId);
155	if ($state['summarized']) {
156	return null;
157	}
158	$state['count']++;
159
160	$previous = self::previousQueryFields($state);
161	$breadcrumb = null;
162	$shape = self::shapeFields($preparedQuery);
163	$identity = array(
164	'q' => $state['count'],
165	'sql_id' => $shape['sql_id'],
166	);
167
168	if ($state['count'] > self::MAX_RECORDED_QUERIES) {
169	$breadcrumb = array_merge(array(
170	'q' => $state['count'],
171	'stage' => self::currentStage(),
172	'src' => substr($sourceLabel === '' ? 'unknown-source' : $sourceLabel, 0, 200),
173	'timeout_s' => max(0, $timeoutSeconds),
174	'preflight_id' => substr($preflightId, 0, 12),
175	), array(
176	'sql_id' => $shape['sql_id'],
177	'sql_len' => $shape['sql_len'],
178	));
179	$state['open'] = array(
180	'q' => $state['count'],
181	'started_at' => self::nowFloat(),
182	'breadcrumb' => $breadcrumb,
183	);
184	self::$state = $state;
185	ABJ_404_Solution_AjaxCheckpointLogger::recordActiveOperation(
186	$requestId, 'query', 'active', $breadcrumb);
187	if (!$state['capped']) {
188	$state['capped'] = true;
189	self::$state = $state;
190	ABJ_404_Solution_AjaxCheckpointBoundaryWriter::record(
191	$requestId,
192	'query_probe_capped',
193	array(
194	'q' => $state['count'],
195	'limit' => self::MAX_RECORDED_QUERIES,
196	)
197	);
198	return $identity;
199	}
200	self::$state = $state;
201	return $identity;
202	}
203
204	$state['open'] = array(
205	'q' => $state['count'],
206	'started_at' => self::nowFloat(),
207	'breadcrumb' => null,
208	);
209	$state['recorded']++;
210	self::$state = $state;
211	ABJ_404_Solution_AjaxCheckpointBoundaryWriter::record(
212	$requestId,
213	'query_probe',
214	array_merge(array(
215	'q' => $state['count'],
216	'stage' => self::currentStage(),
217	'src' => substr($sourceLabel === '' ? 'unknown-source' : $sourceLabel, 0, 200),
218	'timeout_s' => max(0, $timeoutSeconds),
219	'preflight_id' => substr($preflightId, 0, 12),
220	'db_ms' => round($state['db_ms'], 3),
221	), $shape, $previous)
222	);
223	return $identity;
224	} catch (Throwable $e) {
225	self::reportFailure('query probe failed: ' . $e->getMessage());
226	return $identity;
227	}
228	}
229
230	/**
231	* Record that the in-flight query returned, with the duration the executor
232	* measured. In-memory only: the cost of this fact is already paid by the
233	* NEXT probe, which carries it, and by the summary, which carries the last
234	* one. Never throws.
235	*/
236	public static function endQuery(float $elapsedMs): void {
237	try {
238	// No open entry means this query was never announced, so it is not
239	// one of ours: an unarmed request running in a worker that served
240	// an instrumented one earlier must not have its time folded into
241	// that request's totals.
242	if (self::$state === null \|\| self::$state['open'] === null) {
243	return;
244	}
245	$state = self::$state;
246	$elapsedMs = max(0.0, $elapsedMs);
247	$state['db_ms'] += $elapsedMs;
248	$state['last_ms'] = $elapsedMs;
249	$open = $state['open'];
250	if ($open !== null && ($state['slowest'] === null \|\| $elapsedMs > $state['slowest']['ms'])) {
251	// Recorded by sequence number only: the shape is already on the
252	// probe record that carries the same `q`, so repeating it here
253	// would pay for the same bytes twice.
254	$state['slowest'] = array('q' => $open['q'], 'ms' => round($elapsedMs, 3));
255	}
256	if ($open !== null && is_array($open['breadcrumb'] ?? null)) {
257	ABJ_404_Solution_AjaxCheckpointLogger::recordActiveOperation(
258	$state['request_id'], 'query', 'complete', $open['breadcrumb']);
259	}
260	$state['open'] = null;
261	self::$state = $state;
262	} catch (Throwable $e) {
263	self::reportFailure('query completion failed: ' . $e->getMessage());
264	}
265	}
266
267	/**
268	* Emit the closing summary for this request. Never throws.
269	*
270	* Called from the single response choke point rather than from the stage
271	* runner, so the early-response branches -- the rate-limit 429 and the
272	* auth-failure 403, which are also the branches a struggling request is
273	* most likely to take -- are covered by construction instead of by
274	* discipline. Emitted even when the request ran ZERO queries: "no query
275	* ran here" is a finding, and a channel that stays silent when it has
276	* nothing to say is indistinguishable from a channel that is broken.
277	*
278	* @param string $requestId The ledger ID the caller already resolved.
279	*/
280	public static function flushSummary(string $requestId): void {
281	try {
282	if ($requestId === '') {
283	return;
284	}
285	$state = self::stateFor($requestId);
286	if ($state['summarized']) {
287	return;
288	}
289	$state['summarized'] = true;
290	self::$state = $state;
291
292	$summary = array(
293	'queries' => $state['count'],
294	'recorded' => $state['recorded'],
295	'dropped' => max(0, $state['count'] - $state['recorded']),
296	'db_ms' => round($state['db_ms'], 3),
297	'last_ms' => $state['last_ms'] === null ? null : round($state['last_ms'], 3),
298	'slowest' => $state['slowest'],
299	);
300	// A query still open at response time means the executor never
301	// reported its completion. Stated rather than smoothed over: it
302	// changes how every duration above it should be read.
303	$summary['open_query'] = $state['open'] === null ? null : $state['open']['q'];
304	$summary['open_ms'] = self::openMs($state['open']);
305	ABJ_404_Solution_AjaxCheckpointLogger::recordFrequent($requestId, 'query_timeline_summary', $summary);
306	} catch (Throwable $e) {
307	self::reportFailure('query timeline summary failed: ' . $e->getMessage());
308	}
309	}
310
311	/**
312	* The per-request buffer, created on demand and restarted whenever a
313	* different request ID appears.
314	*
315	* The reset matters outside tests: a long-lived SAPI worker, WP-CLI, or a
316	* request that internally dispatches a second instrumented action would
317	* otherwise inherit the previous request's counters and report a query
318	* total that never happened.
319	*
320	* @return AbjTimelineState
321	* @phpstan-return AbjTimelineState
322	*/
323	private static function stateFor(string $requestId): array {
324	if (is_array(self::$state) && self::$state['request_id'] === $requestId) {
325	return self::$state;
326	}
327	self::$state = array(
328	'request_id' => $requestId,
329	'count' => 0,
330	'recorded' => 0,
331	'db_ms' => 0.0,
332	'last_ms' => null,
333	'open' => null,
334	'slowest' => null,
335	'capped' => false,
336	'summarized' => false,
337	);
338	return self::$state;
339	}
340
341	/**
342	* How the preceding query ended, as fields on the probe that follows it.
343	*
344	* @param AbjTimelineState $state
345	* @phpstan-param AbjTimelineState $state
346	* @return array{prev_ms: float\|null, prev_status: string}
347	*/
348	private static function previousQueryFields(array $state): array {
349	if ($state['open'] !== null) {
350	return array('prev_ms' => null, 'prev_status' => self::PREV_UNFINISHED);
351	}
352	if ($state['last_ms'] === null) {
353	return array('prev_ms' => null, 'prev_status' => self::PREV_NONE);
354	}
355	return array('prev_ms' => round($state['last_ms'], 3), 'prev_status' => self::PREV_COMPLETE);
356	}
357
358	/**
359	* The PII-free identity of one query: its redacted shape, a stable hash of
360	* the WHOLE shape, and the shape's true length.
361	*
362	* The hash is taken before truncation so two queries that differ only past
363	* the cut are still distinguishable, and so a shape can be grouped and
364	* counted across a session without shipping it more than once.
365	*
366	* @return array{sql: string, sql_id: string, sql_len: int}
367	*/
368	private static function shapeFields(string $preparedQuery): array {
369	$shape = self::redactor()->redactSqlShape($preparedQuery);
370	return array(
371	'sql' => strlen($shape) > self::MAX_SHAPE_LENGTH ? substr($shape, 0, self::MAX_SHAPE_LENGTH) : $shape,
372	'sql_id' => substr(hash('sha256', $shape), 0, 12),
373	'sql_len' => strlen($shape),
374	);
375	}
376
377	/**
378	* The stage marker the endpoint last set, so a probe is readable without
379	* scanning back to the enclosing stage_start record.
380	*/
381	private static function currentStage(): string {
382	$context = $GLOBALS['abj404_ajax_context'] ?? null;
383	if (!is_array($context) \|\| !isset($context['stage']) \|\| !is_scalar($context['stage'])) {
384	return '';
385	}
386	return substr((string)$context['stage'], 0, 64);
387	}
388
389	/**
390	* The shared redaction helper.
391	*
392	* Constructed directly rather than resolved from the service container:
393	* this runs once per query on an admin read path, redaction needs no
394	* logger, and a container lookup per query would add a cost to the very
395	* path being measured.
396	*/
397	private static function redactor(): ABJ_404_Solution_AjaxFailureLogger {
398	if (!(self::$redactor instanceof ABJ_404_Solution_AjaxFailureLogger)) {
399	self::$redactor = new ABJ_404_Solution_AjaxFailureLogger();
400	}
401	return self::$redactor;
402	}
403
404	/**
405	* Milliseconds an unfinished query has been open, or null when there is
406	* no open query or no clock to measure it with.
407	*
408	* @param array{q: int, started_at: float\|null, breadcrumb: array<string, mixed>\|null}\|null $open
409	*/
410	private static function openMs($open): ?float {
411	if ($open === null \|\| $open['started_at'] === null) {
412	return null;
413	}
414	$now = self::nowFloat();
415	return $now === null ? null : round(($now - $open['started_at']) * 1000.0, 3);
416	}
417
418	/**
419	* Seconds as a float from the clock seam, or null when this process has
420	* no clock.
421	*
422	* flushSummary() is called from ABJ_404_Solution_AjaxResponseEmitter, and
423	* that path is exercised by the response-tail subprocess probe, which
424	* hand-requires a deliberately minimal file set with no service locator
425	* and no autoloader. The same shape covers a corrupt plugin directory,
426	* where the safe autoloader returns silently for a missing class. Reading
427	* the clock must not be able to kill the response it is instrumenting.
428	* See ABJ_404_Solution_AjaxCheckpointLogger::nowFloat().
429	*/
430	private static function nowFloat(): ?float {
431	if (function_exists('abj_clock')) {
432	return abj_clock()->nowFloat();
433	}
434	if (class_exists('ABJ_404_Solution_SystemClock')) {
435	return (new ABJ_404_Solution_SystemClock())->nowFloat();
436	}
437	return null;
438	}
439
440	private static function reportFailure(string $message): void {
441	abj404_logPhpFallback('ajax-query-timeline', $message);
442	}
443
444	/**
445	* Reset all internal state. Test-only; production code never calls this.
446	*
447	* @return void
448	*/
449	public static function resetForTests(): void {
450	self::$state = null;
451	self::$redactor = null;
452	if (class_exists('ABJ_404_Solution_DatabaseQueryFilterTracer', false)) {
453	ABJ_404_Solution_DatabaseQueryFilterTracer::resetForTests();
454	}
455	if (class_exists('ABJ_404_Solution_DatabaseQueryPreflightTracer', false)) {
456	ABJ_404_Solution_DatabaseQueryPreflightTracer::resetForTests();
457	}
458	if (class_exists('ABJ_404_Solution_AjaxFrequentCheckpointWriter', false)) {
459	ABJ_404_Solution_AjaxFrequentCheckpointWriter::resetForTests();
460	}
461	}
462	}
463