Мігруємо наш Backend API з DynamoDB на AWS RDS PostgreSQL, і кілька раз RDS падав.

Власне, враховуючи те, що ми задля економії взяли db.t3.small з двома vCPU і двома гігабайтами пам’яті – то доволі очікувано, але стало цікаво чому ж саме все падало.

Через кілька днів почав цю тему дебажити, і хоча причини поки не знайшли – але з’явилась непогана чернетка того, як можна поінвестигейтити проблеми з перформансом в RDS PostgreSQL.

Пост – не звичайний “як зробити”, а скоріше просто записати для себе – куди і на що наступного разу дивитись, і які зміни в моніторингу можна зробити, аби наступного разу побачити проблему раніше, ніж вона стане критичною.

The Issue

Отже, як все починалось.

Backend API запущений в AWS Elastic Kubernetes Service, і в якийсь момент посипались алерти по 503 помилкам:

З’явились алерти на використання Swap на Production RDS:

В Sentry з’явились помилки про проблеми з підключенням до серверу баз даних:

Починаємо перевіряти моніторинг RDS, і бачимо, що в якийсь момент Freeable Memory впала до 50 мегабайт:

Коли сервер впав, ми його перезапустили – але проблема тут же виникла знов.

Тому вирішили поки що переїхати на db.m5.large – на графіку видно, як вільна пам’ять стала 7.25 GB.

Ну і давайте глянемо, що цікавого ми можемо побачити з всієї цієї історії.

Set “Application Name”

В Performance Insights можна відобразити статистику по окремим Applications:

У нас цього зроблено не було, але, думаю, є сенс налаштувати окремі Applications для підключень експортерів моніторингу та з сервісів Backend API.

Є кілька варіантів, як це зробити – або передавати параметрами в connection strings:

"postgresql://user:password@host:port/database?application_name=MyApp"

Або виконувати прямо з коду при ініціалізації підключень:

with engine.connect() as conn: 
  conn.execute("SET application_name TO 'MyApp'")

Другий варіант виглядає привабливішим, бо connection string до Backend API передається змінною оточення з AWS Secret Store, і робити окремий URL тільки заради одного параметру application_name для кожного сервісу API виглядає трохи костильно.

Тому краще в кожній апці бекенду задавати власний параметр при створенні підключення.

Корисні PostgreSQL Extentions

По ходу діла додавав кілька PostgreSQL Extentions, які прям дуже корисні в таких справах для моніторингу і інвестігейту.

Включення pg_stat_statements

Теж на жаль не було включено на момент проблеми, але в цілому прямо must have штука.

Документація – pg_stat_statements — track statistics of SQL planning and execution та SQL statistics for RDS PostgreSQL.

В RDS PostgreSQL версій 11 і вище бібліотека включена по дефолту, тому все, що треба зробити – це створити EXTENSION, див. CREATE EXTENSION.

Перевіряємо, чи є extention зараз:

dev_kraken_db=> SELECT * 
FROM pg_available_extensions 
WHERE 
    name = 'pg_stat_statements' and 
    installed_version is not null;
 name | default_version | installed_version | comment 
------+-----------------+-------------------+---------
(0 rows)

(0 rows) – ок, пусто.

Створюємо його:

dev_kraken_db=> CREATE EXTENSION pg_stat_statements;
CREATE EXTENSION

Перевіряємо ще раз:

dev_kraken_db=> SELECT *                            
FROM pg_available_extensions 
WHERE 
    name = 'pg_stat_statements' and 
    installed_version is not null;
        name        | default_version | installed_version |                                comment                                 
--------------------+-----------------+-------------------+------------------------------------------------------------------------
 pg_stat_statements | 1.10            | 1.10              | track planning and execution statistics of all SQL statements executed
(1 row)

І спробуємо отримати якусь інформацію з pg_stat_statements і таким запитом:

SELECT query 
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 10;

Далі в цьому пості будуть ще приклади того, яку інформацію з pg_stat_statements можемо отримати.

Включення pg_stat_activity

Окрім pg_stat_statements, корисну інформацію по поточній активності можна отримати з pg_stat_activity, включена по дефолту.

Обидві являють собою views, хоча в різних схемах бази:

dev_kraken_db=> \dv *.pg_stat_(statements|activity)
                 List of relations
   Schema   |        Name        | Type |  Owner   
------------+--------------------+------+----------
 pg_catalog | pg_stat_activity   | view | rdsadmin
 public     | pg_stat_statements | view | rdsadmi

Різниця між pg_stat_activity та pg_stat_statements у PostgreSQL

Обидві допомагають аналізувати запити, але pg_stat_activity – це поточна активність, а pg_stat_statements – “історична”:

CREATE EXTENSION IF NOT EXISTS pg_buffercache;

