Support des Wait Events pour PoWA

By Julien Rouhaud Comment

Vous avez la possibilité de visualiser les Wait Events dans PoWA 3.2.0 grâce à l’extension pg_wait_sampling extension.

Wait Events & pg_wait_sampling

Les wait events sont une fonctionnalité connues, et bien utiles, dans de nombreux moteurs de base de données relationnelles. Ceux-ci ont été ajouté à PostgreSQL 9.6, il y a maintenant quelques versions. Contrairement à la plupart des autres statistiques exposées par PostgreSQL, ceux-ci ne sont qu’une vision à un instant donné des événements sur lesquels les processus sont en attente, et non pas des compteurs cumulés. Vous pouvez consulter cette information en utilisant la vue pg_stat_activity, par exemple :

=# SELECT datid, pid, wait_event_type, wait_event, query FROM pg_stat_activity;
 datid  |  pid  | wait_event_type |     wait_event      |                                  query
--------+-------+-----------------+---------------------+-------------------------------------------------------------------------
 <NULL> | 13782 | Activity        | AutoVacuumMain      |
  16384 | 16615 | Lock            | relation            | SELECT * FROM t1;
  16384 | 16621 | Client          | ClientRead          | LOCK TABLE t1;
 847842 | 16763 | LWLock          | WALWriteLock        | END;
 847842 | 16764 | Lock            | transactionid       | UPDATE pgbench_branches SET bbalance = bbalance + 1229 WHERE bid = 1;
 847842 | 16766 | LWLock          | WALWriteLock        | END;
 847842 | 16767 | Lock            | transactionid       | UPDATE pgbench_tellers SET tbalance = tbalance + 3383 WHERE tid = 86;
 847842 | 16769 | Lock            | transactionid       | UPDATE pgbench_branches SET bbalance = bbalance + -3786 WHERE bid = 10;
[...]

Dans cet exemple, nous voyons que le //wait event// pour le pid 16615 est un Lock sur une Relation. En d’autre terme, la requête est bloquée en attente d’un verrou lourd, alors que le pid 16621, qui clairement détient le verrou, est inactif en attente de commandes du client. Il s’agit d’informations qu’il était déjà possible d’obtenir avec les anciennes versions, bien que cela se faisait d’une autre manière. Mais plus intéressant, nous pouvons également voir que le //wait event// pour le pid 16766 est un LWLock, c’est-à-dire un Lightweight Lock, ou verrou léger. Les verrous légers sont des verrous internes et transitoires qu’il était auparavant impossible de voir au niveau SQL. dans cet exemple, la requête est en attente d’un WALWriteLock, un verrou léger principalement utilisé pour contrôler l’écriture dans les tampons des journaux de transaction. Une liste complète des //wait events// disponible est disponible sur la documentation officielle.

Ces informations manquaient curellement et sont bien utiles pour diagnostiquer les causes de ralentissement. Cependant, n’avoir que la vue de ces //wait events// à l’instant présent n’est clairement pas suffisant pour avoir une bonne idée de ce qu’il se passe sur le serveur. Puisque la plupart des //wait events// sont pas nature très éphémères, ce dont vous avez besoin est de les échantilloner à une fréquence élevée. Tenter de faire cet échantillonage avec un outil externe, même à une seconde d’intervalle, n’est généralement pas suffisant. C’est là que l’extension pg_wait_sampling apporte une solution vraiment brillante. Il s’agit d’une extension écrite par Alexander Korotkov et Ildus Kurbangaliev. Une fois activée (il est nécessaire de la configurer dans le shared_preload_libraries, un redémarrage de l’instance est donc nécessaire), elle échantillonera en mémoire partagée les //wait events// toutes les 10 ms (par défaut), et aggèrega également les compteurs par type de //wait event// (wait_event_type), //wait event// et queryid (si pg_stat_statements est également acctivé). Pour plus de détails sur la configuration et l’utilisation de cette extension, vous pouvez consulter le README de l’extension. Comme tout le travail est fait en mémoire au moyen d’une extension écrite en C, c’est très efficace. De plus, l’implémentation est faite avec très peu de verouillage, le surcoût de cette extension devrait être presque négligable. J’ai fait quelques tests de performance sur mon pc portable (je n’ai malheureusement pas de meilleure machine sur laquelle tester) avec un pgbench en lecture seule où toutes les données tenaient dans le cache de PostgreSQL (shared_buffers), avec 8 puis 90 clients, afin d’essayer d’avoir le maximum de surcoût possible. La moyenne sur 3 tests était d’environ 1% de surcoût, avec des fluctuations entre chaque test d’environ 0.8%.

Et PoWA ?

Ainsi, grâce à cette extension, nous avons à notre disposition une vue cumulée et extrêmement précise des //wait events//. C’est très bien, mais comme toutes les autres statistiques cumulées dans PostgreSQL, vous devez échantillonner ces compteurs régulièrement si vous voulez pouvoir être capable de savoir ce qu’il s’est passé à un certain moment dans le passé, comme c’est d’ailleurs précisé dans le README de l’extension :

