404-solution / includes / diagnostics / AjaxRowLoopProgress.php

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

378 lines 14.5 KB

Raw Download Zip

1	<?php
2
3	if (!defined('ABSPATH')) {
4	exit;
5	}
6
7	/**
8	* Bounded intra-stage progress for a table's row-formatting loop
9	* (Bruno timeout cause matrix, cause class F; gap-hunt iteration 1, gap G5).
10	*
11	* ABJ_404_Solution_AjaxQueryTimeline accounts for the database half of a work
12	* stage. This accounts for the other half. Once the rows are in memory the
13	* stage still runs URL parsing and normalization, destination resolution,
14	* locale-dependent formatting, and every foreign callback other plugins have
15	* attached to the filters the row templates go through -- all of it inside a
16	* single `foreach`, and all of it invisible between `stage_start` and a
17	* `stage_end` that never arrives.
18	*
19	* A hang caused by ONE pathological row is the specific case this localizes.
20	* With per-query records showing every query completed and the row loop
21	* stopping at row 17 of 25, the stall is attributable to PHP-side work on a
22	* specific row rather than to the database, which is a different fix.
23	*
24	* Cost is bounded by construction, not by hope. The tick interval is derived
25	* from the row count so a 25-row page and a 500-row page both emit at most
26	* MAX_PROGRESS_RECORDS progress records, and the record envelope is the
27	* checkpoint logger's high-frequency one.
28	*
29	* The loop is ticked BEFORE each row is formatted, for the same reason the
30	* query probe is written before the query runs: work that never finishes has
31	* to have been announced before it started, or it leaves no trace at all.
32	*
33	* PII: only a SHA-256 prefix of the row's primary key is emitted. Row URLs,
34	* destinations, and freeform content never reach the journal -- the whole row
35	* is accepted only so the key lookup lives here instead of being repeated at
36	* every call site.
37	*/
38	final class ABJ_404_Solution_AjaxRowLoopProgress {
39
40	/**
41	* Progress records emitted per loop, excluding the start and end pair.
42	*
43	* Eight is enough to place a stall inside a default 25-row page to within
44	* about four rows while costing a fraction of the boundary checkpoints
45	* already written for the same request. The interval scales with the row
46	* count, so a 500-row page costs the same as a 25-row one.
47	*/
48	const MAX_PROGRESS_RECORDS = 8;
49
50	/** Row-key columns, in the order they are consulted. */
51	const ROW_KEY_COLUMNS = array('id', 'log_id');
52
53	/** @var string Ledger request ID, or '' when this loop is not instrumented. */
54	private $requestId;
55
56	/** @var string */
57	private $label;
58
59	/** @var int */
60	private $total;
61
62	/** @var int Rows between progress records; always at least 1. */
63	private $interval;
64
65	/** @var int Rows seen so far. */
66	private $index = 0;
67
68	/** @var int Progress records emitted so far. */
69	private $emitted = 0;
70
71	/** @var float */
72	private $startedAt;
73
74	/** @var float Start of the current activity window. */
75	private $activityStartedAt;
76
77	/** @var int Rows completed when the previous activity snapshot was taken. */
78	private $sampledRows = 0;
79
80	/** @var array<string, int> */
81	private $hookCounts = array();
82
83	/** @var array{src: string, calls: int\|null, reads: int\|null, writes: int\|null, hits: int\|null, misses: int\|null, ms: float\|null} */
84	private $cacheSnapshot;
85
86	/** @var ABJ_404_Solution_CacheMetricsProbeTracer\|null */
87	private $cacheMetricsProbe = null;
88
89	/** @var ABJ_404_Solution_RowRenderOperationTracer\|null */
90	private $operationTracer = null;
91
92	/**
93	* Open a progress-tracked row loop. Returns a live tracker on an
94	* instrumented admin-AJAX request and an inert one everywhere else, so
95	* call sites need no conditional and the front-end 404 path pays nothing
96	* beyond one static call per table render.
97	*
98	* @param string $label Loop identity, e.g. 'redirects_rows'.
99	* @param int $totalRows Number of rows the loop is about to format.
100	*/
101	public static function begin(string $label, int $totalRows): self {
102	$progress = new self($label, $totalRows);
103	if ($progress->requestId === '') {
104	return $progress;
105	}
106	try {
107	ABJ_404_Solution_AjaxCheckpointLogger::recordFrequent($progress->requestId, 'row_loop_start', array(
108	'loop' => $progress->label,
109	'rows' => $progress->total,
110	'every' => $progress->interval,
111	));
112	} catch (Throwable $e) {
113	self::reportFailure('row loop start failed: ' . $e->getMessage());
114	}
115	return $progress;
116	}
117
118	private function __construct(string $label, int $totalRows) {
119	$this->label = substr($label, 0, 64);
120	$this->total = max(0, $totalRows);
121	$this->interval = max(1, (int)ceil($this->total / self::MAX_PROGRESS_RECORDS));
122	$this->startedAt = abj_clock()->nowFloat();
123	$this->activityStartedAt = $this->startedAt;
124	$this->requestId = self::resolveRequestId();
125	if ($this->requestId !== '') {
126	$this->hookCounts = self::currentHookCounts();
127	$this->cacheMetricsProbe =
128	new ABJ_404_Solution_CacheMetricsProbeTracer($this->requestId);
129	$this->cacheSnapshot = $this->currentCacheSnapshot('initial');
130	$this->operationTracer = ABJ_404_Solution_RowRenderOperationTracer::begin($this->requestId);
131	}
132	}
133
134	/**
135	* Announce the row that is about to be formatted. Never throws.
136	*
137	* @param array<string, mixed> $row The row being formatted. Only its
138	* primary key is read, and only as a hash.
139	*/
140	public function tick(array $row): void {
141	$this->index++;
142	if ($this->requestId === '' \|\| $this->emitted >= self::MAX_PROGRESS_RECORDS) {
143	if ($this->operationTracer !== null) {
144	$this->operationTracer->enterRow();
145	}
146	return;
147	}
148	// Rows 1, 1+interval, 1+2*interval ... so the FIRST row is always
149	// announced: a loop that hangs immediately is otherwise reported as a
150	// loop that never started, which points at the wrong half of the stage.
151	if (($this->index - 1) % $this->interval !== 0) {
152	if ($this->operationTracer !== null) {
153	$this->operationTracer->enterRow();
154	}
155	return;
156	}
157	$this->emitted++;
158	try {
159	$record = array(
160	'loop' => $this->label,
161	'row' => $this->index,
162	'rows' => $this->total,
163	'rid' => self::hashedRowKey($row),
164	'ms' => self::elapsedMs($this->startedAt),
165	);
166	ABJ_404_Solution_AjaxCheckpointLogger::recordFrequent(
167	$this->requestId,
168	'row_loop_progress',
169	array_merge($record, $this->activityFields(max(0, $this->index - 1), 'progress'))
170	);
171	} catch (Throwable $e) {
172	self::reportFailure('row loop progress failed: ' . $e->getMessage());
173	}
174	if ($this->operationTracer !== null) {
175	$this->operationTracer->enterRow();
176	}
177	}
178
179	/**
180	* Close the loop, recording how many rows it actually formatted. Never
181	* throws. The absence of this record next to a present `row_loop_start` is
182	* itself the finding: the loop was entered and did not come back.
183	*/
184	public function finish(): void {
185	if ($this->requestId === '') {
186	return;
187	}
188	if ($this->operationTracer !== null) {
189	$this->operationTracer->finish();
190	}
191	try {
192	$record = array(
193	'loop' => $this->label,
194	'rows' => $this->total,
195	'rows_done' => $this->index,
196	'ms' => self::elapsedMs($this->startedAt),
197	);
198	if ($this->emitted < self::MAX_PROGRESS_RECORDS) {
199	$record = array_merge($record, $this->activityFields($this->index, 'finish'));
200	}
201	ABJ_404_Solution_AjaxCheckpointLogger::recordFrequent(
202	$this->requestId,
203	'row_loop_end',
204	$record
205	);
206	} catch (Throwable $e) {
207	self::reportFailure('row loop end failed: ' . $e->getMessage());
208	}
209	}
210
211	/** Rows formatted so far. Test-visible accounting; production reads the journal. */
212	public function rowsSeen(): int {
213	return $this->index;
214	}
215
216	private static function resolveRequestId(): string {
217	try {
218	return ABJ_404_Solution_AjaxDiagnosticRequestPolicy::instrumentedRequestIdFromGlobalContext();
219	} catch (Throwable $e) {
220	self::reportFailure('row loop arming failed: ' . $e->getMessage());
221	return '';
222	}
223	}
224
225	/**
226	* A short SHA-256 prefix of the row's primary key, or '' when the row has
227	* no usable key.
228	*
229	* Hashed rather than emitted plainly because the journal's standing
230	* guarantee is that it carries no row-level site data, and a stable hash
231	* is enough for what this field is for: telling whether two attempts
232	* stopped on the SAME row.
233	*
234	* @param array<string, mixed> $row
235	*/
236	private static function hashedRowKey(array $row): string {
237	foreach (self::ROW_KEY_COLUMNS as $column) {
238	if (isset($row[$column]) && is_scalar($row[$column]) && (string)$row[$column] !== '') {
239	return substr(hash('sha256', (string)$row[$column]), 0, 12);
240	}
241	}
242	return '';
243	}
244
245	private static function elapsedMs(float $startedAt): int {
246	return max(0, (int)round((abj_clock()->nowFloat() - $startedAt) * 1000));
247	}
248
249	/**
250	* Snapshot request-local hook counters and object-cache metrics as deltas
251	* for the rows completed since the previous bounded checkpoint.
252	*
253	* Hook counts are temporal evidence, not callback timers. `chunk_ms` is
254	* the only honest wall-time boundary: WordPress exposes trigger counters
255	* and the active hook stack, but not foreign callback durations.
256	*
257	* @return array<string, mixed>
258	*/
259	private function activityFields(int $completedRows, string $phase): array {
260	$sampledAt = abj_clock()->nowFloat();
261	$currentHooks = self::currentHookCounts();
262	$hookDeltas = array();
263	foreach ($currentHooks as $hook => $count) {
264	$delta = $count - ($this->hookCounts[$hook] ?? 0);
265	if ($delta > 0) {
266	$hookDeltas[$hook] = $delta;
267	}
268	}
269	uksort($hookDeltas, static function (string $left, string $right) use ($hookDeltas): int {
270	$byCount = $hookDeltas[$right] <=> $hookDeltas[$left];
271	return ($byCount !== 0) ? $byCount : strcmp($left, $right);
272	});
273	$hookTop = array();
274	foreach (array_slice($hookDeltas, 0, 1, true) as $hook => $calls) {
275	$redactedHook = self::redactedHookName($hook);
276	$hookTop[$redactedHook] = ($hookTop[$redactedHook] ?? 0) + $calls;
277	}
278
279	$currentCache = $this->currentCacheSnapshot($phase);
280	$sameCacheSource = $currentCache['src'] === $this->cacheSnapshot['src'];
281	$cacheCalls = $sameCacheSource
282	? self::numericDelta($currentCache['calls'], $this->cacheSnapshot['calls']) : null;
283	$cacheMilliseconds = $sameCacheSource
284	? self::numericDelta($currentCache['ms'], $this->cacheSnapshot['ms']) : null;
285
286	$fields = array(
287	'chunk_rows' => max(0, $completedRows - $this->sampledRows),
288	'chunk_ms' => max(0, (int)round(($sampledAt - $this->activityStartedAt) * 1000)),
289	'hook_active' => self::activeHookName(),
290	'hook_calls' => array_sum($hookDeltas),
291	'hook_top' => $hookTop,
292	'cache_src' => $currentCache['src'],
293	'cache_calls' => ($cacheCalls === null) ? null : (int)$cacheCalls,
294	'cache_ms' => ($cacheMilliseconds === null) ? null : round($cacheMilliseconds, 3),
295	);
296
297	$this->activityStartedAt = $sampledAt;
298	$this->sampledRows = $completedRows;
299	$this->hookCounts = $currentHooks;
300	$this->cacheSnapshot = $currentCache;
301	return $fields;
302	}
303
304	/** @return array<string, int> */
305	private static function currentHookCounts(): array {
306	$counts = array();
307	foreach (array('wp_filters', 'wp_actions') as $globalName) {
308	$source = $GLOBALS[$globalName] ?? null;
309	if (!is_array($source)) {
310	continue;
311	}
312	foreach ($source as $hook => $count) {
313	if (is_numeric($count) && (int)$count >= 0) {
314	$name = (string)$hook;
315	$counts[$name] = ($counts[$name] ?? 0) + (int)$count;
316	}
317	}
318	}
319	return $counts;
320	}
321
322	private static function activeHookName(): string {
323	$stack = $GLOBALS['wp_current_filter'] ?? null;
324	if (!is_array($stack) \|\| empty($stack)) {
325	return '';
326	}
327	$active = end($stack);
328	return is_string($active) ? self::redactedHookName($active) : '';
329	}
330
331	/**
332	* Keep conventional static hook names actionable. Hash dynamic names that
333	* could contain a URL, email, user value, or another site-specific token.
334	*/
335	private static function redactedHookName(string $hook): string {
336	if (preg_match('/^[A-Za-z_][A-Za-z0-9_.:-]{0,63}$/', $hook) === 1) {
337	return preg_replace('/[0-9]+/', '#', $hook) ?? '';
338	}
339	return 'hook#' . substr(hash('sha256', $hook), 0, 12);
340	}
341
342	/**
343	* Read a durably bracketed cumulative cache snapshot.
344	*
345	* @return array{src: string, calls: int\|null, reads: int\|null, writes: int\|null, hits: int\|null, misses: int\|null, ms: float\|null}
346	*/
347	private function currentCacheSnapshot(string $phase): array {
348	$cache = $GLOBALS['wp_object_cache'] ?? null;
349	return $this->cacheMetricsProbe !== null
350	? $this->cacheMetricsProbe->snapshot($cache, $phase)
351	: array(
352	'src' => 'none',
353	'calls' => null,
354	'reads' => null,
355	'writes' => null,
356	'hits' => null,
357	'misses' => null,
358	'ms' => null,
359	);
360	}
361
362	/**
363	* @param float\|int\|null $current
364	* @param float\|int\|null $previous
365	*/
366	private static function numericDelta($current, $previous): ?float {
367	if ($current === null \|\| $previous === null) {
368	return null;
369	}
370	$delta = (float)$current - (float)$previous;
371	return ($delta >= 0) ? $delta : null;
372	}
373
374	private static function reportFailure(string $message): void {
375	abj404_logPhpFallback('ajax-row-loop', $message);
376	}
377	}
378