Далі теж подивимось на цікаві запити для перевірки стану пам’яті в PostgreSQL.

Окей. Повертаємось на нашої проблеми.

CPU utilization та DBLoad

Перше, на що звернули увагу – це навантаження на CPU.

В Performance Isights це виглядало так:

А в Monitoring самого інстансу – так:

DBLoad (Database Load)

Документація по DBLoad в CloudWatch – тут>>>.

У PostgreSQL кожна клієнтська сесія створює окремий процес (backend process).

DBLoad – це метрика AWS RDS PostgreSQL, яка відображає значення активних сесій, які виконуються або очікують на ресурси – CPU, disk I/O, Locks. Не враховуються сесії в статусі idle, але враховуються сесії в статусі active, idle in transaction або waiting.

DBLoad схожий на Load Average у Linux, але враховує тільки PostgreSQL-сесії:

• У Linux Load Average показує кількість процесів на Linux-сервері, які або використовують CPU, або чекають на нього чи на I/O
• У RDS DBLoad відображає середню кількість активних сесій на сервері PostgreSQL, які або працюють, або чекають ресурси

Тобто в ідеалі кожен backend-процес, який виконує запити від підключеного клієнта, має мати доступ до “власного” ядра vCPU, отже DBLoad має бути ~= кількості vCPU або менше.

Якщо ж DBLoad значно перевищує кількість доступних ядер – то це показник, що система перевантажена і процеси (сесії) очікують в черзі на CPU або інші ресурси.

DBLoad включає в себе ще два показники:

• DBLoadCPU: сесії, які знаходяться саме в очікуванні вільного CPU
• DBLoadNonCPU: сесії, які знаходяться в очікуванні диску, database table locks, networking, etc

Перевірити сесії, які будуть вважатись активними і будуть включені в DBLoad можемо так:

SELECT pid, usename, state, wait_event, backend_type, query
FROM pg_stat_activity
WHERE state != 'idle'

Нормальне значення для DBLoad

DBLoad має бути приблизно рівним або нижче кількості доступних vCPU.

DBLoad vs CPU Utilization

Чому на першому скріні ми бачимо “100%”, а на другому просто кількість в 17.5?

• CPU Utilization: відсоток використання CPU від загальної доступної потужності
• DBLoad: кількість активних сесій

Враховуючи, що на сервері в той момент було 2 доступних vCPU, і при цьому 17 активних сесій – то маємо 100% використання процесорного часу.

Окремо варто завернути увагу на DBLoadRelativeToNumVCPUs – це DBLoad поділений на кількість доступних vCPU, тобто середнє навантаження на кожне ядро CPU.

DBLoadCPU (Database Load on CPU Wait)

DBLoadCPU відображає кількість активних сесій, які очікують на CPU, тобто процеси, які не можуть виконуватись, бо всі доступні CPU зайняті.

В ідеалі має бути близько нуля – тобто, на сервері не має бути процесів, які очікують CPU.

Якщо DBLoadCPU має значення близько DBLoad, то RDS не встигає обробити всі запити – не вистачає CPU time, і вони стають в чергу.

Перевірити можемо тим самим запитом з pg_stat_activity, як вище: якщо в wait_event = "CPU", то це процеси, які чекають вільного CPU.

Нормальне значення для DBLoadCPU

DBLoadCPU має бути якнайнижчим (близьким до нуля).

Якщо DBLoadCPU майже дорівнює DBLoad, то:

• основне навантаження саме на процесор
• сесії не блокуються через Table Locks або повільний диск (I/O), а просто чекають CPU

DBLoadNonCPU (Database Load on Non-CPU)

DBLoadNonCPU, власне, відображає інформацію очікування ресурсів, не пов’язаних з CPU.

Це можуть бути:

• блокування (Locks): очікування доступу до таблиці або рядка
• I/O очікування (I/O Wait): повільне читання або запис через дискові обмеження
• Network Wait: затримки через мережеві операції (наприклад, реплікація або передача даних)
• Other Wait Events: інші очікування, такі як процеси фонового обслуговування

Перевірити такі сесії можемо аналогічно до попередніх запитів з pg_stat_activity, але додамо виборку wait_event_type та wait_event:

SELECT pid, usename, state, wait_event_type, wait_event, query
FROM pg_stat_activity
WHERE state != 'idle'
ORDER BY query_start;

Тут wait_event_type вказує на тип ресурсу, на який очікує процес (CPU, IO, Lock, WAL, Client), а wait_event деталізує яку конкретно операцію процес очікує.

Наприклад, wait_event_type може бути “IO“, тоді в wait_event_type можуть бути значення “DataFileRead” (очікування читання з диска) або “DataFileWrite” – очікування запису на диск.

Або, якщо wait_event_type == Client, тоді wait_event_type може бути “ClientRead“, “ClientWrite“, “ClientSocket“.

