<!-- Triage of infradev Issues is desired to occur asynchronously. For maximum efficiency, please ensure the following, so that your infradev issues can gain maximum traction. https://about.gitlab.com/handbook/engineering/workflow/#a-guide-to-creating-effective-infradev-issues --> ## Summary <!-- Clearly state the scope of the problem, and how it affects GitLab.com --> The gitlab~3713903 incident https://gitlab.com/gitlab-com/gl-infra/production/-/issues/5952 was caused by a frequently run index scan becoming significantly less efficient. This was induced by a sidekiq job performing background data changes on historical data in an order that correlates with a frequently scanned index. The specific details of this data change allow for a work-around -- changing the order of the data changes so they no longer correlate with this particular index's order. But to help prevent future incidents with similar bulk data changes, we ideally want a more generic protection. This issue aims to consider providing a mechanism for detecting if index scan efficiency is being degraded in this way, and pause the data change until the indexes are back in a healthy state. More specifically, if a large number of dead index items accumulate at the start or end of an indexed column's range of live values, this adds overhead to the index scan, measurable as a large value for the "Heap Fetches" counter in the `EXPLAIN ANALYZE` output. This overhead only occurs when querying a standby db (i.e. a replica db, not the primary db or a dblabs clone). Index scans other than searching for a column's min/max value can also be affected by this pathology, but the min/max case is definitely an important and common one. So we are starting with just that. ### Brief intro to the pathology The triggering condition that made this index scan inefficient was a relatively slow background data migration that happened to be choosing which rows to delete by walking the table's most frequently used index. This caused a dense accumulation of dead index items at the low end of the first indexed column's range of values. Meanwhile, on the replica dbs, many concurrent readers were using that index. Each index scan that traversed that range of index items pointing to dead row-versions had to independently perform row-visibility checks for each visited dead item. As the incident progressed, there were as many as 600K of these dead index items that had to be traversed before the index scan found a single live row. That overhead gets repeated during every index scan until the next vacuum cleans up these dead tuples and their index items. This already significant overhead per index scan was compounded by the fact that many of these index scans were running concurrently. Performing the row visibility check requires pinning the shared buffers containing the relevant parts of the table's visibility map, and that frequent pinning/unpinning results in spinlock and lwlock contention. This is where most of the CPU time was being spent. Collectively this index scan inefficiency starved other queries for resources (mainly CPU time and the relevant lwlocks). This lead to overall slowness and saturation for the database connection pool, which emerged as the usual cascade of user-facing slowness and errors. Preventing the index inefficiency from building to a critical point can prevent this causal chain. That approach is what we want to explore in this issue. ### References There are lots of insightful discussion threads in https://gitlab.com/gitlab-org/gitlab/-/issues/346427 and https://gitlab.com/gitlab-org/gitlab/-/issues/346940 and https://gitlab.com/gitlab-com/gl-infra/production/-/issues/5952. The following short list focuses on summaries of the findings, as a primer. * https://gitlab.com/gitlab-com/gl-infra/production/-/issues/5952#note_748517574 - Concise walk-through of the incident pathology. **Recommended to start here.** * https://gitlab.com/gitlab-com/gl-infra/production/-/issues/5952#note_751163463 - This is a direct follow-up to the above walk-through. * https://gitlab.com/gitlab-com/gl-infra/production/-/issues/5952#note_743067011 - Earlier walk-through, focused on the details of why the planner itself was running an index scan. * https://gitlab.com/gitlab-org/gitlab/-/issues/346940#note_752257442 - Illustration that the overall number of dead tuples is a poor indicator of the risk of this regression. Instead, we need to detect dense accumulations of dead tuples. * https://gitlab.com/gitlab-org/gitlab/-/issues/346427#note_746784163 - Marking index tuples as dead only occurs on the writable primary db, not read-only replicas ## Impact <!-- - Quantify the effect of the problem to help ensure that correct prioritization occurs. - Include costs to availability. The Incident Budget Explorer dashboard can help here. - Include the number of times alerts have fired owing to the problem, how much time was spent dealing with the problem, and how many people were involved. - Link to affected incidents, and cross-reference them as related issues. - Include screenshots of visualization from Grafana or Kibana. - Always include a permalink to the source of the screenshot so that others can investigate further. --> During the incident: The database service [apdex dropped below SLO for several hours](https://gitlab.com/gitlab-com/gl-infra/production/-/issues/5952#note_741011427): [Dashboard link](https://dashboards.gitlab.net/d/patroni-main/patroni-overview?orgId=1&from=1637586945000&to=1637602206000&viewPanel=3543037459)  That performance regression put enough backpressure on the rails clients that the db request rate dropped well below its norm: [Dashboard link](https://dashboards.gitlab.net/d/patroni-main/patroni-overview?orgId=1&from=1637586945000&to=1637602206000&viewPanel=1598389883)  [Query duration](https://gitlab.com/gitlab-com/gl-infra/production/-/issues/5952#note_741125194) and [replication lag](https://gitlab.com/gitlab-com/gl-infra/production/-/issues/5952#note_741157586) show the same pattern. Crucially, the batches of deletes run by `ExpireBuildArtifactWorker` also correlate with the regression, [as documented in more of this thread](https://gitlab.com/gitlab-com/gl-infra/production/-/issues/5952#note_741191453). All of the streaming replica dbs had a [large increase in userspace CPU time](https://gitlab.com/gitlab-com/gl-infra/production/-/issues/5952#note_740170412):  A [whole-host CPU profile of an example replica dbs](https://gitlab.com/gitlab-com/gl-infra/production/-/issues/5952#note_740316087) showed over 70% of postgres CPU time was spent in the query planner (not the query executor). Profiles like this were instrumental in post-incident analysis discussions such as [here](https://gitlab.com/gitlab-org/gitlab/-/issues/346427#note_745403561) and [here](https://gitlab.com/gitlab-org/gitlab/-/issues/346427#note_745712901).  ## Recommendation <!-- Provide a clear, unambiguous, self-contained solution to the problem. --> To limit the accumulation of overhead for index scans, we can make the data change job start by checking whether or not any of the indexes have to traverse many dead tuples to return the min/max column value. If that counter exceeds a configured threshold (e.g. 10K heap fetches), then the data change should defer its current batch of work. Vacuum will eventually clean up those dead tuples, at which point the pre-flight check will start to pass again. This check must be run on a replica db, not the primary db. This is crucial, because the primary db will almost never exhibit this pathology, but the replica dbs are all susceptible to it. Concretely we can start with just checking the min and max values of the first column of each full btree index on the table targeted by the data change. Running a query like the following will return a `Heap Fetch` count. If that count is large (e.g. 10K), this is the warning sign to pause the data change until vacuum cleans up the dead tuple references that have accumulated at one end of that index. ``` explain ( analyze ) select min(job_id), max(job_id) from ci_job_artifacts ; QUERY PLAN -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Result (cost=1.21..1.22 rows=1 width=16) (actual time=0.047..0.048 rows=1 loops=1) InitPlan 1 (returns $0) -> Limit (cost=0.58..0.60 rows=1 width=8) (actual time=0.020..0.020 rows=1 loops=1) -> Index Only Scan using index_ci_job_artifacts_on_job_id_and_file_type on ci_job_artifacts (cost=0.58..38998942.87 rows=1452802176 width=8) (actual time=0.019..0.019 rows=1 loops=1) Index Cond: (job_id IS NOT NULL) Heap Fetches: 0 InitPlan 2 (returns $1) -> Limit (cost=0.58..0.60 rows=1 width=8) (actual time=0.025..0.025 rows=1 loops=1) -> Index Only Scan Backward using index_ci_job_artifacts_on_job_id_and_file_type on ci_job_artifacts ci_job_artifacts_1 (cost=0.58..38998942.87 rows=1452802176 width=8) (actual time=0.025..0.025 rows=1 loops=1) Index Cond: (job_id IS NOT NULL) Heap Fetches: 1 Planning Time: 0.148 ms Execution Time: 0.061 ms (13 rows) ``` Note: For easier parsing, we can make that `EXPLAIN ( ANALYZE, FORMAT JSON ) ...`, but for illustration purposes, the default text output format is easier to read. The attached notes demonstrate how to find the list of columns to be checked: [2021-12-07_find_1st_column_of_each_btree_index_on_a_table.txt](/uploads/9faba8515a6c49f080df7fe335e009f9/2021-12-07_find_1st_column_of_each_btree_index_on_a_table.txt) ## Verification <!-- Provide a method for validating that the original issue still exists. Having a way of checking validity can save on a great deal of back-and-forth discussion between Infradev Triage participants including Engineering Managers, Directors and Product Managers and make space for other non-resolved issues to get scheduled sooner. Ideally, provide a link to a Thanos query or an ELK query and clear instructions on how to interpret the results to determine whether the problem is still occurring. --> The pathology we want to avoid is having index scans on the target table have to traverse many dead tuples before finding their intended live tuples. If that starts to happen, we want the data change to pause. The mechanism proposed above attempts to directly measure that overhead. The following Prometheus query compliments that direct measurement by looking at the overall workload for each index on the target table. If many dead tuples accumulate at any frequently scanned range of the index, this will show up as a sharp increase in the mean number of heap fetches per index scan. PromQL: ``` sum by (relname, indexrelname, fqdn) (rate(pg_stat_user_indexes_idx_tup_read{env="gprd", relname="ci_job_artifacts"}[1m]) and on (env, fqdn) (pg_replication_is_replica == 1)) / ( sum by (relname, indexrelname, fqdn) (rate(pg_stat_user_indexes_idx_scan{env="gprd", relname="ci_job_artifacts"}[1m]) and on (env, fqdn) (pg_replication_is_replica == 1)) > 1) ``` [Thanos query](https://thanos.gitlab.net/graph?g0.expr=sum%20by%20(relname%2C%20indexrelname%2C%20fqdn)%20(rate(pg_stat_user_indexes_idx_tup_read%7Benv%3D%22gprd%22%2C%20relname%3D%22ci_job_artifacts%22%7D%5B1m%5D)%20and%20on%20(env%2C%20fqdn)%20(pg_replication_is_replica%20%3D%3D%201))%0A%2F%0A(%20sum%20by%20(relname%2C%20indexrelname%2C%20fqdn)%20(rate(pg_stat_user_indexes_idx_scan%7Benv%3D%22gprd%22%2C%20relname%3D%22ci_job_artifacts%22%7D%5B1m%5D)%20and%20on%20(env%2C%20fqdn)%20(pg_replication_is_replica%20%3D%3D%201))%20%3E%201)&g0.tab=0&g0.stacked=0&g0.range_input=6h&g0.max_source_resolution=0s&g0.deduplicate=1&g0.partial_response=0&g0.store_matches=%5B%5D&g0.end_input=2021-11-22%2018%3A00%3A00&g0.moment_input=2021-11-22%2018%3A00%3A00&g0.step_input=60)  For context, each index's normal ratio of heap fetches per scan depends on the workload characteristics, so there is not a fixed value for that ratio that is "good" or "bad". Instead, a sharp and sustained increase of that ratio is highly suggestive of this pathology -- dead tuples accumulated in a frequently scanned portion of the index (possibly at the min or max value, or possibly elsewhere), and vacuum has not yet cleaned them up. So, if the increase in that ratio correlates with the data change and it does not disappear after a couple minutes, that is likely to indicate a regression. Pausing the data change (via the proposed mechanism or any other mechanism) should stop the increase in that ratio, but only vacuum will reduce that ratio back to where it started. Note: A change in workload or query plan for a frequently run query can potentially also cause a volatile change in the ratio of heap fetches per index scan, but that is unlikely to be both sustained over time and correlated with the data change. For more details on the above example, see: https://gitlab.com/gitlab-com/gl-infra/production/-/issues/5952#note_757151499 <!-- Workflow and other relevant labels See also: - https://about.gitlab.com/handbook/engineering/quality/issue-triage/#availability - https://about.gitlab.com/handbook/product/categories/ - https://gitlab.com/gitlab-com/www-gitlab-com/blob/master/data/stages.yml -->