PostgreSQLのトリガーをデバックする方法

PostgreSQL

ちょっとトリガーを触る機会があって、デバックする良い方法がないかな、と探したのでメモ。 基本的には、debugging postgresql trigger - Stack Overflowに書いてあることの一部試してみた、という記事。

EXPLAIN ANALYZEでTriggerが実行されたか確認する

実行計画を表示するために使うEXPLAINだが、EXPLAIN ANALYZEすると実際にSQL文を実行してくれる。

この時、そのSQLでトリガーが呼び出された場合は、その実行結果（実行時間、回数）も一緒に表示してくれるので、意図した呼び出しが行われているか確認できる。

PL/pgSQLのRAISE文でプリントデバックする

トリガーで呼び出す関数を作成するPL/pgSQLにはRAISE文という、エラーをメッセージとして出力したり、そもそもエラーとして処理を停止させるための仕組みがある。

これを利用すると、トリガー内の任意の箇所で、メッセージを出力できるので、プリントデバックが可能。*1

42.9. エラーとメッセージ

試してみる

前提の環境

dockerで適当なコンテナを立ち上げて、接続する。

docker --version
# Docker version 20.10.8, build 3967b7d

sudo docker run --name example-postgres -e POSTGRES_PASSWORD=hoge -d 
# postgres

docker exec -it example-postgres bash

psql --version
# psql (PostgreSQL) 14.0 (Debian 14.0-1.pgdg110+1)

psql -U postgres

DDL

適当にusersテーブルとusers_historyテーブルを作って、usersの行が更新されたら、変更前後のusers.nameをusers_historyに書き込むようなトリガーを作る。 write_user_history()の中に前述のRAISE文も書いておく。

CREATE TABLE users(
   id serial NOT NULL,
   name text,
   PRIMARY KEY (id)
);

CREATE TABLE users_history(
   id serial NOT NULL,
   user_id integer,
   old_name text,
   new_name text,
   PRIMARY KEY (id)
);


CREATE OR REPLACE FUNCTION write_user_history() RETURNS "trigger" AS
$$
DECLARE
BEGIN
  RAISE NOTICE 'messagea';
  insert into  users_history(
    user_id,
    new_name,
    old_name
  ) values (
    new.id,
    new.name,
    old.name
  );
  RETURN new;
END;
$$
LANGUAGE plpgsql VOLATILE;

CREATE TRIGGER write_user_historys_trigger
  AFTER UPDATE
  ON users
  FOR EACH ROW
  EXECUTE PROCEDURE write_user_history();

トリガーを動かしてみる

実際にトリガーを動かしてみる。 なお、トリガーを動かす前に、NOTICEレベルのログをクライアント(psql)とログに出力するための設定を行う。

ALTER SYSTEM SET client_min_messages = NOTICE;
ALTER SYSTEM SET log_min_messages = NOTICE;

usersテーブルに更新対象になるデータをINSERTします。

INSERT INTO users(name) values('hoge');

-- INSERT 0 1

SELECT * FROM users;

-- id | name
-- ----+------
--  1 | hoge
-- (1 row)

SELECT * FROM users_history;

-- id | user_id | old_name | new_name
-- ----+---------+----------+----------
-- (0 rows)

そのデータに対してEXPLAIN ANALYZEを利用したSQL文で更新をすると、前述の通り、実行計画とともにトリガーが実行されたことと、所要時間、実行回数が分かる。 また、この時点でRAISEしたメッセージもpsql上で確認することができる。

EXPLAIN ANALYZE UPDATE users SET name = 'fuga' where id = 1;

-- NOTICE:  messagea
 
--                                                      QUERY PLAN
-- 
-- -------------------------------------------------------------------------------------------------------------------------
--  Update on users  (cost=0.15..8.17 rows=0 width=0) (actual time=0.026..0.026 rows=0 loops=1)
--   ->  Index Scan using users_pkey on users  (cost=0.15..8.17 rows=1 width=38) (actual time=0.006..0.006 rows=1 loops=1)
--        Index Cond: (id = 1)
-- Planning Time: 0.083 ms
-- Trigger write_user_historys_trigger: time=0.414 calls=1
-- Execution Time: 0.456 ms
-- (6 rows)

users_historyテーブルにもちゃんとデータが入っている。

SELECT * FROM users;
SELECT * FROM users_history;

-- id | name
-- ----+------
--  1 | fuga
-- (1 row)

-- id | user_id | old_name | new_name
-- ----+---------+----------+----------
--   1 |       1 | hoge     | fuga
-- (1 row)

一旦コンテナから抜けて、docker logsを実行すると、RAISE文の結果がログにも出力されていることが確認できる。

docker logs example-postgres

# 2021-10-09 08:07:15.580 UTC [51] NOTICE:  messagea
# 2021-10-09 08:07:15.580 UTC [51] CONTEXT:  PL/pgSQL function write_user_history() line 4 at RAISE

わりと、PostgreSQLだけでもデバックに便利な機能はある、というのが発見だった。

他にもデバックという点でいうと

  • PL/pgSQLのASSERT文を使ってテストを書けそう
  • pgAdmin付属のデバッガ―を使ってブレークポイントを使ったりしてデバックできそう

ということもできるようだが、今回はいったんここまで。

*1:私はあまり複雑なトリガーを書いたことはないが、トランザクション自体を失敗にすることもできるので使いようはいろいろありそう