From 084f2f4f4c7828218b7831cf68f10c73bede2469 Mon Sep 17 00:00:00 2001
From: Joe Fusco <hello@josephfus.co>
Date: Fri, 30 Oct 2026 15:31:13 -0400
Subject: [PATCH 1/4] feat(logging): add request duration to log records

Time the WPGraphQL request lifecycle from the earliest hook (graphql_request_data, falling back to do_graphql_request) until graphql_after_execute. A new RequestDurationProcessor adds the elapsed milliseconds to every record's extra data as request_duration_ms, and the response events add the total to their context so EventManager subscribers receive it.
---
 .../src/Events/QueryActionLogger.php          |   1 +
 .../src/Events/QueryEventLifecycle.php        |   3 +
 .../src/Events/QueryFilterLogger.php          |   1 +
 .../src/Events/RequestTimer.php               | 176 ++++++++++++++++++
 .../src/Logger/LoggerService.php              |   2 +
 .../src/Logger/LoggingHelper.php              |  20 ++
 .../Processors/RequestDurationProcessor.php   |  48 +++++
 .../wpunit/Events/QueryActionLoggerTest.php   |  32 ++++
 .../wpunit/Events/QueryFilterLoggerTest.php   |  36 ++++
 .../tests/wpunit/Events/RequestTimerTest.php  | 175 +++++++++++++++++
 .../RequestDurationProcessorTest.php          |  83 +++++++++
 11 files changed, 577 insertions(+)
 create mode 100644 plugins/wpgraphql-logging/src/Events/RequestTimer.php
 create mode 100644 plugins/wpgraphql-logging/src/Logger/Processors/RequestDurationProcessor.php
 create mode 100644 plugins/wpgraphql-logging/tests/wpunit/Events/RequestTimerTest.php
 create mode 100644 plugins/wpgraphql-logging/tests/wpunit/Logger/Processors/RequestDurationProcessorTest.php

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..52e4c2943
--- /dev/null
+++ b/plugins/wpgraphql-logging/src/Events/RequestTimer.php
@@ -0,0 +1,176 @@
+<?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_request_data`, falling back to `do_graphql_request`), is bound to the
+ * request when `graphql_before_execute` fires, and is 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.
+ *
+ * @package WPGraphQL\Logging
+ *
+ * @since 1.1.0
+ */
+final class RequestTimer {
+	/**
+	 * 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_after_execute.
+	 *
+	 * Fires once after a request (single or batch) has executed. Not a loggable
+	 * event, so it is not part of the Events list.
+	 *
+	 * @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.
+	 *
+	 * @psalm-suppress HookNotFound
+	 */
+	public static function register_hooks(): void {
+		add_filter( Events::REQUEST_DATA, [ self::class, 'on_request_data' ], self::START_PRIORITY, 1 );
+		add_action( Events::PRE_REQUEST, [ self::class, 'on_pre_request' ], 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 );
+	}
+
+	/**
+	 * Starts timing a new request when its data is parsed.
+	 *
+	 * Hooked to the `graphql_request_data` filter, which fires once per request
+	 * before any operation is processed. Always restarts the pending timer, since
+	 * this is the first hook of a new request.
+	 *
+	 * @param array<mixed> $data The request data.
+	 *
+	 * @return array<mixed> The request data, unchanged.
+	 */
+	public static function on_request_data( array $data ): array {
+		self::$pending_start = hrtime( true );
+
+		return $data;
+	}
+
+	/**
+	 * Starts timing if `graphql_request_data` did not fire for this request.
+	 *
+	 * Hooked to `do_graphql_request`, which fires once per operation. For a batch
+	 * this runs several times in a row, so it only starts the timer when one is
+	 * not already pending.
+	 */
+	public static function on_pre_request(): void {
+		if ( null !== self::$pending_start ) {
+			return;
+		}
+
+		self::$pending_start = hrtime( true );
+	}
+
+	/**
+	 * 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 ?? hrtime( true );
+		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 );
+	}
+
+	/**
+	 * Whether a request is currently being timed.
+	 */
+	public static function is_running(): bool {
+		return null !== self::get_start();
+	}
+
+	/**
+	 * 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( ( hrtime( true ) - $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 hrtime start 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 ];
+	}
+}
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..044fc0a0b 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<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['request_duration_ms'] = $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..8421e36e9
--- /dev/null
+++ b/plugins/wpgraphql-logging/src/Logger/Processors/RequestDurationProcessor.php
@@ -0,0 +1,48 @@
+<?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 {
+	/**
+	 * The key added to the record's 'extra' array.
+	 *
+	 * @var string
+	 */
+	public const EXTRA_KEY = 'request_duration_ms';
+
+	/**
+	 * 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 ) {
+			return $record;
+		}
+
+		$record->extra[ self::EXTRA_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..21bd40ca0 100644
--- a/plugins/wpgraphql-logging/tests/wpunit/Events/QueryActionLoggerTest.php
+++ b/plugins/wpgraphql-logging/tests/wpunit/Events/QueryActionLoggerTest.php
@@ -9,6 +9,8 @@
 use lucatume\WPBrowser\TestCase\WPTestCase;
 use WPGraphQL\Logging\Events\QueryActionLogger;
 use WPGraphQL\Logging\Events\Events;
+use WPGraphQL\Logging\Events\RequestTimer;
+use WPGraphQL\Logging\Logger\Processors\RequestDurationProcessor;
 use GraphQL\Executor\ExecutionResult;
 use WPGraphQL\Logging\Logger\LoggerService;
 use WPGraphQL\Logging\Admin\Settings\Fields\Tab\BasicConfigurationTab;
@@ -355,6 +357,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(RequestDurationProcessor::EXTRA_KEY, $extra);
+		$this->assertGreaterThanOrEqual($context['request_duration_ms'], $extra[RequestDurationProcessor::EXTRA_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/QueryFilterLoggerTest.php b/plugins/wpgraphql-logging/tests/wpunit/Events/QueryFilterLoggerTest.php
index 9b4ad6433..600444945 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,41 @@ 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_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..96bea15e8
--- /dev/null
+++ b/plugins/wpgraphql-logging/tests/wpunit/Events/RequestTimerTest.php
@@ -0,0 +1,175 @@
+<?php
+
+declare(strict_types=1);
+
+namespace WPGraphQL\Logging\Tests\Events;
+
+use lucatume\WPBrowser\TestCase\WPTestCase;
+use WPGraphQL\Logging\Events\Events;
+use WPGraphQL\Logging\Events\RequestTimer;
+
+/**
+ * Tests for the RequestTimer class.
+ *
+ * @package WPGraphQL\Logging\Tests\Events
+ *
+ * @since 1.1.0
+ */
+class RequestTimerTest extends WPTestCase {
+
+	public function setUp(): void {
+		parent::setUp();
+		RequestTimer::reset();
+	}
+
+	public function tearDown(): void {
+		RequestTimer::reset();
+		parent::tearDown();
+	}
+
+	public function test_not_running_by_default(): void {
+		$this->assertFalse( RequestTimer::is_running() );
+		$this->assertNull( RequestTimer::get_elapsed_ms() );
+	}
+
+	public function test_register_hooks(): void {
+		RequestTimer::register_hooks();
+
+		$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, 'on_pre_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' ] ) );
+	}
+
+	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->assertTrue( RequestTimer::is_running() );
+
+		$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_pre_request_starts_timer_when_not_pending(): void {
+		RequestTimer::on_pre_request();
+		$this->assertTrue( RequestTimer::is_running() );
+	}
+
+	public function test_pre_request_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::on_pre_request();
+		RequestTimer::on_pre_request();
+
+		$this->assertGreaterThanOrEqual( 5, RequestTimer::get_elapsed_ms() );
+	}
+
+	public function test_request_data_restarts_pending_timer(): void {
+		RequestTimer::on_request_data( [] );
+		usleep( 20000 );
+		RequestTimer::on_request_data( [] );
+
+		$this->assertLessThan( 20, RequestTimer::get_elapsed_ms() );
+	}
+
+	public function test_timer_spans_execution_and_stops_after_execute(): void {
+		RequestTimer::on_request_data( [] );
+		RequestTimer::on_pre_request();
+		usleep( 5000 );
+		RequestTimer::on_before_execute();
+
+		$this->assertTrue( RequestTimer::is_running() );
+		$this->assertGreaterThanOrEqual( 5, RequestTimer::get_elapsed_ms() );
+
+		RequestTimer::on_after_execute();
+
+		$this->assertFalse( RequestTimer::is_running() );
+		$this->assertNull( RequestTimer::get_elapsed_ms() );
+	}
+
+	public function test_before_execute_starts_timer_without_earlier_hooks(): void {
+		RequestTimer::on_before_execute();
+		$this->assertTrue( RequestTimer::is_running() );
+
+		RequestTimer::on_after_execute();
+		$this->assertFalse( RequestTimer::is_running() );
+	}
+
+	public function test_after_execute_without_running_timer_is_safe(): void {
+		RequestTimer::on_after_execute();
+		$this->assertFalse( RequestTimer::is_running() );
+	}
+
+	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->assertTrue( RequestTimer::is_running() );
+		$this->assertGreaterThanOrEqual( 20, RequestTimer::get_elapsed_ms() );
+
+		RequestTimer::on_after_execute();
+		$this->assertFalse( RequestTimer::is_running() );
+	}
+
+	public function test_reset_clears_state(): void {
+		RequestTimer::on_request_data( [] );
+		RequestTimer::on_before_execute();
+		RequestTimer::on_request_data( [] );
+
+		RequestTimer::reset();
+
+		$this->assertFalse( RequestTimer::is_running() );
+	}
+
+	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->assertFalse( RequestTimer::is_running() );
+
+		// 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->assertFalse( RequestTimer::is_running() );
+	}
+}
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..6974852b8
--- /dev/null
+++ b/plugins/wpgraphql-logging/tests/wpunit/Logger/Processors/RequestDurationProcessorTest.php
@@ -0,0 +1,83 @@
+<?php
+
+declare(strict_types=1);
+
+namespace WPGraphQL\Logging\Tests\Logger\Processors;
+
+use DateTimeImmutable;
+use lucatume\WPBrowser\TestCase\WPTestCase;
+use Monolog\Level;
+use Monolog\LogRecord;
+use WPGraphQL\Logging\Events\RequestTimer;
+use WPGraphQL\Logging\Logger\LoggerService;
+use WPGraphQL\Logging\Logger\Processors\RequestDurationProcessor;
+
+/**
+ * Test cases for the RequestDurationProcessor.
+ *
+ * @package WPGraphQL\Logging
+ *
+ * @since 1.1.0
+ */
+class RequestDurationProcessorTest extends WPTestCase {
+
+	public function setUp(): void {
+		parent::setUp();
+		RequestTimer::reset();
+	}
+
+	public function tearDown(): void {
+		RequestTimer::reset();
+		parent::tearDown();
+	}
+
+	private function create_record(): LogRecord {
+		return new LogRecord(
+			new DateTimeImmutable( 'now' ),
+			'wpgraphql_logging',
+			Level::Info,
+			'Test log message',
+			[],
+			[]
+		);
+	}
+
+	public function test_record_unchanged_outside_of_a_request(): void {
+		$processor = new RequestDurationProcessor();
+		$record    = $processor( $this->create_record() );
+
+		$this->assertArrayNotHasKey( RequestDurationProcessor::EXTRA_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( RequestDurationProcessor::EXTRA_KEY, $record->extra );
+		$this->assertIsFloat( $record->extra[ RequestDurationProcessor::EXTRA_KEY ] );
+		$this->assertGreaterThanOrEqual( 5, $record->extra[ RequestDurationProcessor::EXTRA_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[ RequestDurationProcessor::EXTRA_KEY ],
+			$second->extra[ RequestDurationProcessor::EXTRA_KEY ]
+		);
+	}
+
+	public function test_is_a_default_processor(): void {
+		$classes = array_map( 'get_class', LoggerService::get_default_processors() );
+
+		$this->assertContains( RequestDurationProcessor::class, $classes );
+	}
+}

From 482f158e000c7ca502f729873b9a18e9ab8a10ba Mon Sep 17 00:00:00 2001
From: Joe Fusco <hello@josephfus.co>
Date: Fri, 30 Oct 2026 15:40:03 -0400
Subject: [PATCH 2/4] fix(logging): start the request timer per HTTP request
 and guard against leaks

Start timing HTTP requests at graphql_process_http_request (before the WPGraphQL Request exists) and clear all timer state there and on graphql_process_http_request_response, so a request that throws before graphql_after_execute cannot leak its timer into later records. graphql_request_data no longer restarts a timer that is already pending. Accept any value in the graphql_request_data callback and fall back to microtime() if hrtime() is unavailable, so the timer can never break a GraphQL request.
---
 .../src/Events/RequestTimer.php               | 94 ++++++++++++++-----
 .../tests/wpunit/Events/RequestTimerTest.php  | 56 ++++++++---
 2 files changed, 116 insertions(+), 34 deletions(-)

diff --git a/plugins/wpgraphql-logging/src/Events/RequestTimer.php b/plugins/wpgraphql-logging/src/Events/RequestTimer.php
index 52e4c2943..163656363 100644
--- a/plugins/wpgraphql-logging/src/Events/RequestTimer.php
+++ b/plugins/wpgraphql-logging/src/Events/RequestTimer.php
@@ -7,9 +7,10 @@
 /**
  * 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_request_data`, falling back to `do_graphql_request`), is bound to the
