MySQLとPostgreSQLにおけるログの確認方法
TPCCなどをダウンロードして参照のみ、更新と参照、参照と更新の比率変更等して様々な負荷をかけてベンチマークする方が良いと思うが、カジュアルにベンチマークしたいケースもあると思います。毎回、同じ方法でベンチマークする事で、ある程度サーバーの構成変更時のパフォーマンスの変化を把握できるのでMySQLやPostgreSQLにバンドルされているベンチマークツールも便利なベンチマークオプションとして使える。取得したログを簡単に確認したり、実際に運用中のシステムのログも定期的に確認出来れば尚便利。そんなニーズに対して、カジュアルにメモしておきました。
PostgreSQL
postgres@ubuntu:~$ pgbench -i scaffold
NOTICE: table "pgbench_history" does not exist, skipping
NOTICE: table "pgbench_tellers" does not exist, skipping
NOTICE: table "pgbench_accounts" does not exist, skipping
NOTICE: table "pgbench_branches" does not exist, skipping
creating tables...
100000 of 100000 tuples (100%) done (elapsed 0.28 s, remaining 0.00 s)
vacuum...
set primary keys...
done.
postgres@ubuntu:~$ psql scaffold -c "\d"
List of relations
Schema | Name | Type | Owner
--------+------------------+-------+----------
public | pgbench_accounts | table | postgres
public | pgbench_branches | table | postgres
public | pgbench_history | table | postgres
public | pgbench_tellers | table | postgres
(4 rows)
postgres@ubuntu:~$
postgres@ubuntu:~$ pgbench -c 30 -t 1000 scaffold
starting vacuum...end.
transaction type:
scaling factor: 1
query mode: simple
number of clients: 30
number of threads: 1
number of transactions per client: 1000
number of transactions actually processed: 30000/30000
latency average = 41.333 ms
tps = 725.808779 (including connections establishing)
tps = 726.545616 (excluding connections establishing)
postgres@ubuntu:~$
root@ubuntu:/var/log/postgresql# pgbadger postgresql-10-main.log
[========================>] Parsed 96663 bytes of 96663 (100.00%), queries: 0, events: 301
LOG: Ok, generating html report...
root@ubuntu:/var/log/postgresql# ls -l
total 1392
-rw-r--r-- 1 root root 1324353 May 24 10:34 out.html
-rw-r----- 1 postgres adm 96663 May 24 10:23 postgresql-10-main.log
pgbadger
*メモ:それぞれのパッケージは、aptもしくはyumでインストールしています。
pgbadgerのアウトプット

MySQL
負荷をかけてログを記録
[root@GA02 admin]# /usr/local/mysql/bin/mysqlslap --no-defaults --create-schema=SQLSLAP --auto-generate-sql --auto-generate-sql-add-autoincrement --engine=InnoDB --number-int-cols=3 --number-char-cols=5 --concurrency=30 --auto-generate-sql-write-number=1000 --auto-generate-sql-execute-number=1000 --auto-generate-sql-load-type=mixed -u root -p
Enter password:
Benchmark
Running for engine InnoDB
Average number of seconds to run all queries: 19.724 seconds
Minimum number of seconds to run all queries: 19.724 seconds
Maximum number of seconds to run all queries: 19.724 seconds
Number of clients running queries: 30
Average number of queries per client: 1000
[root@GA02 admin]#
mysqldumpslow (MySQL Default)でログ解析
[root@GA02 data]# mysqldumpslow -s c /usr/local/mysql/data/mysql-slow.log
Reading mysql slow query log from /usr/local/mysql/data/mysql-slow.log
Count: 17349 Time=0.03s (463s) Lock=0.00s (5s) Rows=0.0 (0), root[root]@localhost
INSERT INTO t1 VALUES (NULL,N,N,N,'S','S','S','S','S')
Count: 13375 Time=0.00s (2s) Lock=0.00s (1s) Rows=1.0 (13375), root[root]@localhost
SELECT intcol1,intcol2,intcol3,charcol1,charcol2,charcol3,charcol4,charcol5 FROM t1 WHERE id = 'S'
Count: 31 Time=0.00s (0s) Lock=0.00s (0s) Rows=1.0 (30), root[root]@localhost
#
Count: 31 Time=0.00s (0s) Lock=0.00s (0s) Rows=0.0 (0), 0users@0hosts
administrator command: Quit

