Loader cache: build-command tests, discovery timing, and runtime resilience

CHANGELOG.md

@@ -6,10 +6,12 @@ All notable changes to this project will be documented in this file, per [the Ke
 ### Added
 - Build-time class-cache generation: a `tenup-framework-generate-class-cache` command (installed to `vendor/bin/`) and a `composer generate-class-cache` alias that build the cache in CI without bootstrapping WordPress. See [Build and Deployment](docs/Build-and-Deployment.md) ([#30](https://github.com/10up/wp-framework/issues/30)).
 - Hidden admin page (`admin.php?page=tenup-framework-loaders`, `manage_options`) that aggregates every class-loader cache on the site — across all framework copies — and shows each cache's path, status, loaded classes, and an on-demand live-vs-cache staleness check. Admin-only (no front-end overhead) and read-only. Disable with the `tenup_framework_enable_loader_debug` filter or the `TENUP_FRAMEWORK_DISABLE_LOADER_DEBUG` constant. See [Debugging class loaders](docs/Debugging.md).
+- The loader debug page reports per-loader timing: how long class **discovery** took (a cache read when cached, a live filesystem scan otherwise) and how long **class lookup** (reflection, instantiation and registration) took. The staleness check also reports how long its live discovery ran, so the cache's saving on a given site is measurable.
 
 ### Changed
 - The class-loader cache is now **read-only at runtime** and opt-in. The framework reads a pre-built cache if present and discovers live otherwise, but never writes one on the server — fixing stale caches that could only be cleared by hand ([#30](https://github.com/10up/wp-framework/issues/30)).
-- Bumped the cache identifier so a cache written by an older version is ignored after upgrade rather than served stale.
+- A corrupt or truncated shipped cache is caught at runtime and the request falls back to a live scan instead of fataling, so a bad cache degrades performance rather than taking the site down.
+- Bumped the cache filename so a cache written by an older version is ignored after upgrade rather than served stale.
 - `TENUP_FRAMEWORK_DISABLE_CLASS_CACHE` now forces live discovery (ignores any shipped cache).
 
 ### Removed

docs/Build-and-Deployment.md

@@ -158,7 +158,19 @@ workflows:
 
 If the build can't run the generate step for some reason, the deploy still works — it just
 runs uncached. A broken cache after a build means the build is the thing to fix, not the
-server.
+server. A cache file that is corrupt or truncated (a half-finished rsync, an interrupted
+build) is caught at runtime and the request falls back to a live scan, so a bad cache slows
+the site rather than taking it down.
+
+### Opcache and in-place deploys
+
+The cache is a PHP file loaded with `require`, so PHP's opcache caches it like any other
+source file. On hosts with `opcache.validate_timestamps=0` (common on the managed hosts where
+issue #30 was reported), overwriting `class-loader-cache-v2.php` **in place** keeps serving the
+previously compiled array until opcache is reset — which would reintroduce the very staleness
+this design removes. Either deploy to a fresh path (atomic symlink swap, the default on most
+zero-downtime deployers) or reset opcache as part of the deploy. The loader debug page's
+staleness check live-scans and will flag this if it happens.
 
 ## The per-package model
 
@@ -184,6 +196,14 @@ vendor/bin/tenup-framework-generate-class-cache \
   wp-content/plugins/bar/inc
 ```
 
+One caveat for a mono-repo where packages pin **different** framework versions: the single
+invocation above uses one package's `vendor/bin` copy to write every directory's cache. That
+copy determines the cache filename and the Spatie discoverer version used. Today the payload is
+a plain array of class-name strings and the filename is identical across versions, so this is
+safe — but a future cache-format or filename bump would silently mismatch. When packages are on
+different framework versions, run **each package's own** `vendor/bin/tenup-framework-generate-class-cache`
+against its own directory so the writer and the reader are always the same version.
+
 ## See also
 - [Docs Home](README.md)
 - [Autoloading and Modules](Autoloading.md)

docs/Debugging.md

@@ -33,6 +33,11 @@ page aggregates every loader recorded across all of them — even copies that ar
   one (usually leftovers from an older framework version).
 - **Classes loaded** — every class the loader resolved, with the file each one lives in. A class
   that no longer resolves is flagged as a likely stale entry.
+- **Discovery time** — how long this request spent obtaining the class list. With a cache present
+  this is the cost of reading it; uncached it is the cost of a live filesystem scan, so the two
+  states can be compared directly.
+- **Class lookup time** — how long reflecting, instantiating and registering the discovered
+  classes took.
 
 ## Staleness check
 
@@ -42,7 +47,9 @@ directory and diffs the result against what the cache loaded, listing:
 - classes **on disk but missing from the cache** (the cache is behind), and
 - classes **in the cache but no longer on disk** (renamed/removed).
 
-The check runs only when clicked, so the page itself stays cheap. If it reports drift, the cache
+It also reports **how long the live discovery took**, which — compared against the cached
+**Discovery time** above — shows what the cache is actually saving on this site. The check runs
+only when clicked, so the page itself stays cheap. If it reports drift, the cache
 is stale: regenerate it in your build (`composer generate-class-cache`) or remove the file and
 redeploy. The page is **read-only** — it never deletes or rewrites a cache, consistent with the
 read-only runtime.
@@ -52,6 +59,15 @@ read-only runtime.
 The recording and the page are **admin-only**. On front-end requests nothing is recorded, no hooks
 are added, and the debug class is never even loaded.
 
+## Known limitations
+
+- **Per request** — the page shows loaders recorded on the current admin request. A plugin whose
+  `init_classes()` did not run on this request will not appear.
+- **Mixed framework versions render with the oldest UI** — when a mono-repo runs several framework
+  copies on different versions, the first copy to record a loader registers and renders the page,
+  so newer per-loader fields degrade to blank rather than showing. Aligning framework versions
+  across packages avoids this; the data itself is still aggregated correctly across all copies.
+
 ## Disabling it
 
 Enabled by default in the admin. Turn it off with either:

src/Debug/LoaderDebug.php

@@ -88,6 +88,18 @@ public static function record( array $record ) {
 			return;
 		}
 
+		// Keep one record per directory: if init_classes() runs more than once for the same
+		// directory in a request, the latest call (with fresh timing) replaces the earlier one
+		// rather than producing a duplicate card.
+		$directory = isset( $record['directory'] ) && is_string( $record['directory'] ) ? $record['directory'] : '';
+		foreach ( self::$loaders as $index => $existing ) {
+			if ( ( $existing['directory'] ?? null ) === $directory ) {
+				self::$loaders[ $index ] = $record;
+				self::boot();
+				return;
+			}
+		}
+
 		self::$loaders[] = $record;
 
 		self::boot();
@@ -253,6 +265,8 @@ protected static function render_loader( array $loader, string $check ) {
 		self::render_row( __( 'Framework version', 'tenup-framework' ), self::version_label( $loader ) );
 		self::render_row( __( 'Cache file', 'tenup-framework' ), '' !== $cache_file ? $cache_file : '—' );
 		self::render_row( __( 'Cache detail', 'tenup-framework' ), self::cache_detail( $loader ) );
+		self::render_row( __( 'Discovery time', 'tenup-framework' ), self::format_duration( $loader['discovery_seconds'] ?? null ) );
+		self::render_row( __( 'Class lookup time', 'tenup-framework' ), self::format_duration( $loader['lookup_seconds'] ?? null ) );
 		echo '</tbody></table>';
 
 		echo '<details class="tenup-loader__classes">';
@@ -340,18 +354,27 @@ protected static function render_staleness( string $directory, array $classes, s
 			return;
 		}
 
-		$live    = ModuleInitialization::instance()->discover_live( $directory );
+		$live_start   = microtime( true );
+		$live         = ModuleInitialization::instance()->discover_live( $directory );
+		$live_seconds = microtime( true ) - $live_start;
+
 		$loaded  = array_values( $classes );
 		$removed = array_diff( $loaded, $live ); // In cache but no longer on disk.
 		$added   = array_diff( $live, $loaded ); // On disk but missing from the cache.
 
+		$timing = sprintf(
+			/* translators: %s: formatted duration. */
+			__( 'Live discovery took %s.', 'tenup-framework' ),
+			self::format_duration( $live_seconds )
+		);
+
 		if ( empty( $removed ) && empty( $added ) ) {
-			echo '<div class="tenup-notice tenup-notice--ok"><strong>' . esc_html__( 'Up to date — the cache matches a live scan.', 'tenup-framework' ) . '</strong></div>';
+			echo '<div class="tenup-notice tenup-notice--ok"><strong>' . esc_html__( 'Up to date — the cache matches a live scan.', 'tenup-framework' ) . '</strong> ' . esc_html( $timing ) . '</div>';
 			return;
 		}
 
 		echo '<div class="tenup-notice tenup-notice--error">';
-		echo '<strong>' . esc_html__( 'Stale — the cache differs from a live scan.', 'tenup-framework' ) . '</strong>';
+		echo '<strong>' . esc_html__( 'Stale — the cache differs from a live scan.', 'tenup-framework' ) . '</strong> ' . esc_html( $timing );
 
 		if ( ! empty( $added ) ) {
 			echo '<p>' . esc_html__( 'On disk but missing from the cache:', 'tenup-framework' ) . '</p><ul>';
@@ -385,6 +408,39 @@ protected static function to_string( $value ): string {
 		return is_scalar( $value ) ? (string) $value : '';
 	}
 
+	/**
+	 * Format a duration in seconds for display, choosing a sensible unit. Values arrive through
+	 * a filter as mixed, so anything non-numeric or non-positive renders as a placeholder.
+	 *
+	 * @param mixed $seconds The duration in seconds.
+	 *
+	 * @return string
+	 */
+	protected static function format_duration( $seconds ): string {
+		$seconds = is_numeric( $seconds ) ? (float) $seconds : 0.0;
+
+		// Values arrive through the cross-copy filter as mixed, so reject non-positive and
+		// non-finite (INF/NAN) input rather than rendering "inf s" / "nan s".
+		if ( $seconds <= 0.0 || ! is_finite( $seconds ) ) {
+			return '—';
+		}
+
+		$milliseconds = $seconds * 1000;
+
+		if ( $milliseconds < 1 ) {
+			/* translators: %s: duration in milliseconds. */
+			return sprintf( __( '%s ms', 'tenup-framework' ), number_format( $milliseconds, 3 ) );
+		}
+
+		if ( $milliseconds < 1000 ) {
+			/* translators: %s: duration in milliseconds. */
+			return sprintf( __( '%s ms', 'tenup-framework' ), number_format( $milliseconds, 2 ) );
+		}
+
+		/* translators: %s: duration in seconds. */
+		return sprintf( __( '%s s', 'tenup-framework' ), number_format( $seconds, 2 ) );
+	}
+
 	/**
 	 * A stable, opaque token identifying a loader directory in the check link.
 	 *
@@ -517,7 +573,8 @@ protected static function cache_state( array $loader ): array {
 	}
 
 	/**
-	 * A short description of the cache file on disk (age and size), or a placeholder when none.
+	 * A short description of the cache file on disk — relative age, size, and the absolute build
+	 * time in UTC — or a placeholder when none. Format: "Built <age> ago · <size> (<utc>)".
 	 *
 	 * @param array $loader The loader record.
 	 *
@@ -533,11 +590,20 @@ protected static function cache_detail( array $loader ): string {
 		$mtime = (int) filemtime( $cache_file );
 		$size  = (int) filesize( $cache_file );
 
+		if ( ! $mtime ) {
+			return sprintf(
+				/* translators: %s: file size. */
+				__( 'Built at an unknown time · %s', 'tenup-framework' ),
+				size_format( $size )
+			);
+		}
+
 		return sprintf(
-			/* translators: 1: relative age, 2: file size. */
-			__( 'Built %1$s ago · %2$s', 'tenup-framework' ),
-			$mtime ? human_time_diff( $mtime ) : __( 'unknown time', 'tenup-framework' ),
-			size_format( $size )
+			/* translators: 1: relative age (e.g. "5 minutes"); 2: file size; 3: absolute build time in UTC. */
+			__( 'Built %1$s ago · %2$s · %3$s', 'tenup-framework' ),
+			human_time_diff( $mtime ),
+			size_format( $size ),
+			gmdate( 'Y-m-d H:i:s', $mtime ) . ' UTC'
 		);
 	}
 
@@ -548,7 +614,7 @@ protected static function cache_detail( array $loader ): string {
 	 */
 	protected static function render_styles() {
 		echo '<style>
-			.tenup-loaders .tenup-loader { max-width: 60em; margin: 1.25em 0; padding: .5em 1.25em 1.25em; background: #fff; border: 1px solid #c3c4c7; border-radius: 4px; }
+			.tenup-loaders .tenup-loader { width: fit-content; min-width: min(60em, 100%); max-width: 100%; margin: 1.25em 0; padding: .5em 1.25em 1.25em; background: #fff; border: 1px solid #c3c4c7; border-radius: 4px; }
 			.tenup-loaders .tenup-loader__head { display: flex; align-items: center; gap: .75em; flex-wrap: wrap; }
 			.tenup-loaders .tenup-loader__head h2 { margin: .5em 0; }
 			.tenup-loaders .tenup-badge { display: inline-block; padding: .15em .7em; border-radius: 999px; font-size: 12px; font-weight: 600; border: 1px solid; }
@@ -566,6 +632,7 @@ protected static function render_styles() {
 			.tenup-loaders .tenup-loader__classes { margin: .5em 0; }
 			.tenup-loaders .tenup-loader__classes summary { cursor: pointer; font-weight: 600; padding: .4em 0; }
 			.tenup-loaders .tenup-loader__class-table { margin: .5em 0 1em; }
+			.tenup-loaders .tenup-loader__meta td code, .tenup-loaders .tenup-loader__class-table td code { overflow-wrap: anywhere; }
 			.tenup-loaders .tenup-loader__actions { margin: .75em 0 0; }
 		</style>';
 	}

src/ModuleInitialization.php

@@ -12,7 +12,6 @@
 use Composer\InstalledVersions;
 use ReflectionClass;
 use Spatie\StructureDiscoverer\Cache\FileDiscoverCacheDriver;
-use Spatie\StructureDiscoverer\Data\DiscoveredStructure;
 use Spatie\StructureDiscoverer\Discover;
 use TenupFramework\Cache\ReadOnlyFileDiscoverCacheDriver;
 use TenupFramework\Debug\LoaderDebug;
@@ -113,10 +112,18 @@ public function get_classes( $dir ) {
 			);
 		}
 
-		$classes = array_filter( $class_finder->get(), fn( $cl ) => is_string( $cl ) );
+		try {
+			$discovered = $class_finder->get();
+		} catch ( \Throwable $e ) {
+			// A shipped cache file that is corrupt or truncated — a partial deploy, an
+			// interrupted build, a half-written rsync — would otherwise fatal on every request
+			// (the cache is executable PHP loaded with `require`). Fall back to a fresh live
+			// discovery so the site keeps working, uncached, until the cache is rebuilt. This
+			// is the same spirit as issue #30: a bad cache must never take the site down.
+			$discovered = $this->build_discoverer( $dir )->get();
+		}
 
-		// Return the classes
-		return $classes;
+		return array_filter( $discovered, fn( $cl ) => is_string( $cl ) );
 	}
 
 	/**
@@ -217,30 +224,41 @@ public function discover_live( $dir ) {
 	 * gathered there. The is_admin() check happens before LoaderDebug is referenced, so that
 	 * class never autoloads on the front end.
 	 *
-	 * @param string        $dir     The directory that was discovered.
-	 * @param array<string> $classes The discovered class names.
+	 * @param string        $dir               The directory that was discovered.
+	 * @param array<string> $classes           The discovered class names.
+	 * @param float         $discovery_seconds Seconds spent obtaining the class list (cache read or live scan).
+	 * @param float         $lookup_seconds    Seconds spent reflecting, instantiating and registering the classes.
 	 *
 	 * @return void
 	 */
-	protected function record_loader_debug( $dir, array $classes ) {
+	protected function record_loader_debug( $dir, array $classes, float $discovery_seconds = 0.0, float $lookup_seconds = 0.0 ) {
 		if ( ! function_exists( 'is_admin' ) || ! is_admin() ) {
 			return;
 		}
 
+		// is_admin() is also true for admin-ajax.php. The debug page is a normal admin GET that
+		// re-runs discovery and records afresh, so recording on ajax requests is pure waste
+		// (often triggered from the front end). Skip them.
+		if ( function_exists( 'wp_doing_ajax' ) && wp_doing_ajax() ) {
+			return;
+		}
+
 		$cache_file   = $this->get_cache_directory( $dir ) . '/' . self::CACHE_FILENAME;
 		$cache_exists = file_exists( $cache_file );
 		$disabled     = $this->cache_disabled();
 
 		LoaderDebug::record(
 			[
-				'directory'      => $dir,
-				'cache_file'     => $cache_file,
-				'cache_exists'   => $cache_exists,
-				'cache_used'     => $cache_exists && ! $disabled,
-				'cache_disabled' => $disabled,
-				'classes'        => $classes,
-				'version'        => $this->framework_version(),
-				'reference'      => $this->framework_reference(),
+				'directory'         => $dir,
+				'cache_file'        => $cache_file,
+				'cache_exists'      => $cache_exists,
+				'cache_used'        => $cache_exists && ! $disabled,
+				'cache_disabled'    => $disabled,
+				'classes'           => $classes,
+				'version'           => $this->framework_version(),
+				'reference'         => $this->framework_reference(),
+				'discovery_seconds' => $discovery_seconds,
+				'lookup_seconds'    => $lookup_seconds,
 			]
 		);
 	}
@@ -303,9 +321,15 @@ protected function directory_check( $dir ): bool {
 	public function init_classes( $dir = '' ) {
 		$this->directory_check( $dir );
 
-		$classes = $this->get_classes( $dir );
+		// Time discovery (a cache read when a cache is present, a live filesystem scan
+		// otherwise) separately from the reflection/instantiation work below, so the debug
+		// page can show where the request's time actually goes. hrtime() is monotonic, so an
+		// NTP adjustment mid-request cannot produce a negative or wildly wrong delta.
+		$discovery_start   = hrtime( true );
+		$classes           = $this->get_classes( $dir );
+		$discovery_seconds = ( hrtime( true ) - $discovery_start ) / 1e9;
 
-		$this->record_loader_debug( $dir, $classes );
+		$lookup_start = hrtime( true );
 
 		$load_class_order = [];
 		foreach ( $classes as $class ) {
@@ -366,6 +390,10 @@ public function init_classes( $dir = '' ) {
 				}
 			}
 		}
+
+		$lookup_seconds = ( hrtime( true ) - $lookup_start ) / 1e9;
+
+		$this->record_loader_debug( $dir, $classes, $discovery_seconds, $lookup_seconds );
 	}
 
 	/**