- * request when `graphql_before_execute` fires, and is released on
+ * 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
@@ -18,6 +19,10 @@
  * `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
@@ -37,11 +42,29 @@ final class RequestTimer {
 	 */
 	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. Not a loggable
-	 * event, so it is not part of the Events list.
+	 * Fires once after a request (single or batch) has executed.
 	 *
 	 * @var string
 	 */
@@ -65,45 +88,55 @@ final class RequestTimer {
 	/**
 	 * Registers the hooks that drive the timer.
 	 *
+	 * These hooks are not logging events, so they are not part of the Events list.
+	 *
 	 * @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 );
 		add_filter( Events::REQUEST_DATA, [ self::class, 'on_request_data' ], self::START_PRIORITY, 1 );
-		add_action( Events::PRE_REQUEST, [ self::class, 'on_pre_request' ], self::START_PRIORITY, 0 );
+		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 request when its data is parsed.
+	 * Starts timing a new HTTP request.
 	 *
-	 * Hooked to the `graphql_request_data` filter, which fires once per request
-	 * before any operation is processed. Always restarts the pending timer, since
-	 * this is the first hook of a new 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.
 	 *
-	 * @param array<mixed> $data The request data.
+	 * Hooked to the `graphql_request_data` filter.
 	 *
-	 * @return array<mixed> The request data, unchanged.
+	 * @param mixed $data The request data. Returned unchanged.
 	 */
-	public static function on_request_data( array $data ): array {
-		self::$pending_start = hrtime( true );
+	public static function on_request_data( mixed $data ): mixed {
+		self::start();
 
 		return $data;
 	}
 
 	/**
-	 * Starts timing if `graphql_request_data` did not fire for this request.
+	 * Starts timing a request that has been seen but not executed yet.
 	 *
-	 * Hooked to `do_graphql_request`, which fires once per operation. For a batch
-	 * this runs several times in a row, so it only starts the timer when one is
-	 * not already pending.
+	 * 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 on_pre_request(): void {
+	public static function start(): void {
 		if ( null !== self::$pending_start ) {
 			return;
 		}
 
-		self::$pending_start = hrtime( true );
+		self::$pending_start = self::now();
 	}
 
 	/**
@@ -112,7 +145,7 @@ public static function on_pre_request(): void {
 	 * Hooked to `graphql_before_execute`.
 	 */
 	public static function on_before_execute(): void {
-		self::$stack[]       = self::$pending_start ?? hrtime( true );
+		self::$stack[]       = self::$pending_start ?? self::now();
 		self::$pending_start = null;
 	}
 
@@ -143,7 +176,7 @@ public static function get_elapsed_ms(): ?float {
 			return null;
 		}
 
-		return round( ( hrtime( true ) - $start ) / 1000000, 2 );
+		return round( ( self::now() - $start ) / 1000000, 2 );
 	}
 
 	/**
@@ -160,7 +193,7 @@ public static function reset(): void {
 	 * 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 hrtime start in nanoseconds, or null if none.
+	 * @return int|null The start time in nanoseconds, or null if none.
 	 */
 	private static function get_start(): ?int {
 		if ( null !== self::$pending_start ) {
@@ -173,4 +206,19 @@ private static function get_start(): ?int {
 
 		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 ) * 1000000000 );
+	}
 }
diff --git a/plugins/wpgraphql-logging/tests/wpunit/Events/RequestTimerTest.php b/plugins/wpgraphql-logging/tests/wpunit/Events/RequestTimerTest.php
index 96bea15e8..e43607de5 100644
--- a/plugins/wpgraphql-logging/tests/wpunit/Events/RequestTimerTest.php
+++ b/plugins/wpgraphql-logging/tests/wpunit/Events/RequestTimerTest.php
@@ -35,10 +35,40 @@ public function test_not_running_by_default(): void {
 	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, 'on_pre_request' ] ) );
+		$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->assertFalse( RequestTimer::is_running() );
+	}
+
+	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->assertFalse( RequestTimer::is_running() );
 	}
 
 	public function test_request_data_starts_timer_and_returns_data_unchanged(): void {
@@ -59,33 +89,37 @@ public function test_elapsed_time_increases(): void {
 		$this->assertGreaterThanOrEqual( 5, RequestTimer::get_elapsed_ms() );
 	}
 
-	public function test_pre_request_starts_timer_when_not_pending(): void {
-		RequestTimer::on_pre_request();
+	public function test_start_starts_timer_when_not_pending(): void {
+		RequestTimer::start();
 		$this->assertTrue( RequestTimer::is_running() );
 	}
 
-	public function test_pre_request_does_not_restart_pending_timer_for_batch_operations(): void {
+	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::on_pre_request();
-		RequestTimer::on_pre_request();
+		RequestTimer::start();
+		RequestTimer::start();
 
 		$this->assertGreaterThanOrEqual( 5, RequestTimer::get_elapsed_ms() );
 	}
 
-	public function test_request_data_restarts_pending_timer(): void {
-		RequestTimer::on_request_data( [] );
-		usleep( 20000 );
+	public function test_request_data_keeps_earlier_pending_start(): void {
+		RequestTimer::start();
+		usleep( 5000 );
 		RequestTimer::on_request_data( [] );
 
-		$this->assertLessThan( 20, RequestTimer::get_elapsed_ms() );
+		$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::on_pre_request();
+		RequestTimer::start();
 		usleep( 5000 );
 		RequestTimer::on_before_execute();
 

From fb5d969c88bdce919eae0c78644495b890300784 Mon Sep 17 00:00:00 2001
From: Joe Fusco <hello@josephfus.co>
Date: Fri, 30 Oct 2026 15:40:17 -0400
Subject: [PATCH 3/4] test(logging): cover request timer registration, batches
 and context helper

Assert QueryEventLifecycle registers the timer hooks, and test an internal batched graphql() call and LoggingHelper::add_request_duration. Fix two psalm errors: use a float literal in the microtime() fallback so the multiplication is not mixed int/float, and register the graphql_request_data filter by its literal name so psalm's hook checks stop flagging DataDeletionScheduler's action.
---
 .../src/Events/RequestTimer.php               |  6 +++--
 .../wpunit/Events/QueryEventLifecycleTest.php |  6 +++++
 .../wpunit/Events/QueryFilterLoggerTest.php   | 16 +++++++++++++
 .../tests/wpunit/Events/RequestTimerTest.php  | 23 +++++++++++++++++++
 4 files changed, 49 insertions(+), 2 deletions(-)

diff --git a/plugins/wpgraphql-logging/src/Events/RequestTimer.php b/plugins/wpgraphql-logging/src/Events/RequestTimer.php
index 163656363..e8dbeda0a 100644
--- a/plugins/wpgraphql-logging/src/Events/RequestTimer.php
+++ b/plugins/wpgraphql-logging/src/Events/RequestTimer.php
@@ -94,7 +94,9 @@ final class RequestTimer {
 	 */
 	public static function register_hooks(): void {
 		add_action( self::HTTP_REQUEST_START_HOOK, [ self::class, 'on_http_request' ], self::START_PRIORITY, 0 );
-		add_filter( Events::REQUEST_DATA, [ self::class, 'on_request_data' ], self::START_PRIORITY, 1 );
+		// 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 );
@@ -219,6 +221,6 @@ private static function now(): int {
 			return $time;
 		}
 
-		return (int) ( microtime( true ) * 1000000000 );
+		return (int) ( microtime( true ) * 1e9 );
 	}
 }
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 600444945..4e5325048 100644
--- a/plugins/wpgraphql-logging/tests/wpunit/Events/QueryFilterLoggerTest.php
+++ b/plugins/wpgraphql-logging/tests/wpunit/Events/QueryFilterLoggerTest.php
@@ -226,6 +226,22 @@ public function test_graphql_request_results_includes_request_duration(): void {
 		$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
index e43607de5..415ccaa9e 100644
--- a/plugins/wpgraphql-logging/tests/wpunit/Events/RequestTimerTest.php
+++ b/plugins/wpgraphql-logging/tests/wpunit/Events/RequestTimerTest.php
@@ -206,4 +206,27 @@ public function test_graphql_request_is_timed_and_each_request_starts_fresh(): v
 		$this->assertLessThan( 20, $captured[1] );
 		$this->assertFalse( RequestTimer::is_running() );
 	}
+
+	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->assertFalse( RequestTimer::is_running() );
+	}
 }

From 79e8a1ade719b68c6e1e499eb4980880449f1bf6 Mon Sep 17 00:00:00 2001
From: Joe Fusco <hello@josephfus.co>
Date: Fri, 30 Oct 2026 15:40:53 -0400
Subject: [PATCH 4/4] docs(logging): document request duration and share one
 key constant

Document request_duration_ms, where the timer starts and stops, and how batches and nested graphql() calls behave, in the plugin docs and readme.txt. Use a single RequestTimer::DURATION_KEY for the extra and context key instead of a processor constant plus a string literal, and drop RequestTimer::is_running(), which only the tests used.
---
 docs/plugins/wpgraphql-logging/index.md       | 15 ++++++++-
 plugins/wpgraphql-logging/readme.txt          |  1 +
 .../src/Events/RequestTimer.php               | 17 +++++-----
 .../src/Logger/LoggingHelper.php              |  2 +-
 .../Processors/RequestDurationProcessor.php   | 13 ++------
 .../wpunit/Events/QueryActionLoggerTest.php   |  5 ++-
 .../tests/wpunit/Events/RequestTimerTest.php  | 32 +++++++++----------
 .../RequestDurationProcessorTest.php          | 12 +++----
 8 files changed, 51 insertions(+), 46 deletions(-)

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/RequestTimer.php b/plugins/wpgraphql-logging/src/Events/RequestTimer.php
index e8dbeda0a..d5687aac3 100644
--- a/plugins/wpgraphql-logging/src/Events/RequestTimer.php
+++ b/plugins/wpgraphql-logging/src/Events/RequestTimer.php
@@ -28,6 +28,13 @@
  * @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.
 	 *
@@ -88,7 +95,8 @@ final class RequestTimer {
 	/**
 	 * Registers the hooks that drive the timer.
 	 *
-	 * These hooks are not logging events, so they are not part of the Events list.
+	 * The HTTP and after-execute hooks are not logging events, so their names are
+	 * defined here rather than in Events.
 	 *
 	 * @psalm-suppress HookNotFound
 	 */
@@ -160,13 +168,6 @@ public static function on_after_execute(): void {
 		array_pop( self::$stack );
 	}
 
-	/**
-	 * Whether a request is currently being timed.
-	 */
-	public static function is_running(): bool {
-		return null !== self::get_start();
-	}
-
 	/**
 	 * Gets the elapsed time of the current request in milliseconds.
 	 *
diff --git a/plugins/wpgraphql-logging/src/Logger/LoggingHelper.php b/plugins/wpgraphql-logging/src/Logger/LoggingHelper.php
index 044fc0a0b..73c116f4a 100644
--- a/plugins/wpgraphql-logging/src/Logger/LoggingHelper.php
+++ b/plugins/wpgraphql-logging/src/Logger/LoggingHelper.php
@@ -54,7 +54,7 @@ public function should_log_response(array $config): bool {
 	public function add_request_duration(array $context): array {
 		$duration = RequestTimer::get_elapsed_ms();
 		if ( null !== $duration ) {
-			$context['request_duration_ms'] = $duration;
+			$context[ RequestTimer::DURATION_KEY ] = $duration;
 		}
 
 		return $context;
diff --git a/plugins/wpgraphql-logging/src/Logger/Processors/RequestDurationProcessor.php b/plugins/wpgraphql-logging/src/Logger/Processors/RequestDurationProcessor.php
index 8421e36e9..417cc9ba9 100644
--- a/plugins/wpgraphql-logging/src/Logger/Processors/RequestDurationProcessor.php
+++ b/plugins/wpgraphql-logging/src/Logger/Processors/RequestDurationProcessor.php
@@ -20,13 +20,6 @@
  * @since 1.1.0
  */
 class RequestDurationProcessor implements ProcessorInterface {
-	/**
-	 * The key added to the record's 'extra' array.
-	 *
-	 * @var string
-	 */
-	public const EXTRA_KEY = 'request_duration_ms';
-
 	/**
 	 * This method is called for each log record. It adds the elapsed request
 	 * time to the record's 'extra' array.
@@ -37,12 +30,10 @@ class RequestDurationProcessor implements ProcessorInterface {
 	 */
 	public function __invoke( LogRecord $record ): LogRecord {
 		$elapsed = RequestTimer::get_elapsed_ms();
-		if ( null === $elapsed ) {
-			return $record;
+		if ( null !== $elapsed ) {
+			$record->extra[ RequestTimer::DURATION_KEY ] = $elapsed;
 		}
 
-		$record->extra[ self::EXTRA_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 21bd40ca0..c12c0cbdf 100644
--- a/plugins/wpgraphql-logging/tests/wpunit/Events/QueryActionLoggerTest.php
+++ b/plugins/wpgraphql-logging/tests/wpunit/Events/QueryActionLoggerTest.php
@@ -10,7 +10,6 @@
 use WPGraphQL\Logging\Events\QueryActionLogger;
 use WPGraphQL\Logging\Events\Events;
 use WPGraphQL\Logging\Events\RequestTimer;
-use WPGraphQL\Logging\Logger\Processors\RequestDurationProcessor;
 use GraphQL\Executor\ExecutionResult;
 use WPGraphQL\Logging\Logger\LoggerService;
 use WPGraphQL\Logging\Admin\Settings\Fields\Tab\BasicConfigurationTab;
@@ -383,8 +382,8 @@ public function test_log_before_response_returned_includes_request_duration(): v
 		$extra = $logs[0]->get_extra();
 		$this->assertArrayHasKey('request_duration_ms', $context);
 		$this->assertGreaterThanOrEqual(5, $context['request_duration_ms']);
-		$this->assertArrayHasKey(RequestDurationProcessor::EXTRA_KEY, $extra);
-		$this->assertGreaterThanOrEqual($context['request_duration_ms'], $extra[RequestDurationProcessor::EXTRA_KEY]);
+		$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 {
diff --git a/plugins/wpgraphql-logging/tests/wpunit/Events/RequestTimerTest.php b/plugins/wpgraphql-logging/tests/wpunit/Events/RequestTimerTest.php
index 415ccaa9e..ec9f6dc4f 100644
--- a/plugins/wpgraphql-logging/tests/wpunit/Events/RequestTimerTest.php
+++ b/plugins/wpgraphql-logging/tests/wpunit/Events/RequestTimerTest.php
@@ -28,7 +28,7 @@ public function tearDown(): void {
 	}
 
 	public function test_not_running_by_default(): void {
-		$this->assertFalse( RequestTimer::is_running() );
+		$this->assertNull( RequestTimer::get_elapsed_ms() );
 		$this->assertNull( RequestTimer::get_elapsed_ms() );
 	}
 
@@ -54,7 +54,7 @@ public function test_http_request_lifecycle(): void {
 		$this->assertGreaterThanOrEqual( 5, RequestTimer::get_elapsed_ms() );
 
 		RequestTimer::on_after_execute();
-		$this->assertFalse( RequestTimer::is_running() );
+		$this->assertNull( RequestTimer::get_elapsed_ms() );
 	}
 
 	public function test_http_request_clears_state_left_by_a_failed_request(): void {
@@ -68,14 +68,14 @@ public function test_http_request_clears_state_left_by_a_failed_request(): void
 		$this->assertLessThan( 20, RequestTimer::get_elapsed_ms() );
 		RequestTimer::on_before_execute();
 		RequestTimer::on_after_execute();
-		$this->assertFalse( RequestTimer::is_running() );
+		$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->assertTrue( RequestTimer::is_running() );
+		$this->assertNotNull( RequestTimer::get_elapsed_ms() );
 
 		$elapsed = RequestTimer::get_elapsed_ms();
 		$this->assertIsFloat( $elapsed );
@@ -91,7 +91,7 @@ public function test_elapsed_time_increases(): void {
 
 	public function test_start_starts_timer_when_not_pending(): void {
 		RequestTimer::start();
-		$this->assertTrue( RequestTimer::is_running() );
+		$this->assertNotNull( RequestTimer::get_elapsed_ms() );
 	}
 
 	public function test_start_does_not_restart_pending_timer_for_batch_operations(): void {
@@ -123,26 +123,26 @@ public function test_timer_spans_execution_and_stops_after_execute(): void {
 		usleep( 5000 );
 		RequestTimer::on_before_execute();
 
-		$this->assertTrue( RequestTimer::is_running() );
+		$this->assertNotNull( RequestTimer::get_elapsed_ms() );
 		$this->assertGreaterThanOrEqual( 5, RequestTimer::get_elapsed_ms() );
 
 		RequestTimer::on_after_execute();
 
-		$this->assertFalse( RequestTimer::is_running() );
+		$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->assertTrue( RequestTimer::is_running() );
+		$this->assertNotNull( RequestTimer::get_elapsed_ms() );
 
 		RequestTimer::on_after_execute();
-		$this->assertFalse( RequestTimer::is_running() );
+		$this->assertNull( RequestTimer::get_elapsed_ms() );
 	}
 
 	public function test_after_execute_without_running_timer_is_safe(): void {
 		RequestTimer::on_after_execute();
-		$this->assertFalse( RequestTimer::is_running() );
+		$this->assertNull( RequestTimer::get_elapsed_ms() );
 	}
 
 	public function test_nested_request_does_not_reset_outer_request(): void {
@@ -159,11 +159,11 @@ public function test_nested_request_does_not_reset_outer_request(): void {
 		RequestTimer::on_after_execute();
 
 		// Back on the outer request.
-		$this->assertTrue( RequestTimer::is_running() );
+		$this->assertNotNull( RequestTimer::get_elapsed_ms() );
 		$this->assertGreaterThanOrEqual( 20, RequestTimer::get_elapsed_ms() );
 
 		RequestTimer::on_after_execute();
-		$this->assertFalse( RequestTimer::is_running() );
+		$this->assertNull( RequestTimer::get_elapsed_ms() );
 	}
 
 	public function test_reset_clears_state(): void {
@@ -173,7 +173,7 @@ public function test_reset_clears_state(): void {
 
 		RequestTimer::reset();
 
-		$this->assertFalse( RequestTimer::is_running() );
+		$this->assertNull( RequestTimer::get_elapsed_ms() );
 	}
 
 	public function test_graphql_request_is_timed_and_each_request_starts_fresh(): void {
@@ -195,7 +195,7 @@ public function test_graphql_request_is_timed_and_each_request_starts_fresh(): v
 
 		$this->assertCount( 1, $captured );
 		$this->assertGreaterThanOrEqual( 20, $captured[0] );
-		$this->assertFalse( RequestTimer::is_running() );
+		$this->assertNull( RequestTimer::get_elapsed_ms() );
 
 		// The second request must not include the first request's time.
 		add_action( Events::PRE_REQUEST, $capture );
@@ -204,7 +204,7 @@ public function test_graphql_request_is_timed_and_each_request_starts_fresh(): v
 
 		$this->assertCount( 2, $captured );
 		$this->assertLessThan( 20, $captured[1] );
-		$this->assertFalse( RequestTimer::is_running() );
+		$this->assertNull( RequestTimer::get_elapsed_ms() );
 	}
 
 	public function test_batched_graphql_request_times_each_operation(): void {
@@ -227,6 +227,6 @@ public function test_batched_graphql_request_times_each_operation(): void {
 		$this->assertCount( 2, $captured );
 		$this->assertIsFloat( $captured[0] );
 		$this->assertIsFloat( $captured[1] );
-		$this->assertFalse( RequestTimer::is_running() );
+		$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
index 6974852b8..2b4798b58 100644
--- a/plugins/wpgraphql-logging/tests/wpunit/Logger/Processors/RequestDurationProcessorTest.php
+++ b/plugins/wpgraphql-logging/tests/wpunit/Logger/Processors/RequestDurationProcessorTest.php
@@ -46,7 +46,7 @@ public function test_record_unchanged_outside_of_a_request(): void {
 		$processor = new RequestDurationProcessor();
 		$record    = $processor( $this->create_record() );
 
-		$this->assertArrayNotHasKey( RequestDurationProcessor::EXTRA_KEY, $record->extra );
+		$this->assertArrayNotHasKey( RequestTimer::DURATION_KEY, $record->extra );
 	}
 
 	public function test_adds_elapsed_time_during_a_request(): void {
@@ -56,9 +56,9 @@ public function test_adds_elapsed_time_during_a_request(): void {
 		$processor = new RequestDurationProcessor();
 		$record    = $processor( $this->create_record() );
 
-		$this->assertArrayHasKey( RequestDurationProcessor::EXTRA_KEY, $record->extra );
-		$this->assertIsFloat( $record->extra[ RequestDurationProcessor::EXTRA_KEY ] );
-		$this->assertGreaterThanOrEqual( 5, $record->extra[ RequestDurationProcessor::EXTRA_KEY ] );
+		$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 {
@@ -70,8 +70,8 @@ public function test_elapsed_time_grows_across_records_in_the_same_request(): vo
 		$second = $processor( $this->create_record() );
 
 		$this->assertGreaterThan(
-			$first->extra[ RequestDurationProcessor::EXTRA_KEY ],
-			$second->extra[ RequestDurationProcessor::EXTRA_KEY ]
+			$first->extra[ RequestTimer::DURATION_KEY ],
+			$second->extra[ RequestTimer::DURATION_KEY ]
 		);
 	}