Query warnings in application logs

Enterprise Search writes a warning to an environment’s application logs when an Elasticsearch query is slow or has no limiting search condition. Each warning is written as a pair of log lines that both start with VIP_SEARCH_QUERY_WARNING: a machine-readable line of fields, and a human-readable line that describes the request and the location in the site’s code that issued the query.

Warnings can be reviewed in Runtime Logs in the VIP Dashboard or with Runtime Logs with VIP-CLI. Warnings from web requests appear in Application Logs. Warnings from WP-CLI commands and cron events appear in Batch Logs.

Reading a warning

A slow query issued by a theme produces a pair of log lines similar to the following (log timestamps, prefixes and suffixes are omitted):

VIP_SEARCH_QUERY_WARNING v=1 warning_id=VSQ-3F9A0C12 types=slow_query request_ms=436 request_limit_ms=200 engine_ms=412 requested=10 returned=10 total_hits=2381 query_scope=bounded url="https://example.com/?s=climate" deduplicated=true dedupe_window_s=300

VIP_SEARCH_QUERY_WARNING: A request to https://example.com/?s=climate triggered a slow VIP Search query originating from wp-content/themes/example-theme/search.php:42. Elasticsearch took 412 ms to execute the query, above the configured warning threshold of 200 ms. Review how this query is constructed and whether it runs more often than necessary. Similar occurrences are deduplicated for five minutes, so this warning may represent repeated requests. Warning ID: VSQ-3F9A0C12.

A log search for VIP_SEARCH_QUERY_WARNING returns both lines. To return only the machine-readable lines, search for VIP_SEARCH_QUERY_WARNING v=1. The two lines in a pair share the same warning_id.

In the logs, each line is followed by in wp-content/mu-plugins/search/includes/classes/class-query-warning.php on line N, the requested URL and a backtrace. That file is the Enterprise Search code that writes the warning, not the code that issued the query. The location in the site’s code appears only in the text of the human-readable line, after “originating from”. The location is reported only for code in wp-content/client-mu-plugins/, wp-content/plugins/ or wp-content/themes/. Code under any vendor/ directory and under wp-content/mu-plugins/ is skipped, so a query issued entirely from vendored code reports no location. When no location can be determined, the human-readable line reads “during this request” in place of “originating from” and a file location.

Identifying slow queries

A query is classified as slow_query in either of these cases:

• Elasticsearch execution time: engine_ms is greater than request_limit_ms (default 200). engine_ms is the time Elasticsearch reports for executing the query (the took value in the response), including any time the query waited in an Elasticsearch search queue.
• Large payload: request_ms is greater than request_limit_ms, and the request body and the response together are at least 1 MiB. The human-readable line states the size of the data transferred and the Elasticsearch execution time, and recommends requesting fewer results or only the fields that are needed. The 1 MiB limit is fixed and cannot be changed with a filter.

request_ms is the wall-clock time measured in PHP around the HTTP request to Elasticsearch. The difference between request_ms and engine_ms is time spent outside Elasticsearch on connection setup and TLS negotiation, network and proxy hops, and serializing and transferring the response. request_ms does not include the time spent decoding the response in PHP.

A request with a high request_ms, an engine_ms within the threshold and a payload under 1 MiB does not produce a slow_query warning, because that time is usually spent outside Elasticsearch. If the response does not include a took value, no slow_query warning is emitted.

The machine-readable line does not include the payload size. A slow_query line with an engine_ms that is within request_limit_ms was triggered by the large payload rule.

Log line fields

The machine-readable line contains the following fields, in this order:

Unbounded queries

A query is unbounded when the request body has no query key, or when the query contains no condition that limits the results. A match_all query, or a bool query whose filter, must, must_not and should clauses are all empty or contain only match_all, is unbounded. Only the query section of the request body is considered, so conditions in post_filter do not make a query bounded. An unbounded query can search the entire index and becomes more expensive as the index grows.

To resolve an unbounded_query warning, add an appropriate search term or filter condition to the query section of the request.

Deduplication and volume

Warnings are throttled in two ways:

• Deduplication: After a warning is emitted for a query family and combination of types, no further warning is emitted for that same combination until the deduplication window (default 300 seconds) has passed. A single warning can therefore represent many requests.
• Budget: Within each window, at most 5 warning pairs (by default) are emitted for each application and blog. On a multisite network, each network site has its own budget, so the total number of warnings in the logs can be up to the budget multiplied by the number of network sites that issue Elasticsearch queries.

When warnings are not emitted

Warnings are only emitted when all of the following are true:

• The site uses a persistent object cache. Deduplication and budgets rely on the object cache, so warnings are suppressed entirely without one. The VIP Local Development Environment includes a Memcached object cache, so warnings can be reproduced there. A local environment without a persistent object cache does not emit warnings.
• The request is a search query sent to an Elasticsearch _search endpoint. Indexing requests and other non-search requests do not produce warnings.
• Elasticsearch returned a successful response. Failed requests (an error or an HTTP status code of 400 or higher) do not produce warnings.
• The response was not served from the Enterprise Search query cache.

Adjusting the defaults

The threshold, deduplication window and budget can be changed with filters. A filter value outside the accepted range is ignored and the default is used.

vip_search_slow_query_threshold_ms applies to the Elasticsearch execution time (engine_ms), and to request_ms for requests that transfer at least 1 MiB.

In this example, the slow query threshold is raised to 300 ms, the deduplication window is extended to 10 minutes, and the budget is raised to 10 warning pairs per application and blog:

add_filter( 'vip_search_slow_query_threshold_ms', static fn(): int => 300 );
add_filter( 'vip_search_query_warning_dedupe_window_s', static fn(): int => 600 );
add_filter( 'vip_search_query_warning_budget', static fn(): int => 10 );

Raising the threshold reduces the number of slow_query warnings but does not change how long queries take. It is recommended to investigate the queries that trigger warnings with Enterprise Search Dev Tools before changing the defaults.