404-solution / includes / diagnostics / DiagnosticAppendStream.php

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

429 lines 19.0 KB

Raw Download Zip

1	<?php
2
3	if (!defined('ABSPATH')) {
4	exit;
5	}
6
7	/**
8	* One open append handle per diagnostic sink, for the life of the request.
9	*
10	* WHY THIS EXISTS. Every diagnostic journal in this plugin was an append-only
11	* JSONL file written the same way: open the file, write one line, flush it,
12	* close the file, once per record. That is correct and it is durable, and on a
13	* plugin-heavy site it is also the single most expensive thing debug_mode does.
14	* Measured on the owner's localhost on 2026-08-10 (PHP 8.5, APFS,
15	* deliverables/t_260809_224020_311/write-path-microbench.log), replaying one
16	* instrumented table request's 2,200 records through both sinks:
17	*
18	* open/close per record 986.7 ms wall, 484.0 ms SYSTEM cpu, 448.5 us/record
19	* request-scoped handle 54.5 ms wall, 34.6 ms SYSTEM cpu, 24.8 us/record
20	*
21	* 18x, and the difference is almost entirely system cpu, which is what a
22	* syscall costs. The record content, the record COUNT, the per-record flush and
23	* the advisory locking are identical in both arms: the only thing removed is
24	* re-opening a file this process already had open. Nothing about the evidence
25	* changes, which is why this is the fix rather than recording less.
26	*
27	* DURABILITY IS UNCHANGED, and that is the whole design constraint. These
28	* journals exist to explain a request that DIED, so nothing here may buffer a
29	* record in memory: append() still issues one write and one flush per record,
30	* so a SIGKILL milliseconds later still leaves every record that was handed to
31	* this class visible to a separate process. Holding the descriptor open is not
32	* buffering; it removes the open, not the write.
33	*
34	* WHAT A HELD DESCRIPTOR HAS TO DEFEND AGAINST. A per-record fopen() resolves
35	* the PATH every time, so it silently did the right thing when a sibling
36	* request rotated the file out from under it. A held descriptor follows the
37	* INODE instead, and would keep appending to a file that has been renamed away
38	* or deleted outright. Those two are NOT the same failure and do not get the
39	* same guard, because a rename retains the records and a delete destroys them:
40	*
41	* 1. Every append, one fstat asks whether the file still has a directory
42	* entry at all (isUnlinkedSink). It does not after a delete, and writes
43	* through the descriptor then succeed into an inode no reader can reach,
44	* which breaks the per-record durability contract above. So this one
45	* cannot be amortized: a bounded window here would lose whole windows of
46	* evidence silently. nlink survives a rename, so it never fires on (2).
47	* 2. Every REVALIDATE_AFTER_APPENDS appends, one fstat/stat pair checks that
48	* the descriptor still names the path. That bounds mis-targeted records to
49	* one revalidation window, and they land in the rotated file rather than
50	* being lost, since rotation renames rather than deletes.
51	* 3. A caller that rotates the file itself calls invalidate() and gets a
52	* fresh descriptor on the next append.
53	*
54	* The size the caller enforces its cap against is tracked here rather than
55	* stat()ed per record, seeded from one filesize() at open and re-seeded at each
56	* revalidation, so concurrent writers cannot make the cap drift by more than
57	* one window either.
58	*
59	* The open-path cache is bounded (MAX_OPEN_PATHS) and closes least-recently-
60	* used first, because a php-fpm worker outlives the request that opened a
61	* handle, and a diagnostic must never be the reason a worker runs out of
62	* descriptors.
63	*/
64	final class ABJ_404_Solution_DiagnosticAppendStream {
65
66	/**
67	* How many sinks may be held open at once. Four exist today (checkpoint
68	* journal, intent store, stage trace, and their lock files); the headroom
69	* is for the next channel, not for unbounded growth.
70	*/
71	const MAX_OPEN_PATHS = 12;
72
73	/** Appends between descriptor/path identity revalidations. */
74	const REVALIDATE_AFTER_APPENDS = 256;
75
76	/**
77	* @var array<string, array{handle: resource, bytes: int, appends: int, locked: int}>
78	* Open sinks, most-recently-used last (PHP arrays keep insertion order,
79	* and touch() reinserts).
80	*/
81	private static $streams = array();
82
83	/**
84	* @var array<string, int> How many times each path has been opened this
85	* request. Retained after a close: a rising count is real evidence of
86	* rotation churn or descriptor pressure, so the writers report it.
87	*/
88	private static $opens = array();
89
90	/**
91	* Append one line, and flush it, through a descriptor held for the request.
92	*
93	* @return array{status: string, reason: string, bytes: int} bytes is this
94	* sink's tracked size AFTER the append, which is what a caller enforces
95	* its rotation cap against. Zero when the append did not happen.
96	*/
97	public static function append(string $path, string $line): array {
98	$stream = self::stream($path);
99	if ($stream === null) {
100	return array('status' => 'failed', 'reason' => 'open_failed', 'bytes' => 0);
101	}
102	$length = strlen($line);
103	$written = @fwrite($stream['handle'], $line);
104	$flushed = @fflush($stream['handle']);
105	if ($written !== $length \|\| !$flushed) {
106	// A short write leaves a truncated line in a file another process
107	// parses, so the descriptor is not trustworthy any more: drop it
108	// and let the next append start from a fresh one.
109	self::invalidate($path);
110	return array('status' => 'failed', 'reason' => 'append_flush_failed', 'bytes' => 0);
111	}
112	self::$streams[$path]['bytes'] += $length;
113	return array(
114	'status' => 'complete',
115	'reason' => '',
116	'bytes' => self::$streams[$path]['bytes'],
117	);
118	}
119
120	/**
121	* This sink's size, without a stat syscall once it is open.
122	*
123	* Opens the sink if it is not open yet, because the callers that ask are
124	* about to append to it and the alternative is the per-record filesize()
125	* this class exists to remove. Zero when the sink cannot be opened at all,
126	* which is the same answer the callers' own @filesize() gave them.
127	*
128	* Accurate to within one revalidation window when other processes are
129	* appending to the same file (see the class comment).
130	*/
131	public static function sizeOf(string $path): int {
132	$stream = self::stream($path);
133	return $stream === null ? 0 : $stream['bytes'];
134	}
135
136	/**
137	* Revalidate that the held descriptor still names the live path and return
138	* that file's current size.
139	*
140	* Rotation callers use this only when the cached size says a destructive
141	* rename is imminent. A sibling may already have rotated the descriptor's
142	* inode aside; acting on that stale inode's near-cap size would delete the
143	* retained generation and rotate a small live file in its place. The
144	* ordinary append path keeps its bounded revalidation window, while the
145	* destructive boundary always pays one identity check.
146	*/
147	public static function revalidatedSizeOf(string $path): int {
148	$stream = self::stream($path);
149	if ($stream === null) {
150	return 0;
151	}
152	$identity = self::identityOf($stream['handle'], $path);
153	if (!$identity['still_names_path']) {
154	self::invalidate($path);
155	$stream = self::stream($path);
156	return $stream === null ? 0 : $stream['bytes'];
157	}
158	$bytes = is_int($identity['bytes']) ? $identity['bytes'] : $stream['bytes'];
159	$stream['bytes'] = $bytes;
160	$stream['appends'] = 1;
161	self::$streams[$path] = $stream;
162	return $bytes;
163	}
164
165	/**
166	* Take the advisory lock that serializes one sink, reentrantly.
167	*
168	* Reentrancy is the reason this lives here rather than in each writer. With
169	* a per-record fopen(), a nested write took a SECOND descriptor to the same
170	* lock file, could not take the lock its own call stack was holding, and
171	* degraded to the caller's lock-timeout path. One held descriptor makes the
172	* nested acquisition succeed trivially, which would let the inner release
173	* unlock the outer's critical section: the depth count is what stops that.
174	*
175	* @param int $timeoutUs Give up after this long rather than blocking. A
176	* held lock must never manufacture the stall this diagnostic measures.
177	* @return array{status: string, reason: string, held: bool} held is true
178	* only when THIS call took the lock, so only that caller releases it.
179	*/
180	public static function acquireExclusive(string $path, int $timeoutUs): array {
181	$stream = self::stream($path);
182	if ($stream === null) {
183	return array('status' => 'failed', 'reason' => 'lock_open_failed', 'held' => false);
184	}
185	if (self::$streams[$path]['locked'] > 0) {
186	self::$streams[$path]['locked']++;
187	return array('status' => 'complete', 'reason' => 'already_held', 'held' => false);
188	}
189	// A host with no monotonic clock cannot measure the deadline, and a
190	// deadline that always reads as zero elapsed is not a bounded wait, it
191	// is an unbounded one inside the very recorder being used to diagnose
192	// stalls. Such a host gets ONE non-blocking attempt: failing the wait
193	// closed loses a record, waiting forever loses the request.
194	$measurable = function_exists('hrtime');
195	$startedNs = self::monotonicNanoseconds();
196	do {
197	if (@flock($stream['handle'], LOCK_EX \| LOCK_NB)) {
198	self::$streams[$path]['locked'] = 1;
199	return array('status' => 'complete', 'reason' => '', 'held' => true);
200	}
201	if (!$measurable) {
202	return array('status' => 'lock_timeout', 'reason' => 'lock_wait_unmeasurable',
203	'held' => false);
204	}
205	if (self::elapsedMicroseconds($startedNs) >= $timeoutUs) {
206	return array('status' => 'lock_timeout', 'reason' => 'lock_wait_exceeded',
207	'held' => false);
208	}
209	usleep(1000);
210	} while (true);
211	}
212
213	/**
214	* Release a lock taken by acquireExclusive(). Only the outermost holder
215	* actually unlocks.
216	*
217	* @return array{status: string, reason: string}
218	*/
219	public static function release(string $path): array {
220	if (!isset(self::$streams[$path]) \|\| self::$streams[$path]['locked'] <= 0) {
221	return array('status' => 'complete', 'reason' => 'not_held');
222	}
223	self::$streams[$path]['locked']--;
224	if (self::$streams[$path]['locked'] > 0) {
225	return array('status' => 'complete', 'reason' => 'still_nested');
226	}
227	if (!@flock(self::$streams[$path]['handle'], LOCK_UN)) {
228	return array('status' => 'failed', 'reason' => 'unlock_failed');
229	}
230	return array('status' => 'complete', 'reason' => '');
231	}
232
233	/**
234	* Drop this sink's descriptor. Callers that rename, rotate, or delete the
235	* file call this so the next append re-resolves the path.
236	*/
237	public static function invalidate(string $path): void {
238	if (!isset(self::$streams[$path])) {
239	return;
240	}
241	$handle = self::$streams[$path]['handle'];
242	if (self::$streams[$path]['locked'] > 0) {
243	@flock($handle, LOCK_UN);
244	}
245	unset(self::$streams[$path]);
246	@fclose($handle);
247	}
248
249	/** How many descriptors this request has opened for one sink. */
250	public static function opens(string $path): int {
251	return self::$opens[$path] ?? 0;
252	}
253
254	/** Close every held descriptor. */
255	public static function closeAll(): void {
256	foreach (array_keys(self::$streams) as $path) {
257	self::invalidate($path);
258	}
259	}
260
261	/**
262	* The request-scoped reset seam, called by name from
263	* ABJ404_RequestScopedStateReset. A test that deletes its journal
264	* directory between cases must not leave this class writing into the
265	* unlinked inode that used to be there.
266	*/
267	public static function resetForTests(): void {
268	self::closeAll();
269	self::$opens = array();
270	}
271
272	/**
273	* The open descriptor for one sink, opening it if needed.
274	*
275	* @return array{handle: resource, bytes: int, appends: int, locked: int}\|null
276	*/
277	private static function stream(string $path) {
278	if (isset(self::$streams[$path])) {
279	$stream = self::$streams[$path];
280	if (self::isUnlinkedSink($stream['handle'])) {
281	// Nothing links to this inode any more, so every byte written
282	// through this descriptor is reachable by nobody. Re-resolve
283	// the path: if the directory survived, the record lands in a
284	// readable file, and if it did not, the open below fails and
285	// the caller reports it. Either beats a silent write into a
286	// file that no reader can ever find.
287	self::invalidate($path);
288	} else {
289	$appends = $stream['appends'] + 1;
290	if ($appends < self::REVALIDATE_AFTER_APPENDS) {
291	self::$streams[$path] = array(
292	'handle' => $stream['handle'],
293	'bytes' => $stream['bytes'],
294	'appends' => $appends,
295	'locked' => $stream['locked'],
296	);
297	return self::$streams[$path];
298	}
299	$identity = self::identityOf($stream['handle'], $path);
300	if ($identity['still_names_path']) {
301	// The window is spent either way: reset it, and take the size
302	// the descriptor itself reports so a sibling's appends do not
303	// drift our rotation cap.
304	self::$streams[$path] = array(
305	'handle' => $stream['handle'],
306	'bytes' => $identity['bytes'] ?? $stream['bytes'],
307	'appends' => 1,
308	'locked' => $stream['locked'],
309	);
310	return self::$streams[$path];
311	}
312	// Another process rotated this file away. Anything already written
313	// is in the rotated file, which is retained; start a fresh one.
314	self::invalidate($path);
315	}
316	}
317	if ($path === '') {
318	return null;
319	}
320	// 'ab' creates without truncating and positions at the end on every
321	// write, which is what both a journal and a lock file need. 'cb' is the
322	// fallback for a filesystem that refuses the append mode outright.
323	$handle = @fopen($path, 'ab');
324	if ($handle === false) {
325	$handle = @fopen($path, 'cb');
326	}
327	if ($handle === false) {
328	abj404_logPhpFallback(
329	'diagnostic-append-stream',
330	'sink could not be opened: ' . $path
331	);
332	return null;
333	}
334	self::evictOldestWhenFull();
335	clearstatcache(true, $path);
336	$size = @filesize($path);
337	self::$streams[$path] = array(
338	'handle' => $handle,
339	'bytes' => is_int($size) ? $size : 0,
340	'appends' => 1,
341	'locked' => 0,
342	);
343	self::$opens[$path] = (self::$opens[$path] ?? 0) + 1;
344	return self::$streams[$path];
345	}
346
347	/**
348	* Has this descriptor's file been unlinked out from under it?
349	*
350	* This is the per-record half of the identity problem, and it is separate
351	* from identityOf() below because the two failures have different costs.
352	* A rotation RENAME retains every record already written, so noticing it one
353	* revalidation window late loses nothing and the bounded check is enough. An
354	* UNLINK retains nothing: the descriptor keeps accepting writes, fwrite and
355	* fflush both report success, and the bytes are unreachable to every reader.
356	* Measured on APFS 2026-08-10: after the directory was removed, fwrite
357	* returned the full length and fflush returned true, with nlink at 0. That
358	* silently breaks this class's durability contract, which is per-record, so
359	* this check has to be per-record too. It costs one fstat, 1.11 us against
360	* the 24.8 us this class spends per record.
361	*
362	* nlink is the right signal precisely because it stays 1 through a rename,
363	* so this cannot fire on the rotation case the bounded window exists for.
364	*
365	* @param resource $handle
366	*/
367	private static function isUnlinkedSink($handle): bool {
368	$open = @fstat($handle);
369	if (!is_array($open) \|\| !isset($open['nlink'])) {
370	// A filesystem that will not report a link count gets the bounded
371	// path-identity check and nothing stricter. Failing closed here
372	// would re-open on every append and hand back the entire cost this
373	// class exists to remove, on every host with an unusual stat().
374	return false;
375	}
376	return (int)$open['nlink'] === 0;
377	}
378
379	/**
380	* Does this descriptor still point at the file this path names, and how
381	* big does the descriptor itself say the file is?
382	*
383	* Pure: the caller owns the stream table, so this only reports.
384	*
385	* @param resource $handle
386	* @return array{still_names_path: bool, bytes: int\|null}
387	*/
388	private static function identityOf($handle, string $path): array {
389	clearstatcache(true, $path);
390	$onDisk = @stat($path);
391	$open = @fstat($handle);
392	if (!is_array($open)) {
393	// The descriptor itself is unreadable, so there is nothing to
394	// compare and re-opening on every window would give back the cost
395	// this class exists to remove.
396	return array('still_names_path' => true, 'bytes' => null);
397	}
398	$bytes = isset($open['size']) && is_int($open['size']) ? $open['size'] : null;
399	if (!is_array($onDisk)) {
400	// Nothing at the path while our descriptor is still valid: the file
401	// was renamed or unlinked out from under us. This is the window
402	// between a sibling's rotation rename and its first new record.
403	return array('still_names_path' => false, 'bytes' => $bytes);
404	}
405	$sameFile = ($onDisk['ino'] ?? null) === ($open['ino'] ?? null)
406	&& ($onDisk['dev'] ?? null) === ($open['dev'] ?? null);
407	return array('still_names_path' => $sameFile, 'bytes' => $bytes);
408	}
409
410	/** Keep the number of held descriptors bounded, oldest sink first. */
411	private static function evictOldestWhenFull(): void {
412	while (count(self::$streams) >= self::MAX_OPEN_PATHS) {
413	$oldest = array_key_first(self::$streams);
414	if ($oldest === null) {
415	return;
416	}
417	self::invalidate($oldest);
418	}
419	}
420
421	private static function monotonicNanoseconds(): int {
422	return function_exists('hrtime') ? (int)hrtime(true) : 0;
423	}
424
425	private static function elapsedMicroseconds(int $startedNs): int {
426	return max(0, (int)round((self::monotonicNanoseconds() - $startedNs) / 1000));
427	}
428	}
429