[…] Waits profile. It’s implemented as in-memory hash table where count of samples are accumulated per each process and each wait event (and each query with pg_stat_statements). This hash table can be reset by user request. Assuming there is a client who periodically dumps profile and resets it, user can have statistics of intensivity of wait events among time.

C’est exactement le but de PoWA: sauvegarder les compteurs statistiques de manière efficace, et les afficher sur une interface graphique.

PoWA 3.2 détecte automatiquement si l’extension pg_wait_sampling est déjà présente ou si vous l’installez ultérieurement, et commencera à collecter ses données, vous donnant une vue vraiment précise des //wait events// dans le temps sur vos bases de données !

Les données sont centralisée dans des tables PoWA classiques, powa_wait_sampling_history_current pour les 100 dernières collectes (valeur par défaut de powa.coalesce), et les valeurs plus anciennes sont aggrégées dans la table powa_wait_sampling_history, avec un historique allant jusqu’à une période définie par powa.retention. Par exemple, voici une requête simple affichant les 20 premiers changements survenus au sein des 100 premiers instantanés :

WITH s AS (
SELECT (record).ts, queryid, event_type, event,
(record).count - lag((record).count)
    OVER (PARTITION BY queryid, event_type, event ORDER BY (record).ts)
    AS events
FROM powa_wait_sampling_history_current w
JOIN pg_database d ON d.oid = w.dbid
WHERE d.datname = 'bench'
)
SELECT *
FROM s
WHERE events != 0
ORDER BY ts ASC, event DESC
LIMIT 20;
              ts               |       queryid        | event_type |     event      | events
-------------------------------+----------------------+------------+----------------+--------
 2018-07-09 10:44:08.037191+02 | -6531859117817823569 | LWLock     | pg_qualstats   |   1233
 2018-07-09 10:44:28.035212+02 |  8851222058009799098 | Lock       | tuple          |      4
 2018-07-09 10:44:28.035212+02 | -6860707137622661878 | Lock       | tuple          |    149
 2018-07-09 10:44:28.035212+02 |  8851222058009799098 | Lock       | transactionid  |    193
 2018-07-09 10:44:28.035212+02 | -6860707137622661878 | Lock       | transactionid  |   1143
 2018-07-09 10:44:28.035212+02 | -6531859117817823569 | LWLock     | pg_qualstats   |      1
 2018-07-09 10:44:28.035212+02 |  8851222058009799098 | LWLock     | lock_manager   |      2
 2018-07-09 10:44:28.035212+02 | -6860707137622661878 | LWLock     | lock_manager   |      3
 2018-07-09 10:44:28.035212+02 | -6860707137622661878 | LWLock     | buffer_content |      2
 2018-07-09 10:44:48.037205+02 |  8851222058009799098 | Lock       | tuple          |     14
 2018-07-09 10:44:48.037205+02 | -6860707137622661878 | Lock       | tuple          |    335
 2018-07-09 10:44:48.037205+02 | -6860707137622661878 | Lock       | transactionid  |   2604
 2018-07-09 10:44:48.037205+02 |  8851222058009799098 | Lock       | transactionid  |    384
 2018-07-09 10:44:48.037205+02 | -6860707137622661878 | LWLock     | lock_manager   |     13
 2018-07-09 10:44:48.037205+02 |  8851222058009799098 | LWLock     | lock_manager   |      4
 2018-07-09 10:44:48.037205+02 |  8221555873158496753 | IO         | DataFileExtend |      1
 2018-07-09 10:44:48.037205+02 | -6860707137622661878 | LWLock     | buffer_content |      4
 2018-07-09 10:45:08.032938+02 |  8851222058009799098 | Lock       | tuple          |      5
 2018-07-09 10:45:08.032938+02 | -6860707137622661878 | Lock       | tuple          |    312
 2018-07-09 10:45:08.032938+02 | -6860707137622661878 | Lock       | transactionid  |   2586
(20 rows)

NOTE: Il y a également une version par base de données de ces valeurs pour un traitement plus efficace au niveau des basesn dans les tables powa_wait_sampling_history_current_db et powa_wait_sampling_history_db

Et ces données sont visibles avec l’interface powa-web. Voici quelques exemples d’affichage des //wait events// tels qu’affichés par PoWA avec un simple pgbench :

Wait events pour l’instance entière

Wait events pour l'instance entière

Wait events pour une base de données

Wait events pour une base de données

Wait events pour une seule requête

Wait events pour une seule requête

Cette fonctionnalité est disponible depuis la version 3.2 de PoWA. J’espère pouvoir afficher plus de vues de ces données dans le futur, en incluant d’autres graphes, puisque toutes les données sont déjà disponibles en bases. Également, si vous êtes un développeur python ou javascript, les contributions sont toujours bienvenues!