From c583b0fa0fc217435e11baa7d81c957f9071c4c6 Mon Sep 17 00:00:00 2001 From: Miguel Angel Date: Mon, 3 Aug 2026 15:33:31 -0400 Subject: [PATCH 1/2] feat: implement WorkerBootTimingService for improved boot timing tracking --- .../Middleware/ServerTimingMiddleware.php | 9 +- .../Providers/ProcessMakerServiceProvider.php | 75 ++------------- .../Services/WorkerBootTimingService.php | 95 +++++++++++++++++++ .../Traits/PluginServiceProviderTrait.php | 16 +--- 4 files changed, 114 insertions(+), 81 deletions(-) create mode 100644 ProcessMaker/Services/WorkerBootTimingService.php diff --git a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php index aab562465f..958daa6707 100644 --- a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php +++ b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php @@ -5,10 +5,15 @@ use Closure; use Illuminate\Http\Request; use ProcessMaker\Providers\ProcessMakerServiceProvider; +use ProcessMaker\Services\WorkerBootTimingService; use Symfony\Component\HttpFoundation\Response; class ServerTimingMiddleware { + public function __construct(private WorkerBootTimingService $workerBootTimingService) + { + } + /** * Handle an incoming request. * @@ -31,7 +36,7 @@ public function handle(Request $request, Closure $next): Response // Calculate execution times $controllerTime = (microtime(true) - $startController) * 1000; // Convert to ms // Fetch service provider boot time - $serviceProviderTime = ProcessMakerServiceProvider::getBootTime() ?? 0; + $serviceProviderTime = $this->workerBootTimingService->getProviderBootTime() ?? 0; // Fetch query time $queryTime = ProcessMakerServiceProvider::getQueryTime() ?? 0; @@ -47,7 +52,7 @@ public function handle(Request $request, Closure $next): Response array_unshift($serverTiming, "boot;dur={$bootTiming}"); } - $packageTimes = ProcessMakerServiceProvider::getPackageBootTiming(); + $packageTimes = $this->workerBootTimingService->getPackageBootTiming(); $minPackageTime = config('app.server_timing.min_package_time'); foreach ($packageTimes as $package => $timing) { diff --git a/ProcessMaker/Providers/ProcessMakerServiceProvider.php b/ProcessMaker/Providers/ProcessMakerServiceProvider.php index a67e07bb52..1e24c71f51 100644 --- a/ProcessMaker/Providers/ProcessMakerServiceProvider.php +++ b/ProcessMaker/Providers/ProcessMakerServiceProvider.php @@ -57,6 +57,7 @@ use ProcessMaker\Repositories\SettingsConfigRepository; use ProcessMaker\Services\ConditionalRedirectService; use ProcessMaker\Services\RedirectToEventService; +use ProcessMaker\Services\WorkerBootTimingService; use RuntimeException; use Spatie\Multitenancy\Events\MadeTenantCurrentEvent; use Spatie\Multitenancy\Events\TenantNotFoundForRequestEvent; @@ -67,22 +68,13 @@ */ class ProcessMakerServiceProvider extends ServiceProvider { - // Track the start time for service providers boot - private static $bootStart; - - // Track the boot time for service providers - private static $bootTime; - - // Track the boot time for each package - private static $packageBootTiming = []; - // Track the query time for each request private static $queryTime = 0; public function boot(): void { // Track the start time for service providers boot - self::$bootStart = microtime(true); + $bootStart = microtime(true); // Set the current tenant $this->setCurrentTenantForConsoleCommands(); @@ -111,11 +103,15 @@ public function boot(): void $this->registerOctaneListeners(); // Hook after service providers boot - self::$bootTime = (microtime(true) - self::$bootStart) * 1000; // Convert to milliseconds + $this->app->make(WorkerBootTimingService::class) + ->setProviderBootTime((microtime(true) - $bootStart) * 1000); } public function register(): void { + // Boot metrics live for the lifetime of the application worker. + $this->app->singleton(WorkerBootTimingService::class); + if (config('app.server_timing.enabled')) { // Listen to query events and accumulate query execution time DB::listen(function ($query) { @@ -509,16 +505,6 @@ public static function forceHttps(): void } } - /** - * Get the boot time for service providers. - * - * @return float|null - */ - public static function getBootTime(): ?float - { - return self::$bootTime; - } - /** * Reset per-request query timing metrics. */ @@ -537,53 +523,6 @@ public static function getQueryTime(): float return self::$queryTime; } - /** - * Set the boot time for service providers. - * - * @param string $package - * @param float $time - */ - public static function setPackageBootStart(string $package, float $time): void - { - if ($time < 0) { - Log::info("Server Timing: Invalid boot time for package: {$package}, time: {$time}"); - - $time = 0; - } - - self::$packageBootTiming[$package] = [ - 'start' => $time, - 'end' => null, - ]; - } - - /** - * Set the boot time for service providers. - * - * - * @param float $time - */ - public static function setPackageBootedTime(string $package, $time): void - { - if (!isset(self::$packageBootTiming[$package]) || $time < 0) { - Log::info("Server Timing: Invalid booted time for package: {$package}, time: {$time}"); - - return; - } - - self::$packageBootTiming[$package]['end'] = $time; - } - - /** - * Get the boot time for service providers. - * - * @return array - */ - public static function getPackageBootTiming(): array - { - return self::$packageBootTiming; - } - /** * Reset per-request static state between Octane requests. * diff --git a/ProcessMaker/Services/WorkerBootTimingService.php b/ProcessMaker/Services/WorkerBootTimingService.php new file mode 100644 index 0000000000..0e14ae3de9 --- /dev/null +++ b/ProcessMaker/Services/WorkerBootTimingService.php @@ -0,0 +1,95 @@ + + */ + private array $packageBootTiming = []; + + /** + * Store the ProcessMaker service provider boot duration for this worker. + * + * @param float $time Boot duration in milliseconds + */ + public function setProviderBootTime(float $time): void + { + $this->providerBootTime = $time; + } + + /** + * Get the ProcessMaker service provider boot duration for this worker. + * + * @return float|null Boot duration in milliseconds, or null before it is recorded + */ + public function getProviderBootTime(): ?float + { + return $this->providerBootTime; + } + + /** + * Record when a package service provider starts booting. + * + * Invalid negative timestamps are logged and stored as zero. + * Calling this method again for the same package replaces its prior timing. + * + * @param string $package Package name used in the Server-Timing header + * @param float $time Start timestamp in seconds, as returned by microtime(true) + */ + public function setPackageBootStart(string $package, float $time): void + { + if ($time < 0) { + Log::info("Server Timing: Invalid boot time for package: {$package}, time: {$time}"); + + $time = 0.0; + } + + $this->packageBootTiming[$package] = [ + 'start' => $time, + 'end' => null, + ]; + } + + /** + * Record when a package service provider finishes booting. + * + * Invalid negative timestamps and packages without a recorded start are + * logged and ignored. + * + * @param string $package Package name used in the Server-Timing header + * @param float $time End timestamp in seconds, as returned by microtime(true) + */ + public function setPackageBootedTime(string $package, float $time): void + { + if (!isset($this->packageBootTiming[$package]) || $time < 0) { + Log::info("Server Timing: Invalid booted time for package: {$package}, time: {$time}"); + + return; + } + + $this->packageBootTiming[$package]['end'] = $time; + } + + /** + * Get all package boot timestamps recorded for this worker. + * + * @return array + */ + public function getPackageBootTiming(): array + { + return $this->packageBootTiming; + } +} diff --git a/ProcessMaker/Traits/PluginServiceProviderTrait.php b/ProcessMaker/Traits/PluginServiceProviderTrait.php index b03160e575..f049697279 100644 --- a/ProcessMaker/Traits/PluginServiceProviderTrait.php +++ b/ProcessMaker/Traits/PluginServiceProviderTrait.php @@ -11,7 +11,7 @@ use ProcessMaker\Managers\IndexManager; use ProcessMaker\Managers\LoginManager; use ProcessMaker\Managers\PackageManager; -use ProcessMaker\Providers\ProcessMakerServiceProvider; +use ProcessMaker\Services\WorkerBootTimingService; /** * Add functionality to control a PM plug-in @@ -22,10 +22,6 @@ trait PluginServiceProviderTrait private $scriptBuilderScripts = []; - private static $bootStart = null; - - private static $bootTime; - public function __construct($app) { parent::__construct($app); @@ -48,15 +44,13 @@ protected function bootServerTiming(): void $package = $this->getPackageName(); $this->booting(function () use ($package) { - self::$bootStart = microtime(true); - - ProcessMakerServiceProvider::setPackageBootStart($package, self::$bootStart); + $this->app->make(WorkerBootTimingService::class) + ->setPackageBootStart($package, microtime(true)); }); $this->booted(function () use ($package) { - self::$bootTime = microtime(true); - - ProcessMakerServiceProvider::setPackageBootedTime($package, self::$bootTime); + $this->app->make(WorkerBootTimingService::class) + ->setPackageBootedTime($package, microtime(true)); }); } From 9b798c5eb24f2a4d93ae0c330a7071c18b419017 Mon Sep 17 00:00:00 2001 From: Miguel Angel Date: Mon, 3 Aug 2026 16:21:39 -0400 Subject: [PATCH 2/2] test: add middleware request timing validation tests --- tests/Feature/ServerTimingMiddlewareTest.php | 58 ++++- .../Octane/ResetRequestStateTest.php | 21 ++ .../Services/WorkerBootTimingServiceTest.php | 214 ++++++++++++++++++ 3 files changed, 287 insertions(+), 6 deletions(-) create mode 100644 tests/unit/ProcessMaker/Services/WorkerBootTimingServiceTest.php diff --git a/tests/Feature/ServerTimingMiddlewareTest.php b/tests/Feature/ServerTimingMiddlewareTest.php index 63bf54f0bb..b6457dd9d7 100644 --- a/tests/Feature/ServerTimingMiddlewareTest.php +++ b/tests/Feature/ServerTimingMiddlewareTest.php @@ -10,6 +10,7 @@ use ProcessMaker\Http\Middleware\ServerTimingMiddleware; use ProcessMaker\Models\User; use ProcessMaker\Providers\ProcessMakerServiceProvider; +use ProcessMaker\Services\WorkerBootTimingService; use ReflectionClass; use Tests\Feature\Shared\RequestHelper; use Tests\TestCase; @@ -177,6 +178,49 @@ public function testServiceProviderTimeIsMeasured() $this->assertGreaterThanOrEqual(0, (float) $providersTime); } + public function testOctaneGatewayPreservesWorkerBootTimingAcrossConsecutiveRequests() + { + config(['app.server_timing.min_package_time' => 0]); + + $workerTiming = app(WorkerBootTimingService::class); + $workerTiming->setProviderBootTime(12.5); + $workerTiming->setPackageBootStart('four32501-worker-package', 10.0); + $workerTiming->setPackageBootedTime('four32501-worker-package', 10.025); + $expectedPackageTiming = $workerTiming->getPackageBootTiming(); + + Route::middleware(ServerTimingMiddleware::class)->get('/octane-worker-timing', function () { + return response()->json(['message' => 'Octane worker timing test']); + }); + + $firstRequest = Request::create('/octane-worker-timing'); + $firstGateway = new ApplicationGateway($this->app, clone $this->app); + $firstResponse = $firstGateway->handle($firstRequest); + + $this->assertSame(12.5, $this->getMetricDuration($firstResponse, 'provider')); + $this->assertEqualsWithDelta( + 25.0, + $this->getMetricDuration($firstResponse, 'four32501-worker-package'), + 0.001 + ); + + $firstGateway->terminate($firstRequest, $firstResponse); + + $secondRequest = Request::create('/octane-worker-timing'); + $secondGateway = new ApplicationGateway($this->app, clone $this->app); + $secondResponse = $secondGateway->handle($secondRequest); + + $this->assertSame(12.5, $this->getMetricDuration($secondResponse, 'provider')); + $this->assertEqualsWithDelta( + 25.0, + $this->getMetricDuration($secondResponse, 'four32501-worker-package'), + 0.001 + ); + + $secondGateway->terminate($secondRequest, $secondResponse); + + $this->assertSame($expectedPackageTiming, $workerTiming->getPackageBootTiming()); + } + public function testControllerTimingIsMeasuredCorrectly() { // Mock a route @@ -241,11 +285,12 @@ public function testPackageTimingRespectsMinPackageTimeThreshold() 'app.server_timing.min_package_time' => 5, ]); - ProcessMakerServiceProvider::setPackageBootStart('foour32507-fast-package', 0.0); - ProcessMakerServiceProvider::setPackageBootedTime('foour32507-fast-package', 0.002); + $workerTiming = app(WorkerBootTimingService::class); + $workerTiming->setPackageBootStart('foour32507-fast-package', 0.0); + $workerTiming->setPackageBootedTime('foour32507-fast-package', 0.002); - ProcessMakerServiceProvider::setPackageBootStart('foour32507-slow-package', 0.0); - ProcessMakerServiceProvider::setPackageBootedTime('foour32507-slow-package', 0.010); + $workerTiming->setPackageBootStart('foour32507-slow-package', 0.0); + $workerTiming->setPackageBootedTime('foour32507-slow-package', 0.010); Route::middleware(ServerTimingMiddleware::class)->get('/package-threshold-test', function () { return response()->json(['message' => 'Package threshold test']); @@ -264,8 +309,9 @@ public function testMinPackageTimeReadsConfigPerRequest() { config(['app.server_timing.enabled' => true]); - ProcessMakerServiceProvider::setPackageBootStart('foour32507-octane-package', 0.0); - ProcessMakerServiceProvider::setPackageBootedTime('foour32507-octane-package', 0.008); + $workerTiming = app(WorkerBootTimingService::class); + $workerTiming->setPackageBootStart('foour32507-octane-package', 0.0); + $workerTiming->setPackageBootedTime('foour32507-octane-package', 0.008); Route::middleware(ServerTimingMiddleware::class)->get('/octane-min-package-test', function () { return response()->json(['message' => 'Octane min package test']); diff --git a/tests/unit/ProcessMaker/Octane/ResetRequestStateTest.php b/tests/unit/ProcessMaker/Octane/ResetRequestStateTest.php index 556f80d1cd..0af3ee25ad 100644 --- a/tests/unit/ProcessMaker/Octane/ResetRequestStateTest.php +++ b/tests/unit/ProcessMaker/Octane/ResetRequestStateTest.php @@ -15,6 +15,7 @@ use ProcessMaker\Octane\ResetRequestState; use ProcessMaker\Providers\ProcessMakerServiceProvider; use ProcessMaker\Services\RedirectToEventService; +use ProcessMaker\Services\WorkerBootTimingService; use Symfony\Component\HttpFoundation\Response; use Tests\TestCase; @@ -110,6 +111,26 @@ public function test_octane_request_termination_resets_timing_after_an_error_res $this->assertSame(0.0, ProcessMakerServiceProvider::getQueryTime()); } + + public function test_octane_request_termination_preserves_worker_boot_timing(): void + { + $workerTiming = app(WorkerBootTimingService::class); + $workerTiming->setProviderBootTime(12.5); + $workerTiming->setPackageBootStart('ExamplePackage', 10.0); + $workerTiming->setPackageBootedTime('ExamplePackage', 10.25); + $expectedPackageTiming = $workerTiming->getPackageBootTiming(); + + event(new RequestTerminated( + $this->app, + $this->app, + Request::create('/first-request'), + new Response() + )); + + $this->assertSame($workerTiming, app(WorkerBootTimingService::class)); + $this->assertSame(12.5, $workerTiming->getProviderBootTime()); + $this->assertSame($expectedPackageTiming, $workerTiming->getPackageBootTiming()); + } } final class RedirectStateProbe extends HandleRedirectListener diff --git a/tests/unit/ProcessMaker/Services/WorkerBootTimingServiceTest.php b/tests/unit/ProcessMaker/Services/WorkerBootTimingServiceTest.php new file mode 100644 index 0000000000..139211139c --- /dev/null +++ b/tests/unit/ProcessMaker/Services/WorkerBootTimingServiceTest.php @@ -0,0 +1,214 @@ +setProviderBootTime(12.5); + + $this->app->forgetScopedInstances(); + + $this->assertSame($service, app(WorkerBootTimingService::class)); + $this->assertSame(12.5, app(WorkerBootTimingService::class)->getProviderBootTime()); + $this->assertNotContains(WorkerBootTimingService::class, config('octane.flush')); + } + + public function test_octane_application_clone_shares_the_worker_timing_service(): void + { + $service = app(WorkerBootTimingService::class); + $service->setProviderBootTime(18.75); + + $sandbox = clone $this->app; + $sandboxService = $sandbox->make(WorkerBootTimingService::class); + + $this->assertSame($service, $sandboxService); + $this->assertSame(18.75, $sandboxService->getProviderBootTime()); + } + + public function test_it_records_package_boot_start_and_end_times(): void + { + $service = new WorkerBootTimingService(); + + $service->setPackageBootStart('ExamplePackage', 10.25); + $service->setPackageBootedTime('ExamplePackage', 10.75); + + $this->assertSame([ + 'ExamplePackage' => [ + 'start' => 10.25, + 'end' => 10.75, + ], + ], $service->getPackageBootTiming()); + } + + public function test_repeated_package_measurements_replace_the_existing_entry(): void + { + $service = new WorkerBootTimingService(); + + $service->setPackageBootStart('ExamplePackage', 10.0); + $service->setPackageBootedTime('ExamplePackage', 11.0); + $service->setPackageBootStart('ExamplePackage', 20.0); + $service->setPackageBootedTime('ExamplePackage', 20.5); + + $this->assertCount(1, $service->getPackageBootTiming()); + $this->assertSame([ + 'start' => 20.0, + 'end' => 20.5, + ], $service->getPackageBootTiming()['ExamplePackage']); + } + + public function test_many_repeated_measurements_remain_bounded_by_unique_package_names(): void + { + $service = new WorkerBootTimingService(); + + for ($index = 0; $index < 1000; $index++) { + $package = 'Package' . ($index % 5); + $service->setPackageBootStart($package, (float) $index); + $service->setPackageBootedTime($package, $index + 0.5); + } + + $this->assertCount(5, $service->getPackageBootTiming()); + $this->assertSame([ + 'start' => 999.0, + 'end' => 999.5, + ], $service->getPackageBootTiming()['Package4']); + } + + public function test_returned_package_timing_snapshot_cannot_mutate_worker_state(): void + { + $service = new WorkerBootTimingService(); + $service->setPackageBootStart('ExamplePackage', 10.0); + $service->setPackageBootedTime('ExamplePackage', 10.5); + + $snapshot = $service->getPackageBootTiming(); + $snapshot['ExamplePackage']['start'] = 999.0; + $snapshot['InjectedPackage'] = [ + 'start' => 20.0, + 'end' => 21.0, + ]; + + $this->assertSame([ + 'ExamplePackage' => [ + 'start' => 10.0, + 'end' => 10.5, + ], + ], $service->getPackageBootTiming()); + } + + public function test_separate_worker_services_do_not_share_timing_state(): void + { + $firstWorker = new WorkerBootTimingService(); + $secondWorker = new WorkerBootTimingService(); + + $firstWorker->setProviderBootTime(10.0); + $firstWorker->setPackageBootStart('FirstWorkerPackage', 1.0); + $firstWorker->setPackageBootedTime('FirstWorkerPackage', 1.5); + + $secondWorker->setProviderBootTime(20.0); + $secondWorker->setPackageBootStart('SecondWorkerPackage', 2.0); + $secondWorker->setPackageBootedTime('SecondWorkerPackage', 2.5); + + $this->assertSame(10.0, $firstWorker->getProviderBootTime()); + $this->assertSame(20.0, $secondWorker->getProviderBootTime()); + $this->assertArrayHasKey('FirstWorkerPackage', $firstWorker->getPackageBootTiming()); + $this->assertArrayNotHasKey('SecondWorkerPackage', $firstWorker->getPackageBootTiming()); + $this->assertArrayHasKey('SecondWorkerPackage', $secondWorker->getPackageBootTiming()); + $this->assertArrayNotHasKey('FirstWorkerPackage', $secondWorker->getPackageBootTiming()); + } + + public function test_invalid_package_start_time_is_logged_and_clamped_to_zero(): void + { + Log::spy(); + $service = new WorkerBootTimingService(); + + $service->setPackageBootStart('InvalidPackage', -1.5); + + $this->assertSame([ + 'start' => 0.0, + 'end' => null, + ], $service->getPackageBootTiming()['InvalidPackage']); + Log::shouldHaveReceived('info') + ->once() + ->with('Server Timing: Invalid boot time for package: InvalidPackage, time: -1.5'); + } + + public function test_invalid_package_end_time_is_logged_and_ignored(): void + { + Log::spy(); + $service = new WorkerBootTimingService(); + $service->setPackageBootStart('InvalidPackage', 5.0); + + $service->setPackageBootedTime('InvalidPackage', -2.5); + + $this->assertNull($service->getPackageBootTiming()['InvalidPackage']['end']); + Log::shouldHaveReceived('info') + ->once() + ->with('Server Timing: Invalid booted time for package: InvalidPackage, time: -2.5'); + } + + public function test_package_end_without_a_start_is_logged_and_does_not_create_state(): void + { + Log::spy(); + $service = new WorkerBootTimingService(); + + $service->setPackageBootedTime('UnstartedPackage', 10.5); + + $this->assertSame([], $service->getPackageBootTiming()); + Log::shouldHaveReceived('info') + ->once() + ->with('Server Timing: Invalid booted time for package: UnstartedPackage, time: 10.5'); + } + + public function test_plugin_service_provider_records_one_complete_package_interval(): void + { + config(['app.server_timing.enabled' => true]); + + $this->app->register(new WorkerBootTimingTestPluginServiceProvider($this->app)); + + $timing = app(WorkerBootTimingService::class)->getPackageBootTiming(); + $this->assertArrayHasKey('WorkerBootTimingTestPlugin', $timing); + $this->assertIsFloat($timing['WorkerBootTimingTestPlugin']['start']); + $this->assertIsFloat($timing['WorkerBootTimingTestPlugin']['end']); + $this->assertGreaterThanOrEqual( + $timing['WorkerBootTimingTestPlugin']['start'], + $timing['WorkerBootTimingTestPlugin']['end'] + ); + } + + public function test_plugin_service_provider_does_not_record_timing_when_disabled(): void + { + config(['app.server_timing.enabled' => false]); + + $this->app->register(new DisabledWorkerBootTimingTestPluginServiceProvider($this->app)); + + $timing = app(WorkerBootTimingService::class)->getPackageBootTiming(); + $this->assertArrayNotHasKey('DisabledWorkerBootTimingTestPlugin', $timing); + } +} + +final class WorkerBootTimingTestPluginServiceProvider extends ServiceProvider +{ + use PluginServiceProviderTrait; + + public const name = 'worker-boot-timing-test-plugin'; + + public function boot(): void + { + usleep(1000); + } +} + +final class DisabledWorkerBootTimingTestPluginServiceProvider extends ServiceProvider +{ + use PluginServiceProviderTrait; + + public const name = 'disabled-worker-boot-timing-test-plugin'; +}