Див. RDS for PostgreSQL wait events.

Повернемось до наших графіків:

• CPU Utilization 100%: система перенавантажена
• DBLoad 17.5: при двох vCPU – маємо багато активних сесій, процесор не встигає обробити всі запити
• DBLoadCPU 13.9: багато сесій очікують на доступний CPU
• DBLoadNonCPU 3.59: частина запитів очікували диск, блокування, або якісь мережеві запити

Operating System CPU utilization

Окрім метрик DBLoad, які відносяться саме до RDS та PostgreSQL, у нас ще є інформація по самій операційній системі, де маємо інформацію і по диску, і по пам’яті, і по CPU.

Власне в CPU utilization ми маємо графік у відсотках з використання CPU, який складається з кількох метрик, кожна з яких відображає окремий режим:

• os.cpuUtilization.steal.avg (Steal Time): очікування фізичного CPU, якщо AWS виділила його іншому інстансу на цьому фізичному сервері, або якщо CPU Credits використано, і AWS обмежує ваш інстанс
• os.cpuUtilization.guest.avg (Guest Time): CPU, який “з’їла” гостьова операційна система – якщо на сервері є Virtual Machine або Docker, але не про RDS
• os.cpuUtilization.irq.avg (Interrupt Requests, IRQ Time): очікування Interrupt Requests, IRQ Time – обробка апаратних переривань (мережеві запити або диск), може бути пов’язана з високим IOPS на EBS
• os.cpuUtilization.wait.avg (I/O Wait Time): час I/O Wait Time, дискові операції, наприклад – зчитування файлів
• os.cpuUtilization.user.avg (User Time): час на юзер-процеси, в даному випадку це можуть бути обробка запитів PostgreSQL
• os.cpuUtilization.system.avg (System Time): робота ядра операційної системи (обробка процесів з user space, дискові операції, операції з пам’яттю)
• os.cpuUtilization.nice.avg (Nice Time): час на процеси з пріоритетом nice – низькопріоритетні фонові завдання

Схожі дані ми маємо в Linux top:

Tasks: 611 total, 7 running, 603 sleep, 1 d-sleep, 0 stopped, 0 zombie
%Cpu(s):  5.9 us,  3.6 sy,  0.0 ni, 89.8 id,  0.2 wa,  0.0 hi,  0.5 si,  0.0 st 
...

Тут us – user, sy – system, ni – nice, id – idle і так далі.

З нашого графіку в RDS Performance Insights ми маємо найбільшу частину саме по wait – і в той час є спайки по EBS IO operations:

Тобто, “прилетів” якийсь запит, який почав активно вичитувати з диска:

І поки CPU чекав на завершення операцій з диском – решта запитів виконувались повільніше.

В той самий час маємо “провал” по Freeable memory – бо дані з диска записувались в пам’ять.

І хоча саме значення в 460 IOPS не виглядає якимось зависоким, але схоже, що саме в цей момент ми “з’їли” доступну пам’ять.

На що нам в даному випадку може вказувати високий os.cpuUtilization.wait.avg?

• повільний EBS: все ж не наш кейс, бо маємо швидкість до 3000 IOPS; хоча очікування читання з диску в пам’ять могло спричинити ріст I/O Waits на CPU
• блокування/Locks: як варіант, але у нас є метрика db.Transactions.blocked_transactions.avg – і там все було добре, тобто PostgreSQL не чекав на звільнення locks – на транзакції теж зараз глянемо
• мало оперативної пам’яті: читання нових даних з диску в пам’ять витіснило існуючі там дані в Swap, і потім вичитувало їх звідти назад, при цьому скидуючи дані з пам’яті обратно в Swap, аби завантажити зі swap нові  (swap storm)

Використання Swap в цей час теж виросло:

До Swap і ReadIOPS зараз перейдемо, але спочатку давайте глянемо на транзакції.

Transactions

Ще з цікавого – активність транзакцій:

Бачимо, що як тільки почались проблеми з CPU – у нас xact_commit та xact_rollback (графік зліва) впали до нуля, і в той же час кількість active_transactions виросла до ~20, але при цьому blocked_transactions було 0.

Вже не можу зробити скрін, але ще був спайк по “idle in transaction” – тобто, транзакції починались (BEGIN), але не завершувались (не виконали COMMIT або ROLLBACK).

Але як так може бути? Навіть при високому CPU Waits хоча б частина транзакцій мали б завершитись.

• зависокий Read IOPS: система не могла отримати дані з диску?
  • ні – ReadIOPS виріс, але не прям настільки критично
  • однак через те, що FreeableMemory був занизьким, дані з shared_buffers могли бути скинуті до swap, що викликало ще більші затримки у процесів, які ці дані очікували
