feat(logging): add request duration to log records

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

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**

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 );

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              => [

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'] ) ) {

plugins/wpgraphql-logging/src/Events/RequestTimer.php

@@ -0,0 +1,227 @@
+<?php
+
+declare(strict_types=1);
+
+namespace WPGraphQL\Logging\Events;
+
+/**
+ * Tracks the elapsed time of the current WPGraphQL request lifecycle.
+ *
+ * The timer starts at the earliest WPGraphQL hook we can observe for a request:
+ * `graphql_process_http_request` for HTTP requests, otherwise
+ * `graphql_request_data` or `do_graphql_request` for `graphql()` calls. It is
+ * bound to the request when `graphql_before_execute` fires and released on
+ * `graphql_after_execute`.
+ *
+ * Timers are kept on a stack so that a `graphql()` call made while another
+ * request is still executing (e.g. from inside a resolver) gets its own timer
+ * and does not reset the outer request's timer. A batched HTTP request fires
+ * `graphql_before_execute` / `graphql_after_execute` once, so all operations in
+ * the batch share one timer that measures the whole HTTP request.
+ *
+ * All state is cleared when an HTTP request starts and when its response is
+ * ready (`graphql_process_http_request_response`), so a request that throws
+ * before `graphql_after_execute` cannot leak its timer into the next one.
+ *
+ * @package WPGraphQL\Logging
+ *
+ * @since 1.1.0
+ */
+final class RequestTimer {
+	/**
+	 * The log data key for the elapsed time, used in both `extra` and `context`.
+	 *
+	 * @var string
+	 */
+	public const DURATION_KEY = 'request_duration_ms';
+
+	/**
+	 * Earliest hook priority, so the timer starts before other callbacks run.
+	 *
+	 * @var int
+	 */
+	public const START_PRIORITY = PHP_INT_MIN;
+
+	/**
+	 * Latest hook priority, so the timer is released after other callbacks run.
+	 *
+	 * @var int
+	 */
+	public const STOP_PRIORITY = PHP_INT_MAX;
+
+	/**
+	 * WPGraphQL action: graphql_process_http_request.
+	 *
+	 * Fires once per HTTP request, before the WPGraphQL request is created.
+	 *
+	 * @var string
+	 */
+	public const HTTP_REQUEST_START_HOOK = 'graphql_process_http_request';
+
+	/**
+	 * WPGraphQL action: graphql_process_http_request_response.
+	 *
+	 * Fires once per HTTP request when the response is ready to be sent, including
+	 * when execution threw an error.
+	 *
+	 * @var string
+	 */
+	public const HTTP_REQUEST_END_HOOK = 'graphql_process_http_request_response';
+
+	/**
+	 * WPGraphQL action: graphql_after_execute.
+	 *
+	 * Fires once after a request (single or batch) has executed.
+	 *
+	 * @var string
+	 */
+	public const AFTER_EXECUTE_HOOK = 'graphql_after_execute';
+
+	/**
+	 * Start time (hrtime, nanoseconds) of a request that has been seen but has not
+	 * reached `graphql_before_execute` yet.
+	 *
+	 * @var int|null
+	 */
+	private static ?int $pending_start = null;
+
+	/**
+	 * Start times (hrtime, nanoseconds) of the requests currently executing.
+	 *
+	 * @var array<int>
+	 */
+	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 );
+	}
+}

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.
 		];
 

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<string, mixed> $context The event context.
+	 *
+	 * @return array<string, mixed> 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.
 	 *

plugins/wpgraphql-logging/src/Logger/Processors/RequestDurationProcessor.php

@@ -0,0 +1,39 @@
+<?php
+
+declare(strict_types=1);
+
+namespace WPGraphQL\Logging\Logger\Processors;
+
+use Monolog\LogRecord;
+use Monolog\Processor\ProcessorInterface;
+use WPGraphQL\Logging\Events\RequestTimer;
+
+/**
+ * Adds the elapsed time of the current WPGraphQL request to each log record.
+ *
+ * The value is the time in milliseconds between the start of the WPGraphQL
+ * request lifecycle and the moment the record is logged. Records written
+ * outside of a WPGraphQL request are left untouched.
+ *
+ * @package WPGraphQL\Logging
+ *
+ * @since 1.1.0
+ */
+class RequestDurationProcessor implements ProcessorInterface {
+	/**
+	 * This method is called for each log record. It adds the elapsed request
+	 * time to the record's 'extra' array.
+	 *
+	 * @param \Monolog\LogRecord $record The log record to process.
+	 *
+	 * @return \Monolog\LogRecord The processed log record.
+	 */
+	public function __invoke( LogRecord $record ): LogRecord {
+		$elapsed = RequestTimer::get_elapsed_ms();
+		if ( null !== $elapsed ) {
+			$record->extra[ RequestTimer::DURATION_KEY ] = $elapsed;
+		}
+
+		return $record;
+	}
+}