diff --git a/docs/plugins/wpgraphql-logging/index.md b/docs/plugins/wpgraphql-logging/index.md index 0231ad998..353878bff 100644 --- a/docs/plugins/wpgraphql-logging/index.md +++ b/docs/plugins/wpgraphql-logging/index.md @@ -20,6 +20,19 @@ The plugin captures key events for the WPGraphQL event lifecycle (configurable) * **Response Headers** * **Request Results** +### Request Duration + +Each log record written during a WPGraphQL request includes `request_duration_ms` in its `extra` data. This is the time in milliseconds from the start of the request to the moment the record was logged, so you can see where time is spent across the lifecycle. + +The response events (**Request Results** and **Before Response Return**) also include `request_duration_ms` in their `context`. This is the total time for the request, and because it is in the context, [event subscribers and transforms](how-to/event-pub-sub/index.md) receive it too. + +The timer starts at the earliest WPGraphQL hook the plugin can observe (`graphql_process_http_request` for HTTP requests, otherwise `graphql_request_data` or `do_graphql_request`) and stops after execution (`graphql_after_execute`). It resets for every request: + +* **Batch HTTP requests** share one timer, because WPGraphQL executes all operations of a batch in one step. Each operation's response record shows the time for the whole batch so far, not the time for that operation alone. +* **Nested `graphql()` calls**, such as one made from inside a resolver, get their own timer and do not reset the outer request's timer. + +Records logged outside of a WPGraphQL request do not include `request_duration_ms`. + ### Pub/Sub Event System Built with developers and plugins in mind, the plugin allows users to listen to individual events and transform or collect data from those events. @@ -108,7 +121,7 @@ wpgraphql-logging/ │ │ ├── Api/ # Api interfaces for fetching and writing log data │ │ ├── Database/ # Database entity and helper │ │ ├── Handlers/ # Monolog WordPress database handler for logging data -│ │ ├── Processors/ # Monolog processors for data sanitization and request headers +│ │ ├── Processors/ # Monolog processors for data sanitization, request headers and request duration │ │ ├── Rules/ # Rules and RuleManager to decide whether to log a query │ │ ├── Scheduler/ # Automated data cleanup and maintenance tasks │ │ └── Store/ # Log storage service diff --git a/plugins/wpgraphql-logging/readme.txt b/plugins/wpgraphql-logging/readme.txt index 6db70d004..ecec020bd 100644 --- a/plugins/wpgraphql-logging/readme.txt +++ b/plugins/wpgraphql-logging/readme.txt @@ -42,6 +42,7 @@ WPGraphQL Logging plugin provides observability and visibility into the GraphQL * Memory usage tracking * Web request context * Process ID tracking + * Request duration (milliseconds since the WPGraphQL request started) * GraphQL-specific request metadata **Customization Options** diff --git a/plugins/wpgraphql-logging/src/Events/QueryActionLogger.php b/plugins/wpgraphql-logging/src/Events/QueryActionLogger.php index c5423c657..cf3b81468 100644 --- a/plugins/wpgraphql-logging/src/Events/QueryActionLogger.php +++ b/plugins/wpgraphql-logging/src/Events/QueryActionLogger.php @@ -162,6 +162,7 @@ public function log_before_response_returned( if ( ! $this->should_log_response( $this->config ) ) { unset( $context['response'] ); } + $context = $this->add_request_duration( $context ); $level = Level::Info; $message = 'WPGraphQL Response'; $errors = $this->get_response_errors( $response ); diff --git a/plugins/wpgraphql-logging/src/Events/QueryEventLifecycle.php b/plugins/wpgraphql-logging/src/Events/QueryEventLifecycle.php index 86d826079..979e6a163 100644 --- a/plugins/wpgraphql-logging/src/Events/QueryEventLifecycle.php +++ b/plugins/wpgraphql-logging/src/Events/QueryEventLifecycle.php @@ -87,6 +87,9 @@ public static function init(): QueryEventLifecycle { * @psalm-suppress HookNotFound */ protected function setup(): void { + // Time the request lifecycle so records can include the elapsed duration. + RequestTimer::register_hooks(); + // Map of action events to their corresponding logger methods and accepted args. $action_events = [ Events::PRE_REQUEST => [ diff --git a/plugins/wpgraphql-logging/src/Events/QueryFilterLogger.php b/plugins/wpgraphql-logging/src/Events/QueryFilterLogger.php index dd2669fea..2f2154d12 100644 --- a/plugins/wpgraphql-logging/src/Events/QueryFilterLogger.php +++ b/plugins/wpgraphql-logging/src/Events/QueryFilterLogger.php @@ -129,6 +129,7 @@ public function log_graphql_request_results( if ( ! $this->should_log_response( $this->config ) ) { unset( $context['response'] ); } + $context = $this->add_request_duration( $context ); $level = Level::Info; $message = 'WPGraphQL Response'; if ( is_array( $response ) && isset( $response['errors'] ) && ! empty( $response['errors'] ) ) { diff --git a/plugins/wpgraphql-logging/src/Events/RequestTimer.php b/plugins/wpgraphql-logging/src/Events/RequestTimer.php new file mode 100644 index 000000000..d5687aac3 --- /dev/null +++ b/plugins/wpgraphql-logging/src/Events/RequestTimer.php @@ -0,0 +1,227 @@ + + */ + private static array $stack = []; + + /** + * Registers the hooks that drive the timer. + * + * The HTTP and after-execute hooks are not logging events, so their names are + * defined here rather than in Events. + * + * @psalm-suppress HookNotFound + */ + public static function register_hooks(): void { + add_action( self::HTTP_REQUEST_START_HOOK, [ self::class, 'on_http_request' ], self::START_PRIORITY, 0 ); + // Literal name (Events::REQUEST_DATA): psalm's WordPress plugin records hooks named by + // constants under one placeholder, so a filter here clashes with actions registered elsewhere. + add_filter( 'graphql_request_data', [ self::class, 'on_request_data' ], self::START_PRIORITY, 1 ); + add_action( Events::PRE_REQUEST, [ self::class, 'start' ], self::START_PRIORITY, 0 ); + add_action( Events::BEFORE_GRAPHQL_EXECUTION, [ self::class, 'on_before_execute' ], self::START_PRIORITY, 0 ); + add_action( self::AFTER_EXECUTE_HOOK, [ self::class, 'on_after_execute' ], self::STOP_PRIORITY, 0 ); + add_action( self::HTTP_REQUEST_END_HOOK, [ self::class, 'reset' ], self::STOP_PRIORITY, 0 ); + } + + /** + * Starts timing a new HTTP request. + * + * Hooked to `graphql_process_http_request`. An HTTP request is always the + * outermost request, so any state left over from earlier requests is cleared. + */ + public static function on_http_request(): void { + self::reset(); + self::start(); + } + + /** + * Starts timing when the request data is parsed, if not already started. + * + * Hooked to the `graphql_request_data` filter. + * + * @param mixed $data The request data. Returned unchanged. + */ + public static function on_request_data( mixed $data ): mixed { + self::start(); + + return $data; + } + + /** + * Starts timing a request that has been seen but not executed yet. + * + * Does nothing if a pending timer already exists, so the earliest hook wins + * and the repeated `do_graphql_request` calls of a batch do not restart it. + */ + public static function start(): void { + if ( null !== self::$pending_start ) { + return; + } + + self::$pending_start = self::now(); + } + + /** + * Binds the pending timer to the request that is about to execute. + * + * Hooked to `graphql_before_execute`. + */ + public static function on_before_execute(): void { + self::$stack[] = self::$pending_start ?? self::now(); + self::$pending_start = null; + } + + /** + * Releases the timer of the request that just finished. + * + * Hooked to `graphql_after_execute`. + */ + public static function on_after_execute(): void { + array_pop( self::$stack ); + } + + /** + * Gets the elapsed time of the current request in milliseconds. + * + * @return float|null Milliseconds rounded to two decimals, or null if no request is being timed. + */ + public static function get_elapsed_ms(): ?float { + $start = self::get_start(); + if ( null === $start ) { + return null; + } + + return round( ( self::now() - $start ) / 1000000, 2 ); + } + + /** + * Clears all timer state. + */ + public static function reset(): void { + self::$pending_start = null; + self::$stack = []; + } + + /** + * Gets the start time of the request currently being timed. + * + * A pending start belongs to a request that has been seen more recently than + * any executing one, so it takes precedence over the stack. + * + * @return int|null The start time in nanoseconds, or null if none. + */ + private static function get_start(): ?int { + if ( null !== self::$pending_start ) { + return self::$pending_start; + } + + if ( [] === self::$stack ) { + return null; + } + + return self::$stack[ count( self::$stack ) - 1 ]; + } + + /** + * Gets the current monotonic time in nanoseconds. + * + * Falls back to the wall clock if hrtime() is unavailable, so the timer can + * never break a GraphQL request. + */ + private static function now(): int { + $time = hrtime( true ); + if ( is_int( $time ) ) { + return $time; + } + + return (int) ( microtime( true ) * 1e9 ); + } +} diff --git a/plugins/wpgraphql-logging/src/Logger/LoggerService.php b/plugins/wpgraphql-logging/src/Logger/LoggerService.php index 27de8150c..17e0e7be0 100644 --- a/plugins/wpgraphql-logging/src/Logger/LoggerService.php +++ b/plugins/wpgraphql-logging/src/Logger/LoggerService.php @@ -14,6 +14,7 @@ use Monolog\Processor\WebProcessor; use WPGraphQL\Logging\Logger\Handlers\WordPressDatabaseHandler; use WPGraphQL\Logging\Logger\Processors\DataSanitizationProcessor; +use WPGraphQL\Logging\Logger\Processors\RequestDurationProcessor; use WPGraphQL\Logging\Logger\Processors\RequestHeadersProcessor; /** @@ -236,6 +237,7 @@ public static function get_default_processors(): array { new WebProcessor(), // Logs web request data. e.g. IP address, request method, URI, etc. new ProcessIdProcessor(), // Logs the process ID. new RequestHeadersProcessor(), // Custom processor to capture request headers. + new RequestDurationProcessor(), // Custom processor to add the elapsed WPGraphQL request time. new DataSanitizationProcessor(), // Custom processor to sanitize data in log records. ]; diff --git a/plugins/wpgraphql-logging/src/Logger/LoggingHelper.php b/plugins/wpgraphql-logging/src/Logger/LoggingHelper.php index 1c81318cc..73c116f4a 100644 --- a/plugins/wpgraphql-logging/src/Logger/LoggingHelper.php +++ b/plugins/wpgraphql-logging/src/Logger/LoggingHelper.php @@ -5,6 +5,7 @@ namespace WPGraphQL\Logging\Logger; use WPGraphQL\Logging\Admin\Settings\Fields\Tab\BasicConfigurationTab; +use WPGraphQL\Logging\Events\RequestTimer; use WPGraphQL\Logging\Logger\Rules\EnabledRule; use WPGraphQL\Logging\Logger\Rules\ExcludeQueryRule; use WPGraphQL\Logging\Logger\Rules\IpRestrictionsRule; @@ -40,6 +41,25 @@ public function should_log_response(array $config): bool { return $rule->passes( $config ); } + /** + * Adds the elapsed time of the current WPGraphQL request to the context. + * + * Used for the response events so the total request time is part of the + * event context, which is what EventManager transforms and subscribers receive. + * + * @param array $context The event context. + * + * @return array The context, with `request_duration_ms` added when a request is being timed. + */ + public function add_request_duration(array $context): array { + $duration = RequestTimer::get_elapsed_ms(); + if ( null !== $duration ) { + $context[ RequestTimer::DURATION_KEY ] = $duration; + } + + return $context; + } + /** * Determine if the event should be logged based on the configuration and selected events. * diff --git a/plugins/wpgraphql-logging/src/Logger/Processors/RequestDurationProcessor.php b/plugins/wpgraphql-logging/src/Logger/Processors/RequestDurationProcessor.php new file mode 100644 index 000000000..417cc9ba9 --- /dev/null +++ b/plugins/wpgraphql-logging/src/Logger/Processors/RequestDurationProcessor.php @@ -0,0 +1,39 @@ +extra[ RequestTimer::DURATION_KEY ] = $elapsed; + } + + return $record; + } +} diff --git a/plugins/wpgraphql-logging/tests/wpunit/Events/QueryActionLoggerTest.php b/plugins/wpgraphql-logging/tests/wpunit/Events/QueryActionLoggerTest.php index f4f353154..c12c0cbdf 100644 --- a/plugins/wpgraphql-logging/tests/wpunit/Events/QueryActionLoggerTest.php +++ b/plugins/wpgraphql-logging/tests/wpunit/Events/QueryActionLoggerTest.php @@ -9,6 +9,7 @@ use lucatume\WPBrowser\TestCase\WPTestCase; use WPGraphQL\Logging\Events\QueryActionLogger; use WPGraphQL\Logging\Events\Events; +use WPGraphQL\Logging\Events\RequestTimer; use GraphQL\Executor\ExecutionResult; use WPGraphQL\Logging\Logger\LoggerService; use WPGraphQL\Logging\Admin\Settings\Fields\Tab\BasicConfigurationTab; @@ -355,6 +356,36 @@ public function test_log_before_response_returned_log_data(): void { $this->assert_log_count(1); } + public function test_log_before_response_returned_includes_request_duration(): void { + $instance = $this->create_instance( + [ + BasicConfigurationTab::ENABLED => true, + BasicConfigurationTab::EVENT_LOG_SELECTION => [Events::BEFORE_RESPONSE_RETURNED], + ] + ); + + $schema_config = SchemaConfig::create(); + $schema = new WPSchema($schema_config, WPGraphQL::get_type_registry()); + $request = new Request(); + $response = new ExecutionResult(['query' => '{ test_query }']); + + RequestTimer::reset(); + RequestTimer::on_request_data([]); + usleep(5000); + $instance->log_before_response_returned($response, $response, $schema, null, '{ test_query }', null, $request, null); + RequestTimer::reset(); + $this->assert_log_count(1); + + $logs = $this->log_service->find_entities_by_where([]); + $this->assertCount(1, $logs); + $context = $logs[0]->get_context(); + $extra = $logs[0]->get_extra(); + $this->assertArrayHasKey('request_duration_ms', $context); + $this->assertGreaterThanOrEqual(5, $context['request_duration_ms']); + $this->assertArrayHasKey(RequestTimer::DURATION_KEY, $extra); + $this->assertGreaterThanOrEqual($context['request_duration_ms'], $extra[RequestTimer::DURATION_KEY]); + } + public function test_log_before_response_returned_log_data_with_errors(): void { $instance = $this->create_instance( [ diff --git a/plugins/wpgraphql-logging/tests/wpunit/Events/QueryEventLifecycleTest.php b/plugins/wpgraphql-logging/tests/wpunit/Events/QueryEventLifecycleTest.php index 34d661858..5e078c853 100644 --- a/plugins/wpgraphql-logging/tests/wpunit/Events/QueryEventLifecycleTest.php +++ b/plugins/wpgraphql-logging/tests/wpunit/Events/QueryEventLifecycleTest.php @@ -6,6 +6,7 @@ use lucatume\WPBrowser\TestCase\WPTestCase; use WPGraphQL\Logging\Events\QueryEventLifecycle; +use WPGraphQL\Logging\Events\RequestTimer; use \WPGraphQL\Logging\Events\Events; /** @@ -44,5 +45,10 @@ public function test_init_creates_singleton_instance(): void { $this->assertTrue(has_filter(Events::REQUEST_DATA, [$filterLogger, 'log_graphql_request_data']) !== false); $this->assertTrue(has_filter(Events::REQUEST_RESULTS, [$filterLogger, 'log_graphql_request_results']) !== false); $this->assertTrue(has_filter(Events::RESPONSE_HEADERS_TO_SEND, [$filterLogger, 'add_logging_headers']) !== false); + + // Check that the request timer hooks are registered. + $this->assertSame(RequestTimer::START_PRIORITY, has_action(RequestTimer::HTTP_REQUEST_START_HOOK, [RequestTimer::class, 'on_http_request'])); + $this->assertSame(RequestTimer::START_PRIORITY, has_action(Events::BEFORE_GRAPHQL_EXECUTION, [RequestTimer::class, 'on_before_execute'])); + $this->assertSame(RequestTimer::STOP_PRIORITY, has_action(RequestTimer::AFTER_EXECUTE_HOOK, [RequestTimer::class, 'on_after_execute'])); } } diff --git a/plugins/wpgraphql-logging/tests/wpunit/Events/QueryFilterLoggerTest.php b/plugins/wpgraphql-logging/tests/wpunit/Events/QueryFilterLoggerTest.php index 9b4ad6433..4e5325048 100644 --- a/plugins/wpgraphql-logging/tests/wpunit/Events/QueryFilterLoggerTest.php +++ b/plugins/wpgraphql-logging/tests/wpunit/Events/QueryFilterLoggerTest.php @@ -10,6 +10,7 @@ use lucatume\WPBrowser\TestCase\WPTestCase; use WPGraphQL\Logging\Events\QueryFilterLogger; use WPGraphQL\Logging\Events\Events; +use WPGraphQL\Logging\Events\RequestTimer; use GraphQL\Executor\ExecutionResult; use WPGraphQL\Logging\Logger\LoggerService; use WPGraphQL\Logging\Admin\Settings\Fields\Tab\BasicConfigurationTab; @@ -190,6 +191,57 @@ public function test_graphql_request_results_log_event(): void { $this->assert_log_count(1); } + public function test_graphql_request_results_includes_request_duration(): void { + $instance = $this->create_instance( + [ + BasicConfigurationTab::ENABLED => true, + BasicConfigurationTab::EVENT_LOG_SELECTION => [Events::REQUEST_RESULTS], + ] + ); + + $schema_config = SchemaConfig::create(); + $schema = new WPSchema($schema_config, WPGraphQL::get_type_registry()); + $request = new Request(); + $response = new ExecutionResult(['query' => '{ test_query }']); + + // Subscribers receive the context, so the duration must be part of it. + $published_context = null; + Plugin::on(Events::REQUEST_RESULTS, function(array $payload) use (&$published_context): void { + $published_context = $payload['context']; + }); + + RequestTimer::reset(); + RequestTimer::on_request_data([]); + usleep(5000); + $instance->log_graphql_request_results($response, $schema, 'test_operation', '{ test_query }', null, $request, null); + RequestTimer::reset(); + $this->assert_log_count(1); + + $this->assertIsArray($published_context); + $this->assertArrayHasKey('request_duration_ms', $published_context); + $this->assertGreaterThanOrEqual(5, $published_context['request_duration_ms']); + + $logs = $this->log_service->find_entities_by_where([]); + $this->assertCount(1, $logs); + $this->assertArrayHasKey('request_duration_ms', $logs[0]->get_context()); + } + + public function test_add_request_duration(): void { + $instance = $this->create_instance([]); + $context = ['query' => '{ test_query }']; + + RequestTimer::reset(); + $this->assertSame($context, $instance->add_request_duration($context)); + + RequestTimer::start(); + $result = $instance->add_request_duration($context); + RequestTimer::reset(); + + $this->assertSame('{ test_query }', $result['query']); + $this->assertArrayHasKey('request_duration_ms', $result); + $this->assertIsFloat($result['request_duration_ms']); + } + public function test_graphql_request_results_log_data_with_errors_array(): void { $instance = $this->create_instance( [ diff --git a/plugins/wpgraphql-logging/tests/wpunit/Events/RequestTimerTest.php b/plugins/wpgraphql-logging/tests/wpunit/Events/RequestTimerTest.php new file mode 100644 index 000000000..ec9f6dc4f --- /dev/null +++ b/plugins/wpgraphql-logging/tests/wpunit/Events/RequestTimerTest.php @@ -0,0 +1,232 @@ +assertNull( RequestTimer::get_elapsed_ms() ); + $this->assertNull( RequestTimer::get_elapsed_ms() ); + } + + public function test_register_hooks(): void { + RequestTimer::register_hooks(); + + $this->assertSame( RequestTimer::START_PRIORITY, has_action( RequestTimer::HTTP_REQUEST_START_HOOK, [ RequestTimer::class, 'on_http_request' ] ) ); + $this->assertSame( RequestTimer::START_PRIORITY, has_filter( Events::REQUEST_DATA, [ RequestTimer::class, 'on_request_data' ] ) ); + $this->assertSame( RequestTimer::START_PRIORITY, has_action( Events::PRE_REQUEST, [ RequestTimer::class, 'start' ] ) ); + $this->assertSame( RequestTimer::START_PRIORITY, has_action( Events::BEFORE_GRAPHQL_EXECUTION, [ RequestTimer::class, 'on_before_execute' ] ) ); + $this->assertSame( RequestTimer::STOP_PRIORITY, has_action( RequestTimer::AFTER_EXECUTE_HOOK, [ RequestTimer::class, 'on_after_execute' ] ) ); + $this->assertSame( RequestTimer::STOP_PRIORITY, has_action( RequestTimer::HTTP_REQUEST_END_HOOK, [ RequestTimer::class, 'reset' ] ) ); + } + + public function test_http_request_lifecycle(): void { + RequestTimer::on_http_request(); + usleep( 5000 ); + + // Later hooks of the same request keep the HTTP start time. + RequestTimer::on_request_data( [] ); + RequestTimer::start(); + RequestTimer::on_before_execute(); + $this->assertGreaterThanOrEqual( 5, RequestTimer::get_elapsed_ms() ); + + RequestTimer::on_after_execute(); + $this->assertNull( RequestTimer::get_elapsed_ms() ); + } + + public function test_http_request_clears_state_left_by_a_failed_request(): void { + // A request that threw after graphql_before_execute never reaches graphql_after_execute. + RequestTimer::on_request_data( [] ); + RequestTimer::on_before_execute(); + usleep( 20000 ); + + RequestTimer::on_http_request(); + + $this->assertLessThan( 20, RequestTimer::get_elapsed_ms() ); + RequestTimer::on_before_execute(); + RequestTimer::on_after_execute(); + $this->assertNull( RequestTimer::get_elapsed_ms() ); + } + + public function test_request_data_starts_timer_and_returns_data_unchanged(): void { + $data = [ 'query' => '{ posts { nodes { id } } }' ]; + + $this->assertSame( $data, RequestTimer::on_request_data( $data ) ); + $this->assertNotNull( RequestTimer::get_elapsed_ms() ); + + $elapsed = RequestTimer::get_elapsed_ms(); + $this->assertIsFloat( $elapsed ); + $this->assertGreaterThanOrEqual( 0, $elapsed ); + } + + public function test_elapsed_time_increases(): void { + RequestTimer::on_request_data( [] ); + usleep( 5000 ); + + $this->assertGreaterThanOrEqual( 5, RequestTimer::get_elapsed_ms() ); + } + + public function test_start_starts_timer_when_not_pending(): void { + RequestTimer::start(); + $this->assertNotNull( RequestTimer::get_elapsed_ms() ); + } + + public function test_start_does_not_restart_pending_timer_for_batch_operations(): void { + RequestTimer::on_request_data( [] ); + usleep( 5000 ); + + // A batch fires do_graphql_request once per operation. + RequestTimer::start(); + RequestTimer::start(); + + $this->assertGreaterThanOrEqual( 5, RequestTimer::get_elapsed_ms() ); + } + + public function test_request_data_keeps_earlier_pending_start(): void { + RequestTimer::start(); + usleep( 5000 ); + RequestTimer::on_request_data( [] ); + + $this->assertGreaterThanOrEqual( 5, RequestTimer::get_elapsed_ms() ); + } + + public function test_request_data_returns_non_array_data_unchanged(): void { + $this->assertNull( RequestTimer::on_request_data( null ) ); + } + + public function test_timer_spans_execution_and_stops_after_execute(): void { + RequestTimer::on_request_data( [] ); + RequestTimer::start(); + usleep( 5000 ); + RequestTimer::on_before_execute(); + + $this->assertNotNull( RequestTimer::get_elapsed_ms() ); + $this->assertGreaterThanOrEqual( 5, RequestTimer::get_elapsed_ms() ); + + RequestTimer::on_after_execute(); + + $this->assertNull( RequestTimer::get_elapsed_ms() ); + $this->assertNull( RequestTimer::get_elapsed_ms() ); + } + + public function test_before_execute_starts_timer_without_earlier_hooks(): void { + RequestTimer::on_before_execute(); + $this->assertNotNull( RequestTimer::get_elapsed_ms() ); + + RequestTimer::on_after_execute(); + $this->assertNull( RequestTimer::get_elapsed_ms() ); + } + + public function test_after_execute_without_running_timer_is_safe(): void { + RequestTimer::on_after_execute(); + $this->assertNull( RequestTimer::get_elapsed_ms() ); + } + + public function test_nested_request_does_not_reset_outer_request(): void { + // Outer request. + RequestTimer::on_request_data( [] ); + RequestTimer::on_before_execute(); + usleep( 20000 ); + + // Inner request, e.g. graphql() called from a resolver. + RequestTimer::on_request_data( [] ); + $this->assertLessThan( 20, RequestTimer::get_elapsed_ms() ); + RequestTimer::on_before_execute(); + $this->assertLessThan( 20, RequestTimer::get_elapsed_ms() ); + RequestTimer::on_after_execute(); + + // Back on the outer request. + $this->assertNotNull( RequestTimer::get_elapsed_ms() ); + $this->assertGreaterThanOrEqual( 20, RequestTimer::get_elapsed_ms() ); + + RequestTimer::on_after_execute(); + $this->assertNull( RequestTimer::get_elapsed_ms() ); + } + + public function test_reset_clears_state(): void { + RequestTimer::on_request_data( [] ); + RequestTimer::on_before_execute(); + RequestTimer::on_request_data( [] ); + + RequestTimer::reset(); + + $this->assertNull( RequestTimer::get_elapsed_ms() ); + } + + public function test_graphql_request_is_timed_and_each_request_starts_fresh(): void { + RequestTimer::register_hooks(); + + $captured = []; + $capture = static function () use ( &$captured ): void { + $captured[] = RequestTimer::get_elapsed_ms(); + }; + $slow_down = static function (): void { + usleep( 20000 ); + }; + + add_action( Events::BEFORE_RESPONSE_RETURNED, $capture ); + add_action( Events::BEFORE_GRAPHQL_EXECUTION, $slow_down ); + graphql( [ 'query' => '{ __typename }' ] ); + remove_action( Events::BEFORE_GRAPHQL_EXECUTION, $slow_down ); + remove_action( Events::BEFORE_RESPONSE_RETURNED, $capture ); + + $this->assertCount( 1, $captured ); + $this->assertGreaterThanOrEqual( 20, $captured[0] ); + $this->assertNull( RequestTimer::get_elapsed_ms() ); + + // The second request must not include the first request's time. + add_action( Events::PRE_REQUEST, $capture ); + graphql( [ 'query' => '{ __typename }' ] ); + remove_action( Events::PRE_REQUEST, $capture ); + + $this->assertCount( 2, $captured ); + $this->assertLessThan( 20, $captured[1] ); + $this->assertNull( RequestTimer::get_elapsed_ms() ); + } + + public function test_batched_graphql_request_times_each_operation(): void { + RequestTimer::register_hooks(); + + $captured = []; + $capture = static function () use ( &$captured ): void { + $captured[] = RequestTimer::get_elapsed_ms(); + }; + + add_action( Events::BEFORE_RESPONSE_RETURNED, $capture ); + graphql( + [ + [ 'query' => '{ __typename }' ], + [ 'query' => '{ __typename }' ], + ] + ); + remove_action( Events::BEFORE_RESPONSE_RETURNED, $capture ); + + $this->assertCount( 2, $captured ); + $this->assertIsFloat( $captured[0] ); + $this->assertIsFloat( $captured[1] ); + $this->assertNull( RequestTimer::get_elapsed_ms() ); + } +} diff --git a/plugins/wpgraphql-logging/tests/wpunit/Logger/Processors/RequestDurationProcessorTest.php b/plugins/wpgraphql-logging/tests/wpunit/Logger/Processors/RequestDurationProcessorTest.php new file mode 100644 index 000000000..2b4798b58 --- /dev/null +++ b/plugins/wpgraphql-logging/tests/wpunit/Logger/Processors/RequestDurationProcessorTest.php @@ -0,0 +1,83 @@ +create_record() ); + + $this->assertArrayNotHasKey( RequestTimer::DURATION_KEY, $record->extra ); + } + + public function test_adds_elapsed_time_during_a_request(): void { + RequestTimer::on_request_data( [] ); + usleep( 5000 ); + + $processor = new RequestDurationProcessor(); + $record = $processor( $this->create_record() ); + + $this->assertArrayHasKey( RequestTimer::DURATION_KEY, $record->extra ); + $this->assertIsFloat( $record->extra[ RequestTimer::DURATION_KEY ] ); + $this->assertGreaterThanOrEqual( 5, $record->extra[ RequestTimer::DURATION_KEY ] ); + } + + public function test_elapsed_time_grows_across_records_in_the_same_request(): void { + RequestTimer::on_request_data( [] ); + $processor = new RequestDurationProcessor(); + + $first = $processor( $this->create_record() ); + usleep( 5000 ); + $second = $processor( $this->create_record() ); + + $this->assertGreaterThan( + $first->extra[ RequestTimer::DURATION_KEY ], + $second->extra[ RequestTimer::DURATION_KEY ] + ); + } + + public function test_is_a_default_processor(): void { + $classes = array_map( 'get_class', LoggerService::get_default_processors() ); + + $this->assertContains( RequestDurationProcessor::class, $classes ); + } +}