Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Investigate High RDS IOPS Use, Production Service Interruption #3465

Closed
rajadain opened this issue Jan 20, 2022 · 7 comments
Closed

Investigate High RDS IOPS Use, Production Service Interruption #3465

rajadain opened this issue Jan 20, 2022 · 7 comments
Assignees
Labels
bug PA DEP Funding Source: Pennsylvania Department of Environment Protection production

Comments

@rajadain
Copy link
Member

Since the deployment of 1.33, we're observing very high IOPS use of the RDS instance in production:

image

This is coincident with the site going down a lot:

image

And we see these messages in RDS:

image

Since this is happening after 1.33, it is highly likely it has something to do with the High Res Streams, which is a very large table introduced in that release. Also, the high IOPS use may be caused by a very high request rate, possibly caused by a large number of requests from the tiler.

It is possible that #3424 may help. Or batch-generation of tiles. Or transferring the tiles already made for staging to production. Or it may be something else entirely.

Investigate, and if possible, fix.

@rajadain rajadain self-assigned this Jan 20, 2022
@rajadain rajadain added GEN Funding Source: General PA DEP Funding Source: Pennsylvania Department of Environment Protection and removed GEN Funding Source: General labels Jan 20, 2022
@rajadain
Copy link
Member Author

To reduce the load of NHD hi res tile requests, I wrote this script:

import mercantile
import requests

for zoom in range(19):
    # bbox via https://gist.github.com/jsundram/1251783
    for tile in mercantile.tiles(-124.7844079,24.7433195,-66.9513812,49.3457868, zoom):
        url = f'http://33.33.34.35/nhd_streams_hr_v1/{zoom}/{tile.x}/{tile.y}.png'
        requests.get(url)
        print(url)

and then configured the tiler VM to point to (and have access to) the Production tile cache bucket (by configuring the MMW_TILECACHE_BUCKET environment variable, and adding credentials for mmw-prd as the default in /var/lib/mmw/.aws/credentials inside the tiler). Then I ran the script, which ran for 1d 29m 11s before I canceled it, with the final tile getting pre-cached being http://33.33.34.35/nhd_streams_hr_v1/15/7385/11671.png.

This means that all of zoom levels 0-14 for the entire CONUS have tiles pre-cached, and a partial cache for zoom 15 was also added. In most cases, zooming beyond level 15 doesn't result in as many stream reads, so the usage of the burst balance should be reduced.

The tile cache for this layer on production is currently ~30 GB in size:

image

@rajadain
Copy link
Member Author

rajadain commented Jan 24, 2022

It should be noted that even after this, we did see at least one instance of the Burst Balance going down to 0:

image

Looking at the logs, we see queries like this that take a long time (40+ seconds) to run: long-query.sql. This is for the Saco HUC-8:

image

The final output is:

lengthkm stream_order slopesum
2.7824697770005598 -9  
2777.4843327587737 1 174.8754808855135
1094.772595535565 2 33.29209307438515
760.0630001057596 3 9.209074630253456
284.7515363448878 4 1.5203409666684877
154.49228032277207 5 0.2766627177824275
83.42659346525942 6 0.07302188101247957
132.18007018219515 7 0.12741485218159052

Here's the query plan output of EXPLAIN ANALYZE:

Finalize GroupAggregate  (cost=353138.03..1375844.01 rows=11 width=18) (actual time=32163.046..55491.620 rows=8 loops=1)
  Group Key: nhdflowlinehr.stream_order
  ->  Gather Merge  (cost=353138.03..1375843.68 rows=22 width=18) (actual time=8306.590..55491.555 rows=23 loops=1)
        Workers Planned: 2
        Workers Launched: 2
        ->  Partial GroupAggregate  (cost=352138.01..1374841.12 rows=11 width=18) (actual time=3116.023..35914.559 rows=8 loops=3)
              Group Key: nhdflowlinehr.stream_order
              ->  Sort  (cost=352138.01..352163.51 rows=10200 width=1027) (actual time=554.512..561.702 rows=3290 loops=3)
                    Sort Key: nhdflowlinehr.stream_order
                    Sort Method: external merge  Disk: 2888kB
                    Worker 0:  Sort Method: quicksort  Memory: 1644kB
                    Worker 1:  Sort Method: external merge  Disk: 3768kB
                    ->  Parallel Bitmap Heap Scan on nhdflowlinehr  (cost=874.15..346856.38 rows=10200 width=1027) (actual time=350.164..545.643 rows=3290 loops=3)
                          Filter: st_intersects(geom, '01060000...F2274640'::geometry)