• зависокий Write IOPS: система не могла виконати запис WAL (Write Ahead Logs, будемо розбирати далі), якого потребує завершення транзакцій
  • але ми бачили, що Write IOPS був в нормі
• багато table locks, і процеси очікували вивільнення ресурсів?
  • теж ні, бо ми бачили, що blocked_transactions було на нулі
• робота autovacuum або ANALYZE, які могли заблокувати транзакції?
  • але знов-таки – db.Transactions.blocked_transactions.avg був на нулі
• Swap storm: оце вже більше схоже на правду:
  • читання з диску витіснило активні дані на Swap (впав показник FreeableMemory)
  • Swap Usage виріс майже до 3-х гігабайт
  • PostgreSQL не міг отримати сторінки з shared_buffers, бо вони були в SWAP (про пам’ять теж далі буде)
  • через це транзакції “зависли” в очікуванні читання з диска, замість того щоб працювати у RAM

Що ми можемо перевірити в таких випадках?

I/O Waits або Blocks

SELECT pid, usename, query, wait_event_type, wait_event, state 
FROM pg_stat_activity 
WHERE state = 'active';

Якщо в wait_event маємо “I/O” або “Locks” – то причина може бути тут.

WAL – Write Ahead Logs

• при кожній операції DML (Data Manipulation Language), наприклад при INSERT, UPDATE або DELETE, дані спочатку змінюються в пам’яті (shared_buffers – будемо далі про них говорити), де створюється “контекст операції”
• одночасно ця операція заноситься у WAL-буфер (wal_buffers – буфер пам’яті)
• коли wal_buffers заповнюється, або коли транзакція завершена, PostgreSQL-процес wal_writer за допомогою системного виклику fsync() записує дані з буфера у wal-файл (директорія pg_wal/) – це журнал всіх змін, що відбулися перед COMMIT
• клієнт, який запустив виконання запиту отримує повідомлення COMMIT – операція успішно завершена
  • якщо параметр synchronous_commit = on, PostgreSQL чекає завершення fsync() перед відправкою COMMIT
  • якщо synchronous_commit = off, PostgreSQL не чекає fsync() і COMMIT відбувається швидше, але з ризиком втрати даних
  • при неможливості виконати транзакцію – клієнт отримає помилку “could not commit transaction“
• дані з shared_buffers записуються до файлів самої бази даних (каталог base/) – цим займається процес checkpointer, який записує модифіковані в пам’яті дані (dirty pages) на диск
  • це відбувається  за допомогою процесу CHECKPOINT не одразу після COMMIT, а періодично
  • після виконання CHECKPOINT – PostgreSQL виконує архівацію або видалення WAL-файлів

Дуже класний матеріал на тему WAL, memory та checkpoint – PostgreSQL: What is a checkpoint?

Отже, якщо EBS був перенавантажений з Write IOPS – то WAL міг перестати писатись, і це могло призвести до зупинки виконання транзакцій.

Але в нашому випадку ми бачимо, що і db.Transactions.xact_rollback.avg був на нулі, а він не залежить від WAL і Write-операцій на диску.

В PostgreSQL Exporter є кілька корисних метрик, які відображаються активність WAL:

• pg_stat_archiver_archived_count: загальна кількість успішно заархівованих WAL-файлів (що скаже нам, що WAL працює коректно)
• pg_stat_archiver_failed_count: кількість невдалих спроб архівування WAL-файлів
• pg_stat_bgwriter_checkpoint_time: час, витрачений на виконання CHECKPOINTs

Ще можна зробити такий запит:

SELECT * FROM pg_stat_wal;

Якщо wal_buffers_full високий і росте, то, можливо, транзакції чекають на виконання fsync(), або що значення wal_buffers замале, і його треба збільшити аби зменшити частоту примусових записів WAL на диск.

В PostgreSQL такої метрики наче нема, але можемо зробити власну з custom.yaml:

pg_stat_wal:
  query: "SELECT wal_buffers_full FROM pg_stat_wal;"
  metrics:
    - wal_buffers_full:
        usage: "COUNTER"
        description: "Number of times the WAL buffers were completely full, causing WAL data to be written to disk."

Read IOPS та Swap

Добре.

Давайте повернемось до питання з Read IOPS та Swap.

Що тут могло відбутись:

• якийсь запит почав активно зчитувати дані з диску
• вони заносились в shared_buffers, в пам’яті не вистачило місця, і дані, які там були до цього були винесені в Swap
• запити в PostgreSQL продовжують виконуватись, але тепер замість того, аби просто взяти дані з пам’яті – PostgreSQL має йти до Swap, і тому маємо високий ReadIOPS та CPU I/O Waits – тобто CPU чекає, поки дані будуть зчитані з диску

Але тоді наче мало б бути спайк по db.IO.blks_read.avg, раз читаємо з диска?