Percona Tool Kitでログ解析
[root@GA02 admin]# wget https://repo.percona.com/yum/percona-release-latest.noarch.rpm
--2020-05-24 13:51:20-- https://repo.percona.com/yum/percona-release-latest.noarch.rpm
repo.percona.com (repo.percona.com) をDNSに問いあわせています... 167.71.118.3, 157.245.119.64, 167.99.233.229
repo.percona.com (repo.percona.com)|167.71.118.3|:443 に接続しています... 接続しました。
HTTP による接続要求を送信しました、応答を待っています... 200 OK
長さ: 17684 (17K) [application/x-redhat-package-manager]
`percona-release-latest.noarch.rpm' に保存中
100%[==============================================================================================================================================================================================>] 17,684 --.-K/s 時間 0s
2020-05-24 13:51:21 (51.5 GB/s) - `percona-release-latest.noarch.rpm' へ保存完了 [17684/17684]
[root@GA02 admin]# yum install percona-release-latest.noarch.rpm
読み込んだプラグイン:fastestmirror, priorities
percona-release-latest.noarch.rpm を調べています: percona-release-1.0-18.noarch
次のリポジトリーへの更新として percona-release-latest.noarch.rpm を設定します: percona-release-0.1-4.noarch
依存性の解決をしています
--> トランザクションの確認を実行しています。
---> パッケージ percona-release.noarch 0:0.1-4 を 更新
---> パッケージ percona-release.noarch 0:1.0-18 を アップデート
--> 依存性解決を終了しました。
依存性を解決しました
========================================================================================================================================================================================================================================
Package アーキテクチャー バージョン リポジトリー 容量
========================================================================================================================================================================================================================================
更新します:
percona-release noarch 1.0-18 /percona-release-latest.noarch 22 k
トランザクションの要約
========================================================================================================================================================================================================================================
更新 1 パッケージ
合計容量: 22 k
Is this ok [y/d/N]: y
Downloading packages:
Running transaction check
Running transaction test
Transaction test succeeded
Running transaction
更新します : percona-release-1.0-18.noarch 1/2
* Enabling the Percona Original repository
<*> All done!
The percona-release package now contains a percona-release script that can enable additional repositories for our newer products.
For example, to enable the Percona Server 8.0 repository use:
percona-release setup ps80
Note: To avoid conflicts with older product versions, the percona-release setup command may disable our original repository for some products.
For more information, please visit:
https://www.percona.com/doc/percona-repo-config/percona-release.html
整理中 : percona-release-0.1-4.noarch 2/2
検証中 : percona-release-1.0-18.noarch 1/2
検証中 : percona-release-0.1-4.noarch 2/2
更新:
percona-release.noarch 0:1.0-18
完了しました!
[root@GA02 admin]#
[root@GA02 admin]# yum install percona-toolkit
読み込んだプラグイン:fastestmirror, priorities
percona-release-noarch | 2.9 kB 00:00:00
percona-release-x86_64 | 2.9 kB 00:00:00
Loading mirror speeds from cached hostfile
* base: mirrors.cat.net
* epel: ftp.jaist.ac.jp
* extras: mirrors.cat.net
* updates: mirrors.cat.net
依存性の解決をしています
--> トランザクションの確認を実行しています。
---> パッケージ percona-toolkit.x86_64 0:3.2.0-1.el7 を インストール
--> 依存性解決を終了しました。
依存性を解決しました
========================================================================================================================================================================================================================================
Package アーキテクチャー バージョン リポジトリー 容量
========================================================================================================================================================================================================================================
インストール中:
percona-toolkit x86_64 3.2.0-1.el7 percona-release-x86_64 12 M
トランザクションの要約
========================================================================================================================================================================================================================================
インストール 1 パッケージ
総ダウンロード容量: 12 M
インストール容量: 12 M
Is this ok [y/d/N]: y
Downloading packages:
警告: /var/cache/yum/x86_64/7/percona-release-x86_64/packages/percona-toolkit-3.2.0-1.el7.x86_64.rpm: ヘッダー V4 RSA/SHA256 Signature、鍵 ID 8507efa5: NOKEY========================================-] 184 kB/s | 12 MB 00:00:00 ETA
percona-toolkit-3.2.0-1.el7.x86_64.rpm の公開鍵がインストールされていません
percona-toolkit-3.2.0-1.el7.x86_64.rpm | 12 MB 00:00:50
file:///etc/pki/rpm-gpg/PERCONA-PACKAGING-KEY から鍵を取得中です。
Importing GPG key 0x8507EFA5:
Userid : "Percona MySQL Development Team (Packaging key) <mysql-dev@percona.com>"
Fingerprint: 4d1b b29d 63d9 8e42 2b21 13b1 9334 a25f 8507 efa5
Package : percona-release-1.0-18.noarch (@/percona-release-latest.noarch)
From : /etc/pki/rpm-gpg/PERCONA-PACKAGING-KEY
上記の処理を行います。よろしいでしょうか? [y/N]y
Running transaction check
Running transaction test
Transaction test succeeded
Running transaction
インストール中 : percona-toolkit-3.2.0-1.el7.x86_64 1/1
検証中 : percona-toolkit-3.2.0-1.el7.x86_64 1/1
インストール:
percona-toolkit.x86_64 0:3.2.0-1.el7
完了しました!
[root@GA02 admin]#
pt-query-digestのアウトプット
[root@GA02 data]# pt-query-digest /usr/local/mysql/data/mysql-slow.log --no-version-check
# 20.9s user time, 50ms system time, 31.58M rss, 232.37M vsz
# Current date: Sun May 24 14:19:42 2020
# Hostname: GA02
# Files: /usr/local/mysql/data/mysql-slow.log
# Overall: 30.76k total, 9 unique, 242.22 QPS, 3.73x concurrency _________
# Time range: 2020-05-24T05:07:09 to 2020-05-24T05:09:16
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 474s 1us 221ms 15ms 34ms 15ms 20ms
# Lock time 7s 0 179ms 230us 332us 4ms 103us
# Rows sent 14.04k 0 999 0.47 0.99 5.52 0
# Rows examine 14.04k 0 999 0.47 0.99 5.52 0
# Query size 12.96M 17 707 441.72 685.39 291.70 685.39
# Profile
# Rank Query ID Response time Calls R/Call V/M I
# ==== =============================== ============== ===== ====== ===== =
# 1 0x76F7DD6D2A72EB7BCAEC22E79B... 468.9853 99.0% 17349 0.0270 0.00 INSERT t?
# MISC 0xMISC 4.5256 1.0% 13413 0.0003 0.0 <8 ITEMS>
# Query 1: 667.27 QPS, 18.04x concurrency, ID 0x76F7DD6D2A72EB7BCAEC22E79B0EFD3B at byte 988485
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2020-05-24T05:08:50 to 2020-05-24T05:09:16
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 56 17349
# Exec time 99 469s 1ms 221ms 27ms 38ms 11ms 26ms
# Lock time 75 5s 0 179ms 309us 384us 5ms 108us
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 0 0 0 0 0 0 0 0
# Query size 90 11.67M 704 707 705.36 685.39 0 685.39
# String:
# Databases SQLSLAP
# Hosts localhost
# Users root
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms ###
# 10ms ################################################################
# 100ms #
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `SQLSLAP` LIKE 't1'\G
# SHOW CREATE TABLE `SQLSLAP`.`t1`\G
INSERT INTO t1 VALUES (NULL,633998215,1598162325,1839677468,'l4dgQpQ2FFmHegccMlq0FmNIrmjthL1IPWzrCHuRYgk2KDWaqKb57qNyczrAKlSl7JcJcMe8uN26SYhItGF0yXybWhdqQxRQHvltIGuCfwJzTs9M0OEyv4PHl274sQ','W9M7ugNokudvtyn2CnJQmEMBO76N3yqZzCZtkwaSrBGc93XDjqfLwtOK0WkwKaLJeu5MrfiaiyAjuZwdNRyKKMYClG85iMHKGMaztHPR7SA11yWPPKddj9pKQqH8CQ','LKgvKZ4d0C52570cOHw1uXAkjSQ1TeJqy0lAPqoQ2lKzsLR8WG9PnC1NYRG1xbrvbdy1ReJLNfC8sgGFwIgbMhyu0EwxinsHGiAbKLoct1klhs0d2Y4O53J5972run','13L3eiPRAISuv1eoWhKaxQTGNfFIMA5F5QJj0k2A2WwxNRlt8yS5GpEfSTxjXuycD9CDtEGnd4d0XEufCEdS3j0O4p7ckx4x7G2sNAg0FH0mXmIc0nwwWoKaeJ2E87','3FFx0e8YWNpN1C9JgA6T6SHI3vdx1lw4tC2liAH5PySQ2dejfcCd5Lv0HOxA2uFnyHYYJhdcf52ZbYGE9KkEifErw31qx8dnH1KSax4DvzmWXvcY7KmhssOowIWlQz')\G
[root@GA02 data]#

MySQLのエラーログ含めてGUIで確認するのであればこんなツールもあります。
Percona Monitoring and Management
MySQL Enterprise Monitor