Planning Time: 62.047 ms
JIT:
  Functions: 30
  Options: Inlining true, Optimization true, Expressions true, Deforming true
  Timing: Generation 5.602 ms, Inlining 203.120 ms, Optimization 481.906 ms, Emission 324.416 ms, Total 1015.044 ms
Execution Time: 55494.523 ms

In this example, the inner query results in 9869 rows.

@rajadain
Copy link
Member Author

rajadain commented Feb 1, 2022

Seeing 100% CPU use in RDS:

image

Turning off Celery doesn't seem to help. Installed pg_stat_statements as recommended in https://aws.amazon.com/premiumsupport/knowledge-center/rds-aurora-postgresql-high-cpu/ to investigate queries.

Other, non-analyze queries that take a long time are tile requests and text searches:

SELECT round(total_exec_time*1000)/1000 AS total_time,query
FROM pg_stat_statements
ORDER BY total_time DESC limit 3;
  total_time   |                                                                                      query
---------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 272881959.314 | SELECT ST_AsBinary("geom") AS geom,"stream_order" FROM (SELECT geom, stream_order FROM nhdflowlinehr WHERE stream_order >= $1) as cdbq WHERE "geom" && ST_SetSRID($2::box3d, $3)
  125818041.86 | SELECT id, code, name, rank, ST_X(center) AS x, ST_Y(center) AS y                                                                                                               +
               |         FROM ((SELECT id, $1 AS code, name, $2 AS rank,                                                                                                                         +
               |             ST_Centroid(geom) as center                                                                                                                                         +
               |         FROM boundary_huc08                                                                                                                                                     +
               |         WHERE UPPER(name) LIKE UPPER($3)                                                                                                                                        +
               |         LIMIT $4) UNION ALL (SELECT id, $5 AS code, name, $6 AS rank,                                                                                                           +
               |             ST_Centroid(geom) as center                                                                                                                                         +
               |         FROM boundary_huc10                                                                                                                                                     +
               |         WHERE UPPER(name) LIKE UPPER($7)                                                                                                                                        +
               |         LIMIT $8) UNION ALL (SELECT id, $9 AS code, name, $10 AS rank,                                                                                                          +
               |             ST_Centroid(geom) as center                                                                                                                                         +
               |         FROM boundary_huc12                                                                                                                                                     +
               |         WHERE UPPER(name) LIKE UPPER($11)                                                                                                                                       +
               |         LIMIT $12)) AS subquery                                                                                                                                                 +
               |         ORDER BY rank DESC, name
  96767941.593 | WITH stream_intersection AS (                                                                                                                                                   +
               |             SELECT ST_Length(ST_Transform(                                                                                                                                      +
               |                       ST_Intersection(geom,                                                                                                                                     +
               |                                       ST_SetSRID(ST_GeomFromGeoJSON($1),                                                                                                        +
               |                                                  $2)),                                                                                                                          +
               |                       $3)) AS lengthm,                                                                                                                                          +
               |                    stream_order,                                                                                                                                                +
               |                    slope                                                                                                                                                        +
               |             FROM nhdflowlinehr                                                                                                                                                  +
               |             WHERE ST_Intersects(geom,                                                                                                                                           +
               |                                 ST_SetSRID(ST_GeomFromGeoJSON($4), $5)))                                                                                                        +
               |                                                                                                                                                                                 +
               |         SELECT SUM(lengthm) / $6 AS lengthkm,                                                                                                                                   +
               |                stream_order,                                                                                                                                                    +
               |                SUM(lengthm * NULLIF(slope, $7)) / $8 AS slopesum                                                                                                                +
               |         FROM stream_intersection                                                                                                                                                +
               |         GROUP BY stream_order
(3 rows)

@rajadain
Copy link
Member Author

rajadain commented Feb 1, 2022

This does make it look like the stream intersections are the ones taking the longest time:

SELECT pid, age(clock_timestamp(), query_start), usename, query, state
FROM pg_stat_activity
ORDER BY query_start DESC;

image

@rajadain
Copy link
Member Author

rajadain commented Feb 1, 2022

Since CPU usage has been high for more than an hour now, I'm going to try and kill some of those queries.

@rajadain
Copy link
Member Author

rajadain commented Feb 1, 2022

Ah those queries just finished on their own. And we see a corresponding drop in CPU use:

image

@rajadain
Copy link
Member Author

rajadain commented Feb 2, 2022

Anthony mentioned that upping the size or type of the RDS instance may help in the short term. We should keep that in mind if our optimizations do not help.

@jwalgran jwalgran closed this as completed Feb 3, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug PA DEP Funding Source: Pennsylvania Department of Environment Protection production
Projects
None yet
Development

No branches or pull requests

2 participants