Але ні, бо db.IO.blks_read – це запити від самого PostgreSQL на читання данних.

Коли ж він оперує зі свапом – він все одно вважає, що працює з оперативною пам’яттю.

А от метрика ReadIOPS – це вже від самої операційної системи/EBS, і вона як раз показує всі операції читання, а не тільки від процесів PostgreSQL.

Що цікаво, що в момент проблеми у нас db.Cache.blks_hit впав до нуля. Про що це каже? Зазвичай, що backend-процеси (сесії) не знаходили дані в shared_buffers.

Але знаючи, що у нас взагалі всі транзакції зупинились, а db.IO.blks_read теж впав до нуля – то скоріш PostgreSQL просто перестав звертатись до кешу взагалі, бо всі чекали на вільний CPU.

Окей, гугл…

А що зі свапом?

SWAP та Enhanced monitoring

Що у нас є на графіках?

Тут нам буде корисний Enhanced monitoring:

Вибираємо там Swap (Manage graphs), і бачимо цікаву картину:

• Free Memory падає
• Free Swap падає
• але Swaps in та Swaps out без змін

Тобто виглядає так, наче пам’ять закінчується – система скидає дані з RAM у Swap – але при цьому саме операції Swaps in/out “не було”.

Виглядає наче цікаво, і варто було б тут копнути далі – але AWS Console на цих графіках постійно падає:

Див. OS metrics in Enhanced Monitoring.

Втім, хоча ми не можемо отримати метрики з Enhanced monitoring напряму, але – сюрпрайз! вони пишуться до CloudWatch Logs! А вже з логів ми можемо нагенерити собі будь-які метрики з VictoriaLogs або Loki:

І вже в логах бачимо, що Swap In/Out таки відбувався. Тільки простих графіків вже не побачити. Але в майбутньому зробити собі якихось метрик з цих логів було б корисно.

В Log Groups шукаємо RDSOSMetrics, а потім вибираємо лог по RDS ID:

Operating system process list

Ще дуже корисним може бути список процесів:

Якщо починає падати вільна пам’ять – йдемо сюди, дивимось Resident memory, знаходимо PID процесу який жере пам’ять – і дивимось, що саме там за запит:

prod_kraken_db=> SELECT user, pid, query FROM pg_stat_activity WHERE pid = '26421';
       user       |  pid  |  query   
------------------+-------+----------
 prod_kraken_user | 26421 | ROLLBACK

Всі ці процеси ми також маємо в логах, про які згадував вище – але це краще перевіряти в момент, коли виникає проблема, аби знайти який саме виконувався.

Бо так, ми можемо включити slow queries logs – але в тих логах ми не побачимо PID, і не зможемо дізнатись скільки пам’яті цей запит використав.

Пам’ять в PostgreSQL

Давайте трохи копнемо в те, що взагалі в пам’яті PostgreSQL.

Див. RDS for PostgreSQL memory та Tuning memory parameters.

Пам’ять в PostgreSQL ділиться на два основні типи – це “shared memory“, та “local memory” – пам’ять кожного бекенд-процесу (сесії).

В shared memory ми маємо:

• shared_buffers: основна пам’ять, де PostgreSQL тримає кеш даних, які він зчитує з диску при обробці запитів – кешування сторінок таблиць та індексів
  • аналог Heap Memory (Java Heap)
  • shared_buffers за замовчуванням становить 25% від загальної RAM, але можна змінити
• wal_buffers: вже бачили вище – використовується для тимчасового зберігання WAL-записів для буферизації транзакції перед записом у WAL-файл

Із shared_buffers змінені дані (dirty pages) записуються на диск двома процесами:

• Background Writer (bgwriter): працює в фоні, поступово записує дані на диск
• Checkpointer (checkpoint): примусово записує всі сторінки під час CHECKPOINT

Пам’ять процесів має:

• work_mem: виділяється запитам, які виконують сортувань (ORDER BY), хеш-операцій (HASH JOIN) та агрегацій
  • кожен запит отримує свою копію work_mem, тому при великій кількості одночасних запитів пам’ять може швидко закінчитись
  • якщо work_mem процесу не вистачає – PostgreSQL починає записувати тимчасові файли на диск (temp_blks_written), що уповільнює виконання запитів
• maintenance_work_mem: власне, maintenance operations – операції по vacuuming, створення індексів, додавання foreign keys
• temp_buffers: виділяється для тимчасових таблиць (CREATE TEMP TABLE).

Ми можемо отримати всі дані з pg_settings так:

SELECT 
    name, 
    setting, 
    unit,
    CASE 
        WHEN unit = '8kB' THEN setting::bigint * 8 
        WHEN unit = 'kB' THEN setting::bigint 
        ELSE NULL 
    END AS total_kb,
    pg_size_pretty(
        CASE 
            WHEN unit = '8kB' THEN setting::bigint * 8 * 1024
            WHEN unit = 'kB' THEN setting::bigint * 1024
            ELSE NULL 
        END
    ) AS total_pretty
