From bae5940742c22af474bedea36d802097f57ef5e0 Mon Sep 17 00:00:00 2001 From: Miguel Angel Date: Tue, 10 Dec 2024 10:04:18 -0400 Subject: [PATCH 1/9] feat: add server timing header for controller time execution --- ProcessMaker/Http/Kernel.php | 2 ++ .../Middleware/ServerTimingMiddleware.php | 31 +++++++++++++++++++ 2 files changed, 33 insertions(+) create mode 100644 ProcessMaker/Http/Middleware/ServerTimingMiddleware.php diff --git a/ProcessMaker/Http/Kernel.php b/ProcessMaker/Http/Kernel.php index 5fb8432f48..e6ee02c7ee 100644 --- a/ProcessMaker/Http/Kernel.php +++ b/ProcessMaker/Http/Kernel.php @@ -3,6 +3,7 @@ namespace ProcessMaker\Http; use Illuminate\Foundation\Http\Kernel as HttpKernel; +use ProcessMaker\Http\Middleware\ServerTimingMiddleware; class Kernel extends HttpKernel { @@ -20,6 +21,7 @@ class Kernel extends HttpKernel \Illuminate\Foundation\Http\Middleware\ConvertEmptyStringsToNull::class, Middleware\TrustProxies::class, Middleware\BrowserCache::class, + ServerTimingMiddleware::class, ]; /** diff --git a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php new file mode 100644 index 0000000000..03da03470e --- /dev/null +++ b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php @@ -0,0 +1,31 @@ +headers->set('Server-Timing', "controller;dur={$duration}"); + + return $response; + } +} From af61b8c7bb0c48cb1d026fb2f4def72a41b706c3 Mon Sep 17 00:00:00 2001 From: Miguel Angel Date: Tue, 10 Dec 2024 10:12:13 -0400 Subject: [PATCH 2/9] feat: add server timing header for db time execution --- .../Http/Middleware/ServerTimingMiddleware.php | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php index 03da03470e..e6bed89cfa 100644 --- a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php +++ b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php @@ -4,6 +4,7 @@ use Closure; use Illuminate\Http\Request; +use Illuminate\Support\Facades\DB; use Symfony\Component\HttpFoundation\Response; class ServerTimingMiddleware @@ -16,6 +17,12 @@ class ServerTimingMiddleware public function handle(Request $request, Closure $next): Response { $start = microtime(true); + $queryTime = 0; + + // Listen to query events and accumulate query execution time + DB::listen(function ($query) use (&$queryTime) { + $queryTime += $query->time; // Query time in milliseconds + }); // Process the request $response = $next($request); @@ -25,6 +32,10 @@ public function handle(Request $request, Closure $next): Response // Add Server-Timing header $response->headers->set('Server-Timing', "controller;dur={$duration}"); + $response->headers->set('Server-Timing', [ + "controller;dur={$duration}", + "db;dur={$queryTime}" + ]); return $response; } From ebc1c8de2adfc0a2733b6d0fb39c7e46afe5819b Mon Sep 17 00:00:00 2001 From: Miguel Angel Date: Tue, 10 Dec 2024 11:20:29 -0400 Subject: [PATCH 3/9] feat: add server timing header for endpoint time execution --- .../Http/Middleware/ServerTimingMiddleware.php | 18 ++++++++++++------ 1 file changed, 12 insertions(+), 6 deletions(-) diff --git a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php index e6bed89cfa..9e9c7f469b 100644 --- a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php +++ b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php @@ -16,7 +16,9 @@ class ServerTimingMiddleware */ public function handle(Request $request, Closure $next): Response { - $start = microtime(true); + // Start time for the entire request + $startEndpoint = microtime(true); + // Track total query execution time $queryTime = 0; // Listen to query events and accumulate query execution time @@ -24,16 +26,20 @@ public function handle(Request $request, Closure $next): Response $queryTime += $query->time; // Query time in milliseconds }); + // Start time for controller execution + $startController = microtime(true); + // Process the request $response = $next($request); - // Calculate elapsed time - $duration = (microtime(true) - $start) * 1000; // Convert to milliseconds + // Calculate execution times + $controllerTime = (microtime(true) - $startController) * 1000; // Convert to ms + $endpointTime = (microtime(true) - $startEndpoint) * 1000; // Convert to ms // Add Server-Timing header - $response->headers->set('Server-Timing', "controller;dur={$duration}"); - $response->headers->set('Server-Timing', [ - "controller;dur={$duration}", + $response->headers->set('Server-Timing', [ + "endpoint;dur={$endpointTime}", + "controller;dur={$controllerTime}", "db;dur={$queryTime}" ]); From 625e5d994408d33f82d05d3b54b3f02bdded792b Mon Sep 17 00:00:00 2001 From: Miguel Angel Date: Tue, 10 Dec 2024 14:37:28 -0400 Subject: [PATCH 4/9] feat: add server timing header for service provider time execution --- .../Middleware/ServerTimingMiddleware.php | 9 ++++++-- .../Providers/ProcessMakerServiceProvider.php | 21 +++++++++++++++++++ 2 files changed, 28 insertions(+), 2 deletions(-) diff --git a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php index 9e9c7f469b..388944163a 100644 --- a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php +++ b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php @@ -5,6 +5,7 @@ use Closure; use Illuminate\Http\Request; use Illuminate\Support\Facades\DB; +use ProcessMaker\Providers\ProcessMakerServiceProvider; use Symfony\Component\HttpFoundation\Response; class ServerTimingMiddleware @@ -36,11 +37,15 @@ public function handle(Request $request, Closure $next): Response $controllerTime = (microtime(true) - $startController) * 1000; // Convert to ms $endpointTime = (microtime(true) - $startEndpoint) * 1000; // Convert to ms - // Add Server-Timing header + // Fetch service provider boot time + $serviceProviderTime = ProcessMakerServiceProvider::getBootTime() ?? 0; + + // Add Server-Timing headers $response->headers->set('Server-Timing', [ + "providers;dur={$serviceProviderTime}", "endpoint;dur={$endpointTime}", "controller;dur={$controllerTime}", - "db;dur={$queryTime}" + "db;dur={$queryTime}", ]); return $response; diff --git a/ProcessMaker/Providers/ProcessMakerServiceProvider.php b/ProcessMaker/Providers/ProcessMakerServiceProvider.php index ce11b8e437..afdff8660b 100644 --- a/ProcessMaker/Providers/ProcessMakerServiceProvider.php +++ b/ProcessMaker/Providers/ProcessMakerServiceProvider.php @@ -35,6 +35,11 @@ */ 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; + public function boot(): void { $this->app->singleton(Menu::class, function ($app) { @@ -52,10 +57,16 @@ public function boot(): void $this->setupFactories(); parent::boot(); + + // Hook after service providers boot + self::$bootTime = (microtime(true) - self::$bootStart) * 1000; // Convert to milliseconds } public function register(): void { + // Track the start time for service providers boot + self::$bootStart = microtime(true); + // Dusk, if env is appropriate // TODO Remove Dusk references and remove from composer dependencies if (!$this->app->environment('production')) { @@ -358,4 +369,14 @@ public static function forceHttps(): void URL::forceScheme('https'); } } + + /** + * Get the boot time for service providers. + * + * @return float|null + */ + public static function getBootTime(): ?float + { + return self::$bootTime; + } } From f32d25f1bbabdd803690ede1261bb0a79849e22b Mon Sep 17 00:00:00 2001 From: Miguel Angel Date: Wed, 11 Dec 2024 16:17:12 -0400 Subject: [PATCH 5/9] feat: server timing header for package service provider time execution --- .../Middleware/ServerTimingMiddleware.php | 16 +- .../Providers/ProcessMakerServiceProvider.php | 45 ++++- .../Traits/PluginServiceProviderTrait.php | 27 +++ tests/Feature/ServerTimingMiddlewareTest.php | 159 ++++++++++++++++++ 4 files changed, 241 insertions(+), 6 deletions(-) create mode 100644 tests/Feature/ServerTimingMiddlewareTest.php diff --git a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php index 388944163a..249bdae5e9 100644 --- a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php +++ b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php @@ -40,13 +40,23 @@ public function handle(Request $request, Closure $next): Response // Fetch service provider boot time $serviceProviderTime = ProcessMakerServiceProvider::getBootTime() ?? 0; - // Add Server-Timing headers - $response->headers->set('Server-Timing', [ + $serverTiming = [ "providers;dur={$serviceProviderTime}", "endpoint;dur={$endpointTime}", "controller;dur={$controllerTime}", "db;dur={$queryTime}", - ]); + ]; + + $packageTimes = ProcessMakerServiceProvider::getPackageBootTiming(); + + foreach ($packageTimes as $package => $timing) { + $time = ($timing['end'] - $timing['start']) * 1000; + + $serverTiming[] = "{$package};dur={$time}"; + } + + // Add Server-Timing headers + $response->headers->set('Server-Timing', $serverTiming); return $response; } diff --git a/ProcessMaker/Providers/ProcessMakerServiceProvider.php b/ProcessMaker/Providers/ProcessMakerServiceProvider.php index afdff8660b..197ba5a573 100644 --- a/ProcessMaker/Providers/ProcessMakerServiceProvider.php +++ b/ProcessMaker/Providers/ProcessMakerServiceProvider.php @@ -39,9 +39,14 @@ class ProcessMakerServiceProvider extends ServiceProvider private static $bootStart; // Track the boot time for service providers private static $bootTime; + // Track the boot time for each package + private static $packageBootTiming = []; public function boot(): void { + // Track the start time for service providers boot + self::$bootStart = microtime(true); + $this->app->singleton(Menu::class, function ($app) { return new MenuManager(); }); @@ -64,9 +69,6 @@ public function boot(): void public function register(): void { - // Track the start time for service providers boot - self::$bootStart = microtime(true); - // Dusk, if env is appropriate // TODO Remove Dusk references and remove from composer dependencies if (!$this->app->environment('production')) { @@ -379,4 +381,41 @@ public static function getBootTime(): ?float { return self::$bootTime; } + + /** + * Set the boot time for service providers. + * + * @param float $time + */ + public static function setPackageBootStart(string $package, $time): void + { + $package = ucfirst(\Str::camel(str_replace(['ProcessMaker\Packages\\', '\\'], '', $package))); + + 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 + { + $package = ucfirst(\Str::camel(str_replace(['ProcessMaker\Packages\\', '\\'], '', $package))); + + self::$packageBootTiming[$package]['end'] = $time; + } + + /** + * Get the boot time for service providers. + * + * @return array + */ + public static function getPackageBootTiming(): array + { + return self::$packageBootTiming; + } } diff --git a/ProcessMaker/Traits/PluginServiceProviderTrait.php b/ProcessMaker/Traits/PluginServiceProviderTrait.php index 2e25a147ec..028409f4a4 100644 --- a/ProcessMaker/Traits/PluginServiceProviderTrait.php +++ b/ProcessMaker/Traits/PluginServiceProviderTrait.php @@ -11,6 +11,7 @@ use ProcessMaker\Managers\IndexManager; use ProcessMaker\Managers\LoginManager; use ProcessMaker\Managers\PackageManager; +use ProcessMaker\Providers\ProcessMakerServiceProvider; /** * Add functionality to control a PM plug-in @@ -21,6 +22,32 @@ trait PluginServiceProviderTrait private $scriptBuilderScripts = []; + private static $bootStart = null; + + private static $bootTime; + + public function __construct($app) + { + parent::__construct($app); + + $this->booting(function () { + self::$bootStart = microtime(true); + + $package = defined('static::name') ? static::name : $this::class; + + ProcessMakerServiceProvider::setPackageBootStart($package, self::$bootStart); + }); + + $this->booted(function () { + self::$bootTime = microtime(true); + + $package = defined('static::name') ? static::name : $this::class; + + ProcessMakerServiceProvider::setPackageBootedTime($package, self::$bootTime); + }); + + } + /** * Boot the PM plug-in. */ diff --git a/tests/Feature/ServerTimingMiddlewareTest.php b/tests/Feature/ServerTimingMiddlewareTest.php new file mode 100644 index 0000000000..640148b7ac --- /dev/null +++ b/tests/Feature/ServerTimingMiddlewareTest.php @@ -0,0 +1,159 @@ +headers->all(); + return $headers[$header]; + } + + public function testServerTimingHeaderIncludesAllMetrics() + { + Route::middleware(ServerTimingMiddleware::class)->get('/test', function () { + // Simulate a query + DB::select('SELECT SLEEP(1)'); + + return response()->json(['message' => 'Test endpoint']); + }); + + // Send a GET request + $response = $this->get('/test'); + $response->assertStatus(200); + // Assert the response has the Server-Timing header + $response->assertHeader('Server-Timing'); + + $serverTiming = $this->getHeader($response, 'server-timing'); + $this->assertStringContainsString('providers;dur=', $serverTiming[0]); + $this->assertStringContainsString('endpoint;dur=', $serverTiming[1]); + $this->assertStringContainsString('controller;dur=', $serverTiming[2]); + $this->assertStringContainsString('db;dur=', $serverTiming[3]); + } + + public function testQueryTimeIsMeasured() + { + // Mock a route with a query + Route::middleware(ServerTimingMiddleware::class)->get('/query-test', function () { + DB::select('SELECT SLEEP(0.2)'); + return response()->json(['message' => 'Query test']); + }); + + // Send a GET request + $response = $this->get('/query-test'); + // Extract the Server-Timing header + $serverTiming = $this->getHeader($response, 'server-timing'); + // Assert the db timing is greater than 200ms (SLEEP simulates query time) + preg_match('/db;dur=([\d.]+)/', $serverTiming[3], $matches); + $dbTime = $matches[1] ?? 0; + + $this->assertGreaterThanOrEqual(200, (float)$dbTime); + } + + public function testServiceProviderTimeIsMeasured() + { + // Mock a route + Route::middleware(ServerTimingMiddleware::class)->get('/providers-test', function () { + return response()->json(['message' => 'Providers test']); + }); + + // Send a GET request + $response = $this->get('/providers-test'); + // Extract the Server-Timing header + $serverTiming = $this->getHeader($response, 'server-timing'); + + // Assert the providers timing is present and greater than or equal to 0 + preg_match('/providers;dur=([\d.]+)/', $serverTiming[0], $matches); + $providersTime = $matches[1] ?? null; + + $this->assertNotNull($providersTime); + $this->assertGreaterThanOrEqual(0, (float)$providersTime); + } + + public function testEndpointTimingIsMeasuredCorrectly() + { + // Mock a route + Route::middleware(ServerTimingMiddleware::class)->get('/endpoint-test', function () { + usleep(500000); // Simulate 500ms delay + return response()->json(['message' => 'Endpoint timing test']); + }); + + // Send a GET request + $response = $this->get('/endpoint-test'); + // Extract the Server-Timing header + $serverTiming = $this->getHeader($response, 'server-timing'); + + // Assert the endpoint timing is greater than 500ms + preg_match('/endpoint;dur=([\d.]+)/', $serverTiming[1], $matches); + $endpointTime = $matches[1] ?? 0; + + $this->assertGreaterThanOrEqual(500, (float)$endpointTime); + } + + public function testControllerTimingIsMeasuredCorrectly() + { + // Mock a route + Route::middleware(ServerTimingMiddleware::class)->get('/controller-test', function () { + usleep(300000); // Simulate 300ms delay in the controller + return response()->json(['message' => 'Controller timing test']); + }); + + // Send a GET request + $response = $this->get('/controller-test'); + // Extract the Server-Timing header + $serverTiming = $this->getHeader($response, 'server-timing'); + + // Assert the controller timing is greater than 300ms + preg_match('/controller;dur=([\d.]+)/', $serverTiming[2], $matches); + $controllerTime = $matches[1] ?? 0; + + $this->assertGreaterThanOrEqual(300, (float)$controllerTime); + } + + public function testProvidersTimingIsMeasuredCorrectly() + { + // Mock a route + Route::middleware(ServerTimingMiddleware::class)->get('/providers-test', function () { + return response()->json(['message' => 'Providers timing test']); + }); + + // Send a GET request + $response = $this->get('/providers-test'); + // Extract the Server-Timing header + $serverTiming = $this->getHeader($response, 'server-timing'); + + // Assert the providers timing is present and greater than or equal to 0 + preg_match('/providers;dur=([\d.]+)/', $serverTiming[0], $matches); + $providersTime = $matches[1] ?? null; + + $this->assertNotNull($providersTime); + $this->assertGreaterThanOrEqual(0, (float)$providersTime); + } + + public function testServerTimingOnLogin() + { + $user = User::factory()->create([ + 'username' =>'john', + ]); + $this->actingAs($user, 'web'); + + $response = $this->get('/login'); + $response->assertHeader('Server-Timing'); + + $serverTiming = $this->getHeader($response, 'server-timing'); + $this->assertStringContainsString('providers;dur=', $serverTiming[0]); + $this->assertStringContainsString('endpoint;dur=', $serverTiming[1]); + $this->assertStringContainsString('controller;dur=', $serverTiming[2]); + $this->assertStringContainsString('db;dur=', $serverTiming[3]); + } +} From e4769782e5209529fb69afbab10e7fb6651e4692 Mon Sep 17 00:00:00 2001 From: Miguel Angel Date: Wed, 11 Dec 2024 23:39:25 -0400 Subject: [PATCH 6/9] feat: update server timing header for db time execution --- .../Middleware/ServerTimingMiddleware.php | 17 ++------ .../Providers/ProcessMakerServiceProvider.php | 18 ++++++++ tests/Feature/ServerTimingMiddlewareTest.php | 42 +++++-------------- 3 files changed, 31 insertions(+), 46 deletions(-) diff --git a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php index 249bdae5e9..1c687d4f5d 100644 --- a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php +++ b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php @@ -17,16 +17,6 @@ class ServerTimingMiddleware */ public function handle(Request $request, Closure $next): Response { - // Start time for the entire request - $startEndpoint = microtime(true); - // Track total query execution time - $queryTime = 0; - - // Listen to query events and accumulate query execution time - DB::listen(function ($query) use (&$queryTime) { - $queryTime += $query->time; // Query time in milliseconds - }); - // Start time for controller execution $startController = microtime(true); @@ -35,14 +25,13 @@ public function handle(Request $request, Closure $next): Response // Calculate execution times $controllerTime = (microtime(true) - $startController) * 1000; // Convert to ms - $endpointTime = (microtime(true) - $startEndpoint) * 1000; // Convert to ms - // Fetch service provider boot time $serviceProviderTime = ProcessMakerServiceProvider::getBootTime() ?? 0; + // Fetch query time + $queryTime = ProcessMakerServiceProvider::getQueryTime() ?? 0; $serverTiming = [ - "providers;dur={$serviceProviderTime}", - "endpoint;dur={$endpointTime}", + "provider;dur={$serviceProviderTime}", "controller;dur={$controllerTime}", "db;dur={$queryTime}", ]; diff --git a/ProcessMaker/Providers/ProcessMakerServiceProvider.php b/ProcessMaker/Providers/ProcessMakerServiceProvider.php index 197ba5a573..9bb9442cf2 100644 --- a/ProcessMaker/Providers/ProcessMakerServiceProvider.php +++ b/ProcessMaker/Providers/ProcessMakerServiceProvider.php @@ -10,6 +10,7 @@ use Illuminate\Notifications\Events\BroadcastNotificationCreated; use Illuminate\Notifications\Events\NotificationSent; use Illuminate\Support\Facades; +use Illuminate\Support\Facades\DB; use Illuminate\Support\Facades\URL; use Laravel\Dusk\DuskServiceProvider; use Laravel\Horizon\Horizon; @@ -41,6 +42,8 @@ class ProcessMakerServiceProvider extends ServiceProvider 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 { @@ -69,6 +72,11 @@ public function boot(): void public function register(): void { + // Listen to query events and accumulate query execution time + DB::listen(function ($query) { + self::$queryTime += $query->time; + }); + // Dusk, if env is appropriate // TODO Remove Dusk references and remove from composer dependencies if (!$this->app->environment('production')) { @@ -382,6 +390,16 @@ public static function getBootTime(): ?float return self::$bootTime; } + /** + * Get the query time for the request. + * + * @return float + */ + public static function getQueryTime(): float + { + return self::$queryTime; + } + /** * Set the boot time for service providers. * diff --git a/tests/Feature/ServerTimingMiddlewareTest.php b/tests/Feature/ServerTimingMiddlewareTest.php index 640148b7ac..d82aed00d8 100644 --- a/tests/Feature/ServerTimingMiddlewareTest.php +++ b/tests/Feature/ServerTimingMiddlewareTest.php @@ -35,10 +35,9 @@ public function testServerTimingHeaderIncludesAllMetrics() $response->assertHeader('Server-Timing'); $serverTiming = $this->getHeader($response, 'server-timing'); - $this->assertStringContainsString('providers;dur=', $serverTiming[0]); - $this->assertStringContainsString('endpoint;dur=', $serverTiming[1]); - $this->assertStringContainsString('controller;dur=', $serverTiming[2]); - $this->assertStringContainsString('db;dur=', $serverTiming[3]); + $this->assertStringContainsString('provider;dur=', $serverTiming[0]); + $this->assertStringContainsString('controller;dur=', $serverTiming[1]); + $this->assertStringContainsString('db;dur=', $serverTiming[2]); } public function testQueryTimeIsMeasured() @@ -54,7 +53,7 @@ public function testQueryTimeIsMeasured() // Extract the Server-Timing header $serverTiming = $this->getHeader($response, 'server-timing'); // Assert the db timing is greater than 200ms (SLEEP simulates query time) - preg_match('/db;dur=([\d.]+)/', $serverTiming[3], $matches); + preg_match('/db;dur=([\d.]+)/', $serverTiming[2], $matches); $dbTime = $matches[1] ?? 0; $this->assertGreaterThanOrEqual(200, (float)$dbTime); @@ -73,33 +72,13 @@ public function testServiceProviderTimeIsMeasured() $serverTiming = $this->getHeader($response, 'server-timing'); // Assert the providers timing is present and greater than or equal to 0 - preg_match('/providers;dur=([\d.]+)/', $serverTiming[0], $matches); + preg_match('/provider;dur=([\d.]+)/', $serverTiming[0], $matches); $providersTime = $matches[1] ?? null; $this->assertNotNull($providersTime); $this->assertGreaterThanOrEqual(0, (float)$providersTime); } - public function testEndpointTimingIsMeasuredCorrectly() - { - // Mock a route - Route::middleware(ServerTimingMiddleware::class)->get('/endpoint-test', function () { - usleep(500000); // Simulate 500ms delay - return response()->json(['message' => 'Endpoint timing test']); - }); - - // Send a GET request - $response = $this->get('/endpoint-test'); - // Extract the Server-Timing header - $serverTiming = $this->getHeader($response, 'server-timing'); - - // Assert the endpoint timing is greater than 500ms - preg_match('/endpoint;dur=([\d.]+)/', $serverTiming[1], $matches); - $endpointTime = $matches[1] ?? 0; - - $this->assertGreaterThanOrEqual(500, (float)$endpointTime); - } - public function testControllerTimingIsMeasuredCorrectly() { // Mock a route @@ -114,7 +93,7 @@ public function testControllerTimingIsMeasuredCorrectly() $serverTiming = $this->getHeader($response, 'server-timing'); // Assert the controller timing is greater than 300ms - preg_match('/controller;dur=([\d.]+)/', $serverTiming[2], $matches); + preg_match('/controller;dur=([\d.]+)/', $serverTiming[1], $matches); $controllerTime = $matches[1] ?? 0; $this->assertGreaterThanOrEqual(300, (float)$controllerTime); @@ -133,7 +112,7 @@ public function testProvidersTimingIsMeasuredCorrectly() $serverTiming = $this->getHeader($response, 'server-timing'); // Assert the providers timing is present and greater than or equal to 0 - preg_match('/providers;dur=([\d.]+)/', $serverTiming[0], $matches); + preg_match('/provider;dur=([\d.]+)/', $serverTiming[0], $matches); $providersTime = $matches[1] ?? null; $this->assertNotNull($providersTime); @@ -151,9 +130,8 @@ public function testServerTimingOnLogin() $response->assertHeader('Server-Timing'); $serverTiming = $this->getHeader($response, 'server-timing'); - $this->assertStringContainsString('providers;dur=', $serverTiming[0]); - $this->assertStringContainsString('endpoint;dur=', $serverTiming[1]); - $this->assertStringContainsString('controller;dur=', $serverTiming[2]); - $this->assertStringContainsString('db;dur=', $serverTiming[3]); + $this->assertStringContainsString('provider;dur=', $serverTiming[0]); + $this->assertStringContainsString('controller;dur=', $serverTiming[1]); + $this->assertStringContainsString('db;dur=', $serverTiming[2]); } } From bc87d9a27250c4a2face5b06ed1db45d76413bf6 Mon Sep 17 00:00:00 2001 From: Miguel Angel Date: Fri, 13 Dec 2024 10:47:18 -0400 Subject: [PATCH 7/9] feat: improve server timing headers --- .../Middleware/ServerTimingMiddleware.php | 5 +++- .../Providers/ProcessMakerServiceProvider.php | 4 ---- .../Traits/PluginServiceProviderTrait.php | 24 ++++++++++++++----- 3 files changed, 22 insertions(+), 11 deletions(-) diff --git a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php index 1c687d4f5d..50a9bf6a66 100644 --- a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php +++ b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php @@ -41,7 +41,10 @@ public function handle(Request $request, Closure $next): Response foreach ($packageTimes as $package => $timing) { $time = ($timing['end'] - $timing['start']) * 1000; - $serverTiming[] = "{$package};dur={$time}"; + // Only include packages that took more than 5ms + if ($time > 5) { + $serverTiming[] = "{$package};dur={$time}"; + } } // Add Server-Timing headers diff --git a/ProcessMaker/Providers/ProcessMakerServiceProvider.php b/ProcessMaker/Providers/ProcessMakerServiceProvider.php index 9bb9442cf2..75be7f5747 100644 --- a/ProcessMaker/Providers/ProcessMakerServiceProvider.php +++ b/ProcessMaker/Providers/ProcessMakerServiceProvider.php @@ -407,8 +407,6 @@ public static function getQueryTime(): float */ public static function setPackageBootStart(string $package, $time): void { - $package = ucfirst(\Str::camel(str_replace(['ProcessMaker\Packages\\', '\\'], '', $package))); - self::$packageBootTiming[$package] = [ 'start' => $time, 'end' => null, @@ -422,8 +420,6 @@ public static function setPackageBootStart(string $package, $time): void */ public static function setPackageBootedTime(string $package, $time): void { - $package = ucfirst(\Str::camel(str_replace(['ProcessMaker\Packages\\', '\\'], '', $package))); - self::$packageBootTiming[$package]['end'] = $time; } diff --git a/ProcessMaker/Traits/PluginServiceProviderTrait.php b/ProcessMaker/Traits/PluginServiceProviderTrait.php index 028409f4a4..8c4e141b0b 100644 --- a/ProcessMaker/Traits/PluginServiceProviderTrait.php +++ b/ProcessMaker/Traits/PluginServiceProviderTrait.php @@ -30,24 +30,36 @@ public function __construct($app) { parent::__construct($app); - $this->booting(function () { - self::$bootStart = microtime(true); + $package = $this->getPackageName(); - $package = defined('static::name') ? static::name : $this::class; + $this->booting(function () use ($package) { + self::$bootStart = microtime(true); ProcessMakerServiceProvider::setPackageBootStart($package, self::$bootStart); }); - $this->booted(function () { + $this->booted(function () use ($package) { self::$bootTime = microtime(true); - $package = defined('static::name') ? static::name : $this::class; - ProcessMakerServiceProvider::setPackageBootedTime($package, self::$bootTime); }); } + /** + * Get the package name for the Server Timing header + * + * @return string + */ + protected function getPackageName() + { + if (defined('static::name')) { + return ucfirst(\Str::camel(static::name)); + } + + return substr(static::class, strrpos(static::class, '\\') + 1); + } + /** * Boot the PM plug-in. */ From f6fc5ba88d119c7d6226e421fc80bcdadb067832 Mon Sep 17 00:00:00 2001 From: Miguel Angel Date: Fri, 13 Dec 2024 13:16:06 -0400 Subject: [PATCH 8/9] fix(cr): add missing validations --- .../Http/Middleware/ServerTimingMiddleware.php | 12 +++++++++--- .../Providers/ProcessMakerServiceProvider.php | 17 ++++++++++++++++- .../Traits/PluginServiceProviderTrait.php | 2 +- config/app.php | 6 +++++- 4 files changed, 31 insertions(+), 6 deletions(-) diff --git a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php index 50a9bf6a66..b90ce654f4 100644 --- a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php +++ b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php @@ -4,12 +4,18 @@ use Closure; use Illuminate\Http\Request; -use Illuminate\Support\Facades\DB; use ProcessMaker\Providers\ProcessMakerServiceProvider; use Symfony\Component\HttpFoundation\Response; class ServerTimingMiddleware { + // Minimum time in ms to include a package in the Server-Timing header + private static $minPackageTime; + + public function __construct() + { + self::$minPackageTime = config('app.server_timing.min_package_time'); + } /** * Handle an incoming request. * @@ -41,8 +47,8 @@ public function handle(Request $request, Closure $next): Response foreach ($packageTimes as $package => $timing) { $time = ($timing['end'] - $timing['start']) * 1000; - // Only include packages that took more than 5ms - if ($time > 5) { + // Only include packages that took more than MIN_PACKAGE_TIME ms + if ($time > self::$minPackageTime) { $serverTiming[] = "{$package};dur={$time}"; } } diff --git a/ProcessMaker/Providers/ProcessMakerServiceProvider.php b/ProcessMaker/Providers/ProcessMakerServiceProvider.php index 75be7f5747..38bde2a4e2 100644 --- a/ProcessMaker/Providers/ProcessMakerServiceProvider.php +++ b/ProcessMaker/Providers/ProcessMakerServiceProvider.php @@ -11,6 +11,7 @@ use Illuminate\Notifications\Events\NotificationSent; use Illuminate\Support\Facades; use Illuminate\Support\Facades\DB; +use Illuminate\Support\Facades\Log; use Illuminate\Support\Facades\URL; use Laravel\Dusk\DuskServiceProvider; use Laravel\Horizon\Horizon; @@ -403,10 +404,17 @@ public static function getQueryTime(): float /** * Set the boot time for service providers. * + * @param string $package * @param float $time */ - public static function setPackageBootStart(string $package, $time): void + 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, @@ -416,10 +424,17 @@ public static function setPackageBootStart(string $package, $time): void /** * 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; } diff --git a/ProcessMaker/Traits/PluginServiceProviderTrait.php b/ProcessMaker/Traits/PluginServiceProviderTrait.php index 8c4e141b0b..16436d319d 100644 --- a/ProcessMaker/Traits/PluginServiceProviderTrait.php +++ b/ProcessMaker/Traits/PluginServiceProviderTrait.php @@ -51,7 +51,7 @@ public function __construct($app) * * @return string */ - protected function getPackageName() + protected function getPackageName(): string { if (defined('static::name')) { return ucfirst(\Str::camel(static::name)); diff --git a/config/app.php b/config/app.php index a011248e48..ca6b69e43f 100644 --- a/config/app.php +++ b/config/app.php @@ -246,7 +246,7 @@ // Process Request security log rate limit: 1 per day (86400 seconds) 'process_request_errors_rate_limit' => env('PROCESS_REQUEST_ERRORS_RATE_LIMIT', 1), 'process_request_errors_rate_limit_duration' => env('PROCESS_REQUEST_ERRORS_RATE_LIMIT_DURATION', 86400), - + 'default_colors' => [ 'primary' => '#2773F3', 'secondary' => '#728092', @@ -266,4 +266,8 @@ 'vault_token' => env('ENCRYPTED_DATA_VAULT_TOKEN', ''), 'vault_transit_key' => env('ENCRYPTED_DATA_VAULT_TRANSIT_KEY', ''), ], + + 'server_timing' => [ + 'min_package_time' => env('SERVER_TIMING_MIN_PACKAGE_TIME', 5), // Minimum time in milliseconds + ], ]; From 64ba48ba113e08161c4d6effe3fe91f1e9fd2666 Mon Sep 17 00:00:00 2001 From: Miguel Angel Date: Fri, 13 Dec 2024 16:57:20 -0400 Subject: [PATCH 9/9] feat: add configuration option to enable/disable server timing --- .../Http/Middleware/ServerTimingMiddleware.php | 4 ++++ .../Providers/ProcessMakerServiceProvider.php | 10 ++++++---- .../Traits/PluginServiceProviderTrait.php | 16 +++++++++++++++- config/app.php | 1 + tests/Feature/ServerTimingMiddlewareTest.php | 18 ++++++++++++++++++ 5 files changed, 44 insertions(+), 5 deletions(-) diff --git a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php index b90ce654f4..3638bd9ec0 100644 --- a/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php +++ b/ProcessMaker/Http/Middleware/ServerTimingMiddleware.php @@ -23,6 +23,10 @@ public function __construct() */ public function handle(Request $request, Closure $next): Response { + if (!config('app.server_timing.enabled')) { + return $next($request); + } + // Start time for controller execution $startController = microtime(true); diff --git a/ProcessMaker/Providers/ProcessMakerServiceProvider.php b/ProcessMaker/Providers/ProcessMakerServiceProvider.php index 38bde2a4e2..f4e2f9be92 100644 --- a/ProcessMaker/Providers/ProcessMakerServiceProvider.php +++ b/ProcessMaker/Providers/ProcessMakerServiceProvider.php @@ -73,10 +73,12 @@ public function boot(): void public function register(): void { - // Listen to query events and accumulate query execution time - DB::listen(function ($query) { - self::$queryTime += $query->time; - }); + if (config('app.server_timing.enabled')) { + // Listen to query events and accumulate query execution time + DB::listen(function ($query) { + self::$queryTime += $query->time; + }); + } // Dusk, if env is appropriate // TODO Remove Dusk references and remove from composer dependencies diff --git a/ProcessMaker/Traits/PluginServiceProviderTrait.php b/ProcessMaker/Traits/PluginServiceProviderTrait.php index 16436d319d..b27e02482d 100644 --- a/ProcessMaker/Traits/PluginServiceProviderTrait.php +++ b/ProcessMaker/Traits/PluginServiceProviderTrait.php @@ -30,6 +30,21 @@ public function __construct($app) { parent::__construct($app); + $this->bootServerTiming(); + } + + /** + * The `bootServerTiming` function sets up timing measurements for the booting and booted events of the packages + * + * @return void If the condition `config('app.server_timing.enabled')` is false, nothing is being returned as the + * function will exit early. + */ + protected function bootServerTiming(): void + { + if (!config('app.server_timing.enabled')) { + return; + } + $package = $this->getPackageName(); $this->booting(function () use ($package) { @@ -43,7 +58,6 @@ public function __construct($app) ProcessMakerServiceProvider::setPackageBootedTime($package, self::$bootTime); }); - } /** diff --git a/config/app.php b/config/app.php index ca6b69e43f..4727a17ded 100644 --- a/config/app.php +++ b/config/app.php @@ -268,6 +268,7 @@ ], 'server_timing' => [ + 'enabled' => env('SERVER_TIMING_ENABLED', true), 'min_package_time' => env('SERVER_TIMING_MIN_PACKAGE_TIME', 5), // Minimum time in milliseconds ], ]; diff --git a/tests/Feature/ServerTimingMiddlewareTest.php b/tests/Feature/ServerTimingMiddlewareTest.php index d82aed00d8..7cf7072400 100644 --- a/tests/Feature/ServerTimingMiddlewareTest.php +++ b/tests/Feature/ServerTimingMiddlewareTest.php @@ -134,4 +134,22 @@ public function testServerTimingOnLogin() $this->assertStringContainsString('controller;dur=', $serverTiming[1]); $this->assertStringContainsString('db;dur=', $serverTiming[2]); } + + public function testServerTimingIfIsDisabled() + { + config(['app.server_timing.enabled' => false]); + + Route::middleware(ServerTimingMiddleware::class)->get('/test', function () { + // Simulate a query + DB::select('SELECT SLEEP(1)'); + + return response()->json(['message' => 'Test endpoint']); + }); + + // Send a GET request + $response = $this->get('/test'); + $response->assertStatus(200); + // Assert the response has not the Server-Timing header + $response->assertHeaderMissing('Server-Timing'); + } }