A Map for Monitoring PostgreSQL | PgDay San Francisco 2020 | Lukas Fittl

Understanding how your Postgres database works can be difficult. In this talk we’ll take a look at what can be measured to gain better insights into performance, reliability, and other essential functions of the database.

We’ll take a look at some of the advancements in Postgres monitoring over the years, such as being able to see the 95th percentile of the performance of particular queries, watching details of index creation, or tracking details of auto vacuum performance.

Lastly, we’ll also talk about what can not be measured using the standard Postgres statistics system, and how you may still get important details in such cases.

Transcript

1. A Map for Monitoring PostgreSQL #PgDaySF @LukasFittl
2. @LukasFittl
3. > 100 Metrics We Could Talk About > 100 Metrics We Could Talk About
5. Historic Metrics Current Activity Logs Tuning Actions
6. Query Workload
7. pg_stat_statements
8. 1. Install postgresql contrib package (if not installed) 2. Enable in postgresql.conf shared_preload_libraries = ‘pg_stat_statements’ 3. Restart your database 4. Create the extension CREATE EXTENSION pg_stat_statements; Enabling pg_stat_statements
9. Enabled By Default On Most Cloud Platforms
10. SELECT * FROM pg_stat_statements; userid | 10 dbid | 1397527 query | SELECT * FROM x WHERE calls | 5 total_time | 15.249 rows | 0 shared_blks_hit | 451 shared_blks_read | 41 shared_blks_dirtied | 26 shared_blks_written | 0 local_blks_hit | 0 pg_stat_statements
11. queryid | 1720234670 query | SELECT * FROM x WHERE y = ? calls | 567 total_time | 56063.6489 Avg Runtime = 98.87 ms
12. queryid | 1720234670 query | SELECT * FROM x WHERE y = ? calls | 567 total_time | 56063.6489 min_time | 0.0949 max_time | 902.545 mean_time | 98.877687654321 stddev_time | 203.19222186271 Mean Runtime = 98.87 ms 95th Percentile = 505.45 ms Max Runtime = 902.54 ms
13. LOG: duration: 4079.697 ms execute <unnamed>: SELECT * FROM x WHERE y = $1 LIMIT $2 DETAIL: parameters: $1 = 'long string', $2 = ‘1' Slow Queries log_min_duration_statement = 1000 ms
16. pg_stat_database xact_commit: Committed Transactions Per Second tup_*: Rows Updated/etc Per Second
17. Optimize Indices, Tune Postgres or Rewrite/Change Your Queries
18. Index Optimization
19. Important Questions For Indices Should I add an index? Do I need to REINDEX? Should I remove an index?
20. Should I add an index?
21. Should I add an index? Measuring Sequential Scans - Per Table pg_stat_all_tables seq_scan: # of Sequential Scans seq_tup_read: # of rows read by # Sequential Scans
22. SELECT relname, seq_scan + idx_scan, 100 * idx_scan / (seq_scan + idx_scan) FROM pg_stat_user_tables ORDER BY n_live_tup DESC Index Hit Rate Target: >= 95% on large, active tables
23. Should I add an index? Doesn't know about what indices get used / what plan is being executed. Doesn’t have enough details to EXPLAIN a query, because text is normalized. For a Specific Query? Can I use pg_stat_statements?
24. auto_explain logs the query plan for specific slow queries
27. “Discarded 49278 rows and returned none."
28. Create Indices When There Are Frequent Sequential Scans on Large Tables
29. # SELECT index_relid::regclass, phase, blocks_done, blocks_total FROM pg_stat_progress_create_index; index_relid | phase | blocks_done | blocks_total ------------------+--------------------------------+-------------+-------------- index_tab_pkey | building index: scanning table | 27719 | 44248 (1 row) pg_stat_progress_create_index Measure CREATE INDEX Progress Postgres 12+
30. Do I need to REINDEX?
31. Do I need to REINDEX? # SELECT relname, pg_table_size(oid) as index_size, 100-pgstatindex(relname).avg_leaf_density AS leaf_density FROM pg_class; relname | index_size | leaf_density -----------------------------------------------+------------+------------- test_inventory_id_idx | 376832 | 89.75 test_pkey | 376832 | 89.75 test_rental_date_inventory_id_customer_id_idx | 524288 | 89.27 Density of ~90% = Optimal for B-Tree pgstatindex(relname).avg_leaf_density
32. Do I need to REINDEX? # SELECT relname, pg_table_size(oid) as index_size, 100-pgstatindex(relname).avg_leaf_density AS leaf_density FROM pg_class; relname | index_size | leaf_density -----------------------------------------------+------------+------------- test_inventory_id_idx | 376832 | 89.75 test_pkey | 376832 | 89.75 test_rental_date_inventory_id_customer_id_idx | 524288 | 89.27 relname | index_size | leaf_density -----------------------------------------------+------------+------------- test_inventory_id_idx | 745472 | 45.52 test_pkey | 737280 | 46.02 test_rental_date_inventory_id_customer_id_idx | 925696 | 51.04 UPDATE 50% of Rows in Table: Index Size Doubled, 50% Bloated
33. When Indices Have Low Density REINDEX CONCURRENTLY for better performance
34. Should I remove an index? Measuring Index Scans - Per Index pg_stat_all_indices idx_scan: # of Index Scans
35. relname | n_live_tup | scans | index_hit_rate ---------------------------------+------------+------------+---------------- query_fingerprints | 347746140 | 513262821 | 99 queries | 346575911 | 22379253 | 99 schema_table_events | 100746488 | 1459 | 99 queries_schema_tables | 62194571 | 7754 | 99 log_lines | 46629937 | 2 | 0 issue_states | 31861134 | 3 | 0 schema_columns | 31849719 | 6688381553 | 99 query_overview_stats | 26029247 | 13831 | 99 schema_index_stats_2d_20170329 | 18274023 | 1592 | 99 schema_index_stats_2d_20170328 | 18164132 | 6917 | 99 snapshot_benchmarks | 13094945 | 2315069 | 99 schema_index_stats_60d_20170329 | 9818030 | 69 | 20 schema_index_stats_60d_20170328 | 9749146 | 110 | 30 schema_index_stats_60d_20170323 | 9709723 | 103 | 40 schema_index_stats_60d_20170327 | 9702565 | 103 | 33 schema_index_stats_60d_20170324 | 9672853 | 64 | 48 schema_index_stats_60d_20170322 | 9651125 | 141 | 46 schema_index_stats_60d_20170325 | 9647832 | 23 | 69 schema_index_stats_60d_20170326 | 9636532 | 39 | 53 schema_index_stats_60d_20170303 | 9538898 | 174 | 63 schema_index_stats_60d_20170321 | 9522712 | 170 | 49 schema_index_stats_60d_20170309 | 9492844 | 126 | 57 schema_index_stats_60d_20170304 | 9491850 | 64 | 82 schema_index_stats_60d_20170320 | 9486945 | 104 | 56 schema_index_stats_60d_20170319 | 9466378 | 47 | 74 Should I remove an index?
36. Remove Indices When There Are No Index Scans (But watch out for Replicas)
37. Unused Indices: - Make Writes Slower - Cause VACUUM to take longer
38. Index Scans Read From The Table Too!
40. pg_stat_all_tables - idx_tup_fetch pg_stat_all_indices - idx_tup_fetch Bitmap Heap Scan Index Scan Index-Only Scan
41. QUERY PLAN ————— Aggregate (cost=12.53..12.54 rows=1 width=0) (actual time=0.046..0.046 rows=1 loops=1) -> Index Only Scan using categories_pkey on categories (cost=0.00..12.49 rows=16 width=0) (actual time=0.018..0.038 rows=16 loops=1) Heap Fetches: 16 Total runtime: 0.108 ms (4 rows)
42. Query Tags
45. application: pganalyze controller: graphql action: graphql line: /app/graphql/organization_type.rb … graphql: getOrganizationDetails.logVolume24h request_id: 44bd562e-0f53-453f-831f-498e61ab6db5
46. github.com/basecamp/marginalia Automatic Query Tags For Ruby on Rails
47. When A Web Request Is Slow, Find The Slow Queries By Tagging Them In Your App
48. Connection Pooling
49. pg_stat_activity pid: process ID backend_type: “client backend” vs internal processes state: idle/active/idle in transaction state_change: time of state change query: current/last running query backend_start: process start time xact_start: TX start time query_start: query start time wait_event: what backend is waiting for (e.g. Lock, I/O, etc) …
50. # of Connections By State SELECT state, backend_type, COUNT(*) FROM pg_stat_activity GROUP BY 1, 2
51. High Number of Idle Connections => Add a connection pooler
52. work_mem Tuning
53. Out Of Memory vs Operations Spill To Disk
54. Temporary Files Written pg_stat_statements.temp_blks_written pg_stat_database.temp_bytes
55. Temporary Files Written (Per Query) log_temp_files = 0 Jan 20 09:18:58pm PST 28847 LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp28847.9", size 50658332 Jan 20 09:18:58pm PST 28847 STATEMENT: WITH servers AS ( SELECT …
56. When Sorts Spill To Disk, Increase work_mem However, be aware of OOMs!
57. When you get a lot of Out of Memory Errors Reduce work_mem!
58. Buffer Cache Hit Ratio
59. Data Directory Backend Buffer Cache
60. Cache Hit Ratio % pg_stat_statements.shared_blks_hit pg_stat_statements.shared_blks_read pg_stat_database.blks_hit pg_stat_database.blks_read
61. shared_blks_hit | 2447215 shared_blks_read | 55335 hit_rate = shared_blks_hit / (shared_blks_hit + shared_blks_read) 97.78% Cache Hit Rate Cache Hit Ratio % (Per Query)
62. SELECT sum(heap_blks_hit) / nullif(sum(heap_blks_hit + heap_blks_read),0) FROM pg_statio_user_tables Cache Hit Ratio % (Per Table/Index) SELECT sum(idx_blks_hit) / nullif(sum(idx_blks_hit + idx_blks_read),0) FROM pg_statio_user_indexes
63. pg_buffercache
64. Benchmark with higher shared_buffers
65. When Your Workload Doesn’t Fit In Memory Change Your Workload Or Add More Memory
66. Scaling Up 16GB RAM 64GB RAM
67. Scaling Out Shard in your application Use a sharded database (e.g. Citus)
68. Lock Contention
69. Locks Held/Waited On pg_locks pid: process ID (JOIN to pg_stat_activity.pid!) locktype: type of object being locked mode: locking type (e.g. AccessExclusive) granted: Lock Granted vs Being Waited For …
70. Locks Waited On pg_locks SELECT * FROM pg_locks WHERE NOT granted
71. Locks Held pg_locks SELECT locktype, mode, COUNT(*) FROM pg_locks WHERE granted GROUP BY 1, 2
72. Locks Held/Waited On log_lock_waits = on LOG: process 123 still waiting for ShareLock on transaction 12345678 after 1000.606 ms STATEMENT: SELECT table WHERE id = 1 FOR UPDATE; CONTEXT: while updating tuple (1,3) in relation “table” DETAIL: Process holding the lock: 456. Wait queue: 123.
73. Rewrite Transactions To Hold Locks Shorter To Reduce Lock Contention
74. Long Held Locks in Transactions Rails Counter Cache & Timestamps BEGIN SELECT 1 AS one FROM "post_votes" WHERE (…) LIMIT 1 SELECT "posts".* FROM "posts" WHERE "posts"."id" = $1 LIMIT 1 INSERT INTO "notifications" (…) VALUES (…) RETURNING "id" SELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT 1 UPDATE "users" SET "updated_at" = ? WHERE "users"."id" = ? INSERT INTO "post_votes" (…) VALUES (…) RETURNING "id" UPDATE "posts" SET "votes" = COALESCE("votes", 0) + 1 WHERE "posts"."id" = ? UPDATE "posts" SET "credible_post_votes_count" = … WHERE "posts"."id" = ? UPDATE "users" SET "updated_at" = ? WHERE "users"."id" = ? UPDATE "posts" SET "updated_at" = ? WHERE "posts"."id" = ? COMMIT
75. I/O Workload
76. System-Level I/O Metrics
77. pg_stat_statements.shared_blks_read pg_stat_database.blks_read pg_statio_all_tables.heap_blks_read pg_statio_all_indexes.idx_blks_read Data Read from Disk / OS Cache
78. Transactions Per Second pg_stat_database.xact_commit pg_stat_database.xact_rollback
79. Time spent reading/writing to disk track_io_timing = on
80. pg_stat_statements.blk_read_time pg_stat_statements.blk_write_time pg_stat_database.blk_read_time pg_stat_database.blk_write_time
81. Data Directory WAL WAL WAL Backend Buffer Cache Checkpointer BG Writer WAL
82. Checkpoints
83. Data Directory WAL WAL WAL Buffer Cache Checkpointer WAL Checkpoints Are Important For I/O Tuning
84. 16688 LOG: checkpoint starting: xlog xlog = WAL exceeded max_wal_size, checkpoint has to happen quickly time = checkpoint_timeout reached, checkpoint impact spread over time
85. Checkpoint Statistics pg_stat_bgwriter checkpoints_timed: # of scheduled checkpoints checkpoints_req: # of requested checkpoints 1. Time Between Checkpoints 2. % of Timed Checkpoints
86. Increase max_wal_size / Reduce checkpoint_timeout To Have More Timed Checkpoints (but be careful with recovery times)
87. Tune checkpoint_completion_target To Control I/O Impact of Timed Checkpoints (Often 0.9 is a good value, but depends on I/O Subsystem & Workload)
88. Background Writer
89. Data Directory Buffer Cache BG Writer Checkpointer Backend The Buffer Cache Has A Limited (Fixed) Size
90. Who wrote the Buffers? pg_stat_bgwriter BG Writer Checkpointer Backend buffers_checkpoint buffers_clean buffers_backend
91. Reduce bgwriter_delay & Raise bgwriter_lru_maxpages To Have More Buffers Written By The BG Writer
92. VACUUM Tuning
93. autovacuum => SELECT pid, query FROM pg_stat_activity WHERE query LIKE 'autovacuum: %'; 10469 | autovacuum: VACUUM ANALYZE public.schema_columns 12848 | autovacuum: VACUUM public.replication_follower_stats 28626 | autovacuum: VACUUM public.schema_index_stats | (to prevent wraparound) (3 rows) pg_stat_activity
94. autovacuum pg_stat_activity
95. autovacuum pg_stat_progress_vacuum relid: OID of the table phase: current VACUUM phase heap_blks_total: Heap Blocks Total heap_blks_scanned: Heap Blocks Scanned heap_blks_vacuumed: Heap Blocks Vacuumed …
96. autovacuum pg_stat_progress_vacuum
97. Reduce autovacuum_vacuum_cost_delay To Increase VACUUM Speed 80 MB/s 8 MB/s (20ms) (2ms) PG 12+ Older PG Default OS / Disk Reads
98. Use Table Partitioning For Append-Only + Delete Workloads (e.g. Timeseries)
99. Index Optimization Query Workload I/O Workload VACUUM Tuning Query Tags Lock Contention Background Writer Checkpoints Connection Pooling Buffer Cache Hit Ratio work_mem Tuning
100. @LukasFittl Thanks!