FROM pg_settings
WHERE name IN ('shared_buffers', 'work_mem', 'temp_buffers', 'wal_buffers');

Маємо 238967 shared_buffers, кожен по 8КБ, разом ~1.9 GB.

Але це вже зараз, на db.m5.large.

Перевірка shared_buffers

Cache hit ratio покаже скільки даних було отримано з пам’яті, а скільки з самого диску – хоча у нас це є в метриках db.IO.blks_read.avg та db.Cache.blks_hit.avg (або метрики pg_stat_database_blks_hit та pg_stat_database_blks_read в PostgreSQL Exporter):

SELECT 
    blks_read, blks_hit, 
    ROUND(blks_hit::numeric / NULLIF(blks_hit + blks_read, 0), 4) AS cache_hit_ratio
FROM pg_stat_database
WHERE datname = current_database();

Якщо cache_hit_ratio < 0.9, значить, кеш PostgreSQL не ефективний, і забагато даних читається з диска замість кеша.

Побачити скільки з виділених shared_buffers зараз використані (активні), а скільки вільні – тут нам знадобиться extention pg_buffercache.

Запит:

SELECT
    COUNT(*) AS total_buffers,
    SUM(CASE WHEN isdirty THEN 1 ELSE 0 END) AS dirty_buffers,
    SUM(CASE WHEN relfilenode IS NULL THEN 1 ELSE 0 END) AS free_buffers,
    SUM(CASE WHEN relfilenode IS NOT NULL THEN 1 ELSE 0 END) AS used_buffers,
    ROUND(100.0 * SUM(CASE WHEN relfilenode IS NOT NULL THEN 1 ELSE 0 END) / COUNT(*), 2) AS used_percent,
    ROUND(100.0 * SUM(CASE WHEN relfilenode IS NULL THEN 1 ELSE 0 END) / COUNT(*), 2) AS free_percent
FROM pg_buffercache;

Маємо 238967 буферів загалом, з яких використано лише 12280, або 5%.

Або інший варіант – подивитись, скільки всього сторінок зараз в shared_buffers:

prod_kraken_db=> SELECT 
    count(*) AS cached_pages,
    pg_size_pretty(count(*) * 8192) AS cached_size
FROM pg_buffercache;
 cached_pages | cached_size 
--------------+-------------
       117495 | 918 MB

При тому, що всього під shared_buffers виділено:

prod_kraken_db=> SHOW shared_buffers;
 shared_buffers 
----------------
 939960kB

918 мегабайт.

Але чому тоді в попередньому запиті ми бачили, що “зайнято 5%”?

Бо в результаті з pg_buffercache в полях used_buffers та used_percent враховуються тільки активні сторінки (used), тобто ті, які або мають прив’язку до файлу (relfilenode), або були нещодавно використані.

Використання EXPLAIN ANALYZE

Див. EXPLAIN.

EXPLAIN (ANALYZE, BUFFERS) покаже нам скільки даних в буферах зараз, скільки даних буде прочитано з диску:

Тут:

• shared hit: скільки сторінок було прочитано з кешу (shared_buffers)
• shared read: скільки сторінок було прочитано з диска (завантажено в shared_buffers)
• shared dirtied: скільки сторінок було модифіковано

Тема Explain доволі цікава і дає нам багато цікавої інформації, тому написав про неї окремо – PostgreSQL: використання EXPLAIN та налаштування “auto_explain” в AWS RDS.

Подивитись зміст shared_buffers

Отримати кількість буферів по всім таблицям:

SELECT
c.relname, count(*) AS buffers
FROM
pg_buffercache b
INNER JOIN pg_class c ON b.relfilenode = pg_relation_filenode(c.oid)
AND
b.reldatabase IN (0, (SELECT oid FROM pg_database
WHERE
datname = current_database()))
GROUP BY c.relname
ORDER BY 2 DESC
LIMIT 10;

Тут для challenge_progress використано 1636 буферів, що дає нам:

1636*8/1024
12

12 мегабайт.

Або можна отримати з pg_relation_size() – див. System Administration Functions та pg_relation_size():

prod_kraken_db=> SELECT pg_size_pretty(pg_relation_size('challenge_progress'));
 pg_size_pretty 
----------------
 13 MB

Перевірка work_mem

Якщо у нас падає FreeableMemory, то, можливо, використовується забагато work_mem.

Перевірити скільки виділяється на кожен процес:

dev_kraken_db=> SHOW work_mem;
 work_mem 
----------
 4MB

Перевірити чи вистачає процесам цього значення work_mem можна зі значення temp_blks_written, бо коли пам’ять в work_mem закінчується, то процес починає виносити дані в тимчасові таблиці:

