From 9732ba7cd000f7765171c97cb2f391d21b8a31d5 Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 11 Jul 2026 18:34:53 +0000 Subject: [PATCH 1/5] Add drop-in response-time measurement snippet for CB routes --- snippets/cb-response-timer.php | 92 ++++++++++++++++++++++++++++++++++ 1 file changed, 92 insertions(+) create mode 100644 snippets/cb-response-timer.php diff --git a/snippets/cb-response-timer.php b/snippets/cb-response-timer.php new file mode 100644 index 000000000..1516e8bdb --- /dev/null +++ b/snippets/cb-response-timer.php @@ -0,0 +1,92 @@ + self::current_url(), + 'post_type' => get_post_type() ?: null, + 'duration_ms' => round( ( microtime( true ) - self::$start ) * 1000, 1 ), + ) + ); + } + + /** + * Whether the current request touches CommonsBooking: a `cb_*` ajax action, + * a `commonsbooking/v*` REST route, or a page whose queried post type belongs + * to the plugin. Override entirely via the `cb_response_timer_is_relevant` filter. + */ + protected static function is_relevant(): bool { + $action = $_REQUEST['action'] ?? ''; + $uri = $_SERVER['REQUEST_URI'] ?? ''; + + $relevant = ( is_string( $action ) && str_starts_with( $action, 'cb_' ) ) + || str_contains( $uri, '/wp-json/commonsbooking/' ) + || str_contains( $uri, 'rest_route=/commonsbooking/' ) + || in_array( get_post_type(), self::post_types(), true ); + + return (bool) apply_filters( 'cb_response_timer_is_relevant', $relevant ); + } + + protected static function post_types(): array { + return array( 'cb_item', 'cb_location', 'cb_timeframe', 'cb_booking', 'cb_map', 'cb_restriction' ); + } + + protected static function current_url(): string { + $host = $_SERVER['HTTP_HOST'] ?? ''; + $uri = $_SERVER['REQUEST_URI'] ?? ''; + return 'https://' . $host . $uri; + } +} + +CB_Response_Timer::init(); + +// Default sink: write one line per measurement to the PHP error log. +// Replace/remove this listener (or add your own) to send data elsewhere. +add_action( + 'cb_response_timer_measured', + function ( array $data ) { + error_log( + sprintf( + '[cb-response-timer] %sms | post_type=%s | %s', + $data['duration_ms'], + $data['post_type'] ?? '-', + $data['url'] + ) + ); + } +); From ffa973f0f6fa3ca36b2130783035cf4003c0c1ad Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 11 Jul 2026 19:16:35 +0000 Subject: [PATCH 2/5] Track cache hit/miss and URL-derived workload route in response timer - Cache::getCacheItem() now fires commonsbooking_cache_hit/_miss actions - response timer groups requests by route derived from URL/query (ajax action, REST path, or CPT context) instead of raw URL - switches default output to NDJSON written to a dedicated log file - drops the https-only gate so local/staging load tests are captured --- snippets/cb-response-timer.php | 98 +++++++++++++++++++++++++--------- src/Service/Cache.php | 2 + 2 files changed, 76 insertions(+), 24 deletions(-) diff --git a/snippets/cb-response-timer.php b/snippets/cb-response-timer.php index 1516e8bdb..d51080450 100644 --- a/snippets/cb-response-timer.php +++ b/snippets/cb-response-timer.php @@ -1,17 +1,25 @@ gmdate( 'c' ), 'url' => self::current_url(), + 'route' => self::derive_route(), 'post_type' => get_post_type() ?: null, + 'cache' => array( + 'hits' => self::$cache_hits, + 'misses' => self::$cache_misses, + ), 'duration_ms' => round( ( microtime( true ) - self::$start ) * 1000, 1 ), ) ); @@ -51,15 +79,41 @@ public static function maybe_log() { * to the plugin. Override entirely via the `cb_response_timer_is_relevant` filter. */ protected static function is_relevant(): bool { + $relevant = 'other' !== self::derive_route(); + + return (bool) apply_filters( 'cb_response_timer_is_relevant', $relevant ); + } + + /** + * Groups the current request into a workload/route label derived purely from the + * URL and query state - no custom header required. Examples: + * ajax:cb_calendar_data + * rest:/commonsbooking/v1/items/:id + * cb_item:single + * cb_location:archive + * other + */ + protected static function derive_route(): string { $action = $_REQUEST['action'] ?? ''; - $uri = $_SERVER['REQUEST_URI'] ?? ''; + if ( is_string( $action ) && str_starts_with( $action, 'cb_' ) ) { + return 'ajax:' . $action; + } - $relevant = ( is_string( $action ) && str_starts_with( $action, 'cb_' ) ) - || str_contains( $uri, '/wp-json/commonsbooking/' ) - || str_contains( $uri, 'rest_route=/commonsbooking/' ) - || in_array( get_post_type(), self::post_types(), true ); + $uri = $_SERVER['REQUEST_URI'] ?? ''; + if ( preg_match( '#/wp-json(/commonsbooking/v[^/?]+.*?)(?:\?|$)#', $uri, $matches ) + || preg_match( '#[?&]rest_route=(/commonsbooking/v[^&]+)#', $uri, $matches ) + ) { + $path = preg_replace( '#/\d+(?=/|$)#', '/:id', rawurldecode( $matches[1] ) ); + return 'rest:' . $path; + } - return (bool) apply_filters( 'cb_response_timer_is_relevant', $relevant ); + $post_type = get_post_type(); + if ( in_array( $post_type, self::post_types(), true ) ) { + $context = is_singular() ? 'single' : ( is_post_type_archive() ? 'archive' : 'other' ); + return $post_type . ':' . $context; + } + + return 'other'; } protected static function post_types(): array { @@ -67,26 +121,22 @@ protected static function post_types(): array { } protected static function current_url(): string { - $host = $_SERVER['HTTP_HOST'] ?? ''; - $uri = $_SERVER['REQUEST_URI'] ?? ''; - return 'https://' . $host . $uri; + $scheme = is_ssl() ? 'https://' : 'http://'; + $host = $_SERVER['HTTP_HOST'] ?? ''; + $uri = $_SERVER['REQUEST_URI'] ?? ''; + return $scheme . $host . $uri; } } CB_Response_Timer::init(); -// Default sink: write one line per measurement to the PHP error log. +// Default sink: append one NDJSON line per measurement to a dedicated log file +// (kept out of the shared PHP error log to avoid noise/contention under load). // Replace/remove this listener (or add your own) to send data elsewhere. add_action( 'cb_response_timer_measured', function ( array $data ) { - error_log( - sprintf( - '[cb-response-timer] %sms | post_type=%s | %s', - $data['duration_ms'], - $data['post_type'] ?? '-', - $data['url'] - ) - ); + $log_file = apply_filters( 'cb_response_timer_log_file', WP_CONTENT_DIR . '/cb-response-timer.log' ); + error_log( wp_json_encode( $data ) . "\n", 3, $log_file ); } ); diff --git a/src/Service/Cache.php b/src/Service/Cache.php index 61d0c2d83..2a18a8b86 100644 --- a/src/Service/Cache.php +++ b/src/Service/Cache.php @@ -46,6 +46,7 @@ public static function getCacheItem( $custom_id = null ) { $cacheKey = self::getCacheId( $custom_id ); $cacheItem = self::getCache()->getItem( $cacheKey ); if ( $cacheItem->isHit() ) { + do_action( 'commonsbooking_cache_hit', $cacheKey ); return $cacheItem->get(); } } catch ( \CommonsBooking\Psr\Cache\CacheException $exception ) { @@ -54,6 +55,7 @@ public static function getCacheItem( $custom_id = null ) { commonsbooking_write_log( sprintf( 'Could not get cache item (params $custom_id = %s): message: %s, traceback %s', $custom_id, $exception->getMessage(), $exception->getTraceAsString() ) ); } + do_action( 'commonsbooking_cache_miss', $cacheKey ?? null ); return false; } From b6d6e72892439e6f7868b899f324de01f3e96d5b Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 11 Jul 2026 19:35:34 +0000 Subject: [PATCH 3/5] Capture request payload and DB query cost per measured response - derive_payload(): generic sanitized snapshot of $_REQUEST (array values collapsed to counts, noise keys denylisted), so hot-route params (date range, item/location ids, ...) are captured without per-route parsing - derive_db_stats(): turns on $wpdb->save_queries at init and reads query_count/time_ms/slowest_ms/slowest_sql from $wpdb->queries at shutdown - the central point where SQL is actually emitted; slowest query SQL is literal-normalized for grouping and to avoid leaking data values into the log - both are filterable (cb_response_timer_payload_denylist, cb_response_timer_track_queries) and off by default overhead is documented in the file header --- snippets/cb-response-timer.php | 81 +++++++++++++++++++++++++++++++--- 1 file changed, 76 insertions(+), 5 deletions(-) diff --git a/snippets/cb-response-timer.php b/snippets/cb-response-timer.php index d51080450..5c470fd9c 100644 --- a/snippets/cb-response-timer.php +++ b/snippets/cb-response-timer.php @@ -13,13 +13,20 @@ * Note: CommonsBooking's cache layer short-circuits to "miss" whenever WP_DEBUG is * on (see Cache::getCacheItem()), so cache stats are only meaningful with * WP_DEBUG off. + * Note: DB query stats are collected via $wpdb->save_queries, which stores every + * query's SQL and a backtrace for the request - real overhead, intended for + * load-test/staging use, not left running against full production traffic. + * Disable it with the `cb_response_timer_track_queries` filter if needed. * * Extend: - * - filter `cb_response_timer_is_relevant` to change which requests are measured. - * - filter `cb_response_timer_log_file` to change the NDJSON log destination - * (default: wp-content/cb-response-timer.log). - * - action `cb_response_timer_measured` to change where/how a measurement is - * recorded instead (receives the data array). + * - filter `cb_response_timer_is_relevant` to change which requests are measured. + * - filter `cb_response_timer_payload_denylist` to change which $_REQUEST keys are + * stripped from the logged payload. + * - filter `cb_response_timer_track_queries` to turn DB query stats off (default on). + * - filter `cb_response_timer_log_file` to change the NDJSON log destination + * (default: wp-content/cb-response-timer.log). + * - action `cb_response_timer_measured` to change where/how a measurement is + * recorded instead (receives the data array). */ defined( 'ABSPATH' ) || die; @@ -35,6 +42,11 @@ class CB_Response_Timer { public static function init() { self::$start = $_SERVER['REQUEST_TIME_FLOAT'] ?? microtime( true ); + if ( apply_filters( 'cb_response_timer_track_queries', true ) ) { + global $wpdb; + $wpdb->save_queries = true; + } + add_action( 'commonsbooking_cache_hit', array( __CLASS__, 'record_cache_hit' ) ); add_action( 'commonsbooking_cache_miss', array( __CLASS__, 'record_cache_miss' ) ); add_action( 'shutdown', array( __CLASS__, 'maybe_log' ) ); @@ -68,6 +80,8 @@ public static function maybe_log() { 'hits' => self::$cache_hits, 'misses' => self::$cache_misses, ), + 'payload' => self::derive_payload(), + 'db' => self::derive_db_stats(), 'duration_ms' => round( ( microtime( true ) - self::$start ) * 1000, 1 ), ) ); @@ -120,6 +134,63 @@ protected static function post_types(): array { return array( 'cb_item', 'cb_location', 'cb_timeframe', 'cb_booking', 'cb_map', 'cb_restriction' ); } + /** + * Sanitized snapshot of the request params, captured generically - whatever a hot + * route's params are (date range, item/location ids, ...) comes along for free, + * with no per-route parsing. Array values collapse to a count to bound row size and + * avoid leaking list contents; noise/security keys are stripped via a denylist, + * overridable through `cb_response_timer_payload_denylist`. + */ + protected static function derive_payload(): array { + $denylist = apply_filters( + 'cb_response_timer_payload_denylist', + array( 'action', '_wpnonce', 'nonce', '_wp_http_referer', 'apikey', 'rest_route' ) + ); + + $payload = array(); + foreach ( $_REQUEST as $key => $value ) { + if ( in_array( $key, $denylist, true ) ) { + continue; + } + if ( is_array( $value ) ) { + $payload[ $key ] = array( '_count' => count( $value ) ); + continue; + } + $payload[ $key ] = mb_substr( (string) $value, 0, 200 ); + } + + return $payload; + } + + /** + * Aggregate DB cost for the request, sourced from $wpdb->queries (populated because + * init() turns save_queries on). Each entry is [sql, exec_time_seconds, caller, ...]. + * The slowest query's SQL is normalized (literals stripped) so rows are groupable by + * query shape and don't leak literal data values into the log. + */ + protected static function derive_db_stats(): ?array { + global $wpdb; + + if ( empty( $wpdb->save_queries ) || empty( $wpdb->queries ) ) { + return null; + } + + $times = array_column( $wpdb->queries, 1 ); + $slowest = $wpdb->queries[ array_search( max( $times ), $times, true ) ]; + + return array( + 'query_count' => count( $wpdb->queries ), + 'time_ms' => round( array_sum( $times ) * 1000, 1 ), + 'slowest_ms' => round( $slowest[1] * 1000, 1 ), + 'slowest_sql' => self::normalize_sql( $slowest[0] ), + ); + } + + protected static function normalize_sql( string $sql ): string { + $sql = preg_replace( "/'[^']*'/", "'?'", $sql ); + return preg_replace( '/\b\d+\b/', '?', $sql ); + } + protected static function current_url(): string { $scheme = is_ssl() ? 'https://' : 'http://'; $host = $_SERVER['HTTP_HOST'] ?? ''; From 44f7cf799885c7a12d8bc513abd5a426cf9b5386 Mon Sep 17 00:00:00 2001 From: Claude Date: Sun, 12 Jul 2026 12:54:30 +0000 Subject: [PATCH 4/5] Segment measurements into a SQL table via deferred, cron-flushed batch writes - Adds a lazily-created {$wpdb->prefix}cb_response_timer table (dbDelta + versioned option, same pattern as BookingCodes::initBookingCodesTable) with an essentials schema for segmentation: route, duration_ms, cache_hits/misses, db_query_count/time_ms, and a payload JSON column - The default sink now appends a trimmed row to a queue file per request (cheap, same cost as before) instead of writing the full NDJSON record - A WP-Cron job (cb_response_timer_flush, default every 300s) atomically rotates the queue file and bulk-inserts pending rows in one multi-row INSERT per chunk of 500, so no request pays for a synchronous DB write - url/post_type/slowest_sql/slowest_ms are still computed and passed through the cb_response_timer_measured action for custom listeners, just dropped from the built-in SQL persistence layer --- snippets/cb-response-timer.php | 208 ++++++++++++++++++++++++++++++--- 1 file changed, 191 insertions(+), 17 deletions(-) diff --git a/snippets/cb-response-timer.php b/snippets/cb-response-timer.php index 5c470fd9c..d34830542 100644 --- a/snippets/cb-response-timer.php +++ b/snippets/cb-response-timer.php @@ -2,13 +2,16 @@ /** * Plugin Name: CommonsBooking – Response Timer * Description: Drop-in diagnostic snippet. Measures end-to-end response duration, - * cache hit/miss counts and a URL-derived workload route for every - * 200-status response that goes through CommonsBooking (frontend CPT - * pages, admin-ajax `cb_*` actions, `commonsbooking/v*` REST routes). - * Writes one NDJSON line per measurement, suitable for load-test analysis. + * cache hit/miss counts, DB query cost and a URL-derived workload route + * for every 200-status response that goes through CommonsBooking + * (frontend CPT pages, admin-ajax `cb_*` actions, `commonsbooking/v*` + * REST routes). Rows are queued to a file per request (cheap) and bulk- + * inserted into a `{$wpdb->prefix}cb_response_timer` SQL table by a + * WP-Cron job, so no request pays for a synchronous DB write. * * Install: copy this file into wp-content/mu-plugins/ (or `require` it from a - * plugin/theme). No further setup needed - it self-registers on load. + * plugin/theme). No further setup needed - it self-registers on load and + * creates its table lazily on first `init`. * * Note: CommonsBooking's cache layer short-circuits to "miss" whenever WP_DEBUG is * on (see Cache::getCacheItem()), so cache stats are only meaningful with @@ -17,22 +20,33 @@ * query's SQL and a backtrace for the request - real overhead, intended for * load-test/staging use, not left running against full production traffic. * Disable it with the `cb_response_timer_track_queries` filter if needed. + * Note: the flush relies on WP-Cron's normal pseudo-cron (a non-blocking loopback + * request triggered by site traffic). If `DISABLE_WP_CRON` is set with no real + * system cron configured, the queue file will grow until one is set up. * * Extend: - * - filter `cb_response_timer_is_relevant` to change which requests are measured. - * - filter `cb_response_timer_payload_denylist` to change which $_REQUEST keys are - * stripped from the logged payload. - * - filter `cb_response_timer_track_queries` to turn DB query stats off (default on). - * - filter `cb_response_timer_log_file` to change the NDJSON log destination - * (default: wp-content/cb-response-timer.log). - * - action `cb_response_timer_measured` to change where/how a measurement is - * recorded instead (receives the data array). + * - filter `cb_response_timer_is_relevant` to change which requests are measured. + * - filter `cb_response_timer_payload_denylist` to change which $_REQUEST keys are + * stripped from the captured payload. + * - filter `cb_response_timer_track_queries` to turn DB query stats off (default on). + * - filter `cb_response_timer_log_file` to change the queue file location + * (default: wp-content/cb-response-timer-queue.log). + * - filter `cb_response_timer_flush_interval` seconds between cron flushes (default 300). + * - action `cb_response_timer_measured` to change where/how a measurement is + * recorded instead (receives the full + * data array, incl. url/post_type/slowest_sql + * which the default SQL sink drops). */ defined( 'ABSPATH' ) || die; class CB_Response_Timer { + const DB_VERSION = '1.0'; + const TABLE = 'cb_response_timer'; + const FLUSH_HOOK = 'cb_response_timer_flush'; + const FLUSH_SCHEDULE = 'cb_response_timer_interval'; + /** @var float Request start, set as early as PHP itself provides it. */ private static $start; @@ -50,6 +64,12 @@ public static function init() { add_action( 'commonsbooking_cache_hit', array( __CLASS__, 'record_cache_hit' ) ); add_action( 'commonsbooking_cache_miss', array( __CLASS__, 'record_cache_miss' ) ); add_action( 'shutdown', array( __CLASS__, 'maybe_log' ) ); + + add_filter( 'cron_schedules', array( __CLASS__, 'register_cron_schedule' ) ); + add_action( self::FLUSH_HOOK, array( __CLASS__, 'flush_queue' ) ); + + add_action( 'init', array( __CLASS__, 'maybe_create_table' ) ); + add_action( 'init', array( __CLASS__, 'maybe_schedule_flush' ) ); } public static function record_cache_hit() { @@ -197,17 +217,171 @@ protected static function current_url(): string { $uri = $_SERVER['REQUEST_URI'] ?? ''; return $scheme . $host . $uri; } + + public static function queue_file(): string { + return apply_filters( 'cb_response_timer_log_file', WP_CONTENT_DIR . '/cb-response-timer-queue.log' ); + } + + /** + * Creates {$wpdb->prefix}cb_response_timer via dbDelta(), same pattern as + * BookingCodes::initBookingCodesTable() (src/Repository/BookingCodes.php). Runs + * lazily on `init` since a drop-in mu-plugin has no activation hook; guarded by a + * versioned option so it's a single get_option() call on every request after the + * first successful run. + */ + public static function maybe_create_table() { + if ( get_option( 'cb_response_timer_db_version' ) === self::DB_VERSION ) { + return; + } + + global $wpdb; + $table = $wpdb->prefix . self::TABLE; + $charset_collate = $wpdb->get_charset_collate(); + + $sql = "CREATE TABLE $table ( + id BIGINT UNSIGNED NOT NULL AUTO_INCREMENT, + measured_at DATETIME NOT NULL, + route VARCHAR(191) NOT NULL, + duration_ms FLOAT NOT NULL, + cache_hits SMALLINT UNSIGNED NOT NULL DEFAULT 0, + cache_misses SMALLINT UNSIGNED NOT NULL DEFAULT 0, + db_query_count SMALLINT UNSIGNED NOT NULL DEFAULT 0, + db_time_ms FLOAT NOT NULL DEFAULT 0, + payload TEXT NULL, + PRIMARY KEY (id), + KEY route_measured_at (route, measured_at) + ) $charset_collate;"; + + require_once ABSPATH . 'wp-admin/includes/upgrade.php'; + dbDelta( $sql ); + + update_option( 'cb_response_timer_db_version', self::DB_VERSION ); + } + + public static function register_cron_schedule( array $schedules ): array { + $schedules[ self::FLUSH_SCHEDULE ] = array( + 'interval' => apply_filters( 'cb_response_timer_flush_interval', 300 ), + 'display' => 'CB Response Timer flush', + ); + + return $schedules; + } + + public static function maybe_schedule_flush() { + if ( ! wp_next_scheduled( self::FLUSH_HOOK ) ) { + wp_schedule_event( time(), self::FLUSH_SCHEDULE, self::FLUSH_HOOK ); + } + } + + /** + * Flushes the queue into the SQL table. Rotates the live queue file out of the way + * first (rename() is atomic on POSIX filesystems, so concurrent per-request writers + * safely resume onto a fresh file - error_log()'s mode-3 append recreates it as + * needed). Also sweeps up any `.processing.*` file left behind by a previous flush + * that rotated but failed before its insert completed, so nothing is silently lost. + */ + public static function flush_queue() { + $queue = self::queue_file(); + + if ( file_exists( $queue ) ) { + $processing = $queue . '.processing.' . uniqid(); + if ( rename( $queue, $processing ) ) { + self::process_file( $processing ); + } + } + + foreach ( glob( $queue . '.processing.*' ) ?: array() as $leftover ) { + self::process_file( $leftover ); + } + } + + protected static function process_file( string $file ) { + $lines = file( $file, FILE_IGNORE_NEW_LINES | FILE_SKIP_EMPTY_LINES ); + if ( ! $lines ) { + unlink( $file ); + return; + } + + $rows = array(); + foreach ( $lines as $line ) { + $row = json_decode( $line ); + if ( $row !== null ) { + $rows[] = $row; + } + } + + if ( ! self::bulk_insert( $rows ) ) { + return; // Leave the file for the next flush to retry. + } + + unlink( $file ); + } + + /** + * Bulk-inserts rows in chunks (wpdb has no native multi-row insert, so the query is + * built by repeating a placeholder group per row and flattening the args). + */ + protected static function bulk_insert( array $rows ): bool { + if ( empty( $rows ) ) { + return true; + } + + global $wpdb; + $table = $wpdb->prefix . self::TABLE; + $ok = true; + + foreach ( array_chunk( $rows, 500 ) as $chunk ) { + $placeholders = array(); + $args = array(); + + foreach ( $chunk as $row ) { + $placeholders[] = '(%s, %s, %f, %d, %d, %d, %f, %s)'; + $measured_at = ! empty( $row->time ) ? gmdate( 'Y-m-d H:i:s', strtotime( $row->time ) ) : gmdate( 'Y-m-d H:i:s' ); + array_push( + $args, + $measured_at, + $row->route ?? 'other', + $row->duration_ms ?? 0, + $row->cache->hits ?? 0, + $row->cache->misses ?? 0, + $row->db->query_count ?? 0, + $row->db->time_ms ?? 0, + wp_json_encode( $row->payload ?? array() ) + ); + } + + $sql = "INSERT INTO $table (measured_at, route, duration_ms, cache_hits, cache_misses, db_query_count, db_time_ms, payload) VALUES " + . implode( ', ', $placeholders ); + + if ( false === $wpdb->query( $wpdb->prepare( $sql, $args ) ) ) { + $ok = false; + } + } + + return $ok; + } } CB_Response_Timer::init(); -// Default sink: append one NDJSON line per measurement to a dedicated log file -// (kept out of the shared PHP error log to avoid noise/contention under load). +// Default sink: append one trimmed JSON line per measurement to the queue file, which +// a WP-Cron job (see flush_queue()) bulk-inserts into the SQL table. This keeps the +// per-request cost to a single small error_log() call - no synchronous DB write. // Replace/remove this listener (or add your own) to send data elsewhere. add_action( 'cb_response_timer_measured', function ( array $data ) { - $log_file = apply_filters( 'cb_response_timer_log_file', WP_CONTENT_DIR . '/cb-response-timer.log' ); - error_log( wp_json_encode( $data ) . "\n", 3, $log_file ); + $row = array( + 'time' => $data['time'], + 'route' => $data['route'], + 'duration_ms' => $data['duration_ms'], + 'cache' => $data['cache'], + 'db' => array( + 'query_count' => $data['db']['query_count'] ?? 0, + 'time_ms' => $data['db']['time_ms'] ?? 0, + ), + 'payload' => $data['payload'], + ); + error_log( wp_json_encode( $row ) . "\n", 3, CB_Response_Timer::queue_file() ); } ); From 5f323e1060473b8b522d48aff592e5a998c6a791 Mon Sep 17 00:00:00 2001 From: Claude Date: Sun, 12 Jul 2026 13:03:17 +0000 Subject: [PATCH 5/5] Rework response timer to DB-only, add IP/UA tracking and secret CSV export - Drops the file/cron queue entirely: each measured request now does one direct $wpdb->insert() into {$wpdb->prefix}cb_response_timer - zero setup, no dependency on WP-Cron actually firing (tradeoff vs the earlier deferred-write design documented in the file header) - Adds ip and user_agent columns; the IP is redacted (last octet for IPv4, last colon-group for IPv6) before it's ever computed or stored - the raw IP never exists outside $_SERVER - Adds a CSV export at GET /cb-response-timer/{secret}/export.csv, matched directly against the request path (no rewrite rule, nothing to flush) and streamed in chunks so it scales with table size - The secret is a plugin variable: define CB_RESPONSE_TIMER_SECRET in wp-config.php, or let it auto-generate and persist as an option for zero-setup use; overridable via cb_response_timer_export_secret --- snippets/cb-response-timer.php | 290 +++++++++++++++++---------------- 1 file changed, 149 insertions(+), 141 deletions(-) diff --git a/snippets/cb-response-timer.php b/snippets/cb-response-timer.php index d34830542..4a7ff218b 100644 --- a/snippets/cb-response-timer.php +++ b/snippets/cb-response-timer.php @@ -1,51 +1,60 @@ prefix}cb_response_timer` SQL table by a - * WP-Cron job, so no request pays for a synchronous DB write. + * Description: Drop-in diagnostic snippet, DB-only, zero setup. Measures end-to-end + * response duration, cache hit/miss counts, DB query cost, a redacted + * client IP and user agent, and a URL-derived workload route for every + * 200-status response that goes through CommonsBooking (frontend CPT + * pages, admin-ajax `cb_*` actions, `commonsbooking/v*` REST routes). + * Each measured request writes one row directly to a dedicated table - + * no file, no cron, no queue. * * Install: copy this file into wp-content/mu-plugins/ (or `require` it from a - * plugin/theme). No further setup needed - it self-registers on load and - * creates its table lazily on first `init`. + * plugin/theme). Nothing else to configure - it creates its own table lazily + * on first `init` and auto-generates an export secret on first use. * - * Note: CommonsBooking's cache layer short-circuits to "miss" whenever WP_DEBUG is - * on (see Cache::getCacheItem()), so cache stats are only meaningful with - * WP_DEBUG off. - * Note: DB query stats are collected via $wpdb->save_queries, which stores every - * query's SQL and a backtrace for the request - real overhead, intended for - * load-test/staging use, not left running against full production traffic. - * Disable it with the `cb_response_timer_track_queries` filter if needed. - * Note: the flush relies on WP-Cron's normal pseudo-cron (a non-blocking loopback - * request triggered by site traffic). If `DISABLE_WP_CRON` is set with no real - * system cron configured, the queue file will grow until one is set up. + * Export: GET /cb-response-timer/{secret}/export.csv streams the raw table as CSV. + * Matched directly against the request path (no rewrite rule, so nothing to + * flush/configure). The secret is a plugin variable: define it yourself with + * `define('CB_RESPONSE_TIMER_SECRET', '...')` in wp-config.php, or leave it + * unset and read the auto-generated one via + * `get_option('cb_response_timer_export_secret')`. + * + * Note: writes are synchronous (one $wpdb->insert() per measured request) - simple and + * always-on, but real DB cost per request. If that becomes a bottleneck under + * heavy load-test volume, batch/defer it yourself via the + * `cb_response_timer_measured` action instead of using the default listener. + * Note: CommonsBooking's cache layer short-circuits to "miss" whenever WP_DEBUG is on + * (see Cache::getCacheItem()), so cache stats are only meaningful with WP_DEBUG off. + * Note: DB query stats are collected via $wpdb->save_queries, which stores every query's + * SQL and a backtrace for the request - real overhead, intended for load-test/ + * staging use. Disable via the `cb_response_timer_track_queries` filter. + * Note: the client IP is read from $_SERVER['REMOTE_ADDR'] and stored with its last + * octet (IPv4) / last colon-group (IPv6) zeroed out before it ever reaches the + * table - the raw IP is never persisted. * * Extend: - * - filter `cb_response_timer_is_relevant` to change which requests are measured. - * - filter `cb_response_timer_payload_denylist` to change which $_REQUEST keys are - * stripped from the captured payload. - * - filter `cb_response_timer_track_queries` to turn DB query stats off (default on). - * - filter `cb_response_timer_log_file` to change the queue file location - * (default: wp-content/cb-response-timer-queue.log). - * - filter `cb_response_timer_flush_interval` seconds between cron flushes (default 300). - * - action `cb_response_timer_measured` to change where/how a measurement is - * recorded instead (receives the full - * data array, incl. url/post_type/slowest_sql - * which the default SQL sink drops). + * - filter `cb_response_timer_is_relevant` to change which requests are measured. + * - filter `cb_response_timer_payload_denylist` to change which $_REQUEST keys are + * stripped from the captured payload. + * - filter `cb_response_timer_track_queries` to turn DB query stats off (default on). + * - filter `cb_response_timer_client_ip` to change how the client IP is sourced + * (default: $_SERVER['REMOTE_ADDR']). + * - filter `cb_response_timer_export_secret` to override the export secret. + * - action `cb_response_timer_measured` to change where/how a measurement is + * recorded instead (receives the full + * data array, incl. url/post_type/ + * slowest_sql which the default SQL + * sink drops). */ defined( 'ABSPATH' ) || die; class CB_Response_Timer { - const DB_VERSION = '1.0'; - const TABLE = 'cb_response_timer'; - const FLUSH_HOOK = 'cb_response_timer_flush'; - const FLUSH_SCHEDULE = 'cb_response_timer_interval'; + const DB_VERSION = '2.0'; + const TABLE = 'cb_response_timer'; + const EXPORT_REGEX = '#^/cb-response-timer/([^/?]+)/export\.csv#'; /** @var float Request start, set as early as PHP itself provides it. */ private static $start; @@ -65,11 +74,8 @@ public static function init() { add_action( 'commonsbooking_cache_miss', array( __CLASS__, 'record_cache_miss' ) ); add_action( 'shutdown', array( __CLASS__, 'maybe_log' ) ); - add_filter( 'cron_schedules', array( __CLASS__, 'register_cron_schedule' ) ); - add_action( self::FLUSH_HOOK, array( __CLASS__, 'flush_queue' ) ); - add_action( 'init', array( __CLASS__, 'maybe_create_table' ) ); - add_action( 'init', array( __CLASS__, 'maybe_schedule_flush' ) ); + add_action( 'init', array( __CLASS__, 'maybe_handle_export' ) ); } public static function record_cache_hit() { @@ -96,6 +102,8 @@ public static function maybe_log() { 'url' => self::current_url(), 'route' => self::derive_route(), 'post_type' => get_post_type() ?: null, + 'ip' => self::redacted_ip(), + 'user_agent' => mb_substr( (string) ( $_SERVER['HTTP_USER_AGENT'] ?? '' ), 0, 255 ), 'cache' => array( 'hits' => self::$cache_hits, 'misses' => self::$cache_misses, @@ -185,8 +193,8 @@ protected static function derive_payload(): array { /** * Aggregate DB cost for the request, sourced from $wpdb->queries (populated because * init() turns save_queries on). Each entry is [sql, exec_time_seconds, caller, ...]. - * The slowest query's SQL is normalized (literals stripped) so rows are groupable by - * query shape and don't leak literal data values into the log. + * The slowest query's SQL is normalized (literals stripped) so it's groupable by + * query shape and doesn't leak literal data values. */ protected static function derive_db_stats(): ?array { global $wpdb; @@ -211,6 +219,29 @@ protected static function normalize_sql( string $sql ): string { return preg_replace( '/\b\d+\b/', '?', $sql ); } + /** + * Client IP with its last octet (IPv4) / last colon-group (IPv6) zeroed out before + * it's ever used elsewhere - only the redacted form is computed and stored, the raw + * IP is never persisted. Source is filterable for setups behind a trusted proxy. + */ + protected static function redacted_ip(): string { + $ip = (string) apply_filters( 'cb_response_timer_client_ip', $_SERVER['REMOTE_ADDR'] ?? '' ); + + if ( str_contains( $ip, ':' ) ) { + $parts = explode( ':', $ip ); + $parts[ count( $parts ) - 1 ] = '0'; + return implode( ':', $parts ); + } + + $parts = explode( '.', $ip ); + if ( count( $parts ) === 4 ) { + $parts[3] = '0'; + return implode( '.', $parts ); + } + + return $ip; + } + protected static function current_url(): string { $scheme = is_ssl() ? 'https://' : 'http://'; $host = $_SERVER['HTTP_HOST'] ?? ''; @@ -218,16 +249,12 @@ protected static function current_url(): string { return $scheme . $host . $uri; } - public static function queue_file(): string { - return apply_filters( 'cb_response_timer_log_file', WP_CONTENT_DIR . '/cb-response-timer-queue.log' ); - } - /** * Creates {$wpdb->prefix}cb_response_timer via dbDelta(), same pattern as * BookingCodes::initBookingCodesTable() (src/Repository/BookingCodes.php). Runs * lazily on `init` since a drop-in mu-plugin has no activation hook; guarded by a * versioned option so it's a single get_option() call on every request after the - * first successful run. + * first successful (or schema-upgrading) run. */ public static function maybe_create_table() { if ( get_option( 'cb_response_timer_db_version' ) === self::DB_VERSION ) { @@ -247,6 +274,8 @@ public static function maybe_create_table() { cache_misses SMALLINT UNSIGNED NOT NULL DEFAULT 0, db_query_count SMALLINT UNSIGNED NOT NULL DEFAULT 0, db_time_ms FLOAT NOT NULL DEFAULT 0, + ip VARCHAR(45) NULL, + user_agent VARCHAR(255) NULL, payload TEXT NULL, PRIMARY KEY (id), KEY route_measured_at (route, measured_at) @@ -258,130 +287,109 @@ public static function maybe_create_table() { update_option( 'cb_response_timer_db_version', self::DB_VERSION ); } - public static function register_cron_schedule( array $schedules ): array { - $schedules[ self::FLUSH_SCHEDULE ] = array( - 'interval' => apply_filters( 'cb_response_timer_flush_interval', 300 ), - 'display' => 'CB Response Timer flush', - ); - - return $schedules; - } - - public static function maybe_schedule_flush() { - if ( ! wp_next_scheduled( self::FLUSH_HOOK ) ) { - wp_schedule_event( time(), self::FLUSH_SCHEDULE, self::FLUSH_HOOK ); - } - } - /** - * Flushes the queue into the SQL table. Rotates the live queue file out of the way - * first (rename() is atomic on POSIX filesystems, so concurrent per-request writers - * safely resume onto a fresh file - error_log()'s mode-3 append recreates it as - * needed). Also sweeps up any `.processing.*` file left behind by a previous flush - * that rotated but failed before its insert completed, so nothing is silently lost. + * The secret path segment for /cb-response-timer/{secret}/export.csv. Prefers the + * `CB_RESPONSE_TIMER_SECRET` constant (set it in wp-config.php for a real deployment); + * otherwise auto-generates one on first use and persists it as an option, so the + * export route works with zero setup. Always overridable via the + * `cb_response_timer_export_secret` filter. */ - public static function flush_queue() { - $queue = self::queue_file(); - - if ( file_exists( $queue ) ) { - $processing = $queue . '.processing.' . uniqid(); - if ( rename( $queue, $processing ) ) { - self::process_file( $processing ); + public static function export_secret(): string { + $secret = defined( 'CB_RESPONSE_TIMER_SECRET' ) ? CB_RESPONSE_TIMER_SECRET : ''; + + if ( ! $secret ) { + $secret = get_option( 'cb_response_timer_export_secret' ); + if ( ! $secret ) { + $secret = wp_generate_password( 32, false ); + update_option( 'cb_response_timer_export_secret', $secret, false ); } } - foreach ( glob( $queue . '.processing.*' ) ?: array() as $leftover ) { - self::process_file( $leftover ); - } + return (string) apply_filters( 'cb_response_timer_export_secret', $secret ); } - protected static function process_file( string $file ) { - $lines = file( $file, FILE_IGNORE_NEW_LINES | FILE_SKIP_EMPTY_LINES ); - if ( ! $lines ) { - unlink( $file ); - return; - } + /** + * Matches the request path directly against EXPORT_REGEX - no rewrite rule + * registered, so there's nothing to flush/configure. Falls through to normal WP + * routing (404) whenever the path doesn't match or the secret is wrong. + */ + public static function maybe_handle_export() { + $path = (string) parse_url( $_SERVER['REQUEST_URI'] ?? '', PHP_URL_PATH ); - $rows = array(); - foreach ( $lines as $line ) { - $row = json_decode( $line ); - if ( $row !== null ) { - $rows[] = $row; - } + if ( ! preg_match( self::EXPORT_REGEX, $path, $matches ) ) { + return; } - if ( ! self::bulk_insert( $rows ) ) { - return; // Leave the file for the next flush to retry. + if ( ! hash_equals( self::export_secret(), $matches[1] ) ) { + return; } - unlink( $file ); + self::stream_csv(); + exit; } /** - * Bulk-inserts rows in chunks (wpdb has no native multi-row insert, so the query is - * built by repeating a placeholder group per row and flattening the args). + * Streams the raw table as CSV in chunks (rather than loading the whole table into + * memory) so the export stays usable as the table grows. */ - protected static function bulk_insert( array $rows ): bool { - if ( empty( $rows ) ) { - return true; - } - + protected static function stream_csv() { global $wpdb; - $table = $wpdb->prefix . self::TABLE; - $ok = true; - - foreach ( array_chunk( $rows, 500 ) as $chunk ) { - $placeholders = array(); - $args = array(); - - foreach ( $chunk as $row ) { - $placeholders[] = '(%s, %s, %f, %d, %d, %d, %f, %s)'; - $measured_at = ! empty( $row->time ) ? gmdate( 'Y-m-d H:i:s', strtotime( $row->time ) ) : gmdate( 'Y-m-d H:i:s' ); - array_push( - $args, - $measured_at, - $row->route ?? 'other', - $row->duration_ms ?? 0, - $row->cache->hits ?? 0, - $row->cache->misses ?? 0, - $row->db->query_count ?? 0, - $row->db->time_ms ?? 0, - wp_json_encode( $row->payload ?? array() ) - ); + $table = $wpdb->prefix . self::TABLE; + $columns = array( 'id', 'measured_at', 'route', 'duration_ms', 'cache_hits', 'cache_misses', 'db_query_count', 'db_time_ms', 'ip', 'user_agent', 'payload' ); + + nocache_headers(); + header( 'Content-Type: text/csv; charset=utf-8' ); + header( 'Content-Disposition: attachment; filename="cb-response-timer.csv"' ); + + $out = fopen( 'php://output', 'w' ); + fputcsv( $out, $columns ); + + $chunk_size = 1000; + $offset = 0; + do { + $rows = $wpdb->get_results( + $wpdb->prepare( + 'SELECT ' . implode( ', ', $columns ) . " FROM $table ORDER BY id ASC LIMIT %d OFFSET %d", + $chunk_size, + $offset + ), + ARRAY_A + ); + foreach ( $rows as $row ) { + fputcsv( $out, $row ); } + flush(); + $offset += $chunk_size; + } while ( count( $rows ) === $chunk_size ); - $sql = "INSERT INTO $table (measured_at, route, duration_ms, cache_hits, cache_misses, db_query_count, db_time_ms, payload) VALUES " - . implode( ', ', $placeholders ); - - if ( false === $wpdb->query( $wpdb->prepare( $sql, $args ) ) ) { - $ok = false; - } - } - - return $ok; + fclose( $out ); } } CB_Response_Timer::init(); -// Default sink: append one trimmed JSON line per measurement to the queue file, which -// a WP-Cron job (see flush_queue()) bulk-inserts into the SQL table. This keeps the -// per-request cost to a single small error_log() call - no synchronous DB write. -// Replace/remove this listener (or add your own) to send data elsewhere. +// Default sink: one direct, synchronous insert per measured request. See the file +// header for the tradeoff and how to swap this for a deferred/batched sink instead. add_action( 'cb_response_timer_measured', function ( array $data ) { - $row = array( - 'time' => $data['time'], - 'route' => $data['route'], - 'duration_ms' => $data['duration_ms'], - 'cache' => $data['cache'], - 'db' => array( - 'query_count' => $data['db']['query_count'] ?? 0, - 'time_ms' => $data['db']['time_ms'] ?? 0, + global $wpdb; + + $wpdb->insert( + $wpdb->prefix . CB_Response_Timer::TABLE, + array( + 'measured_at' => gmdate( 'Y-m-d H:i:s', strtotime( $data['time'] ) ), + 'route' => $data['route'], + 'duration_ms' => $data['duration_ms'], + 'cache_hits' => $data['cache']['hits'], + 'cache_misses' => $data['cache']['misses'], + 'db_query_count' => $data['db']['query_count'] ?? 0, + 'db_time_ms' => $data['db']['time_ms'] ?? 0, + 'ip' => $data['ip'], + 'user_agent' => $data['user_agent'], + 'payload' => wp_json_encode( $data['payload'] ), ), - 'payload' => $data['payload'], + array( '%s', '%s', '%f', '%d', '%d', '%d', '%f', '%s', '%s', '%s' ) ); - error_log( wp_json_encode( $row ) . "\n", 3, CB_Response_Timer::queue_file() ); } );