KDOC 652: 明示的なトランザクションの小さいINSERTは時間の大半がCOMMITに数えられる

# 書き込む側と標本を取る側の2つのセッションが同時に要るので、pgpg のプロキシを通さず PostgreSQL に直接(15433)つなぐ
sample() {
  psql -h localhost -p 15433 -U postgres -d postgres -qAt -F ' | ' <<'SQL'
CREATE TABLE samples (query text, wait text);
DO $$
BEGIN
  FOR i IN 1..400 LOOP
    PERFORM pg_stat_clear_snapshot();
    INSERT INTO samples
    -- 待機イベントがなければ CPU で動いている
    SELECT query, coalesce(wait_event_type || ':' || wait_event, 'CPU')
    FROM pg_stat_activity
    WHERE application_name = 'pgbench' AND state = 'active';
    PERFORM pg_sleep(0.01);
  END LOOP;
END $$;
SELECT query, wait, count(*) FROM samples GROUP BY 1, 2 ORDER BY 3 DESC;
DROP TABLE samples;
SQL
}

# $1: 説明、$2: pgbench に流す SQL、$3: pgbench のオプション
run() {
  echo "== $1"
  docker exec pgpg-postgres-1 psql -U postgres -qAt \
    -c "DROP TABLE IF EXISTS w" -c "CREATE TABLE w (id int, pad text)" \
    -c "CREATE INDEX ON w (id)" -c "CREATE INDEX ON w (pad)" 2>/dev/null
  printf "$2" | docker exec -i pgpg-postgres-1 sh -c 'cat > /tmp/bench.sql'
  out=$(mktemp)
  # 拡張プロトコル(-M extended)で書き込む
  docker exec pgpg-postgres-1 pgbench -U postgres -n -M extended $3 \
    -f /tmp/bench.sql postgres > "$out" 2>/dev/null &
  sleep 0.3
  sample
  wait
  grep 'latency average' "$out"
  rm -f "$out"
}

run "小さい INSERT を明示的なトランザクションで(4並列、5秒)" \
    'BEGIN;\nINSERT INTO w VALUES (1, md5(random()::text));\nCOMMIT;\n' "-c 4 -T 5"
run "小さい INSERT を自動コミットで(4並列、5秒)" \
    'INSERT INTO w VALUES (1, md5(random()::text));\n' "-c 4 -T 5"
run "50万行の INSERT を明示的なトランザクションで1回" \
    'BEGIN;\nINSERT INTO w SELECT i, md5(i::text) FROM generate_series(1, 500000) i;\nCOMMIT;\n' "-c 1 -t 1"
docker exec pgpg-postgres-1 psql -U postgres -qAt -c "DROP TABLE w"

== 小さい INSERT を明示的なトランザクションで(4並列、5秒)
COMMIT; | LWLock:WALWrite | 1128
COMMIT; | IO:WalSync | 395
INSERT INTO w VALUES (1, md5(random()::text)); | CPU | 21
COMMIT; | CPU | 8
INSERT INTO w VALUES (1, md5(random()::text)); | Client:ClientRead | 3
BEGIN; | CPU | 3
BEGIN; | Client:ClientRead | 2
COMMIT; | IO:WalWrite | 2
INSERT INTO w VALUES (1, md5(random()::text)); | IO:DataFileExtend | 1
latency average = 1.684 ms
== 小さい INSERT を自動コミットで(4並列、5秒)
INSERT INTO w VALUES (1, md5(random()::text)); | LWLock:WALWrite | 1144
INSERT INTO w VALUES (1, md5(random()::text)); | IO:WalSync | 394
INSERT INTO w VALUES (1, md5(random()::text)); | CPU | 38
INSERT INTO w VALUES (1, md5(random()::text)); | Client:ClientRead | 6
INSERT INTO w VALUES (1, md5(random()::text)); | IO:WalWrite | 3
latency average = 1.678 ms
== 50万行の INSERT を明示的なトランザクションで1回
INSERT INTO w SELECT i, md5(i::text) FROM generate_series(1, 500000) i; | CPU | 148
INSERT INTO w SELECT i, md5(i::text) FROM generate_series(1, 500000) i; | IO:DataFileExtend | 6
INSERT INTO w SELECT i, md5(i::text) FROM generate_series(1, 500000) i; | IO:WalWrite | 4
INSERT INTO w SELECT i, md5(i::text) FROM generate_series(1, 500000) i; | IO:WalSync | 4
INSERT INTO w SELECT i, md5(i::text) FROM generate_series(1, 500000) i; | LWLock:WALWrite | 3
COMMIT; | IO:WalSync | 1
latency average = 1934.744 ms