Ну і, власне, на цьому, мабуть, все.

Якісь висновки? Складно робити. Ясно, що db.t3.small з двома гігабайтами нам було замало.

Є підозра який саме запит тоді викликав цю “цепну реакцію”, в slow queries logs побачили “некрасивий” SELECT, і девелопери його наче оптимізували.

Спробуємо зменшити тип інстансу до 4 гігабайт пам’яті, і подивимось, чи виникне проблема знов.

Monitoring summary

Замість висновків – кілька ідей того, що треба моніторити, і що в моніторингу можна покращити.

Наші алерти

Накидаю трохи алертів, які у нас вже є зараз.

CloudWatch метрики

Метрики CloudWatch. Збираємо до VictoriaMetrics з YACE-експортером.

CPUUtilization

Алерт:

- alert: HighCPUUtilization
  expr: avg(aws_rds_cpuutilization_average{dimension_DBInstanceIdentifier!="", dimension_DBInstanceIdentifier!~"kraken-ops-rds-.*"}[5m]) by (dimension_DBInstanceIdentifier) > 80
  for: 5m
  labels:
    severity: warning
    component: devops
    environment: ops
  annotations:
    summary: "High CPU utilization on RDS instance"
    description: "CPU utilization is above 80% for more than 5 minutes on RDS instance {{ "{{" }} $labels.instance }}."

- alert: HighCPULoadPerVCPUWarningAll
  expr: avg(aws_rds_dbload_relative_to_num_vcpus_average{dimension_DBInstanceIdentifier!="", dimension_DBInstanceIdentifier!~"kraken-ops-rds-.*"}[5m]) by (dimension_DBInstanceIdentifier) > 0.8
  for: 5m
  labels:
    severity: warning
    component: devops
    environment: ops
  annotations:
    summary: "High per-core CPU utilization on RDS instance"
    description: |
      CPU utilization is above 80% for more than 5 minutes on RDS instance {{ "{{" }} $labels.instance }}
      *DB instance*: `{{ "{{" }} $labels.dimension_DBInstanceIdentifier }}`
      *Per-vCPU load*: `{{ "{{" }} $value | humanize }}`

- record: aws:rds:free_storage:gigabytes
  expr: sum(aws_rds_free_storage_space_average{dimension_DBInstanceIdentifier!=""}) by (dimension_DBInstanceIdentifier) / 1073741824

# ALL
- alert: LowFreeStorageSpaceCriticalAll
  expr: aws:rds:free_storage:gigabytes < 5
  for: 5m
  labels:
    severity: warning
    component: devops
    environment: ops        
  annotations:
    summary: "Low Disk Space on an RDS instance"
    description: |-
      Free storage below 5 GB
      *DB instance*: `{{ "{{" }} $labels.dimension_DBInstanceIdentifier }}`
      *Free storage*: `{{ "{{" }} $value | humanize }}`

- alert: LowFreeableMemoryDev
  expr: avg(aws_rds_freeable_memory_average{dimension_DBInstanceIdentifier="kraken-ops-rds-dev"}[5m]*0.000001) by (dimension_DBInstanceIdentifier) < 20
  for: 5m
  labels:
    severity: warning
    component: backend
    environment: dev       
  annotations:
    summary: "High memory usage on RDS instance"
    description: |-
      Freeable memory is less than 100mb
      *DB instance*: `{{ "{{" }} $labels.dimension_DBInstanceIdentifier }}`
      *Free memory*: `{{ "{{" }} $value | humanize }}`

- alert: HighDiskReadLatencyKrakenStaging
  expr: sum(aws_rds_read_latency_average{dimension_DBInstanceIdentifier="kraken-ops-rds-dev"}) by (dimension_DBInstanceIdentifier) > 0.1
  for: 1s
  labels:
    severity: warning
    component: backend
    environment: dev
  annotations:
    summary: "High Disk Read Latency on RDS instance"
    description: |-
      Reads from a storage are too slow
      *DB instance*: `{{ "{{" }} $labels.dimension_DBInstanceIdentifier }}`
      *Read Latency*: `{{ "{{" }} $value | humanize }}`

- record: aws:rds:swap_used:gigabytes
  expr: sum(aws_rds_swap_usage_average{dimension_DBInstanceIdentifier!=""}) by (dimension_DBInstanceIdentifier) / 1073741824

# ALL
- alert: SwapUsedAllWarning
  expr: sum(aws:rds:swap_used:gigabytes{dimension_DBInstanceIdentifier!="", dimension_DBInstanceIdentifier!~"kraken-ops-rds-.*"}) by (dimension_DBInstanceIdentifier) > 0.8
  for: 1s
  labels:
    severity: warning
    component: devops
    environment: ops
  annotations:
    summary: "Swap space use is too high on an RDS instance"
    description: |-
      The RDS instance is using more than *0.8 GB* of swap space
      *DB instance*: `{{ "{{" }} $labels.dimension_DBInstanceIdentifier }}`
      *Swap used GB*: `{{ "{{" }} $value | humanize }}`

