## Objective Capture baseline Elasticsearch response times so we have concrete numbers to compare against when we migrate to OpenSearch. Add structured performance logging around all ES HTTP calls. --- ## Problem **Note:** MR !1172 already adds structured logging for ES failures and slow query detection. This issue extends that pattern to capture timing on ALL queries, not just failures, and centralizes the HTTP calls into a single wrapper method. We're planning to migrate from Elasticsearch to OpenSearch. To measure whether OpenSearch performs better, worse, or the same, we need a **baseline** of how Elasticsearch performs right now. Currently there is zero performance logging around ES queries. We don't know how long searches take, which queries are slow, or where the time is spent. ## Goal Add timing and structured logging around all Elasticsearch HTTP calls so we can: 1. Capture baseline response times before migration 2. Compare the same queries against OpenSearch after migration 3. Identify slow queries that might need optimization --- ## Where the ES HTTP calls happen There are only 3 places in the codebase that make HTTP calls to Elasticsearch: | Location | Method | Line | What it does | |----------|--------|------|--------------| | `ElasticSearchQuery.php` | `all()` | 250-252 | `POST /{index}/_search` - main search query | | `ElasticSearchQuery.php` | `countAll()` | 751-753 | `POST /{index}/_count` - count query | | `Admin/SearchController.php` | `view()` | 22-23 | `POST /artifacts/_search` - admin doc lookup | All three use `Cake\Http\Client` to make raw HTTP POST calls. No SDK, no abstraction layer. ## Approach ### Option 1: Direct timing in ElasticSearchQuery (simplest) Wrap the HTTP calls with `microtime(true)` before and after: ```php // In all() method, around lines 250-252: $start = microtime(true); $request = new Client(); $response = $request->post($url . "/$index/_search", $query, ['type' => 'json']); $duration = (microtime(true) - $start) * 1000; // milliseconds Log::info('es_search', [ 'index' => $index, 'endpoint' => '_search', 'duration_ms' => round($duration, 2), 'query_size' => strlen($query), 'hits' => $response['hits']['total']['value'] ?? 0, ]); // Only log slow queries in detail (avoid log noise) if ($duration > 500) { Log::warning('es_slow_query', [ 'duration_ms' => round($duration, 2), 'query' => $query, ]); } ``` Same pattern for `countAll()` and `Admin/SearchController::view()`. **Why this is enough:** There are only 3 call sites. We don't need a framework-level solution for 3 places. ### Option 2: AOP-style approach PHP does have AOP libraries (`goaop/framework`) but the project doesn't use any, and adding one for 3 call sites is overkill. The PHP equivalent of AOP for this case is either: - **A wrapper method** that all ES calls go through: ```php private function executeQuery(string $endpoint, string $body): array { $start = microtime(true); $client = new Client(); $response = $client->post($this->getUrl() . $endpoint, $body, ['type' => 'json']); $duration = (microtime(true) - $start) * 1000; $this->logQuery($endpoint, $duration, $body, $response->getJson()); return $response->getJson(); } ``` Then `all()` and `countAll()` both call `$this->executeQuery()` instead of `new Client()` directly. This centralizes timing and logging in one place. - **CakePHP middleware** could intercept HTTP responses, but ES calls are outbound (PHP to ES), not inbound (browser to PHP). Middleware doesn't help here. **Recommendation:** Option 2 with the wrapper method. It centralizes the HTTP call, timing, and logging in one method. Both `all()` and `countAll()` use it. Clean and gives us the AOP-like separation, without adding a library. ### What to log | Field | Why | |-------|-----| | `index` | Which index was queried (artifacts, publications, etc.) | | `endpoint` | `_search` or `_count` | | `duration_ms` | Response time in milliseconds | | `query_size` | Size of the query JSON (proxy for complexity) | | `hit_count` | Number of results returned | | `status` | success or error | | `slow` | true if duration \> configurable threshold (e.g. 500ms) | For slow queries (above threshold), also log the full query body for debugging. ### Where logs go CakePHP's built-in `Log` class writes to `app/cake/logs/`. The structured fields make it easy to parse later (grep, export to CSV, etc.) for the ES vs OpenSearch comparison. --- ## How this helps the migration Once this is in place: 1. **Before migration:** Collect a week of ES response times under normal usage 2. **After OpenSearch swap:** Same logging, same queries, but hitting OpenSearch 3. **Compare:** Side-by-side timing data for the same query patterns We could even do real-time comparison when both engines are running with the `?engine=opensearch` parameter. Same query hits both, both log their timing, we compare. --- ## Estimate | | Time | |--|------| | Development | \~2-3 days. Create the wrapper method, refactor the 3 call sites to use it, add structured logging with configurable slow-query threshold. | | Testing | \~1 day. Verify logs are written for search and count queries, verify slow query threshold works, check that Admin/SearchController logs correctly, confirm no regressions in search behavior. | | **Total** | **\~3-4 days** | --- ## Acceptance Criteria - [ ] All ES HTTP calls go through a single wrapper method with timing - [ ] Every query logs: index, endpoint, duration_ms, hit_count, status - [ ] Slow queries (above configurable threshold) log the full query body - [ ] Logging works for both `_search` and `_count` endpoints - [ ] `Admin/SearchController::view()` also has timing (currently bypasses ElasticSearchQuery) - [ ] Log format is structured (key-value) for easy parsing and comparison