# db.t3.micro - 112 max_connections (Backend Dev)
# db.t3.small - 225 max_connections (Backend Prod)
# db.t3.medium - 450 max_connections
# db.t3.large - 901 max_connections

# ALL
- alert: HighConnectionCountWarning
  expr: avg(aws_rds_database_connections_average{dimension_DBInstanceIdentifier!="", dimension_DBInstanceIdentifier!~".*kraken.*"}[5m]) by (dimension_DBInstanceIdentifier) > 50
  for: 1m
  labels:
    severity: warning
    component: devops
    environment: ops
  annotations:
    summary: "High number of connections on RDS instance"
    description: |-
      An RDS instance Connections Pool is almost full. New connections may be rejected.
      *DB instance*: `{{ "{{" }} $labels.dimension_DBInstanceIdentifier }}`
      *Instance type*: `db.t3.micro`
      *Max connections*: `112`
      *Current connections*: `{{ "{{" }} $value | humanize }}`

- record: aws:rds:backend:connection_failed:sum:rate:5m
  expr: |
    sum(
        rate(
            {app=~"backend-.*"} 
            != "token_email" 
            |= "sqlalchemy.exc.OperationalError" 
            | regexp `.*OperationalError\) (?P<message>connection to server at "(?P<db_server>[^"]+)".*$)`
            [5m]
        )
    ) by (message, db_server)

- alert: BackendRDSConnectionFailed
  expr: sum(aws:rds:backend:connection_failed:sum:rate:5m{db_server="dev.db.kraken.ops.example.co"}) by (db_server, message) > 0
  for: 1s
  labels:
    severity: critical
    component: backend
    environment: dev
  annotations:
    summary: "Connection to RDS server failed"
    description: |-
      Backend Pods can't connect to an RDS instance
      *Database server:*: {{ "{{" }} $labels.db_server }}
      *Error message*: {{ "{{" }} $labels.message }}

# 'pg_stat_database_numbackends' and 'pg_settings_max_connections' have no common labels
# don't want to waste time with 'label_replace' or similar
# thus just create different 'records' for Prod and Staging
- record: aws:rds:kraken_dev:max_connections_used:percent
  expr: |
    (
      sum(pg_stat_database_numbackends{datname=~"dev_kraken_db", job="atlas-victoriametrics-postgres-exporter-kraken-dev"})
      /
      sum(pg_settings_max_connections{container=~".*kraken-dev"})
    ) * 100

- alert: ExporterHighConnectionPercentBackendDevWarning
  expr: aws:rds:kraken_dev:max_connections_used:percent > 40
  for: 1s
  labels:
    severity: warning
    component: backend
    environment: dev
  annotations:
    summary: "High number of connections on the Backend RDS instance"
    description: |-
      RDS instance Connections Pool is almost full. New connections may be rejected.
      *DB instance*: `kraken-ops-rds-dev`
      *Connections pool use*: `{{ "{{" }} $value | humanize }}%`
    grafana_rds_overview_url: 'https://{{ .Values.monitoring.root_url }}/d/ceao6muzwos1sa/kraken-rds?orgId=1&from=now-1h&to=now&timezone=browser&var-query0=&var-db_name=kraken-ops-rds-dev'

- alert: ExporterTransactionExecutionTimeBackendDevWarning
  expr: sum(rate(pg_stat_activity_max_tx_duration{datname="dev_kraken_db"}[5m])) by (state, datname) > 0.1
  for: 1m
  labels:
    severity: warning
    component: backend
    environment: dev
  annotations:
    summary: "RDS transactions running too long"
    description: |-
      Too long duration in seconds active transaction has been running
      *Database name*: `{{ "{{" }} $labels.datname }}`
      *State*: `{{ "{{" }} $labels.state }}`
      *Duration*: `{{ "{{" }} printf "%.2f" $value }}` seconds
    grafana_rds_overview_url: 'https://{{ .Values.monitoring.root_url }}/d/ceao6muzwos1sa/kraken-rds?orgId=1&from=now-1h&to=now&timezone=browser&var-query0=&var-db_name={{ "{{" }} $labels.datname }}'

SELECT * FROM pg_stat_wal;

SELECT buffers_backend, buffers_checkpoint, buffers_alloc FROM pg_stat_bgwriter;

SELECT checkpoint_write_time, checkpoint_sync_time FROM pg_stat_bgwriter;

SELECT temp_files, temp_bytes FROM pg_stat_database WHERE datname = current_database();